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

INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | only one global indicator window - 
[task 2021-05-19T22:26:11.993Z] 22:26:11     INFO - requesting devices
[task 2021-05-19T22:26:11.994Z] 22:26:11     INFO - Buffered messages finished
[task 2021-05-19T22:26:11.994Z] 22:26:11    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | application timed out after 370 seconds with no output
[task 2021-05-19T22:26:11.995Z] 22:26:11    ERROR - Force-terminating active process(es).
[task 2021-05-19T22:26:11.995Z] 22:26:11     INFO - Determining child pids from psutil...
[task 2021-05-19T22:26:11.996Z] 22:26:11     INFO - [9462, 9484, 9545, 9549, 9564, 9618, 9623, 9630, 9719, 9753, 9804, 9828, 9880, 9928, 9987, 10054]
[task 2021-05-19T22:26:11.996Z] 22:26:11     INFO - ==> process 9403 launched child process 9423
[task 2021-05-19T22:26:11.997Z] 22:26:11     INFO - ==> process 9403 launched child process 9462
[task 2021-05-19T22:26:11.997Z] 22:26:11     INFO - ==> process 9403 launched child process 9484
[task 2021-05-19T22:26:11.998Z] 22:26:11     INFO - ==> process 9403 launched child process 9545
[task 2021-05-19T22:26:11.999Z] 22:26:11     INFO - ==> process 9403 launched child process 9549
[task 2021-05-19T22:26:11.999Z] 22:26:11     INFO - ==> process 9403 launched child process 9564
[task 2021-05-19T22:26:12.000Z] 22:26:12     INFO - ==> process 9403 launched child process 9618
[task 2021-05-19T22:26:12.001Z] 22:26:12     INFO - ==> process 9403 launched child process 9623
[task 2021-05-19T22:26:12.001Z] 22:26:12     INFO - ==> process 9403 launched child process 9630
[task 2021-05-19T22:26:12.002Z] 22:26:12     INFO - ==> process 9403 launched child process 9719
[task 2021-05-19T22:26:12.003Z] 22:26:12     INFO - ==> process 9403 launched child process 9753
[task 2021-05-19T22:26:12.004Z] 22:26:12     INFO - ==> process 9403 launched child process 9804
[task 2021-05-19T22:26:12.004Z] 22:26:12     INFO - ==> process 9403 launched child process 9828
[task 2021-05-19T22:26:12.005Z] 22:26:12     INFO - ==> process 9403 launched child process 9880
[task 2021-05-19T22:26:12.006Z] 22:26:12     INFO - ==> process 9403 launched child process 9928
[task 2021-05-19T22:26:12.006Z] 22:26:12     INFO - ==> process 9403 launched child process 9987
[task 2021-05-19T22:26:12.007Z] 22:26:12     INFO - ==> process 9403 launched child process 10054
[task 2021-05-19T22:26:12.007Z] 22:26:12     INFO - Found child pids: {9719, 9828, 9987, 10054, 9928, 9545, 9484, 9549, 9804, 9423, 9618, 9462, 9623, 9880, 9753, 9564, 9630}
[task 2021-05-19T22:26:12.008Z] 22:26:12     INFO - Failed to get child procs
[task 2021-05-19T22:26:12.008Z] 22:26:12     INFO - Killing process: 9719
[task 2021-05-19T22:26:12.009Z] 22:26:12     INFO - TEST-INFO | started process screentopng
[task 2021-05-19T22:26:12.254Z] 22:26:12     INFO - TEST-INFO | screentopng: exit 0
[task 2021-05-19T22:26:12.254Z] 22:26:12     INFO - Killing process: 9828
[task 2021-05-19T22:26:12.254Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.254Z] 22:26:12     INFO - Killing process: 9987
[task 2021-05-19T22:26:12.254Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.254Z] 22:26:12     INFO - Killing process: 10054
[task 2021-05-19T22:26:12.255Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.256Z] 22:26:12     INFO - Killing process: 9928
[task 2021-05-19T22:26:12.256Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.258Z] 22:26:12     INFO - Killing process: 9545
[task 2021-05-19T22:26:12.260Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.261Z] 22:26:12     INFO - Killing process: 9484
[task 2021-05-19T22:26:12.261Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.262Z] 22:26:12     INFO - Killing process: 9549
[task 2021-05-19T22:26:12.262Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.269Z] 22:26:12     INFO - Killing process: 9804
[task 2021-05-19T22:26:12.269Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.269Z] 22:26:12     INFO - Killing process: 9423
[task 2021-05-19T22:26:12.270Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.270Z] 22:26:12     INFO - Can't trigger Breakpad, process no longer exists
[task 2021-05-19T22:26:12.270Z] 22:26:12     INFO - Killing process: 9618
[task 2021-05-19T22:26:12.270Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.271Z] 22:26:12     INFO - Killing process: 9462
[task 2021-05-19T22:26:12.271Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.271Z] 22:26:12     INFO - Killing process: 9623
[task 2021-05-19T22:26:12.271Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.272Z] 22:26:12     INFO - Killing process: 9880
[task 2021-05-19T22:26:12.272Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.273Z] 22:26:12     INFO - Killing process: 9753
[task 2021-05-19T22:26:12.273Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.274Z] 22:26:12     INFO - Killing process: 9564
[task 2021-05-19T22:26:12.274Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.275Z] 22:26:12     INFO - Killing process: 9630
[task 2021-05-19T22:26:12.275Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.276Z] 22:26:12     INFO - Killing process: 9403
[task 2021-05-19T22:26:12.276Z] 22:26:12     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-19T22:26:12.446Z] 22:26:12     INFO - psutil found pid 9403 dead
[task 2021-05-19T22:26:12.457Z] 22:26:12     INFO - TEST-INFO | Main app process: exit 0
[task 2021-05-19T22:26:12.458Z] 22:26:12    ERROR - TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite
[task 2021-05-19T22:26:12.458Z] 22:26:12     INFO - TEST-INFO | Confirming we saw 68 DOCSHELL created and 46 destroyed log strings.
[task 2021-05-19T22:26:12.458Z] 22:26:12     INFO - TEST-INFO | Confirming we saw 161 DOMWINDOW created and 106 destroyed log strings.
[task 2021-05-19T22:26:12.459Z] 22:26:12     INFO - runtests.py | Application ran for: 0:06:59.413656
[task 2021-05-19T22:26:12.459Z] 22:26:12     INFO - zombiecheck | Reading PID log: /tmp/tmp9g2w6_21pidlog
[task 2021-05-19T22:26:12.460Z] 22:26:12     INFO - ==> process 9403 launched child process 9423
[task 2021-05-19T22:26:12.461Z] 22:26:12     INFO - ==> process 9403 launched child process 9462
[task 2021-05-19T22:26:12.462Z] 22:26:12     INFO - ==> process 9403 launched child process 9484
[task 2021-05-19T22:26:12.463Z] 22:26:12     INFO - ==> process 9403 launched child process 9545
[task 2021-05-19T22:26:12.463Z] 22:26:12     INFO - ==> process 9403 launched child process 9549
[task 2021-05-19T22:26:12.464Z] 22:26:12     INFO - ==> process 9403 launched child process 9564
[task 2021-05-19T22:26:12.466Z] 22:26:12     INFO - ==> process 9403 launched child process 9618
[task 2021-05-19T22:26:12.466Z] 22:26:12     INFO - ==> process 9403 launched child process 9623
[task 2021-05-19T22:26:12.467Z] 22:26:12     INFO - ==> process 9403 launched child process 9630
[task 2021-05-19T22:26:12.467Z] 22:26:12     INFO - ==> process 9403 launched child process 9719
[task 2021-05-19T22:26:12.468Z] 22:26:12     INFO - ==> process 9403 launched child process 9753
[task 2021-05-19T22:26:12.468Z] 22:26:12     INFO - ==> process 9403 launched child process 9804
[task 2021-05-19T22:26:12.473Z] 22:26:12     INFO - ==> process 9403 launched child process 9828
[task 2021-05-19T22:26:12.481Z] 22:26:12     INFO - ==> process 9403 launched child process 9880
[task 2021-05-19T22:26:12.481Z] 22:26:12     INFO - ==> process 9403 launched child process 9928
[task 2021-05-19T22:26:12.482Z] 22:26:12     INFO - ==> process 9403 launched child process 9987
[task 2021-05-19T22:26:12.482Z] 22:26:12     INFO - ==> process 9403 launched child process 10054
[task 2021-05-19T22:26:12.482Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9719
[task 2021-05-19T22:26:12.483Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9828
[task 2021-05-19T22:26:12.483Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9987
[task 2021-05-19T22:26:12.483Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 10054
[task 2021-05-19T22:26:12.484Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9928
[task 2021-05-19T22:26:12.484Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9545
[task 2021-05-19T22:26:12.484Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9484
[task 2021-05-19T22:26:12.484Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9549
[task 2021-05-19T22:26:12.485Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9804
[task 2021-05-19T22:26:12.485Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9423
[task 2021-05-19T22:26:12.485Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9618
[task 2021-05-19T22:26:12.486Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9462
[task 2021-05-19T22:26:12.486Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9623
[task 2021-05-19T22:26:12.486Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9880
[task 2021-05-19T22:26:12.487Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9753
[task 2021-05-19T22:26:12.487Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9564
[task 2021-05-19T22:26:12.487Z] 22:26:12     INFO - zombiecheck | Checking for orphan process with PID: 9630
[task 2021-05-19T22:26:12.488Z] 22:26:12     INFO - mozcrash Copy/paste: /builds/worker/fetches/minidump_stackwalk/minidump_stackwalk /tmp/tmpxf2p3_za.mozrunner/minidumps/76f36a30-ac4a-9ba7-ea59-f37966fdc44f.dmp /builds/worker/workspace/build/symbols
[task 2021-05-19T22:26:12.504Z] 22:26:12     INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/76f36a30-ac4a-9ba7-ea59-f37966fdc44f.dmp
[task 2021-05-19T22:26:12.504Z] 22:26:12     INFO - PROCESS-CRASH | Main app process exited normally | application crashed [None]
[task 2021-05-19T22:26:12.505Z] 22:26:12     INFO - Crash dump filename: /tmp/tmpxf2p3_za.mozrunner/minidumps/76f36a30-ac4a-9ba7-ea59-f37966fdc44f.dmp
[task 2021-05-19T22:26:12.505Z] 22:26:12     INFO - stderr from minidump_stackwalk:
[task 2021-05-19T22:26:12.505Z] 22:26:12     INFO - 2021-05-19 22:26:12: minidump_stackwalk.cc:141: ERROR: MinidumpProcessor::Process failed
[task 2021-05-19T22:26:12.505Z] 22:26:12     INFO - mozcrash Copy/paste: /builds/worker/fetches/minidump_stackwalk/minidump_stackwalk /tmp/tmpxf2p3_za.mozrunner/minidumps/3aabc204-341d-563e-6cc9-a718c6471a7c.dmp /builds/worker/workspace/build/symbols
[task 2021-05-19T22:26:18.190Z] 22:26:18     INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/3aabc204-341d-563e-6cc9-a718c6471a7c.dmp
[task 2021-05-19T22:26:18.190Z] 22:26:18     INFO - mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/3aabc204-341d-563e-6cc9-a718c6471a7c.extra
[task 2021-05-19T22:26:18.377Z] 22:26:18     INFO - PROCESS-CRASH | Main app process exited normally | application crashed [@ js::ShapeIC::init(JSContext*)]
[task 2021-05-19T22:26:18.378Z] 22:26:18     INFO - Crash dump filename: /tmp/tmpxf2p3_za.mozrunner/minidumps/3aabc204-341d-563e-6cc9-a718c6471a7c.dmp
[task 2021-05-19T22:26:18.378Z] 22:26:18     INFO - Operating system: Linux
[task 2021-05-19T22:26:18.378Z] 22:26:18     INFO -                   0.0.0 Linux 4.4.0-1014-aws #14taskcluster1-Ubuntu SMP Tue Apr 3 10:27:00 UTC 2018 x86_64
[task 2021-05-19T22:26:18.378Z] 22:26:18     INFO - CPU: amd64
[task 2021-05-19T22:26:18.378Z] 22:26:18     INFO -      family 6 model 85 stepping 4
[task 2021-05-19T22:26:18.379Z] 22:26:18     INFO -      2 CPUs
[task 2021-05-19T22:26:18.379Z] 22:26:18     INFO - 
[task 2021-05-19T22:26:18.379Z] 22:26:18     INFO - GPU: UNKNOWN
[task 2021-05-19T22:26:18.380Z] 22:26:18     INFO - 
[task 2021-05-19T22:26:18.380Z] 22:26:18     INFO - Crash reason:  SIGABRT
[task 2021-05-19T22:26:18.380Z] 22:26:18     INFO - Crash address: 0x3e8000005d2
[task 2021-05-19T22:26:18.380Z] 22:26:18     INFO - Process uptime: not available
[task 2021-05-19T22:26:18.380Z] 22:26:18     INFO - 
[task 2021-05-19T22:26:18.381Z] 22:26:18     INFO - Thread 0 (crashed)```

Update:
There have been 42 failures within the last 7 days:
• 2 failures on Linux 18.04 x64 WebRender asan opt
• 11 failures on Linux 18.04 x64 WebRender debug
• 19 failures on Linux 18.04 x64 WebRender opt
• 10 failures on Linux 18.04 x64 WebRender Shippable opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=366851930&repo=autoland&lineNumber=5611

[task 2022-02-05T21:49:01.766Z] 21:49:01     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | only one global indicator window - 
[task 2022-02-05T21:49:01.766Z] 21:49:01     INFO - requesting devices
[task 2022-02-05T21:49:01.766Z] 21:49:01     INFO - Buffered messages finished
[task 2022-02-05T21:49:01.766Z] 21:49:01    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | application timed out after 370 seconds with no output
[task 2022-02-05T21:49:01.767Z] 21:49:01    ERROR - Force-terminating active process(es).
[task 2022-02-05T21:49:01.767Z] 21:49:01     INFO - Determining child pids from psutil...
[task 2022-02-05T21:49:01.773Z] 21:49:01     INFO - [5962, 6029, 6087, 6131, 6307, 6337, 6401, 6594]
[task 2022-02-05T21:49:01.774Z] 21:49:01     INFO - ==> process 5928 launched child process 5949
[task 2022-02-05T21:49:01.775Z] 21:49:01     INFO - ==> process 5928 launched child process 5962
[task 2022-02-05T21:49:01.775Z] 21:49:01     INFO - ==> process 5928 launched child process 6007
[task 2022-02-05T21:49:01.776Z] 21:49:01     INFO - ==> process 5928 launched child process 6029
[task 2022-02-05T21:49:01.777Z] 21:49:01     INFO - ==> process 5928 launched child process 6087
[task 2022-02-05T21:49:01.777Z] 21:49:01     INFO - ==> process 5928 launched child process 6131
[task 2022-02-05T21:49:01.778Z] 21:49:01     INFO - ==> process 5928 launched child process 6163
[task 2022-02-05T21:49:01.779Z] 21:49:01     INFO - ==> process 5928 launched child process 6203
[task 2022-02-05T21:49:01.779Z] 21:49:01     INFO - ==> process 5928 launched child process 6239
[task 2022-02-05T21:49:01.780Z] 21:49:01     INFO - ==> process 5928 launched child process 6282
[task 2022-02-05T21:49:01.781Z] 21:49:01     INFO - ==> process 5928 launched child process 6307
[task 2022-02-05T21:49:01.781Z] 21:49:01     INFO - ==> process 5928 launched child process 6337
[task 2022-02-05T21:49:01.782Z] 21:49:01     INFO - ==> process 5928 launched child process 6401
[task 2022-02-05T21:49:01.782Z] 21:49:01     INFO - ==> process 5928 launched child process 6594
[task 2022-02-05T21:49:01.783Z] 21:49:01     INFO - Found child pids: {6337, 6401, 6307, 6594, 6087, 5962, 6282, 6029, 6131, 6163, 6007, 6203, 5949, 6239}
[task 2022-02-05T21:49:01.784Z] 21:49:01     INFO - Failed to get child procs
[task 2022-02-05T21:49:01.784Z] 21:49:01     INFO - Killing process: 6337
[task 2022-02-05T21:49:01.785Z] 21:49:01     INFO - TEST-INFO | started process screentopng
[task 2022-02-05T22:05:41.809Z] 22:05:41     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/mochitest/runtests.py', 'accessible/tests/browser/mac/browser.ini', 'browser/base/content/test/fullscreen/browser.ini', 'browser/base/content/test/menubar/browser.ini', 'browser/base/content/test/performance/hidpi/browser.ini', 'browser/base/content/test/performance/lowdpi/browser.ini', 'browser/base/content/test/plugins/browser.ini', 'browser/base/content/test/referrer/browser.ini', 'browser/base/content/test/startup/browser.ini', 'browser/base/content/test/tabdialogs/browser.ini', 'browser/base/content/test/tabs/browser.ini', 'browser/base/content/test/touch/browser.ini', 'browser/base/content/test/webextensions/browser.ini', 'browser/base/content/test/webrtc/browser.ini', 'browser/components/attribution/test/browser/browser.ini', 'browser/components/enterprisepolicies/tests/browser/disable_default_bookmarks/browser.ini', 'browser/components/enterprisepolicies/tests/browser/disable_developer_tools/browser.ini', 'browser/components/extensions/test/browser/browser-private.ini', 'browser/components/newtab/test/browser/abouthomecache/browser.ini', 'browser/components/pagedata/tests/browser/browser.ini', 'browser/components/payments/test/browser/browser.ini', 'browser/components/safebrowsing/content/test/browser.ini', 'browser/components/sessionstore/test/browser.ini', 'browser/components/shell/test/browser.ini', 'browser/components/tests/browser/browser.ini', 'browser/components/touchbar/tests/browser/browser.ini', 'browser/components/translation/test/browser.ini', 'browser/components/urlbar/tests/quicksuggest/browser/browser.ini', 'browser/extensions/pictureinpicture/tests/browser/browser.ini', 'browser/extensions/report-site-issue/test/browser/browser.ini', 'dom/crypto/test/browser/browser.ini', 'dom/indexedDB/test/browser.ini', 'dom/localstorage/test/browser.ini', 'dom/media/mediacontrol/tests/browser/browser.ini', 'dom/media/test/browser/browser.ini', 'dom/payments/test/browser.ini', 'dom/quota/test/browser/browser.ini', 'dom/serviceworkers/test/isolated/multi-e10s-update/browser.ini', 'dom/xhr/tests/browser.ini', 'editor/libeditor/tests/browser.ini', 'ipc/glue/test/browser/browser.ini', 'layout/tools/layout-debug/tests/browser/browser.ini', 'parser/htmlparser/tests/mochitest/browser.ini', 'testing/mochitest/baselinecoverage/browser_chrome/browser.ini', 'testing/mochitest/tests/browser/browser.ini', 'toolkit/components/alerts/test/browser.ini', 'toolkit/components/backgroundtasks/tests/browser/browser.ini', 'toolkit/components/extensions/test/browser/browser.ini', 'toolkit/components/messaging-system/schemas/TriggerActionSchemas/test/browser/browser.ini', 'toolkit/components/normandy/test/browser/browser.ini', 'toolkit/components/pictureinpicture/tests/browser.ini', 'toolkit/components/processtools/tests/browser/browser.ini', 'toolkit/components/remotepagemanager/tests/browser/browser.ini', 'toolkit/components/startup/tests/browser/browser.ini', 'toolkit/content/tests/browser/browser.ini', 'toolkit/mozapps/update/tests/browser/browser.bits.ini', 'toolkit/xre/test/browser.ini', '--setpref=network.process.enabled=true', '--setpref=network.http.network_access_on_socket_process.enabled=true', '--setpref=network.ssl_tokens_cache_enabled=true', '--setpref=layers.d3d11.enable-blacklist=false', '--setpref=fission.autostart=false', '--appname=/builds/worker/workspace/build/application/firefox/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/eCkgWYFhTUyDBlZmHk335Q/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--setpref=webgl.force-enabled=true', '--quiet', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/mochitest-browser-chrome_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/mochitest-browser-chrome_errorsummary.log', '--use-test-media-devices', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/builds/worker/workspace/build', '--log-raw=-', '--flavor=browser', '--chunk-by-runtime']
[task 2022-02-05T22:05:41.809Z] 22:05:41    ERROR - timed out after 1000 seconds of no output
[task 2022-02-05T22:05:41.810Z] 22:05:41    ERROR - Return code: -15
[task 2022-02-05T22:05:41.811Z] 22:05:41    ERROR - No suite end message was emitted by this harness.
[task 2022-02-05T22:05:41.812Z] 22:05:41     INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>371/0/0
[task 2022-02-05T22:05:41.812Z] 22:05:41    ERROR - # TBPL FAILURE #
[task 2022-02-05T22:05:41.813Z] 22:05:41  WARNING - setting return code to 2
[task 2022-02-05T22:05:41.813Z] 22:05:41    ERROR - The mochitest suite: mochitest-browser-chrome ran with return status: FAILURE

Hi Michael! Can you please take a look at this? And maybe you could help us assign it to someone.
Thank you!

Jan-Ivar, since this is related to get_user_media, is this something you might have insight into and can investigate?

Update:

There have been 50 failures within the last 7 days:

• 17 failures on Linux 18.04 x64 WebRender Shippable opt
• 28 failures on Linux 18.04 x64 WebRender opt/debug
• 5 failures on Linux 18.04 x64 WebRender asan opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=367691649&repo=autoland&lineNumber=7037

[task 2022-02-12T23:43:29.293Z] 23:43:29     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | only one global indicator window - 
[task 2022-02-12T23:43:29.294Z] 23:43:29     INFO - requesting devices
[task 2022-02-12T23:43:29.294Z] 23:43:29     INFO - Buffered messages finished
[task 2022-02-12T23:43:29.295Z] 23:43:29    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | application timed out after 370 seconds with no output
[task 2022-02-12T23:43:29.296Z] 23:43:29    ERROR - Force-terminating active process(es).
[task 2022-02-12T23:43:29.297Z] 23:43:29     INFO - Determining child pids from psutil...

Running on my linux box locally, I see this timeout happen reliably when I run in headless mode, but seemingly never when running with a display.

Also appears to be related to running with privacy.webrtc.legacyGlobalIndicator=true.

I've run some more local tests. When privacy.webrtc.legacyGlobalIndicator=true and --headless, the first test, checkAudioVideoWhileLiveTracksExist_audio_camera always seems to timeout waiting for promiseMessage("ok") here. If I remove that test locally, the other tests seem to be ok.

:mconley, since you split these tests into legacy vs new, do you have any thoughts here? Should we simply disable browser_devices_get_user_media_unprompted_access.js on linux for the legacy indicator case?

Try disabling for the legacyGlobalIndicator case:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=3e20a8fe7b02bc4dd2a1829a4d7a80074a7a2386

Temporarily disable this test on linux for the legacyGlobalIndicator case
since it seems to consistently timeout.

Hi mjf,

Sorry I never got back to you in time. :/ I suspect part of the issue is that the old-school indicator is stealing window focus which is preventing the test from proceeding. I had a patch up at https://treeherder.mozilla.org/jobs?repo=try&revision=75dce818681955cfd381edc40f3c607811ce2471 to try to fix this, but it seemed to cause failures in other tests. :/

Try run looks good. I'll mark this leave-open, and then land the patch to disable.

https://hg.mozilla.org/mozilla-central/rev/8d687d25ef96

Michael, looks like this is still failing quite often: https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2022-02-18&endday=2022-02-25&tree=trunk&bug=1712012
Should we try to disable this one instead? https://searchfox.org/mozilla-central/source/browser/base/content/test/webrtc/browser.ini#72 I could put up a patch for that.

It is odd because I never saw the legacyGlobalIndicator=false case timeout when running it locally. I guess there are simply issues with this test. For now disabling the test seems reasonable until someone has time to look into it.

I also think it is odd that the test stalls right after requesting devices, but then appears to write out all the passing tests:

[task 2022-02-25T15:41:20.224Z] 15:41:20     INFO - TEST-START | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js
[task 2022-02-25T15:41:20.332Z] 15:41:20     INFO - GECKO(20233) | TEST DEVICES: Using media devices:
[task 2022-02-25T15:41:20.333Z] 15:41:20     INFO - GECKO(20233) | audio: Monitor of Null Output
[task 2022-02-25T15:41:20.335Z] 15:41:20     INFO - GECKO(20233) | video: Dummy video device (0x0000)
[task 2022-02-25T15:47:30.916Z] 15:47:30     INFO - Buffered messages logged at 15:41:20
[task 2022-02-25T15:47:30.917Z] 15:47:30     INFO - Entering test bound test
[task 2022-02-25T15:47:30.918Z] 15:47:30     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | should start the test without any prior popup notification - 
[task 2022-02-25T15:47:30.918Z] 15:47:30     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | should start the test with the permission panel hidden - 
<snip>
[task 2022-02-25T15:47:30.965Z] 15:47:30     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | browserwindow global indicator attribute as expected - 
[task 2022-02-25T15:47:30.966Z] 15:47:30     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | only one global indicator window - 
[task 2022-02-25T15:47:30.966Z] 15:47:30     INFO - requesting devices
[task 2022-02-25T15:47:30.967Z] 15:47:30     INFO - Buffered messages finished
[task 2022-02-25T15:47:30.968Z] 15:47:30    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | application timed out after 370 seconds with no output

:jib, do you have time to look into this?

I also think it is odd that the test stalls right after requesting devices, but then appears to write out all the passing tests:

This might be explained by there apparently being some buffering of the output happening:

[task 2022-02-25T15:47:30.916Z] 15:47:30     INFO - Buffered messages logged at 15:41:20

I've never understood why, but it does make it hard to know exactly where things stalled. See also bug 1020516.

I think I might have a solution here.

Some of our WebRTC UI tests wait for a PopupNotification to be shown
requesting performissions for the devices being shared, but those
PopupNotifications will only ever appear if the associated browser
window has focus.

This updates the promiseRequestDevices helper function to ensure that
the associated browser window is focused before resolving.

Try push: https://treeherder.mozilla.org/jobs?repo=try&revision=3cb53a4ef2758ae805713bbecc6493d0d9765a82

Hm, one recurrence of the original failure here in my try push so far: https://treeherder.mozilla.org/jobs?repo=try&revision=3cb53a4ef2758ae805713bbecc6493d0d9765a82&selectedTaskRun=TASA9MegT9eAcCD00scEmQ.0

There are 42 total failures in the last 7 days on

• linux1804-64-shippable-qr opt
• linux1804-64-qr opt
  Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=371321040&repo=autoland&lineNumber=6295

[task 2022-03-17T00:05:25.845Z] 00:05:25     INFO - TEST-START | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js
[task 2022-03-17T00:05:25.940Z] 00:05:25     INFO - GECKO(19909) | TEST DEVICES: Using media devices:
[task 2022-03-17T00:05:25.942Z] 00:05:25     INFO - GECKO(19909) | audio: Monitor of Null Output
[task 2022-03-17T00:05:25.942Z] 00:05:25     INFO - GECKO(19909) | video: Dummy video device (0x0000)
[task 2022-03-17T00:11:36.462Z] 00:11:36     INFO - Buffered messages logged at 00:05:25
[task 2022-03-17T00:11:36.463Z] 00:11:36     INFO - Entering test bound test
[task 2022-03-17T00:11:36.463Z] 00:11:36     INFO - Buffered messages logged at 00:05:26
[task 2022-03-17T00:11:36.463Z] 00:11:36     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | should start the test without any prior popup notification - 
[task 2022-03-17T00:11:36.463Z] 00:11:36     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | should start the test with the permission panel hidden - 
[task 2022-03-17T00:11:36.465Z] 00:11:36     INFO - getUserMedia audio+camera
[task 2022-03-17T00:11:36.466Z] 00:11:36     INFO - requesting devices

[task 2022-03-17T00:11:36.518Z] 00:11:36     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | only one global indicator window - 
[task 2022-03-17T00:11:36.519Z] 00:11:36     INFO - requesting devices
[task 2022-03-17T00:11:36.519Z] 00:11:36     INFO - Buffered messages finished
[task 2022-03-17T00:11:36.519Z] 00:11:36    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/base/content/test/webrtc/browser_devices_get_user_media_unprompted_access.js | application timed out after 370 seconds with no output
[task 2022-03-17T00:11:36.520Z] 00:11:36    ERROR - Force-terminating active process(es).
[task 2022-03-17T00:11:36.521Z] 00:11:36     INFO - Determining child pids from psutil...
[task 2022-03-17T00:11:36.527Z] 00:11:36     INFO - [19974, 20037, 20083, 20260, 21672, 21675, 21681]
[task 2022-03-17T00:11:36.529Z] 00:11:36     INFO - ==> process 19909 launched child process 19930
[task 2022-03-17T00:11:36.531Z] 00:11:36     INFO - ==> process 19909 launched child process 19974
[task 2022-03-17T00:11:36.532Z] 00:11:36     INFO - ==> process 19909 launched child process 20002
[task 2022-03-17T00:11:36.533Z] 00:11:36     INFO - ==> process 19909 launched child process 20037
[task 2022-03-17T00:11:36.535Z] 00:11:36     INFO - ==> process 19909 launched child process 20083
[task 2022-03-17T00:11:36.537Z] 00:11:36     INFO - ==> process 19909 launched child process 20104
[task 2022-03-17T00:11:36.538Z] 00:11:36     INFO - ==> process 19909 launched child process 20160
[task 2022-03-17T00:11:36.539Z] 00:11:36     INFO - ==> process 19909 launched child process 20163
[task 2022-03-17T00:11:36.540Z] 00:11:36     INFO - ==> process 19909 launched child process 20257
[task 2022-03-17T00:11:36.540Z] 00:11:36     INFO - ==> process 19909 launched child process 20260
[task 2022-03-17T00:11:36.541Z] 00:11:36     INFO - ==> process 19909 launched child process 20263
[task 2022-03-17T00:11:36.542Z] 00:11:36     INFO - ==> process 19909 launched child process 20324
[task 2022-03-17T00:11:36.543Z] 00:11:36     INFO - ==> process 19909 launched child process 20357
[task 2022-03-17T00:11:36.544Z] 00:11:36     INFO - ==> process 19909 launched child process 20377
[task 2022-03-17T00:11:36.545Z] 00:11:36     INFO - ==> process 19909 launched child process 20443
[task 2022-03-17T00:11:36.546Z] 00:11:36     INFO - ==> process 19909 launched child process 20545
[task 2022-03-17T00:11:36.547Z] 00:11:36     INFO - ==> process 19909 launched child process 20548
[task 2022-03-17T00:11:36.549Z] 00:11:36     INFO - ==> process 19909 launched child process 20627
[task 2022-03-17T00:11:36.550Z] 00:11:36     INFO - ==> process 19909 launched child process 20756
[task 2022-03-17T00:11:36.551Z] 00:11:36     INFO - ==> process 19909 launched child process 20766
[task 2022-03-17T00:11:36.552Z] 00:11:36     INFO - ==> process 19909 launched child process 20780
[task 2022-03-17T00:11:36.553Z] 00:11:36     INFO - ==> process 19909 launched child process 20783
[task 2022-03-17T00:11:36.554Z] 00:11:36     INFO - ==> process 19909 launched child process 20948
[task 2022-03-17T00:11:36.555Z] 00:11:36     INFO - ==> process 19909 launched child process 20951
[task 2022-03-17T00:11:36.556Z] 00:11:36     INFO - ==> process 19909 launched child process 21002
[task 2022-03-17T00:11:36.557Z] 00:11:36     INFO - ==> process 19909 launched child process 21006
[task 2022-03-17T00:11:36.558Z] 00:11:36     INFO - ==> process 19909 launched child process 21140
[task 2022-03-17T00:11:36.559Z] 00:11:36     INFO - ==> process 19909 launched child process 21143
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - ==> process 19909 launched child process 21194
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - ==> process 19909 launched child process 21367
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - ==> process 19909 launched child process 21429
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - ==> process 19909 launched child process 21459
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - ==> process 19909 launched child process 21469
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - ==> process 19909 launched child process 21536
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - ==> process 19909 launched child process 21577
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - ==> process 19909 launched child process 21672
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - ==> process 19909 launched child process 21675
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - ==> process 19909 launched child process 21681
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - Found child pids: {20357, 19974, 20104, 21002, 21006, 20627, 20756, 21140, 21143, 20377, 20766, 21536, 20257, 20002, 20260, 20263, 21672, 21675, 20780, 20783, 21681, 21429, 20160, 20545, 20163, 20548, 20037, 21577, 21194, 21459, 20948, 20951, 19930, 20443, 21469, 20324, 20083, 21367}
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - Failed to get child procs
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - Killing process: 20357
[task 2022-03-17T00:11:36.560Z] 00:11:36     INFO - TEST-INFO | started process screentopng
[task 2022-03-17T00:28:16.591Z] 00:28:16     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/mochitest/runtests.py', 'browser/base/content/test/outOfProcess/browser.ini', 'browser/base/content/test/pageActions/browser.ini', 'browser/base/content/test/pageinfo/browser.ini', 'browser/base/content/test/referrer/browser.ini', 'browser/base/content/test/statuspanel/browser.ini', 'browser/base/content/test/tabMediaIndicator/browser.ini', 'browser/base/content/test/tabs/browser.ini', 'browser/base/content/test/webrtc/browser.ini', 'browser/base/content/test/zoom/browser.ini', 'browser/components/contextualidentity/test/browser/browser.ini', 'browser/components/pagedata/tests/browser/browser.ini', 'browser/components/sessionstore/test/browser.ini', 'browser/components/urlbar/tests/ext/browser/browser.ini', 'browser/components/urlbar/tests/quicksuggest/browser/browser.ini', 'browser/modules/test/browser/formValidation/browser.ini', 'dom/ipc/tests/JSProcessActor/browser.ini', 'dom/ipc/tests/browser.ini', 'dom/media/test/browser/browser.ini', 'dom/security/test/csp/browser.ini', 'dom/security/test/https-only/browser.ini', 'ipc/glue/test/browser/browser.ini', 'services/fxaccounts/tests/browser/browser.ini', 'toolkit/components/alerts/test/browser.ini', 'toolkit/components/cleardata/tests/browser/browser.ini', 'toolkit/components/enterprisepolicies/tests/browser/browser.ini', 'toolkit/components/pictureinpicture/tests/browser.ini', 'toolkit/components/places/tests/browser/previews/browser.ini', 'toolkit/components/reader/test/browser.ini', 'toolkit/components/thumbnails/test/browser.ini', 'toolkit/components/utils/test/browser/browser.ini', 'toolkit/content/tests/browser/browser.ini', 'toolkit/modules/tests/browser/browser.ini', '--setpref=gfx.webrender.software=true', '--setpref=fission.autostart=true', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--setpref=layers.d3d11.enable-blacklist=false', '--enable-a11y-checks', '--appname=/builds/worker/workspace/build/application/firefox/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/SdR5YzWtRAaZwIij_Bmauw/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--setpref=webgl.force-enabled=true', '--quiet', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/mochitest-browser-chrome_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/mochitest-browser-chrome_errorsummary.log', '--use-test-media-devices', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/builds/worker/workspace/build', '--log-raw=-', '--flavor=browser', '--chunk-by-runtime']
[task 2022-03-17T00:28:16.592Z] 00:28:16    ERROR - timed out after 1000 seconds of no output
[task 2022-03-17T00:28:16.592Z] 00:28:16    ERROR - Return code: -15
[task 2022-03-17T00:28:16.593Z] 00:28:16    ERROR - No suite end message was emitted by this harness.

Mike, are you still working on this?

https://hg.mozilla.org/mozilla-central/rev/4f3a7e094b3a