1827316 - Intermittent automation.py | application terminated with exit code 245

Status: RESOLVED INCOMPLETE

(Testing :: Mochitest, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2023-04-10T23:07:04.403Z] 23:07:04     INFO - TEST-OK | dom/media/test/test_eme_playback.html | took 35277ms
[task 2023-04-10T23:07:04.466Z] 23:07:04     INFO - TEST-START | Shutdown
[task 2023-04-10T23:07:04.471Z] 23:07:04     INFO - Passed:  1437
[task 2023-04-10T23:07:04.471Z] 23:07:04     INFO - Failed:  0
[task 2023-04-10T23:07:04.472Z] 23:07:04     INFO - Todo:    0
[task 2023-04-10T23:07:04.472Z] 23:07:04     INFO - Mode:    e10s
[task 2023-04-10T23:07:04.473Z] 23:07:04     INFO - Slowest: 35278ms - /tests/dom/media/test/test_eme_playback.html
[task 2023-04-10T23:07:04.473Z] 23:07:04     INFO - SimpleTest FINISHED
[task 2023-04-10T23:07:04.474Z] 23:07:04     INFO - TEST-INFO | Ran 1 Loops
[task 2023-04-10T23:07:04.475Z] 23:07:04     INFO - SimpleTest FINISHED
[task 2023-04-10T23:07:04.512Z] 23:07:04     INFO - GECKO(4116) | [Child 6036, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168116171679495/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-10T23:07:04.525Z] 23:07:04     INFO - GECKO(4116) | [Child 6036, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168116171679495/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-10T23:07:04.526Z] 23:07:04     INFO - GECKO(4116) | [Child 6036, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168116171679495/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-10T23:07:04.529Z] 23:07:04     INFO - GECKO(4116) | [Child 6036, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168116171679495/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-10T23:07:04.544Z] 23:07:04     INFO - GECKO(4116) | [Child 6036, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168116171679495/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-10T23:07:04.546Z] 23:07:04     INFO - GECKO(4116) | [Child 6036, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168116171679495/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-10T23:07:04.556Z] 23:07:04     INFO - GECKO(4116) | [Child 6036, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file Z:/task_168116171679495/build/src/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-10T23:07:04.567Z] 23:07:04     INFO - GECKO(4116) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 576: NotFoundError: No such JSWindowActor 'SpecialPowers'
[task 2023-04-10T23:07:04.606Z] 23:07:04     INFO - GECKO(4116) | 1681168024609	Marionette	TRACE	Received observer notification quit-application
[task 2023-04-10T23:07:04.611Z] 23:07:04     INFO - GECKO(4116) | 1681168024609	Marionette	INFO	Stopped listening on port 2828
[task 2023-04-10T23:07:04.612Z] 23:07:04     INFO - GECKO(4116) | 1681168024610	Marionette	DEBUG	Marionette stopped listening
[task 2023-04-10T23:07:22.262Z] 23:07:22     INFO - GECKO(4116) | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.sys.mjs", 370))
[task 2023-04-10T23:07:23.329Z] 23:07:23     INFO - GECKO(4116) | WARNING: A blocker encountered an error while we were waiting.
[task 2023-04-10T23:07:23.337Z] 23:07:23     INFO - GECKO(4116) |           Blocker:  Waiting for ping task
<...>
[task 2023-04-10T23:07:24.264Z] 23:07:24     INFO - GECKO(4116) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-10T23:07:24.265Z] 23:07:24     INFO - GECKO(4116) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-10T23:07:24.265Z] 23:07:24     INFO - GECKO(4116) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-10T23:07:29.262Z] 23:07:29     INFO - GECKO(4116) | [Parent 8268, IPC I/O Parent] WARNING: Process 8124 may be hanging at shutdown; will wait for up to 80000ms: file Z:/task_168116171679495/build/src/ipc/chromium/src/chrome/common/process_watcher_win.cc:129
[task 2023-04-10T23:07:29.419Z] 23:07:29     INFO - GECKO(4116) | [Parent 8268, IPC I/O Parent] WARNING: Process 8936 may be hanging at shutdown; will wait for up to 79843ms: file Z:/task_168116171679495/build/src/ipc/chromium/src/chrome/common/process_watcher_win.cc:129
[task 2023-04-10T23:07:29.450Z] 23:07:29     INFO - GECKO(4116) | [Parent 8268, IPC I/O Parent] WARNING: Process 9036 may be hanging at shutdown; will wait for up to 79812ms: file Z:/task_168116171679495/build/src/ipc/chromium/src/chrome/common/process_watcher_win.cc:129
[task 2023-04-10T23:07:29.513Z] 23:07:29     INFO - GECKO(4116) | [Parent 8268, IPC I/O Parent] WARNING: Process 1624 may be hanging at shutdown; will wait for up to 79750ms: file Z:/task_168116171679495/build/src/ipc/chromium/src/chrome/common/process_watcher_win.cc:129
[task 2023-04-10T23:07:38.173Z] 23:07:38     INFO - TEST-INFO | Main app process: exit 0
[task 2023-04-10T23:07:38.174Z] 23:07:38     INFO - runtests.py | Application ran for: 0:01:15.239619
[task 2023-04-10T23:07:38.175Z] 23:07:38     INFO - zombiecheck | Reading PID log: C:\Users\task_168116590924736\AppData\Local\Temp\tmpl_yepy3gpidlog
[task 2023-04-10T23:07:38.176Z] 23:07:38     INFO - ==> process 8268 launched child process 6300 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="8268.0.258103813\379223419" -parentBuildID 20230410212705 -prefsHandle 2152 -prefMapHandle 2132 -prefsLen 21609 -prefMapSize 250515 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {719e9561-b74e-46ce-aaa6-461af14bcb77} 8268 "\\.\pipe\gecko-crash-server-pipe.8268" 2232 215dfd6b258 gpu)
[task 2023-04-10T23:07:38.177Z] 23:07:38     INFO - ==> process 8268 launched child process 8432 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="8268.1.1743052045\1595369601" -childID 1 -isForBrowser -prefsHandle 2720 -prefMapHandle 2612 -prefsLen 21437 -prefMapSize 250515 -jsInitHandle 1376 -jsInitLen 247672 -parentBuildID 20230410212705 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {0b8c19de-82bf-466e-8527-f34b7f6a8b8f} 8268 "\\.\pipe\gecko-crash-server-pipe.8268" 2732 215e2e34f58 tab)
[task 2023-04-10T23:07:38.178Z] 23:07:38     INFO - ==> process 8268 launched child process 6036 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="8268.2.1451425991\1440066701" -childID 2 -isForBrowser -prefsHandle 2740 -prefMapHandle 3040 -prefsLen 22971 -prefMapSize 250515 -jsInitHandle 1376 -jsInitLen 247672 -parentBuildID 20230410212705 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {40a4c70a-117a-4b09-854b-094e17910723} 8268 "\\.\pipe\gecko-crash-server-pipe.8268" 3076 215e4ab6558 tab)
[task 2023-04-10T23:07:38.179Z] 23:07:38     INFO - ==> process 8268 launched child process 9100 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="8268.3.854575474\132025181" -childID 3 -isForBrowser -prefsHandle 3160 -prefMapHandle 3164 -prefsLen 22633 -prefMapSize 250515 -jsInitHandle 1376 -jsInitLen 247672 -parentBuildID 20230410212705 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {a4caef1c-0cad-4364-8947-2e7022138827} 8268 "\\.\pipe\gecko-crash-server-pipe.8268" 3152 215e4bbeb58 tab)
[task 2023-04-10T23:07:38.180Z] 23:07:38     INFO - ==> process 8268 launched child process 5744 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="8268.4.151937721\1378684758" -childID 4 -isForBrowser -prefsHandle 3540 -prefMapHandle 3496 -prefsLen 22862 -prefMapSize 250515 -jsInitHandle 1376 -jsInitLen 247672 -parentBuildID 20230410212705 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {b6ebc63d-54aa-4d59-b2d4-e65fa56d8d42} 8268 "\\.\pipe\gecko-crash-server-pipe.8268" 3012 215e752bb58 tab)
[task 2023-04-10T23:07:38.181Z] 23:07:38     INFO - ==> process 8268 launched child process 8124 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="8268.5.761157157\1280937748" -childID 5 -isForBrowser -prefsHandle 3220 -prefMapHandle 3060 -prefsLen 22862 -prefMapSize 250515 -jsInitHandle 1376 -jsInitLen 247672 -parentBuildID 20230410212705 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {29c1ef4c-3dcc-49e2-84ef-fca9e2323fb6} 8268 "\\.\pipe\gecko-crash-server-pipe.8268" 3332 215e582a758 tab)
[task 2023-04-10T23:07:38.182Z] 23:07:38     INFO - ==> process 8268 launched child process 9164 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="8268.6.513740652\885971525" -childID 6 -isForBrowser -prefsHandle 3328 -prefMapHandle 3512 -prefsLen 22862 -prefMapSize 250515 -jsInitHandle 1376 -jsInitLen 247672 -parentBuildID 20230410212705 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {ef5d8a55-3d22-4017-bd4c-02d372287419} 8268 "\\.\pipe\gecko-crash-server-pipe.8268" 3396 215e4bc1d58 tab)
[task 2023-04-10T23:07:38.183Z] 23:07:38     INFO - ==> process 8268 launched child process 9036 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="8268.7.596515998\1877669438" -parentBuildID 20230410212705 -sandboxingKind 0 -prefsHandle 2932 -prefMapHandle 2744 -prefsLen 30264 -prefMapSize 250515 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {2c9065f5-d2b0-40b8-bb95-3c6845ca8bc8} 8268 "\\.\pipe\gecko-crash-server-pipe.8268" 3944 215e87bc558 utility)
[task 2023-04-10T23:07:38.184Z] 23:07:38     INFO - ==> process 8268 launched child process 4952 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="8268.8.148078716\1540914556" -childID 7 -isForBrowser -prefsHandle 4012 -prefMapHandle 3740 -prefsLen 30264 -prefMapSize 250515 -jsInitHandle 1376 -jsInitLen 247672 -parentBuildID 20230410212705 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {22ccd181-a5ca-4824-8e5a-fe4d48eff838} 8268 "\\.\pipe\gecko-crash-server-pipe.8268" 4020 215e9254758 tab)
[task 2023-04-10T23:07:38.185Z] 23:07:38     INFO - ==> process 8268 launched child process 8936 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="8268.9.46284338\636827851" -childID 8 -isForBrowser -prefsHandle 4456 -prefMapHandle 4480 -prefsLen 28484 -prefMapSize 250515 -jsInitHandle 1376 -jsInitLen 247672 -parentBuildID 20230410212705 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {51a04dbe-d1bf-4546-9203-0a0a1ba42ef8} 8268 "\\.\pipe\gecko-crash-server-pipe.8268" 4484 215e971e558 tab)
[task 2023-04-10T23:07:38.186Z] 23:07:38     INFO - ==> process 8268 launched child process 1624 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="8268.10.214715319\2076288028" -parentBuildID 20230410212705 -prefsHandle 4536 -prefMapHandle 4548 -prefsLen 31444 -prefMapSize 250515 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {36ef2c5e-e707-4fe7-9d17-1a79d8ec69ae} 8268 "\\.\pipe\gecko-crash-server-pipe.8268" 4556 215e5024d58 rdd)
[task 2023-04-10T23:07:38.187Z] 23:07:38     INFO - ==> process 8268 launched child process 5344 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="8268.11.446542070\1167269384" -parentBuildID 20230410212705 -sandboxingKind 1 -prefsHandle 4520 -prefMapHandle 4528 -prefsLen 31444 -prefMapSize 250515 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {926e04aa-5390-4470-8779-34d6044720f4} 8268 "\\.\pipe\gecko-crash-server-pipe.8268" 4580 215ebe09f58 utility)
[task 2023-04-10T23:07:38.188Z] 23:07:38     INFO - ==> process 8268 launched child process 7760 ("Z:\task_168116590924736\build\application\firefox\plugin-container.exe" --channel="8268.12.2099380752\2022169830" "Z:\task_168116590924736\build\application\firefox\gmp-clearkey\0.1" -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {5ae6c298-37e1-44fa-9f5c-7dffb62c861e} 8268 "\\.\pipe\gecko-crash-server-pipe.8268" 4712 215ebe2db58 gmplugin)
[task 2023-04-10T23:07:38.188Z] 23:07:38     INFO - zombiecheck | Checking for orphan process with PID: 5344
[task 2023-04-10T23:07:38.188Z] 23:07:38     INFO - zombiecheck | Checking for orphan process with PID: 8936
[task 2023-04-10T23:07:38.189Z] 23:07:38     INFO - zombiecheck | Checking for orphan process with PID: 8124
[task 2023-04-10T23:07:38.189Z] 23:07:38     INFO - zombiecheck | Checking for orphan process with PID: 1624
[task 2023-04-10T23:07:38.191Z] 23:07:38     INFO - zombiecheck | Checking for orphan process with PID: 9100
[task 2023-04-10T23:07:38.191Z] 23:07:38     INFO - zombiecheck | Checking for orphan process with PID: 9164
[task 2023-04-10T23:07:38.191Z] 23:07:38     INFO - zombiecheck | Checking for orphan process with PID: 9036
[task 2023-04-10T23:07:38.192Z] 23:07:38     INFO - zombiecheck | Checking for orphan process with PID: 8432
[task 2023-04-10T23:07:38.192Z] 23:07:38     INFO - zombiecheck | Checking for orphan process with PID: 5744
[task 2023-04-10T23:07:38.192Z] 23:07:38     INFO - zombiecheck | Checking for orphan process with PID: 7760
[task 2023-04-10T23:07:38.193Z] 23:07:38     INFO - zombiecheck | Checking for orphan process with PID: 6036
[task 2023-04-10T23:07:38.193Z] 23:07:38     INFO - zombiecheck | Checking for orphan process with PID: 4952
[task 2023-04-10T23:07:38.193Z] 23:07:38     INFO - zombiecheck | Checking for orphan process with PID: 6300
[task 2023-04-10T23:07:38.194Z] 23:07:38     INFO - runtests.py | Running with scheme: https
[task 2023-04-10T23:07:38.194Z] 23:07:38     INFO - runtests.py | Running with e10s: True
[task 2023-04-10T23:07:38.195Z] 23:07:38     INFO - runtests.py | Running with fission: True
[task 2023-04-10T23:07:38.195Z] 23:07:38     INFO - runtests.py | Running with cross-origin iframes: False
[task 2023-04-10T23:07:38.195Z] 23:07:38     INFO - runtests.py | Running with serviceworker_e10s: True
[task 2023-04-10T23:07:38.196Z] 23:07:38     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2023-04-10T23:07:38.196Z] 23:07:38     INFO - runtests.py | Running tests: start.
[task 2023-04-10T23:07:38.196Z] 23:07:38     INFO - 
[task 2023-04-10T23:07:38.267Z] 23:07:38     INFO - Application command: Z:\task_168116590924736\build\application\firefox\firefox.exe -marionette --wait-for-browser -foreground -profile C:\Users\task_168116590924736\AppData\Local\Temp\tmpkazegqe5.mozrunner
[task 2023-04-10T23:07:38.282Z] 23:07:38     INFO - runtests.py | Application pid: 8724
[task 2023-04-10T23:07:38.282Z] 23:07:38     INFO - TEST-INFO | started process GECKO(8724)
[task 2023-04-10T23:07:38.610Z] 23:07:38     INFO - GECKO(8724) | 1681168058617	Marionette	INFO	Marionette enabled
[task 2023-04-10T23:07:38.619Z] 23:07:38     INFO - GECKO(8724) | 1681168058619	Marionette	TRACE	Received observer notification final-ui-startup
[task 2023-04-10T23:07:38.621Z] 23:07:38     INFO - GECKO(8724) | 1681168058620	Marionette	INFO	Listening on port 2828
[task 2023-04-10T23:07:38.621Z] 23:07:38     INFO - GECKO(8724) | 1681168058620	Marionette	DEBUG	Marionette is listening
[task 2023-04-10T23:07:38.657Z] 23:07:38     INFO - GECKO(8724) | console.error: "Warning: unrecognized command line flag -foreground\n"
[task 2023-04-10T23:07:38.923Z] 23:07:38     INFO - GECKO(8724) | 1681168058934	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:60194
[task 2023-04-10T23:07:38.942Z] 23:07:38     INFO - GECKO(8724) | 1681168058941	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:60197
[task 2023-04-10T23:07:38.947Z] 23:07:38     INFO - GECKO(8724) | 1681168058946	Marionette	DEBUG	Closed connection 0
[task 2023-04-10T23:07:39.032Z] 23:07:39     INFO - GECKO(8724) | 1681168059038	Marionette	DEBUG	Closed connection 1
[task 2023-04-10T23:07:39.039Z] 23:07:39     INFO - GECKO(8724) | 1681168059038	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:60198
[task 2023-04-10T23:07:39.064Z] 23:07:39     INFO - GECKO(8724) | 1681168059073	Marionette	DEBUG	2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2023-04-10T23:07:39.077Z] 23:07:39     INFO - GECKO(8724) | 1681168059077	Marionette	DEBUG	Waiting for initial application window
[task 2023-04-10T23:07:39.408Z] 23:07:39     INFO - GECKO(8724) | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-04-10T23:07:50.216Z] 23:07:50     INFO - GECKO(8724) | [Parent 5824, IPC I/O Parent] WARNING: ConnectNamedPipe timed out!: file Z:/task_168116171679495/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:327
[task 2023-04-10T23:07:50.639Z] 23:07:50     INFO - GECKO(8724) | [8508, IPC I/O Child] WARNING: failed to create pipe: 2: file Z:/task_168116171679495/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:237
[task 2023-04-10T23:07:50.641Z] 23:07:50     INFO - GECKO(8724) | [8508, IPC I/O Child] WARNING: Unable to create pipe named "5824.2.658844748\1872372026" in client mode.: file Z:/task_168116171679495/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:55
[task 2023-04-10T23:07:50.648Z] 23:07:50     INFO - GECKO(8724) | Exiting due to channel error.
[task 2023-04-10T23:07:50.843Z] 23:07:50    ERROR - GECKO(8724) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-04-10T23:07:50.937Z] 23:07:50     INFO - GECKO(8724) | JavaScript error: resource://activity-stream/lib/ActivityStreamPrefs.jsm, line 27: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIPrefBranch.removeObserver]
[task 2023-04-10T23:07:51.032Z] 23:07:51     INFO - GECKO(8724) | 1681168071037	Marionette	TRACE	Received observer notification quit-application
[task 2023-04-10T23:07:51.039Z] 23:07:51     INFO - GECKO(8724) | 1681168071037	Marionette	INFO	Stopped listening on port 2828
[task 2023-04-10T23:07:51.040Z] 23:07:51     INFO - GECKO(8724) | 1681168071038	Marionette	DEBUG	Marionette stopped listening
[task 2023-04-10T23:07:51.157Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: chrome://global/content/elements/browser-custom-element.js, line 1013: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIScriptSecurityManager.getLoadContextContentPrincipal]
[task 2023-04-10T23:07:51.171Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: chrome://global/content/elements/browser-custom-element.js, line 1013: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIScriptSecurityManager.getLoadContextContentPrincipal]
[task 2023-04-10T23:07:51.172Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: chrome://global/content/elements/browser-custom-element.js, line 1013: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIScriptSecurityManager.getLoadContextContentPrincipal]
[task 2023-04-10T23:07:51.173Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: chrome://global/content/elements/browser-custom-element.js, line 1013: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIScriptSecurityManager.getLoadContextContentPrincipal]
[task 2023-04-10T23:07:51.175Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: chrome://global/content/elements/browser-custom-element.js, line 1013: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIScriptSecurityManager.getLoadContextContentPrincipal]
[task 2023-04-10T23:07:51.188Z] 23:07:51     INFO - GECKO(8724) | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-04-10T23:07:51.235Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: chrome://global/content/elements/browser-custom-element.js, line 649: TypeError: can't access property "inRDMPane", this.browsingContext is null
[task 2023-04-10T23:07:51.345Z] 23:07:51     INFO - runtests.py | Waiting for browser...
[task 2023-04-10T23:07:51.361Z] 23:07:51     INFO - GECKO(8724) | 1681168071369	Marionette	DEBUG	Failed to remove observer "browser-delayed-startup-finished"
[task 2023-04-10T23:07:51.377Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: chrome://remote/content/marionette/cert.sys.mjs, line 51: NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsICertOverrideService.setDisableAllSecurityChecksAndLetAttackersInterceptMyData]
[task 2023-04-10T23:07:51.382Z] 23:07:51     INFO - GECKO(8724) | console.error: "Could not load engine [e-mail]: Error: XPIProvider can't start bootstrap scope for [e-mail] after shutdown was already granted"
[task 2023-04-10T23:07:51.407Z] 23:07:51     INFO - GECKO(8724) | console.error: "Could not load engine [e-mail]: Error: XPIProvider can't start bootstrap scope for [e-mail] after shutdown was already granted"
[task 2023-04-10T23:07:51.502Z] 23:07:51     INFO - GECKO(8724) | console.error: "Could not load engine [e-mail]: Error: XPIProvider can't start bootstrap scope for [e-mail] after shutdown was already granted"
[task 2023-04-10T23:07:51.517Z] 23:07:51     INFO - GECKO(8724) | console.error: "Could not load engine [e-mail]: Error: XPIProvider can't start bootstrap scope for [e-mail] after shutdown was already granted"
[task 2023-04-10T23:07:51.533Z] 23:07:51     INFO - GECKO(8724) | console.error: "Could not load engine [e-mail]: Error: XPIProvider can't start bootstrap scope for [e-mail] after shutdown was already granted"
[task 2023-04-10T23:07:51.579Z] 23:07:51     INFO - GECKO(8724) | console.error: "Could not load engine [e-mail]: Error: XPIProvider can't start bootstrap scope for [e-mail] after shutdown was already granted"
[task 2023-04-10T23:07:51.587Z] 23:07:51     INFO - GECKO(8724) | console.error: SearchService: "Could not find a replacement default engine."
[task 2023-04-10T23:07:51.587Z] 23:07:51     INFO - GECKO(8724) | console.warn: SearchService: "#init: abandoning init due to shutting down"
[task 2023-04-10T23:07:51.588Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: , line 0: uncaught exception: 2147500036
[task 2023-04-10T23:07:51.588Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: resource:///modules/UrlbarValueFormatter.sys.mjs, line 85: uncaught exception: 2147500036
[task 2023-04-10T23:07:51.589Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: resource:///modules/UrlbarValueFormatter.sys.mjs, line 85: uncaught exception: 2147500036
[task 2023-04-10T23:07:51.590Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: resource://activity-stream/lib/TopSitesFeed.jsm, line 1051: uncaught exception: 2147500036
[task 2023-04-10T23:07:51.590Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: resource://activity-stream/lib/TopSitesFeed.jsm, line 1084: uncaught exception: 2147500036
[task 2023-04-10T23:07:51.712Z] 23:07:51     INFO - GECKO(8724) | WARNING: A blocker encountered an error while we were waiting.
[task 2023-04-10T23:07:51.717Z] 23:07:51     INFO - GECKO(8724) |           Blocker:  Waiting for ping task
[task 2023-04-10T23:07:51.717Z] 23:07:51     INFO - GECKO(8724) |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-04-10T23:07:51.718Z] 23:07:51     INFO - GECKO(8724) |           State: (none)
[task 2023-04-10T23:07:51.719Z] 23:07:51     INFO - GECKO(8724) | 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 2023-04-10T23:07:51.719Z] 23:07:51     INFO - GECKO(8724) | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-04-10T23:07:51.720Z] 23:07:51     INFO - GECKO(8724) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-10T23:07:51.721Z] 23:07:51     INFO - GECKO(8724) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-10T23:07:51.721Z] 23:07:51     INFO - GECKO(8724) | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-10T23:07:51.722Z] 23:07:51     INFO - GECKO(8724) | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-10T23:07:51.722Z] 23:07:51     INFO - GECKO(8724) | @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-10T23:07:51.723Z] 23:07:51     INFO - GECKO(8724) | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-10T23:07:51.723Z] 23:07:51     INFO - GECKO(8724) | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-10T23:07:51.724Z] 23:07:51     INFO - GECKO(8724) | setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-10T23:07:51.724Z] 23:07:51     INFO - GECKO(8724) | setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-10T23:07:51.725Z] 23:07:51     INFO - GECKO(8724) | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-10T23:07:51.726Z] 23:07:51     INFO - GECKO(8724) | async*_runTask@resource://gre/modules/DeferredTask.sys.mjs:347:18
[task 2023-04-10T23:07:51.726Z] 23:07:51     INFO - GECKO(8724) | _timerCallback/<@resource://gre/modules/DeferredTask.sys.mjs:318:20
[task 2023-04-10T23:07:51.727Z] 23:07:51     INFO - GECKO(8724) | _timerCallback@resource://gre/modules/DeferredTask.sys.mjs:337:9
[task 2023-04-10T23:07:51.728Z] 23:07:51     INFO - GECKO(8724) | finalize@resource://gre/modules/DeferredTask.sys.mjs:282:12
[task 2023-04-10T23:07:51.728Z] 23:07:51     INFO - GECKO(8724) | shutdown@resource://gre/modules/TelemetryControllerParent.sys.mjs:984:8
[task 2023-04-10T23:07:51.729Z] 23:07:51     INFO - GECKO(8724) | setupTelemetry/<@resource://gre/modules/TelemetryControllerParent.sys.mjs:892:18
[task 2023-04-10T23:07:51.729Z] 23:07:51     INFO - GECKO(8724) | trigger@resource://gre/modules/AsyncShutdown.sys.mjs:763:23
[task 2023-04-10T23:07:51.730Z] 23:07:51     INFO - GECKO(8724) | _wait@resource://gre/modules/AsyncShutdown.sys.mjs:924:15
[task 2023-04-10T23:07:51.730Z] 23:07:51     INFO - GECKO(8724) | wait@resource://gre/modules/AsyncShutdown.sys.mjs:905:34
[task 2023-04-10T23:07:51.731Z] 23:07:51     INFO - GECKO(8724) | observe@resource://gre/modules/AsyncShutdown.sys.mjs:558:10
[task 2023-04-10T23:07:51.731Z] 23:07:51     INFO - GECKO(8724) | console.error: "TelemetryScheduler.shutdown - Already shut down"
[task 2023-04-10T23:07:51.735Z] 23:07:51     INFO - GECKO(8724) | WARNING: A blocker encountered an error while we were waiting.
[task 2023-04-10T23:07:51.736Z] 23:07:51     INFO - GECKO(8724) |           Blocker:  Waiting for ping task
[task 2023-04-10T23:07:51.737Z] 23:07:51     INFO - GECKO(8724) |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-04-10T23:07:51.737Z] 23:07:51     INFO - GECKO(8724) |           State: (none)
[task 2023-04-10T23:07:51.738Z] 23:07:51     INFO - GECKO(8724) | 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 2023-04-10T23:07:51.738Z] 23:07:51     INFO - GECKO(8724) | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-04-10T23:07:51.739Z] 23:07:51     INFO - GECKO(8724) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-10T23:07:51.740Z] 23:07:51     INFO - GECKO(8724) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-10T23:07:51.740Z] 23:07:51     INFO - GECKO(8724) | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-10T23:07:51.741Z] 23:07:51     INFO - GECKO(8724) | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-10T23:07:51.741Z] 23:07:51     INFO - GECKO(8724) | @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-10T23:07:51.742Z] 23:07:51     INFO - GECKO(8724) | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-10T23:07:51.742Z] 23:07:51     INFO - GECKO(8724) | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-10T23:07:51.743Z] 23:07:51     INFO - GECKO(8724) | setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-10T23:07:51.743Z] 23:07:51     INFO - GECKO(8724) | setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-10T23:07:51.744Z] 23:07:51     INFO - GECKO(8724) | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-10T23:07:51.744Z] 23:07:51     INFO - GECKO(8724) | async*_runTask@resource://gre/modules/DeferredTask.sys.mjs:347:18
[task 2023-04-10T23:07:51.745Z] 23:07:51     INFO - GECKO(8724) | _timerCallback/<@resource://gre/modules/DeferredTask.sys.mjs:318:20
[task 2023-04-10T23:07:51.746Z] 23:07:51     INFO - GECKO(8724) | _timerCallback@resource://gre/modules/DeferredTask.sys.mjs:337:9
[task 2023-04-10T23:07:51.747Z] 23:07:51     INFO - GECKO(8724) | finalize@resource://gre/modules/DeferredTask.sys.mjs:282:12
[task 2023-04-10T23:07:51.747Z] 23:07:51     INFO - GECKO(8724) | shutdown@resource://gre/modules/TelemetryControllerParent.sys.mjs:984:8
[task 2023-04-10T23:07:51.748Z] 23:07:51     INFO - GECKO(8724) | setupTelemetry/<@resource://gre/modules/TelemetryControllerParent.sys.mjs:892:18
[task 2023-04-10T23:07:51.748Z] 23:07:51     INFO - GECKO(8724) | trigger@resource://gre/modules/AsyncShutdown.sys.mjs:763:23
[task 2023-04-10T23:07:51.749Z] 23:07:51     INFO - GECKO(8724) | _wait@resource://gre/modules/AsyncShutdown.sys.mjs:924:15
[task 2023-04-10T23:07:51.749Z] 23:07:51     INFO - GECKO(8724) | wait@resource://gre/modules/AsyncShutdown.sys.mjs:905:34
[task 2023-04-10T23:07:51.750Z] 23:07:51     INFO - GECKO(8724) | observe@resource://gre/modules/AsyncShutdown.sys.mjs:558:10
[task 2023-04-10T23:07:51.751Z] 23:07:51     INFO - GECKO(8724) | WARNING: A blocker encountered an error while we were waiting.
[task 2023-04-10T23:07:51.751Z] 23:07:51     INFO - GECKO(8724) |           Blocker:  TelemetryController: shutting down
[task 2023-04-10T23:07:51.752Z] 23:07:51     INFO - GECKO(8724) |           Phase: profile-before-change-telemetry
[task 2023-04-10T23:07:51.752Z] 23:07:51     INFO - GECKO(8724) |           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.sys.mjs:727:15
[task 2023-04-10T23:07:51.753Z] 23:07:51     INFO - GECKO(8724) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-10T23:07:51.754Z] 23:07:51     INFO - GECKO(8724) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-10T23:07:51.755Z] 23:07:51     INFO - GECKO(8724) | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-10T23:07:51.755Z] 23:07:51     INFO - GECKO(8724) | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-10T23:07:51.755Z] 23:07:51     INFO - GECKO(8724) | @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-10T23:07:51.756Z] 23:07:51     INFO - GECKO(8724) | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-10T23:07:51.757Z] 23:07:51     INFO - GECKO(8724) | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-10T23:07:51.757Z] 23:07:51     INFO - GECKO(8724) | setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-10T23:07:51.758Z] 23:07:51     INFO - GECKO(8724) | setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-10T23:07:51.759Z] 23:07:51     INFO - GECKO(8724) | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-10T23:07:51.759Z] 23:07:51     INFO - GECKO(8724) | async*_runTask@resource://gre/modules/DeferredTask.sys.mjs:347:18
[task 2023-04-10T23:07:51.759Z] 23:07:51     INFO - GECKO(8724) | _timerCallback/<@resource://gre/modules/DeferredTask.sys.mjs:318:20
[task 2023-04-10T23:07:51.761Z] 23:07:51     INFO - GECKO(8724) | _timerCallback@resource://gre/modules/DeferredTask.sys.mjs:337:9
[task 2023-04-10T23:07:51.761Z] 23:07:51     INFO - GECKO(8724) | finalize@resource://gre/modules/DeferredTask.sys.mjs:282:12
[task 2023-04-10T23:07:51.762Z] 23:07:51     INFO - GECKO(8724) | shutdown@resource://gre/modules/TelemetryControllerParent.sys.mjs:984:8
[task 2023-04-10T23:07:51.762Z] 23:07:51     INFO - GECKO(8724) | setupTelemetry/<@resource://gre/modules/TelemetryControllerParent.sys.mjs:892:18
[task 2023-04-10T23:07:51.763Z] 23:07:51     INFO - GECKO(8724) | trigger@resource://gre/modules/AsyncShutdown.sys.mjs:763:23
[task 2023-04-10T23:07:51.763Z] 23:07:51     INFO - GECKO(8724) | _wait@resource://gre/modules/AsyncShutdown.sys.mjs:924:15
[task 2023-04-10T23:07:51.764Z] 23:07:51     INFO - GECKO(8724) | wait@resource://gre/modules/AsyncShutdown.sys.mjs:905:34
[task 2023-04-10T23:07:51.765Z] 23:07:51     INFO - GECKO(8724) | observe@resource://gre/modules/AsyncShutdown.sys.mjs:558:10
[task 2023-04-10T23:07:51.766Z] 23:07:51     INFO - GECKO(8724) | 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 2023-04-10T23:07:51.766Z] 23:07:51     INFO - GECKO(8724) | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-04-10T23:07:51.766Z] 23:07:51     INFO - GECKO(8724) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-10T23:07:51.768Z] 23:07:51     INFO - GECKO(8724) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-10T23:07:51.768Z] 23:07:51     INFO - GECKO(8724) | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-10T23:07:51.769Z] 23:07:51     INFO - GECKO(8724) | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-10T23:07:51.769Z] 23:07:51     INFO - GECKO(8724) | @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-10T23:07:51.770Z] 23:07:51     INFO - GECKO(8724) | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-10T23:07:51.770Z] 23:07:51     INFO - GECKO(8724) | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-10T23:07:51.771Z] 23:07:51     INFO - GECKO(8724) | setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-10T23:07:51.771Z] 23:07:51     INFO - GECKO(8724) | setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-10T23:07:51.772Z] 23:07:51     INFO - GECKO(8724) | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-10T23:07:51.773Z] 23:07:51     INFO - GECKO(8724) | async*_runTask@resource://gre/modules/DeferredTask.sys.mjs:347:18
[task 2023-04-10T23:07:51.773Z] 23:07:51     INFO - GECKO(8724) | _timerCallback/<@resource://gre/modules/DeferredTask.sys.mjs:318:20
[task 2023-04-10T23:07:51.774Z] 23:07:51     INFO - GECKO(8724) | _timerCallback@resource://gre/modules/DeferredTask.sys.mjs:337:9
[task 2023-04-10T23:07:51.774Z] 23:07:51     INFO - GECKO(8724) | finalize@resource://gre/modules/DeferredTask.sys.mjs:282:12
[task 2023-04-10T23:07:51.775Z] 23:07:51     INFO - GECKO(8724) | shutdown@resource://gre/modules/TelemetryControllerParent.sys.mjs:984:8
[task 2023-04-10T23:07:51.775Z] 23:07:51     INFO - GECKO(8724) | setupTelemetry/<@resource://gre/modules/TelemetryControllerParent.sys.mjs:892:18
[task 2023-04-10T23:07:51.776Z] 23:07:51     INFO - GECKO(8724) | trigger@resource://gre/modules/AsyncShutdown.sys.mjs:763:23
[task 2023-04-10T23:07:51.776Z] 23:07:51     INFO - GECKO(8724) | _wait@resource://gre/modules/AsyncShutdown.sys.mjs:924:15
[task 2023-04-10T23:07:51.777Z] 23:07:51     INFO - GECKO(8724) | wait@resource://gre/modules/AsyncShutdown.sys.mjs:905:34
[task 2023-04-10T23:07:51.778Z] 23:07:51     INFO - GECKO(8724) | observe@resource://gre/modules/AsyncShutdown.sys.mjs:558:10
[task 2023-04-10T23:07:51.779Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-10T23:07:51.779Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-10T23:07:51.780Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-10T23:07:51.781Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-10T23:07:51.782Z] 23:07:51     INFO - GECKO(8724) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-04-10T23:07:53.273Z] 23:07:53     INFO - GECKO(8724) | [Parent 5824, IPC I/O Parent] WARNING: Process 4628 may be hanging at shutdown; will wait for up to 80000ms: file Z:/task_168116171679495/build/src/ipc/chromium/src/chrome/common/process_watcher_win.cc:129
[task 2023-04-10T23:08:03.387Z] 23:08:03     INFO - TEST-INFO | Main app process: exit f5
[task 2023-04-10T23:08:03.388Z] 23:08:03     INFO - Buffered messages finished
[task 2023-04-10T23:08:03.389Z] 23:08:03    ERROR - TEST-UNEXPECTED-FAIL | automation.py | application terminated with exit code 245
[task 2023-04-10T23:08:03.389Z] 23:08:03     INFO - runtests.py | Application ran for: 0:00:25.119749
[task 2023-04-10T23:08:03.390Z] 23:08:03     INFO - zombiecheck | Reading PID log: C:\Users\task_168116590924736\AppData\Local\Temp\tmp3iib0nehpidlog
[task 2023-04-10T23:08:03.391Z] 23:08:03     INFO - ==> process 5824 launched child process 4628 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="5824.0.672583361\588289842" -parentBuildID 20230410212705 -prefsHandle 1832 -prefMapHandle 1824 -prefsLen 24706 -prefMapSize 251992 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {0dd106f6-f7ee-49b8-8026-d14b3b344636} 5824 "\\.\pipe\gecko-crash-server-pipe.5824" 1908 2ab7d436d58 gpu)
[task 2023-04-10T23:08:03.392Z] 23:08:03     INFO - ==> process 5824 launched child process 1064 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="5824.1.682269627\1075688870" -childID 1 -isForBrowser -prefsHandle 2744 -prefMapHandle 2740 -prefsLen 24978 -prefMapSize 251992 -jsInitHandle 1432 -jsInitLen 247672 -parentBuildID 20230410212705 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {f669e684-47fe-4749-8c2d-f9b44265f17b} 5824 "\\.\pipe\gecko-crash-server-pipe.5824" 2756 2ab0074e758 tab)
[task 2023-04-10T23:08:03.393Z] 23:08:03     INFO - ==> process 5824 launched child process 8508 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="5824.2.658844748\1872372026" -childID 2 -isForBrowser -prefsHandle 3340 -prefMapHandle 3336 -prefsLen 22090 -prefMapSize 251992 -jsInitHandle 1432 -jsInitLen 247672 -parentBuildID 20230410212705 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {53f764fd-8400-4b9e-b4ee-d3ca0fa85afc} 5824 "\\.\pipe\gecko-crash-server-pipe.5824" 2772 2ab0375cf58 tab)
[task 2023-04-10T23:08:03.394Z] 23:08:03     INFO - ==> process 5824 launched child process 8944 ("Z:\task_168116590924736\build\application\firefox\firefox.exe" -contentproc --channel="5824.3.517892407\1197315381" -childID 3 -isForBrowser -prefsHandle 3452 -prefMapHandle 3220 -prefsLen 27301 -prefMapSize 251992 -jsInitHandle 1432 -jsInitLen 247672 -parentBuildID 20230410212705 -appDir "Z:\task_168116590924736\build\application\firefox\browser" - {6e35a35f-ff87-479b-9fc1-13ab644e1321} 5824 "\\.\pipe\gecko-crash-server-pipe.5824" 2772 2ab7f919758 tab)
[task 2023-04-10T23:08:03.395Z] 23:08:03     INFO - zombiecheck | Checking for orphan process with PID: 1064
[task 2023-04-10T23:08:03.395Z] 23:08:03     INFO - zombiecheck | Checking for orphan process with PID: 8944
[task 2023-04-10T23:08:03.396Z] 23:08:03     INFO - zombiecheck | Checking for orphan process with PID: 4628
[task 2023-04-10T23:08:03.396Z] 23:08:03     INFO - zombiecheck | Checking for orphan process with PID: 8508
[task 2023-04-10T23:08:03.396Z] 23:08:03     INFO -  Traceback (most recent call last):
[task 2023-04-10T23:08:03.396Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\tests\mochitest\runtests.py", line 3697, in doTests
[task 2023-04-10T23:08:03.397Z] 23:08:03     INFO -      ret, _ = self.runApp(
[task 2023-04-10T23:08:03.397Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\tests\mochitest\runtests.py", line 3011, in runApp
[task 2023-04-10T23:08:03.397Z] 23:08:03     INFO -      six.reraise(exc, value, tb)
[task 2023-04-10T23:08:03.398Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\venv\lib\site-packages\six.py", line 696, in reraise
[task 2023-04-10T23:08:03.398Z] 23:08:03     INFO -      raise value
[task 2023-04-10T23:08:03.399Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\tests\mochitest\runtests.py", line 2871, in runApp
[task 2023-04-10T23:08:03.399Z] 23:08:03     INFO -      self.marionette.start_session()
[task 2023-04-10T23:08:03.399Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\venv\lib\site-packages\marionette_driver\decorators.py", line 34, in _
[task 2023-04-10T23:08:03.400Z] 23:08:03     INFO -      m._handle_socket_failure()
[task 2023-04-10T23:08:03.400Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\venv\lib\site-packages\marionette_driver\marionette.py", line 747, in _handle_socket_failure
[task 2023-04-10T23:08:03.400Z] 23:08:03     INFO -      reraise(exc_cls, exc, tb)
[task 2023-04-10T23:08:03.400Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\venv\lib\site-packages\six.py", line 696, in reraise
[task 2023-04-10T23:08:03.401Z] 23:08:03     INFO -      raise value
[task 2023-04-10T23:08:03.401Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\venv\lib\site-packages\marionette_driver\decorators.py", line 24, in _
[task 2023-04-10T23:08:03.401Z] 23:08:03     INFO -      return func(*args, **kwargs)
[task 2023-04-10T23:08:03.402Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1298, in start_session
[task 2023-04-10T23:08:03.402Z] 23:08:03     INFO -      resp = self._send_message("WebDriver:NewSession", capabilities)
[task 2023-04-10T23:08:03.402Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\venv\lib\site-packages\marionette_driver\decorators.py", line 34, in _
[task 2023-04-10T23:08:03.402Z] 23:08:03     INFO -      m._handle_socket_failure()
[task 2023-04-10T23:08:03.403Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\venv\lib\site-packages\marionette_driver\marionette.py", line 747, in _handle_socket_failure
[task 2023-04-10T23:08:03.403Z] 23:08:03     INFO -      reraise(exc_cls, exc, tb)
[task 2023-04-10T23:08:03.403Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\venv\lib\site-packages\six.py", line 696, in reraise
[task 2023-04-10T23:08:03.403Z] 23:08:03     INFO -      raise value
[task 2023-04-10T23:08:03.404Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\venv\lib\site-packages\marionette_driver\decorators.py", line 24, in _
[task 2023-04-10T23:08:03.404Z] 23:08:03     INFO -      return func(*args, **kwargs)
[task 2023-04-10T23:08:03.404Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\venv\lib\site-packages\marionette_driver\marionette.py", line 696, in _send_message
[task 2023-04-10T23:08:03.404Z] 23:08:03     INFO -      msg = self.client.request(name, params)
[task 2023-04-10T23:08:03.405Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\venv\lib\site-packages\marionette_driver\transport.py", line 381, in request
[task 2023-04-10T23:08:03.405Z] 23:08:03     INFO -      return self.receive()
[task 2023-04-10T23:08:03.406Z] 23:08:03     INFO -    File "Z:\task_168116590924736\build\venv\lib\site-packages\marionette_driver\transport.py", line 228, in receive
[task 2023-04-10T23:08:03.406Z] 23:08:03     INFO -      raise socket.error("No data received over socket")
[task 2023-04-10T23:08:03.406Z] 23:08:03     INFO -  OSError: No data received over socket
[task 2023-04-10T23:08:03.407Z] 23:08:03    ERROR - Automation Error: Received unexpected exception while running application
[task 2023-04-10T23:08:03.407Z] 23:08:03    ERROR - 
[task 2023-04-10T23:08:03.407Z] 23:08:03     INFO - Stopping web server
[task 2023-04-10T23:08:03.407Z] 23:08:03     INFO - Server shut down.
[task 2023-04-10T23:08:03.420Z] 23:08:03     INFO - Web server killed.
[task 2023-04-10T23:08:03.421Z] 23:08:03     INFO - Stopping web socket server
[task 2023-04-10T23:08:03.450Z] 23:08:03     INFO - Stopping ssltunnel
[task 2023-04-10T23:08:03.513Z] 23:08:03     INFO - Stopping websocket/process bridge
[task 2023-04-10T23:08:03.514Z] 23:08:03  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2023-04-10T23:08:03.514Z] 23:08:03     INFO - runtests.py | Running tests: end.
[task 2023-04-10T23:08:03.514Z] 23:08:03     INFO - Buffered messages finished
[task 2023-04-10T23:08:03.515Z] 23:08:03     INFO - Running manifest: dom\media\test\mochitest_media_recorder.ini
[task 2023-04-10T23:08:03.515Z] 23:08:03     INFO - The following extra prefs will be set:
[task 2023-04-10T23:08:03.515Z] 23:08:03     INFO -   media.recorder.video.frame_drops=false
[task 2023-04-10T23:08:10.812Z] 23:08:10     INFO - PID 3396 | Z:\task_168116590924736\build\tests\bin\pk12util.exe: PKCS12 IMPORT SUCCESSFUL
[task 2023-04-10T23:08:11.265Z] 23:08:11     INFO - MochitestServer : launching ['Z:\\task_168116590924736\\build\\tests\\bin\\xpcshell.exe', '-g', 'Z:\\task_168116590924736\\build\\application\\firefox', '-f', 'Z:\\task_168116590924736\\build\\tests\\bin\\components\\httpd.js', '-e', "const _PROFILE_PATH = 'C:\\\\Users\\\\task_168116590924736\\\\AppData\\\\Local\\\\Temp\\\\tmp59xn16r_.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', 'Z:\\task_168116590924736\\build\\tests\\mochitest\\server.js']
[task 2023-04-10T23:08:11.272Z] 23:08:11     INFO - runtests.py | Server pid: 7296
[task 2023-04-10T23:08:11.275Z] 23:08:11     INFO - runtests.py | Websocket server pid: 7708
[task 2023-04-10T23:08:11.327Z] 23:08:11     INFO - runtests.py | websocket/process bridge pid: 1248
[task 2023-04-10T23:08:12.359Z] 23:08:12     INFO - runtests.py | SSL tunnel pid: 8200
[task 2023-04-10T23:08:12.366Z] 23:08:12     INFO - use http3 server: 0
[task 2023-04-10T23:08:12.367Z] 23:08:12     INFO - runtests.py | Running with scheme: http
[task 2023-04-10T23:08:12.368Z] 23:08:12     INFO - runtests.py | Running with e10s: True
[task 2023-04-10T23:08:12.369Z] 23:08:12     INFO - runtests.py | Running with fission: True
[task 2023-04-10T23:08:12.369Z] 23:08:12     INFO - runtests.py | Running with cross-origin iframes: False
[task 2023-04-10T23:08:12.370Z] 23:08:12     INFO - runtests.py | Running with serviceworker_e10s: True
[task 2023-04-10T23:08:12.370Z] 23:08:12     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2023-04-10T23:08:12.371Z] 23:08:12     INFO - runtests.py | Running tests: start.
[task 2023-04-10T23:08:12.371Z] 23:08:12     INFO - 
[task 2023-04-10T23:08:12.453Z] 23:08:12     INFO - Application command: Z:\task_168116590924736\build\application\firefox\firefox.exe -marionette --wait-for-browser -foreground -profile C:\Users\task_168116590924736\AppData\Local\Temp\tmp59xn16r_.mozrunner
[task 2023-04-10T23:08:12.462Z] 23:08:12     INFO - runtests.py | Application pid: 3320
[task 2023-04-10T23:08:12.462Z] 23:08:12     INFO - TEST-INFO | started process GECKO(3320)

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• autoland: 3

Platform and build breakdown:

• windows11-64-2009-ccov-qr: 1
  • opt: 1
• windows11-64-2009-qr: 2
  • opt: 1
  • debug: 1
• windows11-64-2009-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1827316&startday=2023-04-10&endday=2023-04-16&tree=all

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 5

Platform and build breakdown:

• windows11-32-2009-qr: 3
  • debug: 3
• windows11-64-2009-asan-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1827316&startday=2023-04-17&endday=2023-04-23&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows11-64-2009-ccov-qr: 1
  • opt: 1

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

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform and build breakdown:

• windows11-32-2009-qr: 1
  • debug: 1

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

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows11-64-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1827316&startday=2023-05-08&endday=2023-05-14&tree=all

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1
• mozilla-release: 1

Platform and build breakdown:

• windows11-64-2009-asan-qr: 1
  • opt: 1
• windows11-64-2009-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1827316&startday=2023-05-15&endday=2023-05-21&tree=all

Comment 7

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.