1797816 - Intermittent macmini Automation Error: Received unexpected exception while running application | socket.timeout: Timed out waiting for connection on 127.0.0.1:2828! , socket.timeout: Connection timed out after 360s

Status: RESOLVED FIXED

(Taskcluster :: Workers, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-10-27T17:41:20.788Z] 17:41:20     INFO - TEST-START | dom/canvas/test/webgl-mochitest/test_video_fastpath_vp9.html
[task 2022-10-27T17:41:20.788Z] 17:41:20     INFO - TEST-SKIP | dom/canvas/test/webgl-mochitest/test_video_fastpath_vp9.html | took 0ms
[task 2022-10-27T17:41:20.788Z] 17:41:20     INFO - Running manifest: dom/canvas/test/crash/mochitest.ini
[task 2022-10-27T17:41:21.356Z] 17:41:21     INFO - PID 68613 | pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2022-10-27T17:41:21.381Z] 17:41:21     INFO - MochitestServer : launching ['/opt/worker/tasks/task_166689226531198/build/tests/bin/xpcshell', '-g', '/opt/worker/tasks/task_166689226531198/build/application/Firefox Nightly.app/Contents/Resources', '-f', '/opt/worker/tasks/task_166689226531198/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/var/folders/gz/xn423lkx6c72bb3j7gjgny4r000014/T/tmpv_ap5s8n.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/opt/worker/tasks/task_166689226531198/build/tests/mochitest/server.js']
[task 2022-10-27T17:41:21.381Z] 17:41:21     INFO - runtests.py | Server pid: 68614
[task 2022-10-27T17:41:21.384Z] 17:41:21     INFO - runtests.py | Websocket server pid: 68615
[task 2022-10-27T17:41:21.389Z] 17:41:21     INFO - runtests.py | SSL tunnel pid: 68616
[task 2022-10-27T17:41:21.404Z] 17:41:21     INFO -  failed to bind socket on port 4443: error -5982
[task 2022-10-27T17:41:21.404Z] 17:41:21     INFO -  Shutting down...
[task 2022-10-27T17:41:21.508Z] 17:41:21     INFO - runtests.py | Running with scheme: http
[task 2022-10-27T17:41:21.508Z] 17:41:21     INFO - runtests.py | Running with e10s: True
[task 2022-10-27T17:41:21.508Z] 17:41:21     INFO - runtests.py | Running with fission: True
[task 2022-10-27T17:41:21.509Z] 17:41:21     INFO - runtests.py | Running with cross-origin iframes: False
[task 2022-10-27T17:41:21.509Z] 17:41:21     INFO - runtests.py | Running with serviceworker_e10s: True
[task 2022-10-27T17:41:21.510Z] 17:41:21     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2022-10-27T17:41:21.510Z] 17:41:21     INFO - runtests.py | Running tests: start.
[task 2022-10-27T17:41:21.510Z] 17:41:21     INFO - 
[task 2022-10-27T17:41:21.536Z] 17:41:21  WARNING - Found 'firefox' running before starting test browser!
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '6631c65b-440a-4817-a9c1-c6458084953d'], 'name': 'firefox', 'pid': 36743, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'success'], 'name': 'firefox', 'pid': 36750, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'localization', 'toolkit/global/commonDialog.ftl', 'common-dialog-title-system', '{-brand-short-name}'], 'name': 'firefox', 'pid': 36753, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'message', '--sentinel', 'ef20665d-71b5-43af-aeba-9685faf85540', '--profile', '/var/folders/gz/xn423lkx6c72bb3j7gjgny4r000014/T/xpc-profile-wmky1zjc/test_backgroundtask_experiments_task', '--disable-alerts-service', '--no-experiments', '--url', 'file:///opt/worker/tasks/task_166662661974058/build/tests/xpcshell/tests/toolkit/components/backgroundtasks/tests/xpcshell/experiment.json?optin_branch=treatment-a'], 'name': 'firefox', 'pid': 36755, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '2dfa417f-c8e3-401b-9be0-1346a7205f34', '--profile', '/var/folders/gz/xn423lkx6c72bb3j7gjgny4r000014/T/xpc-profile-d4754wnt'], 'name': 'firefox', 'pid': 36758, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'profile_is_slim', 'http://localhost:51231/success'], 'name': 'firefox', 'pid': 36760, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'shouldprocessupdates', '--test-process-updates'], 'name': 'firefox', 'pid': 36763, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'removeDirectory', '/var/folders/gz/xn423lkx6c72bb3j7gjgny4r000014/T/xpc-profile-mnpdperj', 'newCacheFolder', '10', '.abc'], 'name': 'firefox', 'pid': 36765, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'targeting'], 'name': 'firefox', 'pid': 36766, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', 'e0657193-ab9f-4656-8d73-a55fc4f0c92d', '3'], 'name': 'firefox', 'pid': 36767, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'backgroundtask_specific_pref', 'test.backgroundtask_specific_pref.exitCode'], 'name': 'firefox', 'pid': 36771, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'policies', '/var/folders/gz/xn423lkx6c72bb3j7gjgny4r000014/T/testdir-851933/policies-1.json', 'https://www.example.com/'], 'name': 'firefox', 'pid': 36772, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'update_sync_manager', '/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/xpcshell'], 'name': 'firefox', 'pid': 36782, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '8184cfd9-bb90-415a-968a-371a2e6347c4'], 'name': 'firefox', 'pid': 36791, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', 'd10b8153-ebb9-4d13-a88e-7de927f99bc6'], 'name': 'firefox', 'pid': 36792, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', 'f78214f0-9d84-42fd-b96a-15e219a0e029'], 'name': 'firefox', 'pid': 36793, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.549Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', 'e9fea580-1c29-48fc-bc88-c0f631fff95d'], 'name': 'firefox', 'pid': 36794, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', 'e5e0d710-2bf4-41d7-91d4-9e3365b3298a'], 'name': 'firefox', 'pid': 36795, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '3fc0b5b4-be82-4d92-898b-c7c8b9936cfd'], 'name': 'firefox', 'pid': 36796, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '99cfcaa5-64d3-422f-9b66-2149899d469c'], 'name': 'firefox', 'pid': 36797, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', 'a6eb0449-1de6-48ed-8443-808129185748'], 'name': 'firefox', 'pid': 36798, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', 'e80607b0-4aa4-49e8-bd46-445746772ec1'], 'name': 'firefox', 'pid': 36799, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '8f2e7a8a-ca29-4802-a1a4-cb19ec11034b'], 'name': 'firefox', 'pid': 36800, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'crash', '4', 'TestKey', 'TestValue'], 'name': 'firefox', 'pid': 37380, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'not_ephemeral_profile', 'test.backgroundtask_specific_pref.exitCode', '80'], 'name': 'firefox', 'pid': 38056, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '340837b4-052e-4ee6-89fb-d99611e96ea5'], 'name': 'firefox', 'pid': 38408, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'success'], 'name': 'firefox', 'pid': 38573, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'message', '--sentinel', '66142dd6-99cf-4c36-99f9-4bb81c7dcb87', '--profile', '/var/folders/gz/xn423lkx6c72bb3j7gjgny4r000014/T/xpc-profile-346dx6of/test_backgroundtask_experiments_task', '--disable-alerts-service', '--no-experiments', '--url', 'file:///opt/worker/tasks/task_166662661974058/build/tests/xpcshell/tests/toolkit/components/backgroundtasks/tests/xpcshell/experiment.json?optin_branch=treatment-a'], 'name': 'firefox', 'pid': 38738, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'localization', 'toolkit/global/commonDialog.ftl', 'common-dialog-title-system', '{-brand-short-name}'], 'name': 'firefox', 'pid': 38907, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'policies', '/var/folders/gz/xn423lkx6c72bb3j7gjgny4r000014/T/testdir-96559/policies-1.json', 'https://www.example.com/'], 'name': 'firefox', 'pid': 39073, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'profile_is_slim', 'http://localhost:54597/success'], 'name': 'firefox', 'pid': 39238, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '0eb1bc74-5f6d-4a7e-87b1-c5675e40f4f1', '--profile', '/var/folders/gz/xn423lkx6c72bb3j7gjgny4r000014/T/xpc-profile-036rrk60'], 'name': 'firefox', 'pid': 39408, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'removeDirectory', '/var/folders/gz/xn423lkx6c72bb3j7gjgny4r000014/T/xpc-profile-tnitdq1f', 'newCacheFolder', '10', '.abc'], 'name': 'firefox', 'pid': 39578, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'shouldprocessupdates', '--test-process-updates'], 'name': 'firefox', 'pid': 39745, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '9ea9f3f7-721e-4bd6-8da2-7ca109f60684'], 'name': 'firefox', 'pid': 39910, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.550Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '83261699-c019-465d-9981-c0eae9b81a37'], 'name': 'firefox', 'pid': 39911, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', 'b868910f-32e9-4cf1-92df-9e72b341e70c'], 'name': 'firefox', 'pid': 39912, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '0b785f02-3f07-46f1-8752-58f77c9a8b33'], 'name': 'firefox', 'pid': 39913, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', 'febc1e18-09cb-48be-9ad7-4b0aadfeef07'], 'name': 'firefox', 'pid': 39914, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '4a31ec98-ede8-4852-a4c4-4b831bdc4296'], 'name': 'firefox', 'pid': 39915, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', 'aebc2051-39fd-4b36-b897-68baa2937288'], 'name': 'firefox', 'pid': 39916, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '2b70e6a9-68e6-47de-a0cf-65fa638b731c'], 'name': 'firefox', 'pid': 39917, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '6e372b3c-8673-4d65-a6d3-3b0f2015a35d'], 'name': 'firefox', 'pid': 39918, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', 'e7499c37-75a5-4d71-9ed9-6461a5d0021c'], 'name': 'firefox', 'pid': 39919, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'backgroundtask_specific_pref', 'test.backgroundtask_specific_pref.exitCode'], 'name': 'firefox', 'pid': 40087, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'targeting'], 'name': 'firefox', 'pid': 40262, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', 'b24de983-3996-4184-8178-5c1463dfb41e', '3'], 'name': 'firefox', 'pid': 40426, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'update_sync_manager', '/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/xpcshell'], 'name': 'firefox', 'pid': 40592, 'ppid': 40591, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - {'cmdline': ['/opt/worker/tasks/task_166688405386710/build/application/Firefox NightlyDebug.app/Contents/MacOS/firefox', '-marionette', '-foreground', '-profile', '/var/folders/gz/xn423lkx6c72bb3j7gjgny4r000014/T/tmpyra1k9ki.mozrunner'], 'name': 'firefox', 'pid': 64619, 'ppid': 61622, 'username': 'cltbld'}
[task 2022-10-27T17:41:21.551Z] 17:41:21  WARNING - 
[task 2022-10-27T17:41:21.552Z] 17:41:21     INFO - Application command: /opt/worker/tasks/task_166689226531198/build/application/Firefox Nightly.app/Contents/MacOS/firefox -marionette -foreground -profile /var/folders/gz/xn423lkx6c72bb3j7gjgny4r000014/T/tmpv_ap5s8n.mozrunner
[task 2022-10-27T17:41:21.552Z] 17:41:21     INFO - runtests.py | Application pid: 68617
[task 2022-10-27T17:41:21.552Z] 17:41:21     INFO - TEST-INFO | started process GECKO(68617)
[task 2022-10-27T17:41:22.032Z] 17:41:22     INFO - GECKO(68617) | 1666892482032	Marionette	INFO	Marionette enabled
[task 2022-10-27T17:41:22.059Z] 17:41:22     INFO - GECKO(68617) | 1666892482058	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-10-27T17:41:22.060Z] 17:41:22     INFO - GECKO(68617) | 1666892482059	Marionette	FATAL	Marionette server failed to start: Error: Could not bind to port 2828 (NS_ERROR_SOCKET_ADDRESS_IN_USE)(chrome://remote/content/marionette/server.sys.mjs:77:17) JS Stack trace: set [e-mail]:77:17
[task 2022-10-27T17:41:22.060Z] 17:41:22     INFO - GECKO(68617) | [e-mail]:107:5
[task 2022-10-27T17:41:22.061Z] 17:41:22     INFO - GECKO(68617) | [e-mail]:233:19
[task 2022-10-27T17:41:22.061Z] 17:41:22     INFO - GECKO(68617) | [e-mail]:185:20
[task 2022-10-27T17:41:22.144Z] 17:41:22     INFO - GECKO(68617) | 1666892482143	Marionette	TRACE	Received observer notification quit-application
[task 2022-10-27T17:41:22.568Z] 17:41:22     INFO - GECKO(68617) | WARNING: A blocker encountered an error while we were waiting.
[task 2022-10-27T17:41:22.568Z] 17:41:22     INFO - GECKO(68617) |           Blocker:  Waiting for ping task
[task 2022-10-27T17:41:22.569Z] 17:41:22     INFO - GECKO(68617) |           Phase: TelemetryController: Waiting for pending ping activity
[task 2022-10-27T17:41:22.569Z] 17:41:22     INFO - GECKO(68617) |           State: (none)
[task 2022-10-27T17:41:22.569Z] 17:41:22     INFO - GECKO(68617) | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-10-27T17:41:22.570Z] 17:41:22     INFO - GECKO(68617) | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-10-27T17:41:22.570Z] 17:41:22     INFO - GECKO(68617) | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-10-27T17:41:22.571Z] 17:41:22     INFO - GECKO(68617) | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-10-27T17:41:22.571Z] 17:41:22     INFO - GECKO(68617) | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-10-27T17:41:22.571Z] 17:41:22     INFO - GECKO(68617) | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-10-27T17:41:22.572Z] 17:41:22     INFO - GECKO(68617) | @resource://gre/modules/osfile.jsm:12:30
[task 2022-10-27T17:41:22.572Z] 17:41:22     INFO - GECKO(68617) | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-10-27T17:41:22.572Z] 17:41:22     INFO - GECKO(68617) | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
[task 2022-10-27T17:41:22.573Z] 17:41:22     INFO - GECKO(68617) | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
[task 2022-10-27T17:41:22.573Z] 17:41:22     INFO - GECKO(68617) | _submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:554:48
[task 2022-10-27T17:41:22.574Z] 17:41:22     INFO - GECKO(68617) | send@resource://gre/modules/TelemetryControllerParent.jsm:642:24
[task 2022-10-27T17:41:22.574Z] 17:41:22     INFO - GECKO(68617) | submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
[task 2022-10-27T17:41:22.574Z] 17:41:22     INFO - GECKO(68617) | sendPing@resource://gre/modules/EventPing.jsm:51:30
[task 2022-10-27T17:41:22.575Z] 17:41:22     INFO - GECKO(68617) | _submitPing@resource://gre/modules/EventPing.jsm:229:12
[task 2022-10-27T17:41:22.575Z] 17:41:22     INFO - GECKO(68617) | shutdown@resource://gre/modules/EventPing.jsm:112:10
[task 2022-10-27T17:41:22.576Z] 17:41:22     INFO - GECKO(68617) | _cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:954:31
[task 2022-10-27T17:41:22.576Z] 17:41:22     INFO - GECKO(68617) | shutdown/<@resource://gre/modules/TelemetryControllerParent.jsm:1024:24
[task 2022-10-27T17:41:22.576Z] 17:41:22     INFO - GECKO(68617) | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-10-27T17:41:22.577Z] 17:41:22     INFO - GECKO(68617) | WARNING: A blocker encountered an error while we were waiting.
[task 2022-10-27T17:41:22.577Z] 17:41:22     INFO - GECKO(68617) |           Blocker:  Waiting for ping task
[task 2022-10-27T17:41:22.578Z] 17:41:22     INFO - GECKO(68617) |           Phase: TelemetryController: Waiting for pending ping activity
[task 2022-10-27T17:41:22.578Z] 17:41:22     INFO - GECKO(68617) |           State: (none)
[task 2022-10-27T17:41:22.578Z] 17:41:22     INFO - GECKO(68617) | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-10-27T17:41:22.579Z] 17:41:22     INFO - GECKO(68617) | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-10-27T17:41:22.579Z] 17:41:22     INFO - GECKO(68617) | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-10-27T17:41:22.580Z] 17:41:22     INFO - GECKO(68617) | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-10-27T17:41:22.580Z] 17:41:22     INFO - GECKO(68617) | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-10-27T17:41:22.580Z] 17:41:22     INFO - GECKO(68617) | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-10-27T17:41:22.581Z] 17:41:22     INFO - GECKO(68617) | @resource://gre/modules/osfile.jsm:12:30
[task 2022-10-27T17:41:22.581Z] 17:41:22     INFO - GECKO(68617) | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-10-27T17:41:22.581Z] 17:41:22     INFO - GECKO(68617) | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
[task 2022-10-27T17:41:22.582Z] 17:41:22     INFO - GECKO(68617) | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
[task 2022-10-27T17:41:22.582Z] 17:41:22     INFO - GECKO(68617) | _submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:554:48
[task 2022-10-27T17:41:22.583Z] 17:41:22     INFO - GECKO(68617) | send@resource://gre/modules/TelemetryControllerParent.jsm:642:24
[task 2022-10-27T17:41:22.583Z] 17:41:22     INFO - GECKO(68617) | submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
[task 2022-10-27T17:41:22.583Z] 17:41:22     INFO - GECKO(68617) | saveShutdownPings@resource://gre/modules/TelemetrySession.jsm:982:34
[task 2022-10-27T17:41:22.584Z] 17:41:22     INFO - GECKO(68617) | shutdownChromeProcess/cleanup/<@resource://gre/modules/TelemetrySession.jsm:1232:20
[task 2022-10-27T17:41:22.584Z] 17:41:22     INFO - GECKO(68617) | cleanup@resource://gre/modules/TelemetrySession.jsm:1239:9
[task 2022-10-27T17:41:22.585Z] 17:41:22     INFO - GECKO(68617) | shutdownChromeProcess@resource://gre/modules/TelemetrySession.jsm:1256:14
[task 2022-10-27T17:41:22.585Z] 17:41:22     INFO - GECKO(68617) | shutdown@resource://gre/modules/TelemetrySession.jsm:247:17
[task 2022-10-27T17:41:22.585Z] 17:41:22     INFO - GECKO(68617) | _cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:973:35
[task 2022-10-27T17:41:22.586Z] 17:41:22     INFO - GECKO(68617) | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-10-27T17:41:22.586Z] 17:41:22     INFO - GECKO(68617) | WARNING: A blocker encountered an error while we were waiting.
[task 2022-10-27T17:41:22.586Z] 17:41:22     INFO - GECKO(68617) |           Blocker:  TelemetryController: shutting down
[task 2022-10-27T17:41:22.587Z] 17:41:22     INFO - GECKO(68617) |           Phase: profile-before-change-telemetry
[task 2022-10-27T17:41:22.587Z] 17:41:22     INFO - GECKO(68617) |           State: Error getting state: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange" at addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-10-27T17:41:22.588Z] 17:41:22     INFO - GECKO(68617) | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-10-27T17:41:22.588Z] 17:41:22     INFO - GECKO(68617) | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-10-27T17:41:22.589Z] 17:41:22     INFO - GECKO(68617) | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-10-27T17:41:22.589Z] 17:41:22     INFO - GECKO(68617) | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-10-27T17:41:22.589Z] 17:41:22     INFO - GECKO(68617) | @resource://gre/modules/osfile.jsm:12:30
[task 2022-10-27T17:41:22.590Z] 17:41:22     INFO - GECKO(68617) | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-10-27T17:41:22.590Z] 17:41:22     INFO - GECKO(68617) | getShutdownState@resource://gre/modules/TelemetrySend.jsm:1687:7
[task 2022-10-27T17:41:22.591Z] 17:41:22     INFO - GECKO(68617) | getShutdownState@resource://gre/modules/TelemetrySend.jsm:369:30
[task 2022-10-27T17:41:22.591Z] 17:41:22     INFO - GECKO(68617) | _getState@resource://gre/modules/TelemetryControllerParent.jsm:1072:38
[task 2022-10-27T17:41:22.591Z] 17:41:22     INFO - GECKO(68617) | setupTelemetry/<@resource://gre/modules/TelemetryControllerParent.jsm:931:18
[task 2022-10-27T17:41:22.592Z] 17:41:22     INFO - GECKO(68617) | safeGetState@resource://gre/modules/AsyncShutdown.jsm:242:17
[task 2022-10-27T17:41:22.592Z] 17:41:22     INFO - GECKO(68617) | Barrier/addBlocker/promise<@resource://gre/modules/AsyncShutdown.jsm:751:20
[task 2022-10-27T17:41:22.592Z] 17:41:22     INFO - GECKO(68617) | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-10-27T17:41:22.593Z] 17:41:22     INFO - GECKO(68617) | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-10-27T17:41:22.593Z] 17:41:22     INFO - GECKO(68617) | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-10-27T17:41:22.594Z] 17:41:22     INFO - GECKO(68617) | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-10-27T17:41:22.594Z] 17:41:22     INFO - GECKO(68617) | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-10-27T17:41:22.595Z] 17:41:22     INFO - GECKO(68617) | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-10-27T17:41:22.595Z] 17:41:22     INFO - GECKO(68617) | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-10-27T17:41:22.595Z] 17:41:22     INFO - GECKO(68617) | @resource://gre/modules/osfile.jsm:12:30
[task 2022-10-27T17:41:22.596Z] 17:41:22     INFO - GECKO(68617) | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-10-27T17:41:22.596Z] 17:41:22     INFO - GECKO(68617) | removeAbortedSessionPing@resource://gre/modules/TelemetryControllerParent.jsm:735:5
[task 2022-10-27T17:41:22.596Z] 17:41:22     INFO - GECKO(68617) | removeAbortedSessionPing@resource://gre/modules/TelemetryControllerParent.jsm:249:17
[task 2022-10-27T17:41:22.597Z] 17:41:22     INFO - GECKO(68617) | shutdownChromeProcess/cleanup/<@resource://gre/modules/TelemetrySession.jsm:1235:42
[task 2022-10-27T17:41:22.597Z] 17:41:22     INFO - GECKO(68617) | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-10-27T17:41:22.598Z] 17:41:22     INFO - GECKO(68617) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-10-27T17:41:22.598Z] 17:41:22     INFO - GECKO(68617) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-10-27T17:41:22.599Z] 17:41:22     INFO - GECKO(68617) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-10-27T17:41:22.600Z] 17:41:22     INFO - GECKO(68617) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-10-27T17:41:22.600Z] 17:41:22     INFO - GECKO(68617) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-10-27T17:47:21.794Z] 17:47:21     INFO - runtests.py | Waiting for browser...
[task 2022-10-27T17:47:21.795Z] 17:47:21     INFO - TEST-INFO | Main app process: exit 0
[task 2022-10-27T17:47:21.795Z] 17:47:21     INFO - runtests.py | Application ran for: 0:06:00.258398
[task 2022-10-27T17:47:21.796Z] 17:47:21     INFO - zombiecheck | Reading PID log: /var/folders/gz/xn423lkx6c72bb3j7gjgny4r000014/T/tmp2xl427etpidlog
[task 2022-10-27T17:47:21.796Z] 17:47:21     INFO - ==> process 68617 launched child process 68619
[task 2022-10-27T17:47:21.797Z] 17:47:21     INFO - zombiecheck | Checking for orphan process with PID: 68619
[task 2022-10-27T17:47:21.798Z] 17:47:21     INFO -  Traceback (most recent call last):
[task 2022-10-27T17:47:21.798Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/tests/mochitest/runtests.py", line 3528, in doTests
[task 2022-10-27T17:47:21.798Z] 17:47:21     INFO -      crashAsPass=options.crashAsPass,
[task 2022-10-27T17:47:21.799Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/tests/mochitest/runtests.py", line 2835, in runApp
[task 2022-10-27T17:47:21.799Z] 17:47:21     INFO -      six.reraise(exc, value, tb)
[task 2022-10-27T17:47:21.799Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/venv/lib/python3.7/site-packages/six.py", line 696, in reraise
[task 2022-10-27T17:47:21.799Z] 17:47:21     INFO -      raise value
[task 2022-10-27T17:47:21.799Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/tests/mochitest/runtests.py", line 2695, in runApp
[task 2022-10-27T17:47:21.800Z] 17:47:21     INFO -      self.marionette.start_session()
[task 2022-10-27T17:47:21.800Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 37, in _
[task 2022-10-27T17:47:21.800Z] 17:47:21     INFO -      m._handle_socket_failure()
[task 2022-10-27T17:47:21.801Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 712, in _handle_socket_failure
[task 2022-10-27T17:47:21.801Z] 17:47:21     INFO -      reraise(exc_cls, exc, tb)
[task 2022-10-27T17:47:21.801Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/venv/lib/python3.7/site-packages/six.py", line 696, in reraise
task 2022-10-27T17:47:21.801Z] 17:47:21     INFO -      raise value
[task 2022-10-27T17:47:21.801Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2022-10-27T17:47:21.802Z] 17:47:21     INFO -      return func(*args, **kwargs)
[task 2022-10-27T17:47:21.802Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 1263, in start_session
[task 2022-10-27T17:47:21.802Z] 17:47:21     INFO -      resp = self._send_message("WebDriver:NewSession", capabilities)
[task 2022-10-27T17:47:21.802Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 37, in _
[task 2022-10-27T17:47:21.802Z] 17:47:21     INFO -      m._handle_socket_failure()
[task 2022-10-27T17:47:21.803Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 712, in _handle_socket_failure
[task 2022-10-27T17:47:21.803Z] 17:47:21     INFO -      reraise(exc_cls, exc, tb)
[task 2022-10-27T17:47:21.803Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/venv/lib/python3.7/site-packages/six.py", line 696, in reraise
[task 2022-10-27T17:47:21.804Z] 17:47:21     INFO -      raise value
[task 2022-10-27T17:47:21.804Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2022-10-27T17:47:21.804Z] 17:47:21     INFO -      return func(*args, **kwargs)
[task 2022-10-27T17:47:21.804Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 661, in _send_message
[task 2022-10-27T17:47:21.805Z] 17:47:21     INFO -      msg = self.client.request(name, params)
[task 2022-10-27T17:47:21.805Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/venv/lib/python3.7/site-packages/marionette_driver/transport.py", line 383, in request
[task 2022-10-27T17:47:21.805Z] 17:47:21     INFO -      return self.receive()
[task 2022-10-27T17:47:21.805Z] 17:47:21     INFO -    File "/opt/worker/tasks/task_166689226531198/build/venv/lib/python3.7/site-packages/marionette_driver/transport.py", line 221, in receive
[task 2022-10-27T17:47:21.806Z] 17:47:21     INFO -      "Connection timed out after {}s".format(self.socket_timeout)
[task 2022-10-27T17:47:21.806Z] 17:47:21     INFO -  socket.timeout: Connection timed out after 360s
[task 2022-10-27T17:47:21.806Z] 17:47:21    ERROR - Automation Error: Received unexpected exception while running application
[task 2022-10-27T17:47:21.806Z] 17:47:21    ERROR - 
[task 2022-10-27T17:47:21.807Z] 17:47:21     INFO - Stopping web server
[task 2022-10-27T17:47:21.811Z] 17:47:21     INFO - Server shut down.
[task 2022-10-27T17:47:21.925Z] 17:47:21     INFO - Web server killed.
[task 2022-10-27T17:47:21.925Z] 17:47:21     INFO - Stopping web socket server
[task 2022-10-27T17:47:22.095Z] 17:47:22     INFO - Stopping ssltunnel
[task 2022-10-27T17:47:22.096Z] 17:47:22  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2022-10-27T17:47:22.096Z] 17:47:22     INFO - runtests.py | Running tests: end.
[task 2022-10-27T17:47:22.097Z] 17:47:22     INFO - Buffered messages finished
[task 2022-10-27T17:47:22.097Z] 17:47:22     INFO - Running manifest: dom/canvas/test/webgl-conf/generated-mochitest.ini
[task 2022-10-27T17:47:22.376Z] 17:47:22     INFO - PID 68833 | pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2022-10-27T17:47:22.410Z] 17:47:22     INFO - MochitestServer : launching ['/opt/worker/tasks/task_166689226531198/build/tests/bin/xpcshell', '-g', '/opt/worker/tasks/task_166689226531198/build/application/Firefox Nightly.app/Contents/Resources', '-f', '/opt/worker/tasks/task_166689226531198/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/var/folders/gz/xn423lkx6c72bb3j7gjgny4r000014/T/tmpmi89_406.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/opt/worker/tasks/task_166689226531198/build/tests/mochitest/server.js']
[task 2022-10-27T17:47:22.410Z] 17:47:22     INFO - runtests.py | Server pid: 68834
[task 2022-10-27T17:47:22.414Z] 17:47:22     INFO - runtests.py | Websocket server pid: 68835
[task 2022-10-27T17:47:22.419Z] 17:47:22     INFO - runtests.py | SSL tunnel pid: 68836
[task 2022-10-27T17:47:22.434Z] 17:47:22     INFO -  failed to bind socket on port 4443: error -5982
[task 2022-10-27T17:47:22.435Z] 17:47:22     INFO -  Shutting down...
[task 2022-10-27T17:47:22.607Z] 17:47:22     INFO - runtests.py | Running with scheme: http
[task 2022-10-27T17:47:22.608Z] 17:47:22     INFO - runtests.py | Running with e10s: True
[task 2022-10-27T17:47:22.608Z] 17:47:22     INFO - runtests.py | Running with fission: True
[task 2022-10-27T17:47:22.608Z] 17:47:22     INFO - runtests.py | Running with cross-origin iframes: False
[task 2022-10-27T17:47:22.609Z] 17:47:22     INFO - runtests.py | Running with serviceworker_e10s: True
[task 2022-10-27T17:47:22.609Z] 17:47:22     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2022-10-27T17:47:22.609Z] 17:47:22     INFO - runtests.py | Running tests: start.
[task 2022-10-27T17:47:22.609Z] 17:47:22     INFO - 
[task 2022-10-27T17:47:22.637Z] 17:47:22  WARNING - Found 'firefox' running before starting test browser!
[task 2022-10-27T17:47:22.650Z] 17:47:22  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'unique_profile', '6631c65b-440a-4817-a9c1-c6458084953d'], 'name': 'firefox', 'pid': 36743, 'ppid': 1, 'username': 'cltbld'}
[task 2022-10-27T17:47:22.650Z] 17:47:22  WARNING - {'cmdline': ['/opt/worker/tasks/task_166662661974058/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--backgroundtask', 'success'], 'name': 'firefox', 'pid': 36750, 'ppid': 1, 'username': 'cltbld'}

Comment 1

[Cosmin Sabou [:CosminS]]

Any chance one of you could look into these workers? Happens on whatever tests are run on them.
I've quarantined macmini-r8-115 and macmini-r8-140 as all failures so far were on these two. Thanks in advance.

Comment 2

[Intermittent Failures Robot]

28 failures in 688 pushes (0.041 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 19
• mozilla-central: 5
• try: 2
• mozilla-beta: 2

Platform and build breakdown:

• macosx1015-64-qr: 16
  • debug: 10
  • opt: 6
• macosx1015-64-shippable-qr: 10
  • opt: 10
• macosx1015-64-devedition-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1797816&startday=2022-10-28&endday=2022-10-28&tree=all

Comment 3

[:dhouse]

Thanks :CosminS I'll check these two early this week.
from the log it looks like a fluke causing Firefox to be already running--and probably the local server in the error message was already running or stuck somehow

Comment 4

[Cosmin Sabou [:CosminS]]

Also these ones

• macmini-r8-225
• macmini-r8-43
• macmini-r8-19

Comment 5

[Intermittent Failures Robot]

42 failures in 3743 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #25 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 31
• mozilla-beta: 3
• mozilla-central: 6
• try: 2

Platform and build breakdown:

• macosx1015-64-qr: 27
  • opt: 13
  • debug: 14
• macosx1015-64-shippable-qr: 13
  • opt: 13
• macosx1015-64-devedition-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1797816&startday=2022-10-24&endday=2022-10-30&tree=all

Comment 6

[Intermittent Failures Robot]

16 failures in 571 pushes (0.028 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 11
• mozilla-central: 3
• try: 1
• mozilla-beta: 1

Platform and build breakdown:

• macosx1015-64-qr: 8
  • opt: 5
  • debug: 3
• macosx1015-64-shippable-qr: 7
  • opt: 7
• macosx1015-64-devedition-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1797816&startday=2022-10-31&endday=2022-10-31&tree=all

Comment 7

[Intermittent Failures Robot]

48 failures in 675 pushes (0.071 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 27
• mozilla-central: 10
• try: 4
• mozilla-beta: 7

Platform and build breakdown:

• macosx1015-64-qr: 30
  • opt: 9
  • debug: 21
• macosx1015-64-shippable-qr: 12
  • opt: 12
• macosx1015-64-devedition-qr: 6
  • opt: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1797816&startday=2022-11-01&endday=2022-11-01&tree=all

Comment 8

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

There is an increase in socket related test failures on macOS across all machines. Dave, do the machines mentioned earlier here provide any clues what is going on?

Comment 9

[Cosmin Sabou [:CosminS]]

Added these workers to the quarantined list:

• macmini-r8-212
• macmini-r8-233
• macmini-r8-55
• macmini-r8-112
• macmini-r8-160
• macmini-r8-165
• macmini-r8-188

Comment 10

[Intermittent Failures Robot]

36 failures in 733 pushes (0.049 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 21
• mozilla-central: 6
• try: 4
• mozilla-beta: 5

Platform and build breakdown:

• macosx1015-64-qr: 22
  • debug: 15
  • opt: 7
• macosx1015-64-shippable-qr: 11
  • opt: 11
• macosx1015-64-devedition-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1797816&startday=2022-11-02&endday=2022-11-02&tree=all

Comment 11

[Iulian Moraru]

Added to the quarantine list:

• macmini-r8-275
• macmini-r8-284
• macmini-r8-75
• macmini-r8-223
• macmini-r8-203
• macmini-r8-213
• macmini-r8-161
• macmini-r8-67
• macmini-r8-102
• macmini-r8-132
• macmini-r8-185

Comment 12

[Andrew Erickson [:aerickson]]

I see lots of lines regarding issues killing ssltunnel and xpcshell processes in many but not all of the failed jobs (output below). The machines are supposed to reboot after every test.

I recently ran Puppet on all of the r8 hosts (to enable Safari driver for automation) and noticed psutil was upgraded from '5.8.0' to '5.9.3' (but I don't think that is the cause). I don't think enabling Safari automation was the cause. I noticed that worker-runner-config.yml was changed (due to 10796bdc65bb29f9c80c46d8f6e2385152824ee2 in ronin-puppet)... but that was supposed to fix not rebooting.

I just looked at two host with a really bad success rates (79 and 105) and they've been up for 5 days... so reboots are not happening. I've quarantined them.

[[e-mail] ~]$ uptime
22:07  up 5 days, 16:21, 2 users, load averages: 2.30 2.28 2.35

---

[task 2022-10-27T17:41:20.297Z] 17:41:20     INFO - Checking for ssltunnel processes...
[task 2022-10-27T17:41:20.298Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=5835)
[task 2022-10-27T17:41:20.298Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=8095)
[task 2022-10-27T17:41:20.299Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=18625)
[task 2022-10-27T17:41:20.299Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=19897)
[task 2022-10-27T17:41:20.300Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=21938)
[task 2022-10-27T17:41:20.300Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=31973)
[task 2022-10-27T17:41:20.300Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=53079)
[task 2022-10-27T17:41:20.301Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=57257)
[task 2022-10-27T17:41:20.301Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=58115)
[task 2022-10-27T17:41:20.301Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=60048)
[task 2022-10-27T17:41:20.302Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=63092)
[task 2022-10-27T17:41:20.302Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=63678)
[task 2022-10-27T17:41:20.302Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=64364)
[task 2022-10-27T17:41:20.303Z] 17:41:20     INFO - NOT killing {'pid': 64618, 'name': 'ssltunnel', 'ppid': 61622, 'username': 'cltbld'} (not an orphan?)
[task 2022-10-27T17:41:20.303Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=67804)
[task 2022-10-27T17:41:20.304Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=69721)
[task 2022-10-27T17:41:20.304Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=76639)
[task 2022-10-27T17:41:20.304Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=78117)
[task 2022-10-27T17:41:20.305Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=90311)
[task 2022-10-27T17:41:20.305Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=97752)
[task 2022-10-27T17:41:20.306Z] 17:41:20     INFO - Warning: Unable to kill process ssltunnel: psutil.ZombieProcess process still exists but it's a zombie (pid=99094)
[task 2022-10-27T17:41:20.306Z] 17:41:20     INFO - Checking for xpcshell processes...
[task 2022-10-27T17:41:20.309Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=5835)
[task 2022-10-27T17:41:20.309Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=8095)
[task 2022-10-27T17:41:20.310Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=18625)
[task 2022-10-27T17:41:20.310Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=19897)
[task 2022-10-27T17:41:20.310Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=21938)
[task 2022-10-27T17:41:20.311Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=31973)
[task 2022-10-27T17:41:20.311Z] 17:41:20     INFO - NOT killing {'pid': 37363, 'name': 'xpcshell', 'ppid': 34611, 'username': 'cltbld'} (not an orphan?)
[task 2022-10-27T17:41:20.312Z] 17:41:20     INFO - NOT killing {'pid': 40591, 'name': 'xpcshell', 'ppid': 34611, 'username': 'cltbld'} (not an orphan?)
[task 2022-10-27T17:41:20.313Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=53079)
[task 2022-10-27T17:41:20.314Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=57257)
[task 2022-10-27T17:41:20.314Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=58115)
[task 2022-10-27T17:41:20.315Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=60048)
[task 2022-10-27T17:41:20.315Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=63092)
[task 2022-10-27T17:41:20.315Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=63678)
[task 2022-10-27T17:41:20.315Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=64364)
[task 2022-10-27T17:41:20.316Z] 17:41:20     INFO - NOT killing {'pid': 64616, 'name': 'xpcshell', 'ppid': 61622, 'username': 'cltbld'} (not an orphan?)
[task 2022-10-27T17:41:20.316Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=67804)
[task 2022-10-27T17:41:20.317Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=69721)
[task 2022-10-27T17:41:20.317Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=76639)
[task 2022-10-27T17:41:20.317Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=78117)
[task 2022-10-27T17:41:20.318Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=90311)
[task 2022-10-27T17:41:20.318Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=97752)
[task 2022-10-27T17:41:20.318Z] 17:41:20     INFO - Warning: Unable to kill process xpcshell: psutil.ZombieProcess process still exists but it's a zombie (pid=99094)

Comment 13

[Intermittent Failures Robot]

86 failures in 686 pushes (0.125 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 53
• mozilla-central: 21
• try: 9
• mozilla-release: 1
• mozilla-beta: 2

Platform and build breakdown:

• macosx1015-64-qr: 60
  • debug: 42
  • opt: 18
• macosx1015-64-shippable-qr: 20
  • opt: 20
• macosx1015-64-devedition-qr: 6
  • opt: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1797816&startday=2022-11-04&endday=2022-11-04&tree=all

Comment 14

[Intermittent Failures Robot]

202 failures in 3626 pushes (0.056 failures/push) were associated with this bug in the last 7 days.

This is the #7 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 116
• mozilla-central: 48
• try: 19
• mozilla-beta: 15
• mozilla-esr102: 3
• mozilla-release: 1

Platform and build breakdown:

• macosx1015-64-qr: 129
  • opt: 40
  • debug: 89
• macosx1015-64-shippable-qr: 57
  • opt: 57
• macosx1015-64-devedition-qr: 16
  • opt: 16

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1797816&startday=2022-10-31&endday=2022-11-06&tree=all

Comment 15

[Andrew Erickson [:aerickson]]

We've deployed a fix for the issue that caused the machines to not reboot (which should reduce the number of errors we're seeing back to normal levels).

Comment 16

[Intermittent Failures Robot]

1 failures in 3445 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• macosx1015-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1797816&startday=2022-11-07&endday=2022-11-13&tree=all

Comment 17

[Intermittent Failures Robot]

1 failures in 3606 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-esr102: 1

Platform and build breakdown:

• macosx1015-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1797816&startday=2023-01-30&endday=2023-02-05&tree=all

Comment 18

[Valentin Gosu [:valentin] (he/him) {{ FYI: OOO 14 June - 4 August }}]

(In reply to Andrew Erickson [:aerickson] from comment #15)

We've deployed a fix for the issue that caused the machines to not reboot (which should reduce the number of errors we're seeing back to normal levels).

We're seeing some more intermittent failures on mac in bug 1765790 and bug 1801420
Do we need to do something else here?

Comment 19

[Andrew Erickson [:aerickson]]

I checked one host with a lot of failures (macmini-r8-9.test.releng.mdc1.mozilla.com) and it has been rebooting, so it seems like a different problem.

:dhouse, do you have any ideas?

Comment 20

[:dhouse]

I had un-quarantined the failing mac last week and re-quarantined it after the repeat failures. It appears to be a hardware failure.

Comment 21

[Intermittent Failures Robot]

2 failures in 3766 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• macosx1015-64-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1797816&startday=2023-02-06&endday=2023-02-12&tree=all