Open Bug 1791951 Opened 3 years ago Updated 2 days ago

Intermittent Mn, Wd TEST-UNEXPECTED-TIMEOUT | expected OK (Waiting for initial application window)

Categories

(Remote Protocol :: Marionette, defect, P5)

Product:
Remote Protocol
Component:
Marionette
Type:
defect

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 2 open bugs, Blocks 2 open bugs)

Details

(Keywords: intermittent-failure)

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

[task 2022-09-22T06:09:27.393Z] 06:09:27     INFO - TEST-START | /_mozilla/webdriver/new_session/bidi_disabled.py
[task 2022-09-22T06:09:28.532Z] 06:09:28     INFO - STDOUT: ============================= test session starts =============================
[task 2022-09-22T06:09:28.539Z] 06:09:28     INFO - STDOUT: platform win32 -- Python 3.9.5, pytest-7.0.1, pluggy-unknown -- Z:\task_166382506491026\build\venv\Scripts\python.exe
[task 2022-09-22T06:09:28.540Z] 06:09:28     INFO - STDOUT: rootdir: Z:\task_166382506491026\build
[task 2022-09-22T06:09:28.541Z] 06:09:28     INFO - STDOUT: plugins: asyncio-0.14.0
[task 2022-09-22T06:09:28.541Z] 06:09:28     INFO - STDOUT: collecting ... 
[task 2022-09-22T06:09:28.552Z] 06:09:28     INFO - STDOUT: collected 1 item
[task 2022-09-22T06:09:28.562Z] 06:09:28     INFO - STDOUT: tests/web-platform/mozilla/tests/webdriver/new_session/bidi_disabled.py::test_marionette_fallback_webdriver_session 
[task 2022-09-22T06:09:28.563Z] 06:09:28     INFO - STDOUT: Running command: ['Z:\\task_166382506491026\\fetches\\geckodriver.exe', '--port', '49595', '-vv']
[task 2022-09-22T06:09:28.575Z] 06:09:28     INFO - STDOUT: 1663826968574	geckodriver	INFO	Listening on 127.0.0.1:49595
[task 2022-09-22T06:09:29.070Z] 06:09:29     INFO - STDOUT: 1663826969071	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_166382506491026\\AppData\\Local\\Temp\\tmp2u6skeuh.mozrunner"], "binary": "Z:\\task_166382506491026\\build\\application\\firefox\\firefox.exe", "prefs": {"remote.active-protocols": 2}}, "webSocketUrl": true}}}
[task 2022-09-22T06:09:29.074Z] 06:09:29     INFO - STDOUT: 1663826969071	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2022-09-22T06:09:29.075Z] 06:09:29     INFO - STDOUT: 1663826969072	geckodriver::capabilities	DEBUG	Found version 107.0a1
[task 2022-09-22T06:09:29.075Z] 06:09:29     INFO - STDOUT: 1663826969073	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_166382506491026\\AppData\\Local\\Temp\\tmp2u6skeuh.mozrunner\\user.geckodriver_backup"
[task 2022-09-22T06:09:29.087Z] 06:09:29     INFO - STDOUT: 1663826969093	mozrunner::runner	INFO	Running command: "Z:\\task_166382506491026\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_166382506491026\\AppData\\Local\\Temp\\tmp2u6skeuh.mozrunner" "--remote-debugging-port" "9222" "--remote-allow-hosts" "localhost" "-no-remote"
[task 2022-09-22T06:09:29.096Z] 06:09:29     INFO - STDOUT: 1663826969095	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-09-22T06:09:29.097Z] 06:09:29     INFO - STDOUT: 1663826969095	geckodriver::browser	TRACE	Failed to open C:\Users\task_166382506491026\AppData\Local\Temp\tmp2u6skeuh.mozrunner\MarionetteActivePort
[task 2022-09-22T06:09:29.098Z] 06:09:29     INFO - STDOUT: 1663826969095	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-09-22T06:09:29.203Z] 06:09:29     INFO - STDOUT: 1663826969203	geckodriver::browser	TRACE	Failed to open C:\Users\task_166382506491026\AppData\Local\Temp\tmp2u6skeuh.mozrunner\MarionetteActivePort
[task 2022-09-22T06:09:29.205Z] 06:09:29     INFO - STDOUT: 1663826969203	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-09-22T06:09:29.295Z] 06:09:29     INFO - STDOUT: 1663826969295	RemoteAgent	DEBUG	CDP enabled
[task 2022-09-22T06:09:29.297Z] 06:09:29     INFO - STDOUT: 1663826969295	Marionette	INFO	Marionette enabled
[task 2022-09-22T06:09:29.299Z] 06:09:29     INFO - STDOUT: 1663826969296	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-09-22T06:09:29.299Z] 06:09:29     INFO - STDOUT: 1663826969297	Marionette	INFO	Listening on port 49600
[task 2022-09-22T06:09:29.300Z] 06:09:29     INFO - STDOUT: 1663826969297	Marionette	DEBUG	Marionette is listening
[task 2022-09-22T06:09:29.301Z] 06:09:29     INFO - STDOUT: 1663826969297	RemoteAgent	TRACE	Received observer notification final-ui-startup
[task 2022-09-22T06:09:29.311Z] 06:09:29     INFO - STDOUT: Read port: 49600
[task 2022-09-22T06:09:29.323Z] 06:09:29     INFO - STDOUT: 1663826969330	CDP	DEBUG	Waiting for initial application window
[task 2022-09-22T06:09:29.336Z] 06:09:29     INFO - STDOUT: 1663826969335	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:49601
[task 2022-09-22T06:09:29.339Z] 06:09:29     INFO - STDOUT: 1663826969338	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:49600.
[task 2022-09-22T06:09:29.343Z] 06:09:29     INFO - STDOUT: 1663826969341	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"webSocketUrl":true}]
[task 2022-09-22T06:09:29.344Z] 06:09:29     INFO - STDOUT: 1663826969343	Marionette	DEBUG	Waiting for initial application window
[task 2022-09-22T06:09:30.198Z] 06:09:30     INFO - STDOUT: *** You are running in background task mode. ***
[task 2022-09-22T06:09:30.211Z] 06:09:30     INFO - STDOUT: *** You are running in headless mode.
[task 2022-09-22T06:09:30.583Z] 06:09:30     INFO - STDOUT: 1663826970584	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2022-09-22T06:09:30.587Z] 06:09:30     INFO - STDOUT: 1663826970584	RemoteAgent	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2022-09-22T06:09:30.588Z] 06:09:30     INFO - STDOUT: 1663826970590	RemoteAgent	TRACE	[3] Document already finished loading: about:blank
[task 2022-09-22T06:09:30.592Z] 06:09:30     INFO - STDOUT: DevTools listening on ws://127.0.0.1:9222/devtools/browser/79162a6c-6a3d-4893-ac53-6ebaa6d203e0
[task 2022-09-22T06:09:30.594Z] 06:09:30     INFO - STDOUT: 1663826970596	Marionette	DEBUG	0 <- [1,1,null,{"sessionId":"52c8cc59-215c-4070-a18e-694e360b846f","capabilities":{"browserName":"firefox","browserVersion":"107.0a1","platformName":"windows","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":false,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20220922045843","moz:debuggerAddress":"127.0.0.1:9222","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":1260,"moz:profile":"C:\\Users\\task_166382506491026\\AppData\\Local\\Temp\\tmp2u6skeuh.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2022-09-22T06:09:30.600Z] 06:09:30     INFO - STDOUT: 1663826970599	webdriver::server	DEBUG	<- 200 OK {"value":{"sessionId":"52c8cc59-215c-4070-a18e-694e360b846f","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"107.0a1","moz:accessibilityChecks":false,"moz:buildID":"20220922045843","moz:debuggerAddress":"127.0.0.1:9222","moz:geckodriverVersion":"0.31.0","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":1260,"moz:profile":"C:\\Users\\task_166382506491026\\AppData\\Local\\Temp\\tmp2u6skeuh.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"pageLoadStrategy":"normal","platformName":"windows","proxy":{},"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
[task 2022-09-22T06:09:30.600Z] 06:09:30     INFO - STDOUT: 1663826970601	webdriver::server	DEBUG	-> GET /session/52c8cc59-215c-4070-a18e-694e360b846f/window/handles
[task 2022-09-22T06:09:30.600Z] 06:09:30     INFO - STDOUT: 1663826970603	Marionette	DEBUG	0 -> [0,2,"WebDriver:GetWindowHandles",{}]
[task 2022-09-22T06:09:30.606Z] 06:09:30     INFO - STDOUT: 1663826970604	Marionette	DEBUG	0 <- [1,2,null,["05b84850-69b1-4a24-97c8-73c2753a2da5"]]
[task 2022-09-22T06:09:30.606Z] 06:09:30     INFO - STDOUT: 1663826970604	webdriver::server	DEBUG	<- 200 OK {"value":["05b84850-69b1-4a24-97c8-73c2753a2da5"]}
[task 2022-09-22T06:09:30.608Z] 06:09:30     INFO - STDOUT: 1663826970605	webdriver::server	DEBUG	-> DELETE /session/52c8cc59-215c-4070-a18e-694e360b846f
[task 2022-09-22T06:09:30.610Z] 06:09:30     INFO - STDOUT: 1663826970606	Marionette	DEBUG	0 -> [0,3,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-09-22T06:09:30.611Z] 06:09:30     INFO - STDOUT: 1663826970606	Marionette	INFO	Stopped listening on port 49600
[task 2022-09-22T06:09:30.615Z] 06:09:30     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d207700 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3634
[task 2022-09-22T06:09:30.616Z] 06:09:30     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d207700 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3640
[task 2022-09-22T06:09:30.617Z] 06:09:30     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954edb6e00 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3634
[task 2022-09-22T06:09:30.619Z] 06:09:30     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954edb6e00 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3640
[task 2022-09-22T06:09:30.620Z] 06:09:30     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954f4e8800 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3634
[task 2022-09-22T06:09:30.622Z] 06:09:30     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954f4e8800 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3640
[task 2022-09-22T06:09:30.623Z] 06:09:30     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d206300 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3634
[task 2022-09-22T06:09:30.624Z] 06:09:30     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d206300 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3640
[task 2022-09-22T06:09:30.626Z] 06:09:30     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d208100 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3634
[task 2022-09-22T06:09:30.627Z] 06:09:30     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d208100 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3640
[task 2022-09-22T06:09:30.628Z] 06:09:30     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d3f2b00 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3634
[task 2022-09-22T06:09:30.629Z] 06:09:30     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d3f2b00 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3640
[task 2022-09-22T06:09:30.640Z] 06:09:30     INFO - STDOUT: 1663826970651	Marionette	TRACE	Received observer notification quit-application
[task 2022-09-22T06:09:30.655Z] 06:09:30     INFO - STDOUT: 1663826970654	Marionette	TRACE	Received observer notification quit-application
[task 2022-09-22T06:09:30.656Z] 06:09:30     INFO - STDOUT: 1663826970654	Marionette	DEBUG	Marionette stopped listening
[task 2022-09-22T06:09:30.658Z] 06:09:30     INFO - STDOUT: 1663826970654	RemoteAgent	TRACE	Received observer notification quit-application
[task 2022-09-22T06:09:30.659Z] 06:09:30     INFO - STDOUT: 1663826970655	Marionette	DEBUG	0 <- [1,3,null,{"cause":"shutdown","forced":false}]
[task 2022-09-22T06:09:30.670Z] 06:09:30     INFO - STDOUT: 1663826970670	RemoteAgent	DEBUG	Resetting recommended pref browser.contentblocking.features.standard
[task 2022-09-22T06:09:30.672Z] 06:09:30     INFO - STDOUT: 1663826970670	RemoteAgent	DEBUG	Resetting recommended pref network.cookie.cookieBehavior
[task 2022-09-22T06:09:30.673Z] 06:09:30     INFO - STDOUT: 1663826970671	webdriver::server	DEBUG	Teardown session
[task 2022-09-22T06:09:30.676Z] 06:09:30     INFO - STDOUT: 1663826970674	Marionette	DEBUG	Closed connection 0
[task 2022-09-22T06:09:31.532Z] 06:09:31     INFO - STDOUT: console.error: "C:\\Users\\task_166382506491026\\AppData\\Local\\Temp\\tmp2u6skeuh.mozrunner" "" 0 ".purge.bg_rm"
[task 2022-09-22T06:09:31.836Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d207700 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3679
[task 2022-09-22T06:09:31.845Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d207700 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1802
[task 2022-09-22T06:09:31.845Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d206300 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3679
[task 2022-09-22T06:09:31.846Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d206300 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1802
[task 2022-09-22T06:09:31.847Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d208100 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3679
[task 2022-09-22T06:09:31.848Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d208100 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1802
[task 2022-09-22T06:09:31.848Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d3f2b00 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3679
[task 2022-09-22T06:09:31.850Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d3f2b00 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1802
[task 2022-09-22T06:09:31.856Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d207700 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1842
[task 2022-09-22T06:09:31.857Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d207700 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3794
[task 2022-09-22T06:09:31.858Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d206300 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1842
[task 2022-09-22T06:09:31.859Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d206300 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3794
[task 2022-09-22T06:09:31.861Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d208100 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1842
[task 2022-09-22T06:09:31.862Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d208100 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3794
[task 2022-09-22T06:09:31.863Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d3f2b00 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1842
[task 2022-09-22T06:09:31.864Z] 06:09:31     INFO - STDOUT: [Parent 1260, Main Thread] WARNING: ContentParent: id=2954d3f2b00 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3794
[task 2022-09-22T06:09:45.674Z] 06:09:45     INFO - STDOUT: console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 380))
[task 2022-09-22T06:09:47.089Z] 06:09:47     INFO - STDOUT: 1663826987090	geckodriver::browser	DEBUG	Browser process stopped: exit code: 0
[task 2022-09-22T06:09:47.092Z] 06:09:47     INFO - STDOUT: 1663826987090	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-09-22T06:09:47.119Z] 06:09:47     INFO - STDOUT: Running command: ['Z:\\task_166382506491026\\fetches\\geckodriver.exe', '--port', '49606', '-vv']
[task 2022-09-22T06:09:47.122Z] 06:09:47     INFO - STDOUT: 1663826987130	geckodriver	INFO	Listening on 127.0.0.1:49606
[task 2022-09-22T06:09:47.628Z] 06:09:47     INFO - STDOUT: 1663826987629	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_166382506491026\\AppData\\Local\\Temp\\tmp2u6skeuh.mozrunner"], "binary": "Z:\\task_166382506491026\\build\\application\\firefox\\firefox.exe", "prefs": {"remote.active-protocols": 3}}, "webSocketUrl": true}}}
[task 2022-09-22T06:09:47.632Z] 06:09:47     INFO - STDOUT: 1663826987629	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2022-09-22T06:09:47.632Z] 06:09:47     INFO - STDOUT: 1663826987630	geckodriver::capabilities	DEBUG	Found version 107.0a1
[task 2022-09-22T06:09:47.633Z] 06:09:47     INFO - STDOUT: 1663826987631	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_166382506491026\\AppData\\Local\\Temp\\tmp2u6skeuh.mozrunner\\user.geckodriver_backup"
[task 2022-09-22T06:09:47.645Z] 06:09:47     INFO - STDOUT: 1663826987644	mozrunner::runner	INFO	Running command: "Z:\\task_166382506491026\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_166382506491026\\AppData\\Local\\Temp\\tmp2u6skeuh.mozrunner" "--remote-debugging-port" "9222" "--remote-allow-hosts" "localhost" "-no-remote"
[task 2022-09-22T06:09:47.647Z] 06:09:47     INFO - STDOUT: 1663826987646	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-09-22T06:09:47.648Z] 06:09:47     INFO - STDOUT: 1663826987646	geckodriver::browser	TRACE	Failed to open C:\Users\task_166382506491026\AppData\Local\Temp\tmp2u6skeuh.mozrunner\MarionetteActivePort
[task 2022-09-22T06:09:47.649Z] 06:09:47     INFO - STDOUT: 1663826987646	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-09-22T06:09:47.754Z] 06:09:47     INFO - STDOUT: 1663826987754	geckodriver::browser	TRACE	Failed to open C:\Users\task_166382506491026\AppData\Local\Temp\tmp2u6skeuh.mozrunner\MarionetteActivePort
[task 2022-09-22T06:09:47.756Z] 06:09:47     INFO - STDOUT: 1663826987754	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-09-22T06:09:47.845Z] 06:09:47     INFO - STDOUT: 1663826987852	RemoteAgent	DEBUG	WebDriver BiDi enabled
[task 2022-09-22T06:09:47.855Z] 06:09:47     INFO - STDOUT: 1663826987853	RemoteAgent	DEBUG	CDP enabled
[task 2022-09-22T06:09:47.856Z] 06:09:47     INFO - STDOUT: 1663826987853	Marionette	INFO	Marionette enabled
[task 2022-09-22T06:09:47.857Z] 06:09:47     INFO - STDOUT: 1663826987854	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-09-22T06:09:47.858Z] 06:09:47     INFO - STDOUT: 1663826987854	Marionette	INFO	Listening on port 49611
[task 2022-09-22T06:09:47.858Z] 06:09:47     INFO - STDOUT: 1663826987854	Marionette	DEBUG	Marionette is listening
[task 2022-09-22T06:09:47.859Z] 06:09:47     INFO - STDOUT: 1663826987855	RemoteAgent	TRACE	Received observer notification final-ui-startup
[task 2022-09-22T06:09:47.862Z] 06:09:47     INFO - STDOUT: Read port: 49611
[task 2022-09-22T06:09:47.873Z] 06:09:47     INFO - STDOUT: WebDriver BiDi listening on ws://127.0.0.1:9222
[task 2022-09-22T06:09:47.886Z] 06:09:47     INFO - STDOUT: 1663826987885	CDP	DEBUG	Waiting for initial application window
[task 2022-09-22T06:09:47.888Z] 06:09:47     INFO - STDOUT: 1663826987887	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:49612
[task 2022-09-22T06:09:47.891Z] 06:09:47     INFO - STDOUT: 1663826987890	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:49611.
[task 2022-09-22T06:09:47.895Z] 06:09:47     INFO - STDOUT: 1663826987894	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"webSocketUrl":true}]
[task 2022-09-22T06:09:47.896Z] 06:09:47     INFO - STDOUT: 1663826987895	WebDriver BiDi	DEBUG	Waiting for initial application window
[task 2022-09-22T06:09:48.756Z] 06:09:48     INFO - STDOUT: *** You are running in background task mode. ***
[task 2022-09-22T06:09:48.758Z] 06:09:48     INFO - STDOUT: *** You are running in headless mode.
[task 2022-09-22T06:09:48.857Z] 06:09:48     INFO - STDOUT: console.error: "C:\\Users\\task_166382506491026\\AppData\\Local\\Temp\\tmp2u6skeuh.mozrunner" "" 0 ".purge.bg_rm"
[task 2022-09-22T06:09:49.108Z] 06:09:49     INFO - STDOUT: 1663826989108	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2022-09-22T06:09:49.112Z] 06:09:49     INFO - STDOUT: 1663826989108	RemoteAgent	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2022-09-22T06:09:49.113Z] 06:09:49     INFO - STDOUT: 1663826989117	WebDriver BiDi	DEBUG	Registered session handler: /session/23502aef-c6a0-459f-a6bd-356cb5aaef9d
[task 2022-09-22T06:09:49.120Z] 06:09:49     INFO - STDOUT: 1663826989118	Marionette	DEBUG	Waiting for initial application window
[task 2022-09-22T06:09:49.121Z] 06:09:49     INFO - STDOUT: DevTools listening on ws://127.0.0.1:9222/devtools/browser/bf1dc6c5-a0f7-4309-a8c5-737590730886
[task 2022-09-22T06:09:49.122Z] 06:09:49     INFO - STDOUT: 1663826989120	RemoteAgent	TRACE	[3] Document already finished loading: about:blank
[task 2022-09-22T06:09:49.129Z] 06:09:49     INFO - STDOUT: 1663826989126	Marionette	DEBUG	0 <- [1,1,null,{"sessionId":"23502aef-c6a0-459f-a6bd-356cb5aaef9d","capabilities":{"browserName":"firefox","browserVersion":"107.0a1","platformName":"windows","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":false,"unhandledPromptBehavior":"dismiss and notify","webSocketUrl":"ws://127.0.0.1:9222/session/23502aef-c6a0-459f-a6bd-356cb5aaef9d","moz:accessibilityChecks":false,"moz:buildID":"20220922045843","moz:debuggerAddress":"127.0.0.1:9222","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":1156,"moz:profile":"C:\\Users\\task_166382506491026\\AppData\\Local\\Temp\\tmp2u6skeuh.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2022-09-22T06:09:49.135Z] 06:09:49     INFO - STDOUT: 1663826989131	webdriver::server	DEBUG	<- 200 OK {"value":{"sessionId":"23502aef-c6a0-459f-a6bd-356cb5aaef9d","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"107.0a1","moz:accessibilityChecks":false,"moz:buildID":"20220922045843","moz:debuggerAddress":"127.0.0.1:9222","moz:geckodriverVersion":"0.31.0","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":1156,"moz:profile":"C:\\Users\\task_166382506491026\\AppData\\Local\\Temp\\tmp2u6skeuh.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"pageLoadStrategy":"normal","platformName":"windows","proxy":{},"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify","webSocketUrl":"ws://127.0.0.1:9222/session/23502aef-c6a0-459f-a6bd-356cb5aaef9d"}}}
[task 2022-09-22T06:09:49.135Z] 06:09:49     INFO - STDOUT: PASSED
[task 2022-09-22T06:09:49.138Z] 06:09:49     INFO - STDOUT: 1663826989133	webdriver::server	DEBUG	-> DELETE /session/23502aef-c6a0-459f-a6bd-356cb5aaef9d
[task 2022-09-22T06:09:49.139Z] 06:09:49     INFO - STDOUT: 1663826989135	Marionette	DEBUG	0 -> [0,2,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-09-22T06:09:49.140Z] 06:09:49     INFO - STDOUT: 1663826989136	Marionette	INFO	Stopped listening on port 49611
[task 2022-09-22T06:09:49.140Z] 06:09:49     INFO - STDOUT: 1663826989137	WebDriver BiDi	DEBUG	Unregistered session handler: /session/23502aef-c6a0-459f-a6bd-356cb5aaef9d
[task 2022-09-22T06:09:49.143Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bed00 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3634
[task 2022-09-22T06:09:49.145Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bed00 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3640
[task 2022-09-22T06:09:49.146Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd9687f400 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3634
[task 2022-09-22T06:09:49.147Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd9687f400 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3640
[task 2022-09-22T06:09:49.149Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd96fb5600 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3634
[task 2022-09-22T06:09:49.150Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd96fb5600 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3640
[task 2022-09-22T06:09:49.151Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bca00 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3634
[task 2022-09-22T06:09:49.152Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bca00 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3640
[task 2022-09-22T06:09:49.154Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bcf00 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3634
[task 2022-09-22T06:09:49.155Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bcf00 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3640
[task 2022-09-22T06:09:49.156Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd94fb9100 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3634
[task 2022-09-22T06:09:49.157Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd94fb9100 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3640
[task 2022-09-22T06:09:49.177Z] 06:09:49     INFO - STDOUT: 1663826989179	Marionette	TRACE	Received observer notification quit-application
[task 2022-09-22T06:09:49.185Z] 06:09:49     INFO - STDOUT: 1663826989183	Marionette	TRACE	Received observer notification quit-application
[task 2022-09-22T06:09:49.186Z] 06:09:49     INFO - STDOUT: 1663826989183	Marionette	DEBUG	Marionette stopped listening
[task 2022-09-22T06:09:49.186Z] 06:09:49     INFO - STDOUT: 1663826989183	RemoteAgent	TRACE	Received observer notification quit-application
[task 2022-09-22T06:09:49.187Z] 06:09:49     INFO - STDOUT: 1663826989184	Marionette	DEBUG	0 <- [1,2,null,{"cause":"shutdown","forced":false}]
[task 2022-09-22T06:09:49.198Z] 06:09:49     INFO - STDOUT: 1663826989202	RemoteAgent	DEBUG	Resetting recommended pref browser.contentblocking.features.standard
[task 2022-09-22T06:09:49.204Z] 06:09:49     INFO - STDOUT: 1663826989202	RemoteAgent	DEBUG	Resetting recommended pref network.cookie.cookieBehavior
[task 2022-09-22T06:09:49.205Z] 06:09:49     INFO - STDOUT: 1663826989202	webdriver::server	DEBUG	Teardown session
[task 2022-09-22T06:09:49.208Z] 06:09:49     INFO - STDOUT: 1663826989207	Marionette	DEBUG	Closed connection 0
[task 2022-09-22T06:09:49.308Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bed00 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3679
[task 2022-09-22T06:09:49.315Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bed00 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1802
[task 2022-09-22T06:09:49.316Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bca00 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3679
[task 2022-09-22T06:09:49.317Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bca00 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1802
[task 2022-09-22T06:09:49.318Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bcf00 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3679
[task 2022-09-22T06:09:49.319Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bcf00 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1802
[task 2022-09-22T06:09:49.320Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd94fb9100 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3679
[task 2022-09-22T06:09:49.321Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd94fb9100 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1802
[task 2022-09-22T06:09:49.326Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bed00 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1842
[task 2022-09-22T06:09:49.327Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bed00 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3794
[task 2022-09-22T06:09:49.329Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bca00 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1842
[task 2022-09-22T06:09:49.330Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bca00 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3794
[task 2022-09-22T06:09:49.331Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bcf00 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1842
[task 2022-09-22T06:09:49.332Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd949bcf00 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3794
[task 2022-09-22T06:09:49.333Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd94fb9100 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1842
[task 2022-09-22T06:09:49.334Z] 06:09:49     INFO - STDOUT: [Parent 1156, Main Thread] WARNING: ContentParent: id=1dd94fb9100 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3794
[task 2022-09-22T06:09:57.404Z] 06:09:57     INFO - TEST-UNEXPECTED-TIMEOUT | /_mozilla/webdriver/new_session/bidi_disabled.py | expected OK
[task 2022-09-22T06:09:57.404Z] 06:09:57     INFO - TEST-INFO took 30011ms
[task 2022-09-22T06:09:59.489Z] 06:09:59 CRITICAL - Test harness output was not a valid structured log message: 
[task 2022-09-22T06:09:59.489Z] 06:09:59 CRITICAL - 1663826999458	geckodriver::browser	DEBUG	Browser process stopped: exit code: 0
[task 2022-09-22T06:09:59.492Z] 06:09:59 CRITICAL - 1663826999459	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-09-22T06:09:59.534Z] 06:09:59     INFO - Closing logging queue
[task 2022-09-22T06:09:59.540Z] 06:09:59     INFO - queue closed
[task 2022-09-22T06:10:00.051Z] 06:10:00     INFO - PID 5876 | 1663826999551	geckodriver	INFO	Listening on 127.0.0.1:49880
[task 2022-09-22T06:10:00.053Z] 06:10:00     INFO - Starting runner
[task 2022-09-22T06:10:00.596Z] 06:10:00     INFO - TEST-START | /_mozilla/webdriver/new_session/binary.py

The first failure in this log is related to a not that clear shutdown delay of Firefox some lines earlier.

But the 2nd failure is more interesting because it hangs in the Wait for initial application window state again (see bug 1784870). Florian, given that you landed your Background Hang monitor patch (bug 965392) yesterday again I have the feeling that this could be related again? At least we haven't seen this issue since the backout. This time it's for opt builds even as it looks like with a way lower failure rate.

https://treeherder.mozilla.org/logviewer?job_id=391127690&repo=autoland&lineNumber=80302-80305

[task 2022-09-22T06:10:21.482Z] 06:10:21     INFO - STDOUT: 1663827021492	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{}]
[task 2022-09-22T06:10:21.496Z] 06:10:21     INFO - STDOUT: 1663827021495	Marionette	DEBUG	Waiting for initial application window
[task 2022-09-22T06:10:45.898Z] 06:10:45     INFO - TEST-UNEXPECTED-TIMEOUT | /_mozilla/webdriver/new_session/profile_root.py | expected OK
[task 2022-09-22T06:10:45.898Z] 06:10:45     INFO - TEST-INFO took 30009ms
Flags: needinfo?(florian)
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | mozilla/tests/webdriver/new_session/bidi_disabled.py | expected OK → Intermittent Windows TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/<test-name> | expected OK (Waiting for initial application window)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #1)

This time it's for opt builds even as it looks like with a way lower failure rate.

Extended telemetry is not enabled for opt builds, only on shipable builds. So hopefully BHR doesn't do anything in that case. But that's hard to say for sure until we figure out what's actually happening.

[task 2022-09-22T06:10:45.898Z] 06:10:45 INFO - TEST-INFO took 30009ms

Is it possible that startup wasn't blocked, but just took a very long time and wasn't done after 30s?

Flags: needinfo?(florian)

Thanks for your reply! Yes, that could be the case as well that we hit the test timeout of wpt here while Firefox was starting up very slowly.

Given that this failure appeared only once so far lets not focus on anything for now but keep an eye on it.

No more failures since the bug was filed. Closing as WFM for now.

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → WORKSFORME

Still happens very infrequently:
https://treeherder.mozilla.org/logviewer?job_id=395140607&repo=autoland&lineNumber=94916

Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---

Interesting case from the following test failure:
https://treeherder.mozilla.org/logviewer?job_id=399143273&repo=try&lineNumber=78331-78347

[task 2022-12-09T12:43:07.778Z] 12:43:07     INFO - STDOUT: 1670589787774	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-12-09T12:43:07.779Z] 12:43:07     INFO - STDOUT: 1670589787775	Marionette	INFO	Listening on port 49588
[task 2022-12-09T12:43:07.780Z] 12:43:07     INFO - STDOUT: 1670589787776	Marionette	DEBUG	Marionette is listening
[task 2022-12-09T12:43:07.780Z] 12:43:07     INFO - STDOUT: 1670589787776	RemoteAgent	TRACE	Received observer notification final-ui-startup
[task 2022-12-09T12:43:07.792Z] 12:43:07     INFO - STDOUT: 1670589787800	RemoteAgent	TRACE	Available local IP addresses: 127.0.0.1, [::1]
[task 2022-12-09T12:43:07.804Z] 12:43:07     INFO - STDOUT: WebDriver BiDi listening on ws://127.0.0.1:9222
[task 2022-12-09T12:43:07.805Z] 12:43:07     INFO - STDOUT: 1670589787803	CDP	DEBUG	Waiting for initial application window
[task 2022-12-09T12:43:07.863Z] 12:43:07     INFO - STDOUT: Read port: 49588
[task 2022-12-09T12:43:07.872Z] 12:43:07     INFO - STDOUT: 1670589787870	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:49589
[task 2022-12-09T12:43:07.879Z] 12:43:07     INFO - STDOUT: 1670589787878	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:49588.
[task 2022-12-09T12:43:07.890Z] 12:43:07     INFO - STDOUT: 1670589787899	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"acceptInsecureCerts":false,"webSocketUrl":true}]
[task 2022-12-09T12:43:07.901Z] 12:43:07     INFO - STDOUT: 1670589787900	WebDriver BiDi	DEBUG	Waiting for initial application window
[task 2022-12-09T12:43:08.006Z] 12:43:08     INFO - STDOUT: [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
[task 2022-12-09T12:43:31.314Z] 12:43:31     INFO - STDOUT: JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 89: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsITelemetry.getHistogramById]
[task 2022-12-09T12:43:31.317Z] 12:43:31     INFO - STDOUT: JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 89: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsITelemetry.getHistogramById]
[task 2022-12-09T12:43:31.318Z] 12:43:31     INFO - STDOUT: JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 89: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsITelemetry.getHistogramById]
[task 2022-12-09T12:43:31.818Z] 12:43:31     INFO - STDOUT: 1670589811821	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished

It takes 24s further seconds until the browser-idle-startup-tasks-finished notification gets send out after final-ui-startup. I wonder if those errors from Telemetry might be related, when it tries to maybe get the history for that amount of time but then finally fails?

Chris, is that an already known failure and might it be related?

Flags: needinfo?(chutten)

Huh. That's weird. We try really hard to make instrumentation not error in most cases.

getHistogramById can only return NS_ERROR_FAILURE for the following cases:

  1. The histogram isn't in in the lookup
  2. The histogram is keyed (this API is for non-keyed histograms)
    • Nope. None of them are.
  3. One of JS_NewObject or JS_DefineFunction fails
    • Uh... how?

The only thing that isn't refutable through inspection is... maybe the jsapi calls are failing? Who's a good person to ask about js/src stuff... according to module info we can ask... Yulia?

Flags: needinfo?(chutten) → needinfo?(ystartsev)

Interesting! I think maybe the best person to ask from our team would be Jan de Mooij, as I see that he most recently updated this code. I'll cc him.

Flags: needinfo?(ystartsev) → needinfo?(jdemooij)

(In reply to Chris H-C :chutten from comment #11)

The only thing that isn't refutable through inspection is... maybe the jsapi calls are failing?

If these JSAPI calls are failing intermittently, it's probably due to OOM. That also seems likely because the last two failures in this bug are on 32-bit Windows.

If I'm reading the log output right, we do start a new Firefox instance right before this happens? Is it possible there are active Firefox processes from previous tests?

Flags: needinfo?(jdemooij) → needinfo?(hskupin)

Most of the test failures were wrongly classified. I've fixed that and those are remaining:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2022-08-16&endday=2022-12-14&tree=all&failurehash=all&bug=1791951

But those two remaining jobs do not show anything regarding Telemetry. Maybe Firefox got stuck already earlier.

The number of failures is low so maybe we just ignore that for now.

Flags: needinfo?(hskupin)

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

Status: REOPENED → RESOLVED
Closed: 3 years ago → 3 years ago
Resolution: --- → INCOMPLETE
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol

New failure:
https://treeherder.mozilla.org/logviewer?job_id=408306426&repo=autoland&lineNumber=1331

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent Windows TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/<test-name> | expected OK (Waiting for initial application window) → Intermittent Windows Wd TEST-UNEXPECTED-TIMEOUT | expected OK (Waiting for initial application window)
Status: REOPENED → NEW
Summary: Intermittent Windows Wd TEST-UNEXPECTED-TIMEOUT | expected OK (Waiting for initial application window) → Intermittent Wd TEST-UNEXPECTED-TIMEOUT | expected OK (Waiting for initial application window)
Duplicate of this bug: 1821910
Duplicate of this bug: 1822902
Summary: Intermittent Wd TEST-UNEXPECTED-TIMEOUT | expected OK (Waiting for initial application window) → Intermittent Mn, Wd TEST-UNEXPECTED-TIMEOUT | expected OK (Waiting for initial application window)
Duplicate of this bug: 1827370
Duplicate of this bug: 1830564

(In reply to Intermittent Failures Robot from comment #30)

Platform and build breakdown:

  • linux1804-64-tsan-qr: 14
    • opt: 14

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

All the TSAN failures were actually wrongly classified. I've filed bug 1834248 to cover that specific scenario.

Duplicate of this bug: 1837776
Duplicate of this bug: 1838681
Duplicate of this bug: 1839677
Duplicate of this bug: 1840351
Duplicate of this bug: 1841132
Duplicate of this bug: 1839453
Duplicate of this bug: 1848274
Duplicate of this bug: 1851330
Duplicate of this bug: 1852609
Duplicate of this bug: 1857910
See Also: → 1879795
Duplicate of this bug: 1904919
Duplicate of this bug: 1934736

Copying crash signatures from duplicate bugs.

Crash Signature: [@ CrashChannel::OpenContentStream]
Crash Signature: [@ CrashChannel::OpenContentStream]
Duplicate of this bug: 1951327

Given that this happens more often for CCOV builds I've pushed a try build with the BCWebProgress logs enabled. Lets see if I can get it reproduced and that those logs might give an insight why the navigation is hanging.

https://treeherder.mozilla.org/jobs?repo=try&revision=c9d8ceea074fd6d9dae48c2dcc0d18f57c3cfd4d

Maybe this is related as well to bug 1935939 where we experience hangs in various IPC calls into child actors.

The problem here is indeed that a navigation is started but it never reaches the initial about:blank page including the stop state so that it times out 12 seconds later:

https://treeherder.mozilla.org/logviewer?job_id=500615410&repo=try&lineNumber=268254-268261

[task 2025-03-24T12:14:39.304Z] 12:14:39     INFO - PID 10470 | [Parent 19559: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:0}, {URI:about:blank, originalURI:about:blank}, STATE_START|STATE_IS_REQUEST|STATE_IS_DOCUMENT|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:3, url:about:blank}
[task 2025-03-24T12:14:39.699Z] 12:14:39     INFO - PID 10470 | 1742818479698	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2025-03-24T12:14:39.707Z] 12:14:39     INFO - PID 10470 | 1742818479706	RemoteAgent	TRACE	[3] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=80000 waitForExplicitStart=false
[task 2025-03-24T12:14:39.708Z] 12:14:39     INFO - PID 10470 | 1742818479706	RemoteAgent	TRACE	[3] ProgressListener Document already loading about:blank
[task 2025-03-24T12:14:39.709Z] 12:14:39     INFO - PID 10470 | 1742818479706	RemoteAgent	TRACE	[3] ProgressListener Loading state: isStart=true isStop=false status=0x0, loadType=0x1
[task 2025-03-24T12:14:39.709Z] 12:14:39     INFO - PID 10470 | 1742818479707	RemoteAgent	TRACE	[3] ProgressListener Started loading about:blank
[task 2025-03-24T12:14:39.709Z] 12:14:39     INFO - PID 10470 | 1742818479707	RemoteAgent	TRACE	[3] Wait for initial navigation: isInitial=true, isLoadingDocument=true
[task 2025-03-24T12:26:17.629Z] 12:26:17     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/classic/perform_actions/user_prompts.py | expected OK

In a working case like the following BCWebProgress logs are coming in immediately:
https://treeherder.mozilla.org/logviewer?job_id=500615410&repo=try&lineNumber=279444-279460

Olli, do you have an idea? The BCWebProgress logs are all from the parent process, so could there be IPC issues with the content process so that no messages are passed? Enabling logs for IPC in CI might not be helpful given that it would produce massive log files.

Flags: needinfo?(smaug)

Might be worth to try to create performance profiles for this, with a run which succeeds and with a run which fails.
And enable IPC marker when profiling. That might tell if there are any differences in that level.

Flags: needinfo?(smaug)

I've discovered something very strange today. While fully building Firefox and seeing all the CPU cores under 100% load I was trying to run a very simple Marionette test:

    def test(self):
        result = self.marionette.open(type="tab", focus=False)

And I saw that this test stalled in the call to open because the initial about:blank for the newly opened background tab never started to load. But I got it to work when I manually moved the mouse pointer over the tab in the toolbar. Then the navigation was started. Also after the build finished it was working fine as well.

I wonder if we somehow miss events when the CPUs are under high load and something hangs when initializing a new tab.

I was able to hit the hang again when compiling Firefox and all CPU cores at 100%. The following Gecko profile shows everything what happened during the call to the WebDriver:NewWindow command. As it can be seen the WebProgress stopped right after about:blank started loading and then no further update are sent out, until I actually moved the mouse above the background tab.

https://share.firefox.dev/4iUDgxP

Olli, do you see what might go wrong here?

Flags: needinfo?(smaug)

There isn't much in the profile.

Task unloadNonRequiredTabs/this.unloadTimer<[AsyncTabSwitcher.sys.mjs]:JS looks a bit suspicious.
Does something add more and more tabs and then eventually they are all unloaded at once?

Flags: needinfo?(smaug)

(In reply to Olli Pettay [:smaug][bugs@pettay.fi] from comment #151)

There isn't much in the profile.

That's sad. Are there any other logs that might be helpful to enable to get more details?

Task unloadNonRequiredTabs/this.unloadTimer<[AsyncTabSwitcher.sys.mjs]:JS looks a bit suspicious.
Does something add more and more tabs and then eventually they are all unloaded at once?

No, this test only adds a single new background tab where about:blank is not getting loaded.

Here a Gecko Profile with IPC markers enabled. Looks like I forgot it the last time.

https://share.firefox.dev/3EbIaHu

What's interesting as well is that the screenshots during the whole time do not even show the newly opened background tab, but only the initial one.

(In reply to Henrik Skupin [:whimboo][⌚️UTC+2] from comment #154)

Here a Gecko Profile with IPC markers enabled. Looks like I forgot it the last time.

https://share.firefox.dev/3EbIaHu

What's interesting as well is that the screenshots during the whole time do not even show the newly opened background tab, but only the initial one.

Olli, maybe this profile has more information? If not any suggestion what to log specifically?

Flags: needinfo?(smaug)

I had a session with Olli yesterday. He checked the created Gecko Profile and mentioned that it looks like the WebContent process doesn't run at all. And after further checks it turned out that the mouse move over the tab actually changed its priority and that after the Msg_NotifyProcessPriorityChanged marker the processing of the initial load of about:blank started as usual.

I did a quick search if there is maybe a preference related to priority handling of processes and I found threads.lower_mainthread_priority_in_background.enabled. It's set to true on MacOS everywhere and on other platforms only for Nightly. Now when I flipped its value and run the above Marionette test again it worked just fine. No more hang was visible. Also there is the preference dom.ipc.processPriorityManager.enabled which might turn off the priority manager completely.

For Marionette and especially for WebDriver BiDi (where we are running commands in background tabs way more often) this prioritization is problematic and we should turn off this feature in test suites related to those automation protocols. When doing so we should check to note cause side-effects especially not for mochitests where Marionette is used to install the required add-ons and then maybe doesn't reset the prefs.

I'll file a new bug for specifically the handling in Remote Agent.

Joel, do you think that other test suites would benefit from it as well? Note that given that in CI we run multiple test jobs on the same worker in parallel it could happen that all CPUs are fully utilized and the priority manager kicks in and causes processes in background tabs to be stalled - causing timeouts. If it's unclear we could wait until my patch landed for the Remote Agent, and check again. What do you think?

Flags: needinfo?(smaug) → needinfo?(jmaher)

I checked the dom.ipc.processPriorityManager.enabled preference but this doesn't cause any difference on MacOS. So we need threads.lower_mainthread_priority_in_background.enabled for that platform. Not sure yet what applies to Linux, Windows, and Android.

Duplicate of this bug: 1960711

interesting find!

for hardware (like macosx) we do not run anything in parallel. The one exception I am aware of is xpcshell as this typically runs a few threads, then if anything fails is retested solo.

for windows/android-emulator/linux- we run on docker/vm, nothing in parallel there- but these are on "shared machines". Theoretically the virtualized layer will handle allocating dedicated CPU threads/cores to a single instance.

one thought is if this preference is enabled on nightly, will it be going to end users? Do we risk skewing our test environments more and missing important coverage for end users? We do a lot of "fake stuff" to make testing work and we do 1000x what an end user would realistically do, so we could be missing coverage but that is ok.

As for extending this pref change to all harnesses, I think it would be ideal to put it in the common scenario:
https://searchfox.org/mozilla-central/source/testing/profiles/common/user.js

if things look good, we should check with the perf team, I believe they use common/user.js as well, so that might be something to verify with :kshampur or :sparky.

Flags: needinfo?(jmaher)

(In reply to Joel Maher ( :jmaher ) (UTC -8) from comment #160)

for hardware (like macosx) we do not run anything in parallel. The one exception I am aware of is xpcshell as this typically runs a few threads, then if anything fails is retested solo.

This is good information and actually reflects the so for classified failures which only happen on non-Mac systems.

for windows/android-emulator/linux- we run on docker/vm, nothing in parallel there- but these are on "shared machines". Theoretically the virtualized layer will handle allocating dedicated CPU threads/cores to a single instance.

Yes, that is what I actually meant with parallel. Virtual machines on the same host have limited resources and may see situations like that as well? I don't know how CPU load is actually scheduled.

one thought is if this preference is enabled on nightly, will it be going to end users? Do we risk skewing our test environments more and missing important coverage for end users? We do a lot of "fake stuff" to make testing work and we do 1000x what an end user would realistically do, so we could be missing coverage but that is ok.

Yes, end users will see it and we have bug 1960741 on file for now, which should help at least with opening tabs and loading the initial URL. But for automation it will not be enough to have foreground priority for just loading the page. We are going to investigate more on bug 1960734 before actually landing the changes.

As for extending this pref change to all harnesses, I think it would be ideal to put it in the common scenario:
https://searchfox.org/mozilla-central/source/testing/profiles/common/user.js

if things look good, we should check with the perf team, I believe they use common/user.js as well, so that might be something to verify with :kshampur or :sparky.

I've informed them for now and will take a note once we are sure that we can land.

Thanks!

Duplicate of this bug: 1960780

I got the patch for the Remote Agent landed on autoland. I'll observe today and tomorrow what the results are and if / how much test failures are gone.

A recent log shows still a very long time before the browser-idle-startup-tasks-finished observer notification is sent out. Usually it's just some milliseconds after final-ui-startup:

https://treeherder.mozilla.org/logviewer?job_id=504389291&repo=mozilla-central&lineNumber=312241-312243

[task 2025-04-17T07:42:04.272Z] 07:42:04     INFO - PID 4703 | 1744875724271	Marionette	TRACE	Received observer notification final-ui-startup
[task 2025-04-17T07:42:04.338Z] 07:42:04     INFO - PID 4703 | 1744875724337	Marionette	INFO	Listening on port 53043
[task 2025-04-17T07:42:04.339Z] 07:42:04     INFO - PID 4703 | 1744875724338	Marionette	DEBUG	Marionette is listening
[task 2025-04-17T07:42:04.370Z] 07:42:04     INFO - PID 4703 | Read port: 53043
[task 2025-04-17T07:42:05.371Z] 07:42:05     INFO - PID 4703 | 1744875725370	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2025-04-17T07:42:05.578Z] 07:42:05     INFO - PID 4703 | Read port: 53043
[task 2025-04-17T07:42:05.587Z] 07:42:05     INFO - PID 4703 | 1744875725586	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:53044
[task 2025-04-17T07:42:05.588Z] 07:42:05     INFO - PID 4703 | 1744875725587	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:53045
[task 2025-04-17T07:42:05.876Z] 07:42:05     INFO - PID 4703 | 1744875725875	Marionette	DEBUG	Closed connection 0
[task 2025-04-17T07:42:05.877Z] 07:42:05     INFO - PID 4703 | 1744875725876	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:53043.
[task 2025-04-17T07:42:05.963Z] 07:42:05     INFO - PID 4703 | 1744875725962	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{}]
[task 2025-04-17T07:42:05.964Z] 07:42:05     INFO - PID 4703 | 1744875725963	Marionette	DEBUG	Waiting for initial application window
[task 2025-04-17T07:42:20.527Z] 07:42:20     INFO - PID 4703 | 1744875740526	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished

Some more log entries in the browser startup code might help on try to figure out where we are hanging.

(In reply to Intermittent Failures Robot from comment #166)

14 failures were associated with this bug in the last 7 days.

Nearly all of these failures were wrongly classified. After correcting that only 2 failures for CCOV builds remain which could actually be caused by a different issue.

I filed bug 1963001 to investigate why the load of the initial about:blank in the one and only open tab during startup is delayed that much in some cases.

There are lots of new failures for macOS. All of those seem to be related to very slow startup times of Firefox in CI which is covered by bug 1964338.

Depends on: 1964338
No longer depends on: 1964338

The potential fix for bug 1988261 might have an impact here. Lets see if I can get to it in the near future.

Depends on: 1988261
No longer duplicate of this bug: 1848274

(In reply to Henrik Skupin [:whimboo][⌚️UTC+2] from comment #10)

It takes 24s further seconds until the browser-idle-startup-tasks-finished notification gets send out after final-ui-startup. I wonder if those errors from Telemetry might be related, when it tries to maybe get the history for that amount of time but then finally fails?

This seems to be still the main reason when the startup time is massively delayed:
https://treeherder.mozilla.org/logviewer?job_id=561598881&repo=mozilla-beta&task=JW4e09UPQeOzTLWQzxf87w.0&lineNumber=1160-1177

[task 2026-04-22T03:12:10.490+00:00] 03:12:10     INFO - PID 1633 | 1776827530489	RemoteAgent	TRACE	Received observer notification final-ui-startup
[..]
[task 2026-04-22T03:12:19.366+00:00] 03:12:19     INFO - PID 1633 | 1776827539364	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished

Dave, would it be feasible to add some debug logging for each startup task so that we know how long it takes? Or do we have profile markers? The former might be better given that we don't record profiles for Marionette related jobs.

Flags: needinfo?(dtownsend)

(In reply to Henrik Skupin [:whimboo][⌚️UTC+2] from comment #225)

Dave, would it be feasible to add some debug logging for each startup task so that we know how long it takes? Or do we have profile markers? The former might be better given that we don't record profiles for Marionette related jobs.

In general, no. There is a lot that happens between final-ui-startup (called before the first window has started opening) and browser-idle-startup-tasks-finished (called after the browser windows have opened, session restore has run and all tasks that we want to defer from the startup path have completed) and those things aren't all called in a standard way so it would be a lot of work to instrument everything.

We do however have a number of the startup tasks instrumented by profile markers and also there are a number of observer notifications that would fire between those and they are also instrumented with profile markers. If it is possible to get a profile of the slow startup that could go a long way to narrowing down the specific section of startup that is slow.

Flags: needinfo?(dtownsend)

Thanks Dave! I think that in such a case we would have to put this bug into the backlog for now. The number of failures is pretty low for this issue and it won't be possible to get a profile for it (at least for now). But once the number of failures increase again, we could try.

You need to log in before you can comment on or make changes to this bug.