1832385 - Intermittent Mn | OSError: Process has been unexpectedly closed (Exit code: <code>) [shutdown hang of Firefox]

Status: RESOLVED INCOMPLETE

(Testing :: Marionette Client and Harness, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2023-05-10T18:59:51.820Z] 18:59:51     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_cli_arguments.py TestCommandLineArguments.test_debugger_address_cdp_status
[task 2023-05-10T18:59:51.832Z] 18:59:51     INFO -  1683745191831	Marionette	DEBUG	Accepted connection 104 from 127.0.0.1:63407
[task 2023-05-10T18:59:51.833Z] 18:59:51     INFO -  1683745191833	Marionette	DEBUG	104 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2023-05-10T18:59:51.834Z] 18:59:51     INFO -  1683745191834	Marionette	DEBUG	Waiting for initial application window
[task 2023-05-10T18:59:51.836Z] 18:59:51     INFO -  1683745191836	RemoteAgent	TRACE	[13] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=1600 waitForExplicitStart=false
[task 2023-05-10T18:59:51.836Z] 18:59:51     INFO -  1683745191836	RemoteAgent	TRACE	[13] ProgressListener Setting unload timer (1600ms)
[task 2023-05-10T18:59:51.837Z] 18:59:51     INFO -  1683745191836	RemoteAgent	TRACE	[13] Document already finished loading: http://127.0.0.1:63285/test.html
[task 2023-05-10T18:59:51.837Z] 18:59:51     INFO -  1683745191836	RemoteAgent	TRACE	[13] ProgressListener Stop: has error=false
[task 2023-05-10T18:59:51.840Z] 18:59:51     INFO -  1683745191839	Marionette	DEBUG	104 <- [1,1,null,{"sessionId":"1a59bb5e-75a2-49b5-ae99-8a4e192b5b20","capabilities":{"browserName":"firefox","browserVersion":"115.0a1","platformName":"windows","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20230510182735","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":4696,"moz:profile":"C:\\Users\\task_168374347943291\\AppData\\Local\\Temp\\tmp42y_ngdj.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2023-05-10T18:59:51.841Z] 18:59:51     INFO -  1683745191841	Marionette	DEBUG	104 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2023-05-10T18:59:51.841Z] 18:59:51     INFO -  1683745191841	Marionette	DEBUG	104 <- [1,2,null,{"value":null}]
[task 2023-05-10T18:59:51.842Z] 18:59:51     INFO -  1683745191842	Marionette	DEBUG	104 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2023-05-10T18:59:51.843Z] 18:59:51     INFO -  1683745191843	Marionette	DEBUG	104 <- [1,3,null,{"value":null}]
[task 2023-05-10T18:59:51.844Z] 18:59:51     INFO -  1683745191844	Marionette	DEBUG	104 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2023-05-10T18:59:51.844Z] 18:59:51     INFO -  1683745191844	Marionette	DEBUG	104 <- [1,4,null,{"value":null}]
[task 2023-05-10T18:59:51.845Z] 18:59:51     INFO -  1683745191845	Marionette	DEBUG	104 -> [0,5,"Marionette:GetContext",{}]
[task 2023-05-10T18:59:51.846Z] 18:59:51     INFO -  1683745191846	Marionette	DEBUG	104 <- [1,5,null,{"value":"content"}]
[task 2023-05-10T18:59:51.847Z] 18:59:51     INFO -  1683745191847	Marionette	DEBUG	104 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-05-10T18:59:51.847Z] 18:59:51     INFO -  1683745191847	Marionette	DEBUG	104 <- [1,6,null,{"value":null}]
[task 2023-05-10T18:59:51.849Z] 18:59:51     INFO -  1683745191848	Marionette	DEBUG	104 -> [0,7,"WebDriver:ExecuteScript",{"script":"const { Preferences } = ChromeUtils.importESModule(\n                  \"resource://gre/modules/Preferences.sys.mjs\"\n           ... guments[2];\n\n                prefs = new Preferences({defaultBranch: defaultBranch});\n                prefs.set(pref, value);","args":["remote.active-protocols",1,false],"newSandbox":true,"sandbox":"default","line":871,"filename":"Z:\\task_168374347943291\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py"}]
[task 2023-05-10T18:59:51.850Z] 18:59:51     INFO -  1683745191850	RemoteAgent	TRACE	WebDriverProcessData actor created for PID 4696
[task 2023-05-10T18:59:51.850Z] 18:59:51     INFO -  1683745191850	Marionette	TRACE	[1] MarionetteCommands actor created for window id 2
[task 2023-05-10T18:59:51.854Z] 18:59:51     INFO -  1683745191854	Marionette	DEBUG	104 <- [1,7,null,{"value":null}]
[task 2023-05-10T18:59:51.855Z] 18:59:51     INFO -  1683745191855	Marionette	DEBUG	104 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2023-05-10T18:59:51.855Z] 18:59:51     INFO -  1683745191855	Marionette	DEBUG	104 <- [1,8,null,{"value":null}]
[task 2023-05-10T18:59:51.856Z] 18:59:51     INFO -  1683745191856	Marionette	DEBUG	104 -> [0,9,"Marionette:AcceptConnections",{"value":false}]
[task 2023-05-10T18:59:51.856Z] 18:59:51     INFO -  1683745191856	Marionette	INFO	Stopped listening on port 2828
[task 2023-05-10T18:59:51.857Z] 18:59:51     INFO -  1683745191857	Marionette	DEBUG	104 <- [1,9,null,{"value":null}]
[task 2023-05-10T18:59:51.858Z] 18:59:51     INFO -  1683745191858	Marionette	DEBUG	104 -> [0,10,"Marionette:Quit",{}]
[task 2023-05-10T18:59:51.859Z] 18:59:51     INFO -  1683745191859	Marionette	TRACE	[1] MarionetteCommands actor destroyed for window id 2
[task 2023-05-10T18:59:51.862Z] 18:59:51     INFO -  DEBUG: Adding blocker SessionStore: flushing all windows for phase quit-application-granted
[task 2023-05-10T18:59:51.864Z] 18:59:51     INFO -  DEBUG: Starting phase quit-application-granted
[task 2023-05-10T18:59:51.871Z] 18:59:51     INFO -  DEBUG: Spinning the event loop
[task 2023-05-10T18:59:51.873Z] 18:59:51     INFO -  DEBUG: Adding blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:51.874Z] 18:59:51     INFO -  DEBUG: Adding blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:51.875Z] 18:59:51     INFO -  DEBUG: Adding blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:51.875Z] 18:59:51     INFO -  DEBUG: Adding blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:51.875Z] 18:59:51     INFO -  DEBUG: Adding blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:51.876Z] 18:59:51     INFO -  DEBUG: Adding blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:51.876Z] 18:59:51     INFO -  DEBUG: Adding blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:51.899Z] 18:59:51     INFO -  [Child 7328, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-10T18:59:51.904Z] 18:59:51     INFO -  [Child 7328, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-10T18:59:51.913Z] 18:59:51     INFO -  [Child 7328, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-10T18:59:51.916Z] 18:59:51     INFO -  [Child 7328, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-10T18:59:51.917Z] 18:59:51     INFO -  [Child 7328, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-10T18:59:51.917Z] 18:59:51     INFO -  [Child 7328, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-10T18:59:51.918Z] 18:59:51     INFO -  DEBUG: Completed blocker XPIProvider shutdown for phase quit-application-granted
[task 2023-05-10T18:59:51.920Z] 18:59:51     INFO -  [Child 7328, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-10T18:59:51.920Z] 18:59:51     INFO -  [Child 7328, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-10T18:59:51.921Z] 18:59:51     INFO -  [Child 7328, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-10T18:59:51.945Z] 18:59:51     INFO -  DEBUG: Completed blocker SessionStore: flushing all windows for phase quit-application-granted
[task 2023-05-10T18:59:51.949Z] 18:59:51     INFO -  DEBUG: Finished phase quit-application-granted
[task 2023-05-10T18:59:51.950Z] 18:59:51     INFO -  DEBUG: Adding blocker ShieldRecipeClient: Cleaning up for phase profile-before-change
[task 2023-05-10T18:59:52.620Z] 18:59:52     INFO -  DEBUG: Completed blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:52.627Z] 18:59:52     INFO -  DEBUG: Completed blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:52.628Z] 18:59:52     INFO -  DEBUG: Completed blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:52.629Z] 18:59:52     INFO -  DEBUG: Completed blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:52.629Z] 18:59:52     INFO -  DEBUG: Completed blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:52.630Z] 18:59:52     INFO -  DEBUG: Completed blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:52.630Z] 18:59:52     INFO -  DEBUG: Completed blocker Extension shutdown: [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:52.638Z] 18:59:52     INFO -  [Child 6400, Main Thread] WARNING: DispatchEvent called on non-current inner window, dropping. Please check the window in the caller instead.: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowInner.cpp:4380
[task 2023-05-10T18:59:52.654Z] 18:59:52     INFO -  [GPU 6508, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:371
[task 2023-05-10T18:59:52.664Z] 18:59:52     INFO -  1683745192663	Marionette	TRACE	Received observer notification quit-application
[task 2023-05-10T18:59:52.666Z] 18:59:52     INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T18:59:52.666Z] 18:59:52     INFO -  1683745192666	Marionette	TRACE	Received observer notification quit-application
[task 2023-05-10T18:59:52.667Z] 18:59:52     INFO -  1683745192666	Marionette	DEBUG	Marionette stopped listening
[task 2023-05-10T18:59:52.668Z] 18:59:52     INFO -  1683745192668	Marionette	DEBUG	104 <- [1,10,null,{"cause":"shutdown","forced":false,"in_app":true}]
[task 2023-05-10T18:59:52.669Z] 18:59:52     INFO -  DEBUG: Completed blocker ShieldRecipeClient: Cleaning up for phase profile-before-change
[task 2023-05-10T18:59:52.673Z] 18:59:52     INFO -  [GPU 6508, Compositor] WARNING: IPC Connection Error: [Parent][PCompositorManagerParent] RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost: file /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1927
[task 2023-05-10T18:59:52.682Z] 18:59:52     INFO -  1683745192682	Marionette	DEBUG	Closed connection 104
[task 2023-05-10T18:59:52.683Z] 18:59:52     INFO -  DEBUG: Starting phase xpcom-will-shutdown
[task 2023-05-10T18:59:52.684Z] 18:59:52     INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T18:59:52.685Z] 18:59:52     INFO -  [Child 6400, Main Thread] WARNING: IPC message 'PContent::Msg_StoreUserInteractionAsPermission' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:504
[task 2023-05-10T18:59:52.686Z] 18:59:52     INFO -  [Child 6400, Main Thread] WARNING: IPC message 'PContent::Msg_StoreUserInteractionAsPermission' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:504
[task 2023-05-10T18:59:52.686Z] 18:59:52     INFO -  DEBUG: Spinning the event loop
[task 2023-05-10T18:59:52.686Z] 18:59:52     INFO -  DEBUG: Finished phase xpcom-will-shutdown
[task 2023-05-10T18:59:52.691Z] 18:59:52     INFO -  [Parent 4696, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:232
[task 2023-05-10T18:59:52.693Z] 18:59:52     INFO -  DEBUG: Starting phase profile-change-teardown
[task 2023-05-10T18:59:52.701Z] 18:59:52     INFO -  DEBUG: Spinning the event loop
[task 2023-05-10T18:59:52.706Z] 18:59:52     INFO -  DEBUG: Adding blocker places.sqlite#0: Interactions.jsm::updateDatabase (23) for phase places.sqlite#0: waiting for clients
[task 2023-05-10T18:59:52.707Z] 18:59:52     INFO -  DEBUG: Completed blocker PlacesFrecencyRecalculator: shutdown for phase profile-change-teardown
[task 2023-05-10T18:59:52.708Z] 18:59:52     INFO -  DEBUG: Completed blocker sanitize.js: Sanitize on shutdown for phase Places Clients shutdown
[task 2023-05-10T18:59:52.708Z] 18:59:52     INFO -  DEBUG: Completed blocker places.sqlite#0: Interactions.jsm::updateDatabase (23) for phase places.sqlite#0: waiting for clients
[task 2023-05-10T18:59:52.709Z] 18:59:52     INFO -  DEBUG: Completed blocker Interactions.jsm:: store for phase Places Clients shutdown
[task 2023-05-10T18:59:52.722Z] 18:59:52     INFO -  [Child 6400, Main Thread] WARNING: IPC message 'PContent::Msg_CleanupPendingLoadState' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:504
[task 2023-05-10T18:59:52.761Z] 18:59:52     INFO -  [Child 6400, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3426
[task 2023-05-10T18:59:52.767Z] 18:59:52     INFO -  [Child 6400, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2023-05-10T18:59:52.769Z] 18:59:52     INFO -  [Child 7328, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3426
[task 2023-05-10T18:59:52.771Z] 18:59:52     INFO -  [Child 7328, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2023-05-10T18:59:52.779Z] 18:59:52     INFO -  [Child 7328, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4688
[task 2023-05-10T18:59:52.779Z] 18:59:52     INFO -  [Child 6400, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4688
[task 2023-05-10T18:59:52.780Z] 18:59:52     INFO -  nsStringStats
[task 2023-05-10T18:59:52.781Z] 18:59:52     INFO -   => mAllocCount:          31736
[task 2023-05-10T18:59:52.781Z] 18:59:52     INFO -   => mReallocCount:            0
[task 2023-05-10T18:59:52.781Z] 18:59:52     INFO -   => mFreeCount:           31735  --  LEAKED 1 !!!
[task 2023-05-10T18:59:52.781Z] 18:59:52     INFO -   => mShareCount:          41762
[task 2023-05-10T18:59:52.782Z] 18:59:52     INFO -   => mAdoptCount:            889
[task 2023-05-10T18:59:52.782Z] 18:59:52     INFO -   => mAdoptFreeCount:        941
[task 2023-05-10T18:59:52.782Z] 18:59:52     INFO -   => Process ID: 6400, Thread ID: 6568
[task 2023-05-10T18:59:59.417Z] 18:59:59     INFO -  DEBUG: Completed blocker Clear Extension StorageSync {d3e7c1f1-2e35-4a49-89fe-9f46eb8abf0a} for phase profile-change-teardown
[task 2023-05-10T18:59:59.428Z] 18:59:59     INFO -  DEBUG: Completed blocker Clear Extension StorageSync [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:59.429Z] 18:59:59     INFO -  DEBUG: Completed blocker Clear Extension StorageSync [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:59.429Z] 18:59:59     INFO -  DEBUG: Completed blocker Clear Extension StorageSync [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:59.429Z] 18:59:59     INFO -  DEBUG: Completed blocker Clear Extension StorageSync {d3e7c1f1-2e35-4a49-89fe-9f46eb8abf0a} for phase profile-change-teardown
[task 2023-05-10T18:59:59.430Z] 18:59:59     INFO -  DEBUG: Completed blocker Clear Extension StorageSync [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:59.430Z] 18:59:59     INFO -  DEBUG: Completed blocker Clear Extension StorageSync [e-mail] for phase profile-change-teardown
[task 2023-05-10T18:59:59.430Z] 18:59:59     INFO -  DEBUG: Completed blocker Clear Extension StorageSync {d3e7c1f1-2e35-4a49-89fe-9f46eb8abf0a} for phase profile-change-teardown
[task 2023-05-10T19:00:01.818Z] 19:00:01     INFO -  DEBUG: Completed blocker StorageSyncService: shutdown for phase profile-change-teardown
[task 2023-05-10T19:00:01.821Z] 19:00:01     INFO -  DEBUG: Finished phase profile-change-teardown
[task 2023-05-10T19:00:46.110Z] 19:00:46     INFO -  DEBUG: Starting phase profile-before-change
[task 2023-05-10T19:00:46.122Z] 19:00:46     INFO -  DEBUG: Spinning the event loop
[task 2023-05-10T19:00:46.124Z] 19:00:46     INFO -  DEBUG: Completed blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2023-05-10T19:00:46.125Z] 19:00:46     INFO -  DEBUG: Completed blocker PageActions: purging unregistered actions from cache for phase profile-before-change
[task 2023-05-10T19:00:46.125Z] 19:00:46     INFO -  DEBUG: Completed blocker Places Expiration: shutdown for phase Places Connection shutdown
[task 2023-05-10T19:00:46.126Z] 19:00:46     INFO -  DEBUG: Completed blocker Flush WebExtension StartupCache for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.126Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'handlers' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.126Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'logins' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.127Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'broadcastlisteners' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.127Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'autofillprofiles' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.127Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'shieldpreferenceexperiments' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.128Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'ExperimentStoreData' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.128Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'extensionsettings' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.129Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'storage.js' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.129Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'storage.js' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.129Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'storage.js' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.130Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'storage.js' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.131Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'storage.js' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.131Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'storage.js' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.131Z] 19:00:46     INFO -  DEBUG: Completed blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change
[task 2023-05-10T19:00:46.132Z] 19:00:46     INFO -  DEBUG: Completed blocker DownloadAutoSaveView: writing data for phase profile-before-change
[task 2023-05-10T19:00:46.132Z] 19:00:46     INFO -  DEBUG: Completed blocker Remote Settings profile-before-change for phase profile-before-change
[task 2023-05-10T19:00:46.132Z] 19:00:46     INFO -  DEBUG: Completed blocker Search service: shutting down for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.132Z] 19:00:46     INFO -  DEBUG: Completed blocker places.sqlite#0: waiting for shutdown for phase Sqlite.sys.mjs: wait until all connections are closed
[task 2023-05-10T19:00:46.134Z] 19:00:46     INFO -  DEBUG: Completed blocker PlacesUtils wrapped connection closing as part of Places shutdown for phase Places Connection shutdown
[task 2023-05-10T19:00:46.134Z] 19:00:46     INFO -  DEBUG: Completed blocker PlacesUtils wrapped connection must be closed before Sqlite.sys.mjs for phase Sqlite.sys.mjs: wait until all clients have completed their task
[task 2023-05-10T19:00:46.134Z] 19:00:46     INFO -  DEBUG: Completed blocker JSON store: writing data for 'addonStartup' for phase AddonManager: Waiting for providers to shut down.
[task 2023-05-10T19:00:46.135Z] 19:00:46     INFO -  DEBUG: Completed blocker SitePermsAddonProvider for phase AddonManager: Waiting for providers to shut down.
[task 2023-05-10T19:00:46.135Z] 19:00:46     INFO -  DEBUG: Completed blocker GMPProvider for phase AddonManager: Waiting for providers to shut down.
[task 2023-05-10T19:00:46.135Z] 19:00:46     INFO -  DEBUG: Completed blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2023-05-10T19:00:46.135Z] 19:00:46     INFO -  DEBUG: Completed blocker AddonManager: shutting down. for phase profile-before-change
[task 2023-05-10T19:00:46.137Z] 19:00:46     INFO -  DEBUG: Completed blocker CrashMonitor: Writing notifications to file after receiving profile-before-change and awaiting all checkpoints written for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:00:46.144Z] 19:00:46     INFO -  DEBUG: Completed blocker content-prefs.sqlite#0: waiting for shutdown for phase Sqlite.sys.mjs: wait until all connections are closed
[task 2023-05-10T19:00:46.144Z] 19:00:46     INFO -  DEBUG: Completed blocker Closing ContentPrefService2 connection. for phase Sqlite.sys.mjs: wait until all clients have completed their task
[task 2023-05-10T19:00:46.145Z] 19:00:46     INFO -  DEBUG: Completed blocker formhistory.sqlite#0: waiting for shutdown for phase Sqlite.sys.mjs: wait until all connections are closed
[task 2023-05-10T19:00:46.146Z] 19:00:46     INFO -  DEBUG: Completed blocker Closing FormHistory database. for phase Sqlite.sys.mjs: wait until all clients have completed their task
[task 2023-05-10T19:00:46.146Z] 19:00:46     INFO -  DEBUG: Completed blocker places.sqlite#1: waiting for shutdown for phase Sqlite.sys.mjs: wait until all connections are closed
[task 2023-05-10T19:00:46.147Z] 19:00:46     INFO -  DEBUG: Completed blocker PlacesUtils read-only connection closing as part of Places shutdown for phase Places Connection shutdown
[task 2023-05-10T19:00:46.147Z] 19:00:46     INFO -  DEBUG: Completed blocker PlacesUtils read-only connection must be closed before Sqlite.sys.mjs for phase Sqlite.sys.mjs: wait until all clients have completed their task
[task 2023-05-10T19:00:46.149Z] 19:00:46     INFO -  DEBUG: Completed blocker protections.sqlite#0: waiting for shutdown for phase Sqlite.sys.mjs: wait until all connections are closed
[task 2023-05-10T19:00:46.149Z] 19:00:46     INFO -  DEBUG: Completed blocker TrackingDBService: Shutting down the content blocking database. for phase profile-before-change
[task 2023-05-10T19:00:46.149Z] 19:00:46     INFO -  DEBUG: Completed blocker Sqlite.sys.mjs shutdown blocker for phase profile-before-change
[task 2023-05-10T19:00:46.154Z] 19:00:46     INFO -  [Child 8580, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3426
[task 2023-05-10T19:00:46.154Z] 19:00:46     INFO -  console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.sys.mjs", 370))
[task 2023-05-10T19:00:46.156Z] 19:00:46     INFO -  [Child 5660, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3426
[task 2023-05-10T19:00:46.157Z] 19:00:46     INFO -  [Child 8580, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2023-05-10T19:00:46.157Z] 19:00:46     INFO -  [Child 3464, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3426
[task 2023-05-10T19:00:46.158Z] 19:00:46     INFO -  [Child 5660, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2023-05-10T19:00:46.159Z] 19:00:46     INFO -  [Child 3464, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2023-05-10T19:00:46.160Z] 19:00:46     INFO -  [Child 5660, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4688
[task 2023-05-10T19:00:46.163Z] 19:00:46     INFO -  [Child 8580, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4688
[task 2023-05-10T19:00:46.164Z] 19:00:46     INFO -  [Child 3464, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4688
[task 2023-05-10T19:00:56.123Z] 19:00:56     INFO -  WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"Places Connection shutdown","state":{"PlacesShutdownProgress":5},"filename":"/builds/worker/checkouts/gecko/toolkit/components/places/Database.cpp","lineNumber":466,"stack":""}] Barrier: profile-before-change
[task 2023-05-10T19:00:57.440Z] 19:00:57     INFO -  DEBUG: Finished phase profile-before-change
[task 2023-05-10T19:00:57.456Z] 19:00:57     INFO -  [Parent 4696, IPDL Background] WARNING: quota manager shutdown step: '0.000000s: startCrashBrowserTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:00:57.457Z] 19:00:57     INFO -  [Parent 4696, IPDL Background] WARNING: quota manager shutdown step: '0.000000s: initiateShutdownWorkThreads', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:00:57.457Z] 19:00:57     INFO -  [Parent 4696, IPDL Background] WARNING: idb: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:00:57.457Z] 19:00:57     INFO -  [Parent 4696, IPDL Background] WARNING: cache: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:00:57.458Z] 19:00:57     INFO -  [Parent 4696, IPDL Background] WARNING: sdb: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:00:57.458Z] 19:00:57     INFO -  [Parent 4696, IPDL Background] WARNING: fs: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:00:57.458Z] 19:00:57     INFO -  [Parent 4696, IPDL Background] WARNING: ls: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:00:57.459Z] 19:00:57     INFO -  [Parent 4696, IPDL Background] WARNING: quota manager shutdown step: '0.000000s: startKillActorsTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:00:57.459Z] 19:00:57     INFO -  [Parent 4696, IPDL Background] WARNING: idb: '0.000000s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:00:57.459Z] 19:00:57     INFO -  [Parent 4696, IPDL Background] WARNING: idb: '0.000000s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:01:02.225Z] 19:01:02     INFO -  [Parent 4696, IPDL Background] WARNING: quota manager shutdown step: '4.765000s: stopKillActorsTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:01:02.235Z] 19:01:02     INFO -  [Parent 4696, IPDL Background] WARNING: quota manager shutdown step: '4.765000s: shutdownAndJoinWorkThreads', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:01:02.235Z] 19:01:02     INFO -  [Parent 4696, IPDL Background] WARNING: idb: '4.765000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:01:02.235Z] 19:01:02     INFO -  [Parent 4696, IPDL Background] WARNING: cache: '4.765000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:01:02.236Z] 19:01:02     INFO -  [Parent 4696, IPDL Background] WARNING: sdb: '4.765000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:01:02.236Z] 19:01:02     INFO -  [Parent 4696, IPDL Background] WARNING: fs: '4.765000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:01:02.236Z] 19:01:02     INFO -  [Parent 4696, IPDL Background] WARNING: ls: '4.765000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:01:02.237Z] 19:01:02     INFO -  [Parent 4696, IPDL Background] WARNING: quota manager shutdown step: '4.765000s: shutdownAndJoinIOThread', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:01:02.237Z] 19:01:02     INFO -  [Parent 4696, IPDL Background] WARNING: quota manager shutdown step: '4.765000s: invalidatePendingDirectoryLocks', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:01:02.237Z] 19:01:02     INFO -  [Parent 4696, IPDL Background] WARNING: quota manager shutdown step: '4.765000s: stopCrashBrowserTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-05-10T19:01:02.238Z] 19:01:02     INFO -  DEBUG: Starting phase profile-before-change-telemetry
[task 2023-05-10T19:01:02.238Z] 19:01:02     INFO -  DEBUG: Spinning the event loop
[task 2023-05-10T19:01:02.241Z] 19:01:02     INFO -  DEBUG: Adding blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2023-05-10T19:01:02.244Z] 19:01:02     INFO -  DEBUG: Completed blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2023-05-10T19:01:02.249Z] 19:01:02     INFO -  DEBUG: Adding blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2023-05-10T19:01:02.260Z] 19:01:02     INFO -  DEBUG: Adding blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2023-05-10T19:01:02.275Z] 19:01:02     INFO -  DEBUG: Adding blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2023-05-10T19:01:02.282Z] 19:01:02     INFO -  DEBUG: Completed blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2023-05-10T19:01:02.283Z] 19:01:02     INFO -  DEBUG: Completed blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2023-05-10T19:01:02.284Z] 19:01:02     INFO -  DEBUG: Completed blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2023-05-10T19:01:02.286Z] 19:01:02     INFO -  DEBUG: Completed blocker TelemetryController: shutting down for phase IOUtils: waiting for sendTelemetry IO to complete
[task 2023-05-10T19:01:02.286Z] 19:01:02     INFO -  DEBUG: Finished phase profile-before-change-telemetry
[task 2023-05-10T19:01:02.287Z] 19:01:02     INFO -  DEBUG: Starting phase xpcom-will-shutdown
[task 2023-05-10T19:01:02.288Z] 19:01:02     INFO -  DEBUG: Spinning the event loop
[task 2023-05-10T19:01:02.289Z] 19:01:02     INFO -  DEBUG: Finished phase xpcom-will-shutdown
[task 2023-05-10T19:01:02.294Z] 19:01:02     INFO -  [Utility 8812, Main Thread] WARNING: IPC message 'PUtilityProcess::Msg_FOGData' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:504
[task 2023-05-10T19:01:02.294Z] 19:01:02     INFO -  DEBUG: Starting phase web-workers-shutdown
[task 2023-05-10T19:01:02.295Z] 19:01:02     INFO -  DEBUG: Spinning the event loop
[task 2023-05-10T19:01:02.295Z] 19:01:02     INFO -  DEBUG: Finished phase web-workers-shutdown
[task 2023-05-10T19:01:02.298Z] 19:01:02     INFO -  [GPU 6508, Main Thread] WARNING: IPC Connection Error: [Parent][PGPUParent] RunMessage(msgname=PGPU::Msg_ShutdownVR) Channel closing: too late to send/recv, messages will be lost: file /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1927
[task 2023-05-10T19:01:02.298Z] 19:01:02     INFO -  [GPU 6508, Main Thread] WARNING: IPC message 'PGPU::Msg_FOGData' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:504
[task 2023-05-10T19:01:02.299Z] 19:01:02     INFO -  [Parent 4696, IPDL Background] WARNING: IPC Connection Error: [Parent][PBackgroundParent] RunMessage(msgname=PRemoteWorkerService::Msg___delete__) Channel closing: too late to send/recv, messages will be lost: file /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1927
[task 2023-05-10T19:01:02.300Z] 19:01:02     INFO -  [Utility 8812, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4688
[task 2023-05-10T19:01:02.309Z] 19:01:02     INFO -  Destroying context 06E6C000 surface 0517E820 on display 06E33200
[task 2023-05-10T19:01:02.318Z] 19:01:02     INFO -  [GPU 6508, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4688
[task 2023-05-10T19:01:02.915Z] 19:01:02     INFO -  [Parent 4696, Main Thread] WARNING: '!top', file /builds/worker/checkouts/gecko/dom/xul/MenuBarListener.cpp:99
[task 2023-05-10T19:01:02.927Z] 19:01:02     INFO -  [Parent 4696, Main Thread] WARNING: '!top', file /builds/worker/checkouts/gecko/dom/xul/MenuBarListener.cpp:99
[task 2023-05-10T19:01:03.087Z] 19:01:03     INFO -  [Parent 4696, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3426
[task 2023-05-10T19:01:03.110Z] 19:01:03     INFO -  [Parent 4696, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2023-05-10T19:01:03.167Z] 19:01:03     INFO -  [Parent 4696, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4688
[task 2023-05-10T19:01:03.261Z] 19:01:03    ERROR -  TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_cli_arguments.py TestCommandLineArguments.test_debugger_address_cdp_status | OSError: Process has been unexpectedly closed (Exit code: 0) (Reason: Process still running 70.0s after quit request)
[task 2023-05-10T19:01:03.274Z] 19:01:03     INFO -  Traceback (most recent call last):
[task 2023-05-10T19:01:03.274Z] 19:01:03     INFO -    File "Z:\task_168374347943291\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 198, in run
[task 2023-05-10T19:01:03.274Z] 19:01:03     INFO -      testMethod()
[task 2023-05-10T19:01:03.275Z] 19:01:03     INFO -    File "Z:\task_168374347943291\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_cli_arguments.py", line 33, in test_debugger_address_cdp_status
[task 2023-05-10T19:01:03.275Z] 19:01:03     INFO -      self.marionette.quit()
[task 2023-05-10T19:01:03.275Z] 19:01:03     INFO -    File "Z:\task_168374347943291\build\venv\lib\site-packages\marionette_driver\decorators.py", line 34, in _
[task 2023-05-10T19:01:03.275Z] 19:01:03     INFO -      m._handle_socket_failure()
[task 2023-05-10T19:01:03.276Z] 19:01:03     INFO -    File "Z:\task_168374347943291\build\venv\lib\site-packages\marionette_driver\marionette.py", line 780, in _handle_socket_failure
[task 2023-05-10T19:01:03.276Z] 19:01:03     INFO -      reraise(
[task 2023-05-10T19:01:03.277Z] 19:01:03     INFO -    File "Z:\task_168374347943291\build\venv\lib\site-packages\six.py", line 702, in reraise
[task 2023-05-10T19:01:03.277Z] 19:01:03     INFO -      raise value.with_traceback(tb)
[task 2023-05-10T19:01:03.277Z] 19:01:03     INFO -    File "Z:\task_168374347943291\build\venv\lib\site-packages\marionette_driver\decorators.py", line 24, in _
[task 2023-05-10T19:01:03.277Z] 19:01:03     INFO -      return func(*args, **kwargs)
[task 2023-05-10T19:01:03.278Z] 19:01:03     INFO -    File "Z:\task_168374347943291\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1090, in quit
[task 2023-05-10T19:01:03.278Z] 19:01:03     INFO -      raise IOError(message.format(self.shutdown_timeout))
[task 2023-05-10T19:01:03.278Z] 19:01:03     INFO -  TEST-INFO took 71441ms
[task 2023-05-10T19:01:03.278Z] 19:01:03     INFO -  Application command: Z:\task_168374347943291\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile C:\Users\task_168374347943291\AppData\Local\Temp\tmpn57y308t.mozrunner
[task 2023-05-10T19:01:03.355Z] 19:01:03     INFO -  [4456, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:475
[task 2023-05-10T19:01:03.418Z] 19:01:03     INFO -  [Parent 4456, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:475
[task 2023-05-10T19:01:03.430Z] 19:01:03     INFO -  [Parent 4456, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:475
[task 2023-05-10T19:01:03.465Z] 19:01:03     INFO -  [Parent 4456, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:475
[task 2023-05-10T19:01:03.466Z] 19:01:03     INFO -  [Parent 4456, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:475
[task 2023-05-10T19:01:03.527Z] 19:01:03     INFO -  DEBUG: Adding blocker AddonManager: shutting down. for phase profile-before-change
[task 2023-05-10T19:01:03.574Z] 19:01:03     INFO -  DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase profile-before-change
[task 2023-05-10T19:01:03.575Z] 19:01:03     INFO -  DEBUG: Adding blocker IOUtils Blocker (profile-before-change-telemetry) for phase profile-before-change-telemetry
[task 2023-05-10T19:01:03.575Z] 19:01:03     INFO -  DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase IOUtils: waiting for sendTelemetry IO to complete
[task 2023-05-10T19:01:03.575Z] 19:01:03     INFO -  DEBUG: Adding blocker IOUtils Blocker (xpcom-will-shutdown) for phase xpcom-will-shutdown
[task 2023-05-10T19:01:03.576Z] 19:01:03     INFO -  DEBUG: Adding blocker IOUtils Blocker (profile-before-change-telemetry) for phase IOUtils: waiting for xpcomWillShutdown IO to complete
[task 2023-05-10T19:01:03.653Z] 19:01:03     INFO -  DEBUG: Adding blocker Flush WebExtension StartupCache for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:01:03.872Z] 19:01:03     INFO -  [WARN  rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
[task 2023-05-10T19:01:03.966Z] 19:01:03     INFO -  DEBUG: Adding blocker JSON store: writing data for 'addonStartup' for phase AddonManager: Waiting for providers to shut down.
[task 2023-05-10T19:01:03.975Z] 19:01:03     INFO -  DEBUG: Adding blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2023-05-10T19:01:03.986Z] 19:01:03     INFO -  DEBUG: Adding blocker XPIProvider shutdown for phase quit-application-granted
[task 2023-05-10T19:01:03.988Z] 19:01:03     INFO -  DEBUG: Adding blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2023-05-10T19:01:03.989Z] 19:01:03     INFO -  DEBUG: Adding blocker ServiceWorkerRegistrar: Flushing data for phase profile-before-change
[task 2023-05-10T19:01:03.992Z] 19:01:03     INFO -  DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change and awaiting all checkpoints written for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-05-10T19:01:04.028Z] 19:01:04     INFO -  DEBUG: Adding blocker TelemetryController: shutting down for phase IOUtils: waiting for sendTelemetry IO to complete
[task 2023-05-10T19:01:04.075Z] 19:01:04     INFO -  DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2023-05-10T19:01:04.096Z] 19:01:04     INFO -  DEBUG: Adding blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change
[task 2023-05-10T19:01:04.105Z] 19:01:04     INFO -  DEBUG: Adding blocker TerminatoryTelemetry: Waiting to submit telemetry for phase IOUtils: waiting for sendTelemetry IO to complete
[task 2023-05-10T19:01:04.109Z] 19:01:04     INFO -  1683745264109	Marionette	INFO	Marionette enabled
[task 2023-05-10T19:01:04.112Z] 19:01:04     INFO -  [Parent 4456, Main Thread] WARNING: NS_ENSURE_SUCCESS_VOID(rv) failed with result 0x8000FFFF (NS_ERROR_UNEXPECTED): file /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:2459
[task 2023-05-10T19:01:04.113Z] 19:01:04     INFO -  1683745264112	Marionette	TRACE	Received observer notification final-ui-startup
[task 2023-05-10T19:01:04.115Z] 19:01:04     INFO -  1683745264115	Marionette	INFO	Listening on port 2828
[task 2023-05-10T19:01:04.116Z] 19:01:04     INFO -  1683745264116	Marionette	DEBUG	Marionette is listening
[task 2023-05-10T19:01:04.247Z] 19:01:04     INFO -  DEBUG: Adding blocker PermissionManager: Flushing data for phase xpcom-will-shutdown
[task 2023-05-10T19:01:04.247Z] 19:01:04     INFO -  [Parent 4456, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:475
[task 2023-05-10T19:01:04.259Z] 19:01:04     INFO -  [Parent 4456, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:475
[task 2023-05-10T19:01:04.270Z] 19:01:04     INFO -  DEBUG: Completed blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2023-05-10T19:01:04.284Z] 19:01:04     INFO -  DEBUG: Adding blocker ClientManagerService: start destroying IPC actors early for phase xpcom-will-shutdown
[task 2023-05-10T19:01:04.309Z] 19:01:04     INFO -  Initializing context 0725A000 surface 0577E280 on display 07232200
[task 2023-05-10T19:01:04.321Z] 19:01:04     INFO -  [GPU 7928, Renderer] WARNING: Failed to make GL context current!: file /builds/worker/checkouts/gecko/gfx/gl/GLContextProviderEGL.cpp:473
[task 2023-05-10T19:01:04.321Z] 19:01:04     INFO -  EGL Error: 0x3009
[task 2023-05-10T19:01:04.321Z] 19:01:04     INFO -  [GPU 7928, Renderer] WARNING: GLContext::InitWithPrefix failed!: file /builds/worker/checkouts/gecko/gfx/gl/GLContext.cpp:331
[task 2023-05-10T19:01:04.322Z] 19:01:04     INFO -  Destroying context 0725A000 surface 0577E280 on display 07232200
[task 2023-05-10T19:01:04.323Z] 19:01:04     INFO -  [GPU 7928, Renderer] WARNING: Failed to create GLContext from PBuffer: file /builds/worker/checkouts/gecko/gfx/gl/GLContextProviderEGL.cpp:1171
[task 2023-05-10T19:01:04.323Z] 19:01:04     INFO -  Initializing context 0726C000 surface 0577E280 on display 07232200
[task 2023-05-10T19:01:04.323Z] 19:01:04     INFO -  GL_VENDOR: Google Inc. (Microsoft)
[task 2023-05-10T19:01:04.323Z] 19:01:04     INFO -  mVendor: Unknown
[task 2023-05-10T19:01:04.324Z] 19:01:04     INFO -  GL_RENDERER: ANGLE (Microsoft, Microsoft Basic Render Driver Direct3D11 vs_5_0 ps_5_0, D3D11-10.0.22621.1194)
[task 2023-05-10T19:01:04.324Z] 19:01:04     INFO -  mRenderer: Microsoft Basic Render Driver
<...>
[task 2023-05-10T19:02:44.162Z] 19:02:44     INFO -  1683745364162	Marionette	DEBUG	1 <- [1,2,null,{"value":null}]
[task 2023-05-10T19:02:44.163Z] 19:02:44     INFO -  TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_cli_arguments.py TestCommandLineArguments.test_start_page_about_blank | took 36117ms
[task 2023-05-10T19:02:44.164Z] 19:02:44     INFO -  1683745364163	Marionette	DEBUG	Closed connection 1

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This is a shutdown hang of Firefox and similar to bug 1630162 for Wd tests. Lets make this a general bug.

Comment 2

[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-32-2009-qr: 1
  • debug: 1

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

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1832385&startday=2023-07-31&endday=2023-08-06&tree=all

Comment 4

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

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