Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=363864007&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/O_eD48qJQnW4XT2T3Dt4Sg/runs/0/artifacts/public/logs/live_backing.log

[task 2022-01-12T14:00:05.253Z] 14:00:05     INFO - TEST-OK | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access_queue_request.js | took 967ms
[task 2022-01-12T14:00:05.322Z] 14:00:05     INFO - checking window state
[task 2022-01-12T14:00:05.346Z] 14:00:05     INFO - GECKO(2998) | (firefox:2998): Gdk-ERROR **: 14:00:05.343: The program 'firefox' received an X Window System error.
[task 2022-01-12T14:00:05.346Z] 14:00:05     INFO - GECKO(2998) | This probably reflects a bug in the program.
[task 2022-01-12T14:00:05.346Z] 14:00:05     INFO - GECKO(2998) | The error was 'BadDrawable (invalid Pixmap or Window parameter)'.
[task 2022-01-12T14:00:05.347Z] 14:00:05     INFO - GECKO(2998) |   (Details: serial 32162 error_code 9 request_code 55 (core protocol) minor_code 0)
[task 2022-01-12T14:00:05.348Z] 14:00:05     INFO - GECKO(2998) |   (Note to programmers: normally, X errors are reported asynchronously;
[task 2022-01-12T14:00:05.349Z] 14:00:05     INFO - GECKO(2998) |    that is, you will receive the error a while after causing it.
[task 2022-01-12T14:00:05.356Z] 14:00:05     INFO - GECKO(2998) |    To debug your program, run it with the GDK_SYNCHRONIZE environment
[task 2022-01-12T14:00:05.356Z] 14:00:05     INFO - GECKO(2998) |    variable to change this behavior. You can then get a meaningful
[task 2022-01-12T14:00:05.356Z] 14:00:05     INFO - GECKO(2998) |    backtrace from your debugger if you break on the gdk_x_error() function.)
[task 2022-01-12T14:00:05.437Z] 14:00:05     INFO - GECKO(2998) | Exiting due to channel error.
[task 2022-01-12T14:00:05.438Z] 14:00:05     INFO - GECKO(2998) | Exiting due to channel error.
[task 2022-01-12T14:00:05.438Z] 14:00:05     INFO - GECKO(2998) | Exiting due to channel error.
[task 2022-01-12T14:00:05.439Z] 14:00:05     INFO - GECKO(2998) | Exiting due to channel error.
[task 2022-01-12T14:00:05.440Z] 14:00:05     INFO - GECKO(2998) | Exiting due to channel error.
[task 2022-01-12T14:00:05.440Z] 14:00:05     INFO - GECKO(2998) | Exiting due to channel error.
[task 2022-01-12T14:00:05.528Z] 14:00:05     INFO - TEST-INFO | Main app process: killed by SIGTRAP
[task 2022-01-12T14:00:05.529Z] 14:00:05     INFO - Buffered messages finished
[task 2022-01-12T14:00:05.530Z] 14:00:05    ERROR - TEST-UNEXPECTED-FAIL | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access_queue_request.js (finished) | application terminated with exit code -5
[task 2022-01-12T14:00:05.531Z] 14:00:05     INFO - runtests.py | Application ran for: 0:01:10.324645
[task 2022-01-12T14:00:05.533Z] 14:00:05     INFO - zombiecheck | Reading PID log: /tmp/tmps810denvpidlog
[task 2022-01-12T14:00:05.534Z] 14:00:05     INFO - ==> process 2998 launched child process 3015
[task 2022-01-12T14:00:05.535Z] 14:00:05     INFO - ==> process 2998 launched child process 3066
[task 2022-01-12T14:00:05.536Z] 14:00:05     INFO - ==> process 2998 launched child process 3084
[task 2022-01-12T14:00:05.537Z] 14:00:05     INFO - ==> process 2998 launched child process 3139
[task 2022-01-12T14:00:05.540Z] 14:00:05     INFO - ==> process 2998 launched child process 3173
[task 2022-01-12T14:00:05.540Z] 14:00:05     INFO - ==> process 2998 launched child process 3188
[task 2022-01-12T14:00:05.540Z] 14:00:05     INFO - ==> process 2998 launched child process 3224
[task 2022-01-12T14:00:05.540Z] 14:00:05     INFO - zombiecheck | Checking for orphan process with PID: 3139
[task 2022-01-12T14:00:05.540Z] 14:00:05     INFO - zombiecheck | Checking for orphan process with PID: 3173
[task 2022-01-12T14:00:05.540Z] 14:00:05     INFO - zombiecheck | Checking for orphan process with PID: 3015
[task 2022-01-12T14:00:05.541Z] 14:00:05     INFO - zombiecheck | Checking for orphan process with PID: 3084
[task 2022-01-12T14:00:05.541Z] 14:00:05     INFO - zombiecheck | Checking for orphan process with PID: 3188
[task 2022-01-12T14:00:05.541Z] 14:00:05     INFO - zombiecheck | Checking for orphan process with PID: 3224
[task 2022-01-12T14:00:05.541Z] 14:00:05     INFO - zombiecheck | Checking for orphan process with PID: 3066
[task 2022-01-12T14:00:05.541Z] 14:00:05     INFO - Stopping web server
[task 2022-01-12T14:00:05.541Z] 14:00:05     INFO - Server shut down.
[task 2022-01-12T14:00:05.558Z] 14:00:05     INFO - Web server killed.
[task 2022-01-12T14:00:05.559Z] 14:00:05     INFO - Stopping web socket server
[task 2022-01-12T14:00:05.578Z] 14:00:05     INFO - Stopping ssltunnel
[task 2022-01-12T14:00:05.599Z] 14:00:05  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2022-01-12T14:00:05.599Z] 14:00:05     INFO - runtests.py | Running tests: end.
[task 2022-01-12T14:00:05.618Z] 14:00:05     INFO - Buffered messages finished
[task 2022-01-12T14:00:05.618Z] 14:00:05     INFO - Running manifest: browser/components/pocket/test/browser.ini
[task 2022-01-12T14:00:05.636Z] 14:00:05     INFO -  Setting pipeline to PAUSED ...
[task 2022-01-12T14:00:05.637Z] 14:00:05     INFO -  Pipeline is PREROLLING ...
[task 2022-01-12T14:00:05.639Z] 14:00:05     INFO -  Pipeline is PREROLLED ...
[task 2022-01-12T14:00:05.639Z] 14:00:05     INFO -  Setting pipeline to PLAYING ...
[task 2022-01-12T14:00:05.639Z] 14:00:05     INFO -  New clock: GstSystemClock
[task 2022-01-12T14:00:05.673Z] 14:00:05     INFO -  Got EOS from element "pipeline0".
[task 2022-01-12T14:00:05.673Z] 14:00:05     INFO -  Execution ended after 0:00:00.033390665
[task 2022-01-12T14:00:05.673Z] 14:00:05     INFO -  Setting pipeline to PAUSED ...
[task 2022-01-12T14:00:05.673Z] 14:00:05     INFO -  Setting pipeline to READY ...
[task 2022-01-12T14:00:05.674Z] 14:00:05     INFO -  (gst-launch-1.0:4076): GStreamer-CRITICAL **: 14:00:05.672: gst_object_unref: assertion '((GObject *) object)->ref_count > 0' failed
[task 2022-01-12T14:00:05.674Z] 14:00:05     INFO -  Setting pipeline to NULL ...
[task 2022-01-12T14:00:05.674Z] 14:00:05     INFO -  Freeing pipeline ...
[task 2022-01-12T14:00:05.699Z] 14:00:05     INFO - INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2022-01-12T14:00:05.702Z] 14:00:05     INFO - INFO | runtests.py | ASan running in default memory configuration
[task 2022-01-12T14:00:05.703Z] 14:00:05     INFO - UBSan enabled.
[task 2022-01-12T14:00:06.072Z] 14:00:06     INFO - PID 4094 | pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2022-01-12T14:00:06.104Z] 14:00:06     INFO - Increasing default timeout to 90 seconds
[task 2022-01-12T14:00:06.105Z] 14:00:06     INFO - INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2022-01-12T14:00:06.109Z] 14:00:06     INFO - LSan enabled.
[task 2022-01-12T14:00:06.109Z] 14:00:06     INFO - INFO | runtests.py | ASan running in default memory configuration
[task 2022-01-12T14:00:06.109Z] 14:00:06     INFO - UBSan enabled.
[task 2022-01-12T14:00:06.110Z] 14:00:06     INFO - INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2022-01-12T14:00:06.113Z] 14:00:06     INFO - INFO | runtests.py | ASan running in default memory configuration
[task 2022-01-12T14:00:06.114Z] 14:00:06     INFO - UBSan enabled.
[task 2022-01-12T14:00:06.123Z] 14:00:06     INFO - MochitestServer : launching ['/builds/worker/workspace/build/tests/bin/xpcshell', '-g', '/builds/worker/workspace/build/application/firefox', '-f', '/builds/worker/workspace/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmpvng7giwy.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/builds/worker/workspace/build/tests/mochitest/server.js']
[task 2022-01-12T14:00:06.123Z] 14:00:06     INFO - runtests.py | Server pid: 4101
[task 2022-01-12T14:00:06.137Z] 14:00:06     INFO - runtests.py | Websocket server pid: 4104
[task 2022-01-12T14:00:06.139Z] 14:00:06     INFO - INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2022-01-12T14:00:06.154Z] 14:00:06     INFO - INFO | runtests.py | ASan running in default memory configuration
[task 2022-01-12T14:00:06.154Z] 14:00:06     INFO - UBSan enabled.
[task 2022-01-12T14:00:06.174Z] 14:00:06     INFO - runtests.py | SSL tunnel pid: 4110
[task 2022-01-12T14:00:06.428Z] 14:00:06     INFO - runtests.py | Running with scheme: http
[task 2022-01-12T14:00:06.428Z] 14:00:06     INFO - runtests.py | Running with e10s: True
[task 2022-01-12T14:00:06.428Z] 14:00:06     INFO - runtests.py | Running with fission: False
[task 2022-01-12T14:00:06.428Z] 14:00:06     INFO - runtests.py | Running with cross-origin iframes: False
[task 2022-01-12T14:00:06.428Z] 14:00:06     INFO - runtests.py | Running with serviceworker_e10s: True
[task 2022-01-12T14:00:06.428Z] 14:00:06     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2022-01-12T14:00:06.428Z] 14:00:06     INFO - runtests.py | Running tests: start.
[task 2022-01-12T14:00:06.428Z] 14:00:06     INFO - 
[task 2022-01-12T14:00:06.443Z] 14:00:06     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpvng7giwy.mozrunner
[task 2022-01-12T14:00:06.457Z] 14:00:06     INFO - runtests.py | Application pid: 4126
[task 2022-01-12T14:00:06.457Z] 14:00:06     INFO - TEST-INFO | started process GECKO(4126)
[task 2022-01-12T14:00:07.618Z] 14:00:07     INFO - GECKO(4126) | 1641996007617	Marionette	INFO	Marionette enabled
[task 2022-01-12T14:00:07.812Z] 14:00:07     INFO - GECKO(4126) | 1641996007810	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2022-01-12T14:00:10.646Z] 14:00:10     INFO - GECKO(4126) | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpvng7giwy.mozrunner/search.json.mozlz4", (void 0)))
[task 2022-01-12T14:00:13.297Z] 14:00:13     INFO - GECKO(4126) | 1641996013296	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2022-01-12T14:00:13.299Z] 14:00:13     INFO - GECKO(4126) | 1641996013296	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2022-01-12T14:00:13.329Z] 14:00:13     INFO - GECKO(4126) | 1641996013328	Marionette	TRACE	All scripts recorded.
[task 2022-01-12T14:00:13.335Z] 14:00:13     INFO - GECKO(4126) | 1641996013334	Marionette	INFO	Listening on port 2828
[task 2022-01-12T14:00:13.337Z] 14:00:13     INFO - GECKO(4126) | 1641996013335	Marionette	DEBUG	Marionette is listening
[task 2022-01-12T14:00:13.443Z] 14:00:13     INFO - GECKO(4126) | 1641996013442	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:36010
[task 2022-01-12T14:00:13.456Z] 14:00:13     INFO - GECKO(4126) | 1641996013455	Marionette	DEBUG	Closed connection 0
[task 2022-01-12T14:00:13.457Z] 14:00:13     INFO - GECKO(4126) | 1641996013456	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:36012
[task 2022-01-12T14:00:13.474Z] 14:00:13     INFO - GECKO(4126) | 1641996013473	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2022-01-12T14:00:13.497Z] 14:00:13     INFO - GECKO(4126) | 1641996013496	RemoteAgent	TRACE	Initial navigation already completed
[task 2022-01-12T14:00:13.511Z] 14:00:13     INFO - GECKO(4126) | 1641996013510	Marionette	DEBUG	1 <- [1,1,null,{"sessionId":"ac7129da-8b0c-44f6-811b-42bea53c39a2","capabilities":{"browserName":"firefox","browserVersion":"98.0a ... .mozrunner","moz:shutdownTimeout":300000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2022-01-12T14:00:13.537Z] 14:00:13     INFO - GECKO(4126) | 1641996013533	Marionette	DEBUG	1 -> [0,2,"Addon:Install",{"path":"/tmp/tmprn96ll_s.zip","temporary":false}]
[task 2022-01-12T14:00:13.696Z] 14:00:13     INFO - GECKO(4126) | 1641996013695	Marionette	DEBUG	1 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
[task 2022-01-12T14:00:13.746Z] 14:00:13     INFO - GECKO(4126) | 1641996013743	Marionette	DEBUG	1 -> [0,3,"Addon:Install",{"path":"/tmp/tmpez2c_hl7.zip","temporary":false}]
[task 2022-01-12T14:00:13.790Z] 14:00:13     INFO - GECKO(4126) | 1641996013789	Marionette	DEBUG	1 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
[task 2022-01-12T14:00:13.793Z] 14:00:13     INFO - GECKO(4126) | 1641996013793	Marionette	DEBUG	1 -> [0,4,"Marionette:GetContext",{}]
[task 2022-01-12T14:00:13.795Z] 14:00:13     INFO - GECKO(4126) | 1641996013794	Marionette	DEBUG	1 <- [1,4,null,{"value":"content"}]
[task 2022-01-12T14:00:13.797Z] 14:00:13     INFO - GECKO(4126) | 1641996013797	Marionette	DEBUG	1 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-01-12T14:00:13.799Z] 14:00:13     INFO - GECKO(4126) | 1641996013798	Marionette	DEBUG	1 <- [1,5,null,{"value":null}]
[task 2022-01-12T14:00:13.806Z] 14:00:13     INFO - GECKO(4126) | 1641996013805	Marionette	DEBUG	1 -> [0,6,"WebDriver:ExecuteScript",{"script":"/* This Source Code Form is subject to the terms of the Mozilla Public\n * License, ... hrome","testUrl":"about:blank"}],"newSandbox":true,"sandbox":"default","line":1945,"filename":"tests/mochitest/runtests.py"}]
[task 2022-01-12T14:00:13.816Z] 14:00:13     INFO - GECKO(4126) | 1641996013815	Marionette	TRACE	[7] MarionetteCommands actor created for window id 2
[task 2022-01-12T14:00:13.867Z] 14:00:13     INFO - GECKO(4126) | 1641996013867	Marionette	TRACE	Received observer notification domwindowopened
[task 2022-01-12T14:00:13.881Z] 14:00:13     INFO - GECKO(4126) | 1641996013878	Marionette	DEBUG	1 <- [1,6,null,{"value":null}]
[task 2022-01-12T14:00:13.944Z] 14:00:13     INFO - GECKO(4126) | 1641996013943	Marionette	DEBUG	1 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2022-01-12T14:00:13.947Z] 14:00:13     INFO - GECKO(4126) | 1641996013946	Marionette	DEBUG	1 <- [1,7,null,{"value":null}]
[task 2022-01-12T14:00:13.993Z] 14:00:13     INFO - GECKO(4126) | 1641996013992	Marionette	DEBUG	1 -> [0,8,"WebDriver:DeleteSession",{}]
[task 2022-01-12T14:00:13.999Z] 14:00:13     INFO - GECKO(4126) | 1641996013998	Marionette	DEBUG	1 <- [1,8,null,{"value":null}]
[task 2022-01-12T14:00:14.003Z] 14:00:14     INFO - runtests.py | Waiting for browser...
[task 2022-01-12T14:00:14.008Z] 14:00:14     INFO - GECKO(4126) | 1641996014007	Marionette	DEBUG	Closed connection 1
[task 2022-01-12T14:00:14.412Z] 14:00:14     INFO - *** Start BrowserChrome Test Results ***
[task 2022-01-12T14:00:14.565Z] 14:00:14     INFO - checking window state
[task 2022-01-12T14:00:14.720Z] 14:00:14     INFO - TEST-START | browser/components/pocket/test/browser_pocket_button_icon_state.js