1769749 - Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/timeouts.py | single tracking bug

Status: RESOLVED INCOMPLETE

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-05-17T12:02:38.264Z] 12:02:38     INFO - TEST-START | /webdriver/tests/new_session/timeouts.py
[task 2022-05-17T12:02:38.354Z] 12:02:38     INFO - STDOUT: ============================= test session starts =============================
[task 2022-05-17T12:02:38.355Z] 12:02:38     INFO - STDOUT: platform win32 -- Python 3.9.5, pytest-7.0.1, pluggy-unknown -- Z:\task_165278501043466\build\venv\Scripts\python.exe
[task 2022-05-17T12:02:38.356Z] 12:02:38     INFO - STDOUT: rootdir: Z:\task_165278501043466\build
[task 2022-05-17T12:02:38.357Z] 12:02:38     INFO - STDOUT: plugins: asyncio-0.14.0
[task 2022-05-17T12:02:38.357Z] 12:02:38     INFO - STDOUT: collecting ... 
[task 2022-05-17T12:02:38.370Z] 12:02:38     INFO - STDOUT: collected 8 items
[task 2022-05-17T12:02:38.379Z] 12:02:38     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/timeouts.py::test_default_values 
[task 2022-05-17T12:02:38.387Z] 12:02:38     INFO - PID 7492 | 1652788958385	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_165278501043466\\AppData\\Local\\Temp\\tmplx6l1m3w.mozrunner"], "binary": "Z:\\task_165278501043466\\build\\application\\firefox\\firefox.exe"}}}}
[task 2022-05-17T12:02:38.387Z] 12:02:38     INFO - PID 7492 | 1652788958386	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2022-05-17T12:02:38.387Z] 12:02:38     INFO - PID 7492 | 1652788958386	geckodriver::capabilities	DEBUG	Found version 102.0
[task 2022-05-17T12:02:38.393Z] 12:02:38     INFO - PID 7492 | 1652788958392	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_165278501043466\\AppData\\Local\\Temp\\tmplx6l1m3w.mozrunner\\user.geckodriver_backup"
[task 2022-05-17T12:02:38.406Z] 12:02:38     INFO - PID 7492 | 1652788958406	mozrunner::runner	INFO	Running command: "Z:\\task_165278501043466\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_165278501043466\\AppData\\Local\\Temp\\tmplx6l1m3w.mozrunner" "-no-remote"
[task 2022-05-17T12:02:38.411Z] 12:02:38     INFO - PID 7492 | 1652788958410	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-05-17T12:02:38.411Z] 12:02:38     INFO - PID 7492 | 1652788958410	geckodriver::browser	TRACE	Failed to open C:\Users\task_165278501043466\AppData\Local\Temp\tmplx6l1m3w.mozrunner\MarionetteActivePort
[task 2022-05-17T12:02:38.412Z] 12:02:38     INFO - PID 7492 | 1652788958410	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-17T12:02:38.519Z] 12:02:38     INFO - PID 7492 | 1652788958519	geckodriver::browser	TRACE	Failed to open C:\Users\task_165278501043466\AppData\Local\Temp\tmplx6l1m3w.mozrunner\MarionetteActivePort
[task 2022-05-17T12:02:38.520Z] 12:02:38     INFO - PID 7492 | 1652788958519	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-17T12:02:38.564Z] 12:02:38     INFO - PID 7492 | 1652788958572	Marionette	INFO	Marionette enabled
[task 2022-05-17T12:02:38.573Z] 12:02:38     INFO - PID 7492 | 1652788958573	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-05-17T12:02:38.574Z] 12:02:38     INFO - PID 7492 | 1652788958574	Marionette	INFO	Listening on port 64185
[task 2022-05-17T12:02:38.574Z] 12:02:38     INFO - PID 7492 | 1652788958574	Marionette	DEBUG	Marionette is listening
[task 2022-05-17T12:02:38.634Z] 12:02:38     INFO - PID 7492 | Read port: 64185
[task 2022-05-17T12:02:38.681Z] 12:02:38     INFO - PID 7492 | 1652788958680	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:64186
[task 2022-05-17T12:02:38.683Z] 12:02:38     INFO - PID 7492 | 1652788958683	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:64185.
[task 2022-05-17T12:02:38.696Z] 12:02:38     INFO - PID 7492 | 1652788958705	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{}]
[task 2022-05-17T12:02:38.706Z] 12:02:38     INFO - PID 7492 | 1652788958706	Marionette	DEBUG	Waiting for initial application window
[task 2022-05-17T12:02:39.823Z] 12:02:39     INFO - PID 7492 | 1652788959824	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2022-05-17T12:02:39.826Z] 12:02:39     INFO - PID 7492 | 1652788959826	RemoteAgent	TRACE	[30] Document already finished loading: about:blank
[task 2022-05-17T12:02:39.833Z] 12:02:39     INFO - PID 7492 | 1652788959832	Marionette	DEBUG	0 <- [1,1,null,{"sessionId":"e6c96072-0c1f-4185-a536-d55973fa68cc","capabilities":{"browserName":"firefox","browserVersion":"102.0 ... ownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2022-05-17T12:02:39.836Z] 12:02:39     INFO - PID 7492 | 1652788959834	webdriver::server	DEBUG	<- 200 OK {"value":{"sessionId":"e6c96072-0c1f-4185-a536-d55973fa68cc","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"102.0","moz:accessibilityChecks":false,"moz:buildID":"20220517094814","moz:geckodriverVersion":"0.31.0","moz:headless":false,"moz:processID":728,"moz:profile":"C:\\Users\\task_165278501043466\\AppData\\Local\\Temp\\tmplx6l1m3w.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"pageLoadStrategy":"normal","platformName":"windows","platformVersion":"10.0","proxy":{},"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
[task 2022-05-17T12:02:39.837Z] 12:02:39     INFO - PID 7492 | 1652788959835	webdriver::server	DEBUG	-> POST /session/e6c96072-0c1f-4185-a536-d55973fa68cc/window/rect {"width": 800, "height": 600}
[task 2022-05-17T12:02:39.838Z] 12:02:39     INFO - PID 7492 | 1652788959837	Marionette	DEBUG	0 -> [0,2,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2022-05-17T12:02:39.838Z] 12:02:39     INFO - PID 7492 | 1652788959838	Marionette	DEBUG	0 <- [1,2,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-05-17T12:02:39.839Z] 12:02:39     INFO - PID 7492 | 1652788959838	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-05-17T12:02:39.840Z] 12:02:39     INFO - PID 7492 | 1652788959839	webdriver::server	DEBUG	-> POST /session/e6c96072-0c1f-4185-a536-d55973fa68cc/window/rect {"x": 100, "y": 100}
[task 2022-05-17T12:02:39.841Z] 12:02:39     INFO - PID 7492 | 1652788959840	Marionette	DEBUG	0 -> [0,3,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2022-05-17T12:02:39.841Z] 12:02:39     INFO - PID 7492 | 1652788959840	Marionette	DEBUG	0 <- [1,3,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-05-17T12:02:39.842Z] 12:02:39     INFO - PID 7492 | 1652788959840	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-05-17T12:02:39.843Z] 12:02:39     INFO - STDOUT: PASSED
[task 2022-05-17T12:02:39.844Z] 12:02:39     INFO - PID 7492 | 1652788959843	webdriver::server	DEBUG	-> POST /session/e6c96072-0c1f-4185-a536-d55973fa68cc/timeouts {"implicit": 0}
[task 2022-05-17T12:02:39.844Z] 12:02:39     INFO - PID 7492 | 1652788959843	Marionette	DEBUG	0 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-05-17T12:02:39.845Z] 12:02:39     INFO - PID 7492 | 1652788959843	Marionette	DEBUG	0 <- [1,4,null,{"value":null}]
[task 2022-05-17T12:02:39.846Z] 12:02:39     INFO - PID 7492 | 1652788959844	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-05-17T12:02:39.847Z] 12:02:39     INFO - PID 7492 | 1652788959845	webdriver::server	DEBUG	-> POST /session/e6c96072-0c1f-4185-a536-d55973fa68cc/timeouts {"pageLoad": 300000}
[task 2022-05-17T12:02:39.848Z] 12:02:39     INFO - PID 7492 | 1652788959845	Marionette	DEBUG	0 -> [0,5,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-05-17T12:02:39.848Z] 12:02:39     INFO - PID 7492 | 1652788959845	Marionette	DEBUG	0 <- [1,5,null,{"value":null}]
[task 2022-05-17T12:02:39.849Z] 12:02:39     INFO - PID 7492 | 1652788959846	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-05-17T12:02:39.850Z] 12:02:39     INFO - PID 7492 | 1652788959847	webdriver::server	DEBUG	-> POST /session/e6c96072-0c1f-4185-a536-d55973fa68cc/timeouts {"script": 30000}
[task 2022-05-17T12:02:39.850Z] 12:02:39     INFO - PID 7492 | 1652788959847	Marionette	DEBUG	0 -> [0,6,"WebDriver:SetTimeouts",{"script":30000}]
[task 2022-05-17T12:02:39.851Z] 12:02:39     INFO - PID 7492 | 1652788959847	Marionette	DEBUG	0 <- [1,6,null,{"value":null}]
[task 2022-05-17T12:02:39.852Z] 12:02:39     INFO - PID 7492 | 1652788959848	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-05-17T12:02:39.853Z] 12:02:39     INFO - PID 7492 | 1652788959849	webdriver::server	DEBUG	-> GET /session/e6c96072-0c1f-4185-a536-d55973fa68cc/window
[task 2022-05-17T12:02:39.853Z] 12:02:39     INFO - PID 7492 | 1652788959849	Marionette	DEBUG	0 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2022-05-17T12:02:39.854Z] 12:02:39     INFO - PID 7492 | 1652788959849	Marionette	DEBUG	0 <- [1,7,null,{"value":"484bd9d3-1f3e-4476-a257-e4908f1e3614"}]
[task 2022-05-17T12:02:39.855Z] 12:02:39     INFO - PID 7492 | 1652788959849	webdriver::server	DEBUG	<- 200 OK {"value":"484bd9d3-1f3e-4476-a257-e4908f1e3614"}
[task 2022-05-17T12:02:39.855Z] 12:02:39     INFO - PID 7492 | 1652788959850	webdriver::server	DEBUG	-> GET /session/e6c96072-0c1f-4185-a536-d55973fa68cc/window
[task 2022-05-17T12:02:39.856Z] 12:02:39     INFO - PID 7492 | 1652788959851	Marionette	DEBUG	0 -> [0,8,"WebDriver:GetWindowHandle",{}]
[task 2022-05-17T12:02:39.857Z] 12:02:39     INFO - PID 7492 | 1652788959851	Marionette	DEBUG	0 <- [1,8,null,{"value":"484bd9d3-1f3e-4476-a257-e4908f1e3614"}]
[task 2022-05-17T12:02:39.857Z] 12:02:39     INFO - PID 7492 | 1652788959851	webdriver::server	DEBUG	<- 200 OK {"value":"484bd9d3-1f3e-4476-a257-e4908f1e3614"}
[task 2022-05-17T12:02:39.858Z] 12:02:39     INFO - PID 7492 | 1652788959852	webdriver::server	DEBUG	-> GET /session/e6c96072-0c1f-4185-a536-d55973fa68cc/window/handles
[task 2022-05-17T12:02:39.859Z] 12:02:39     INFO - PID 7492 | 1652788959852	Marionette	DEBUG	0 -> [0,9,"WebDriver:GetWindowHandles",{}]
[task 2022-05-17T12:02:39.860Z] 12:02:39     INFO - PID 7492 | 1652788959852	Marionette	DEBUG	0 <- [1,9,null,["484bd9d3-1f3e-4476-a257-e4908f1e3614"]]
[task 2022-05-17T12:02:39.860Z] 12:02:39     INFO - PID 7492 | 1652788959853	webdriver::server	DEBUG	<- 200 OK {"value":["484bd9d3-1f3e-4476-a257-e4908f1e3614"]}
[task 2022-05-17T12:02:39.861Z] 12:02:39     INFO - PID 7492 | 1652788959853	webdriver::server	DEBUG	-> POST /session/e6c96072-0c1f-4185-a536-d55973fa68cc/window {"handle": "484bd9d3-1f3e-4476-a257-e4908f1e3614"}
[task 2022-05-17T12:02:39.862Z] 12:02:39     INFO - PID 7492 | 1652788959854	Marionette	DEBUG	0 -> [0,10,"WebDriver:SwitchToWindow",{"handle":"484bd9d3-1f3e-4476-a257-e4908f1e3614"}]
[task 2022-05-17T12:02:39.863Z] 12:02:39     INFO - PID 7492 | 1652788959854	Marionette	DEBUG	0 <- [1,10,null,{"value":null}]
[task 2022-05-17T12:02:39.863Z] 12:02:39     INFO - PID 7492 | 1652788959855	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-05-17T12:02:39.864Z] 12:02:39     INFO - PID 7492 | 1652788959856	webdriver::server	DEBUG	-> POST /session/e6c96072-0c1f-4185-a536-d55973fa68cc/alert/dismiss {}
[task 2022-05-17T12:02:39.865Z] 12:02:39     INFO - PID 7492 | 1652788959856	Marionette	DEBUG	0 -> [0,11,"WebDriver:DismissAlert",{}]
[task 2022-05-17T12:02:39.866Z] 12:02:39     INFO - PID 7492 | 1652788959857	Marionette	DEBUG	0 <- [1,11,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm: ... ote/content/marionette/server.js:253:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:500:20\n"},null]
[task 2022-05-17T12:02:39.867Z] 12:02:39     INFO - PID 7492 | 1652788959857	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm:186:5\nNoSuchAlertError@chrome://remote/content/shared/webdriver/Errors.jsm:387:5\nGeckoDriver.prototype._checkIfAlertIsPresent@chrome://remote/content/marionette/driver.js:2523:11\nGeckoDriver.prototype.dismissDialog@chrome://remote/content/marionette/driver.js:2434:8\ndespatch@chrome://remote/content/marionette/server.js:306:40\nexecute@chrome://remote/content/marionette/server.js:279:16\nonPacket/<@chrome://remote/content/marionette/server.js:252:20\nonPacket@chrome://remote/content/marionette/server.js:253:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:500:20\n"}}
[task 2022-05-17T12:02:39.868Z] 12:02:39     INFO - PID 7492 | 1652788959858	webdriver::server	DEBUG	-> POST /session/e6c96072-0c1f-4185-a536-d55973fa68cc/window {"handle": "484bd9d3-1f3e-4476-a257-e4908f1e3614"}
[task 2022-05-17T12:02:39.869Z] 12:02:39     INFO - PID 7492 | 1652788959859	Marionette	DEBUG	0 -> [0,12,"WebDriver:SwitchToWindow",{"handle":"484bd9d3-1f3e-4476-a257-e4908f1e3614"}]
[task 2022-05-17T12:02:39.870Z] 12:02:39     INFO - PID 7492 | 1652788959859	Marionette	DEBUG	0 <- [1,12,null,{"value":null}]
[task 2022-05-17T12:02:39.870Z] 12:02:39     INFO - PID 7492 | 1652788959859	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-05-17T12:02:39.871Z] 12:02:39     INFO - PID 7492 | 1652788959860	webdriver::server	DEBUG	-> GET /session/e6c96072-0c1f-4185-a536-d55973fa68cc/window
[task 2022-05-17T12:02:39.872Z] 12:02:39     INFO - PID 7492 | 1652788959860	Marionette	DEBUG	0 -> [0,13,"WebDriver:GetWindowHandle",{}]
[task 2022-05-17T12:02:39.873Z] 12:02:39     INFO - PID 7492 | 1652788959861	Marionette	DEBUG	0 <- [1,13,null,{"value":"484bd9d3-1f3e-4476-a257-e4908f1e3614"}]
[task 2022-05-17T12:02:39.873Z] 12:02:39     INFO - PID 7492 | 1652788959861	webdriver::server	DEBUG	<- 200 OK {"value":"484bd9d3-1f3e-4476-a257-e4908f1e3614"}
[task 2022-05-17T12:02:39.874Z] 12:02:39     INFO - PID 7492 | 1652788959862	webdriver::server	DEBUG	-> GET /session/e6c96072-0c1f-4185-a536-d55973fa68cc/window/handles
[task 2022-05-17T12:02:39.875Z] 12:02:39     INFO - PID 7492 | 1652788959862	Marionette	DEBUG	0 -> [0,14,"WebDriver:GetWindowHandles",{}]
[task 2022-05-17T12:02:39.876Z] 12:02:39     INFO - PID 7492 | 1652788959862	Marionette	DEBUG	0 <- [1,14,null,["484bd9d3-1f3e-4476-a257-e4908f1e3614"]]
[task 2022-05-17T12:02:39.876Z] 12:02:39     INFO - PID 7492 | 1652788959862	webdriver::server	DEBUG	<- 200 OK {"value":["484bd9d3-1f3e-4476-a257-e4908f1e3614"]}
[task 2022-05-17T12:02:39.877Z] 12:02:39     INFO - PID 7492 | 1652788959863	webdriver::server	DEBUG	-> POST /session/e6c96072-0c1f-4185-a536-d55973fa68cc/window {"handle": "484bd9d3-1f3e-4476-a257-e4908f1e3614"}
[task 2022-05-17T12:02:39.878Z] 12:02:39     INFO - PID 7492 | 1652788959864	Marionette	DEBUG	0 -> [0,15,"WebDriver:SwitchToWindow",{"handle":"484bd9d3-1f3e-4476-a257-e4908f1e3614"}]
[task 2022-05-17T12:02:39.878Z] 12:02:39     INFO - PID 7492 | 1652788959864	Marionette	DEBUG	0 <- [1,15,null,{"value":null}]
[task 2022-05-17T12:02:39.879Z] 12:02:39     INFO - PID 7492 | 1652788959864	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-05-17T12:02:39.880Z] 12:02:39     INFO - PID 7492 | 1652788959865	webdriver::server	DEBUG	-> POST /session/e6c96072-0c1f-4185-a536-d55973fa68cc/window/rect {"width": 800, "height": 600}
[task 2022-05-17T12:02:39.880Z] 12:02:39     INFO - PID 7492 | 1652788959866	Marionette	DEBUG	0 -> [0,16,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2022-05-17T12:02:39.881Z] 12:02:39     INFO - PID 7492 | 1652788959866	Marionette	DEBUG	0 <- [1,16,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-05-17T12:02:39.881Z] 12:02:39     INFO - PID 7492 | 1652788959866	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-05-17T12:02:39.882Z] 12:02:39     INFO - PID 7492 | 1652788959867	webdriver::server	DEBUG	-> POST /session/e6c96072-0c1f-4185-a536-d55973fa68cc/frame {"id": null}
[task 2022-05-17T12:02:39.883Z] 12:02:39     INFO - PID 7492 | 1652788959867	Marionette	DEBUG	0 -> [0,17,"WebDriver:SwitchToFrame",{"id":null}]
[task 2022-05-17T12:02:39.883Z] 12:02:39     INFO - PID 7492 | 1652788959871	Marionette	TRACE	[30] MarionetteCommands actor created for window id 4294967297
[task 2022-05-17T12:02:39.884Z] 12:02:39     INFO - PID 7492 | 1652788959875	Marionette	DEBUG	0 <- [1,17,null,{"value":null}]
[task 2022-05-17T12:02:39.884Z] 12:02:39     INFO - PID 7492 | 1652788959875	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-05-17T12:02:39.885Z] 12:02:39     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/timeouts.py::test_timeouts[timeouts0] 
[task 2022-05-17T12:02:39.886Z] 12:02:39     INFO - PID 7492 | 1652788959879	webdriver::server	DEBUG	-> DELETE /session/e6c96072-0c1f-4185-a536-d55973fa68cc
[task 2022-05-17T12:02:39.887Z] 12:02:39     INFO - PID 7492 | 1652788959879	Marionette	DEBUG	0 -> [0,18,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-05-17T12:02:39.888Z] 12:02:39     INFO - PID 7492 | 1652788959879	Marionette	INFO	Stopped listening on port 64185
[task 2022-05-17T12:02:39.907Z] 12:02:39     INFO - PID 7492 | 1652788959912	Marionette	TRACE	Received observer notification quit-application
[task 2022-05-17T12:02:39.915Z] 12:02:39     INFO - PID 7492 | 1652788959914	Marionette	TRACE	Received observer notification quit-application
[task 2022-05-17T12:02:39.916Z] 12:02:39     INFO - PID 7492 | 1652788959914	Marionette	DEBUG	Marionette stopped listening
[task 2022-05-17T12:02:39.917Z] 12:02:39     INFO - PID 7492 | 1652788959915	Marionette	DEBUG	0 <- [1,18,null,{"cause":"shutdown","forced":false}]
[task 2022-05-17T12:02:39.929Z] 12:02:39     INFO - PID 7492 | 1652788959929	webdriver::server	DEBUG	Teardown session
[task 2022-05-17T12:02:39.931Z] 12:02:39     INFO - PID 7492 | 1652788959930	Marionette	DEBUG	Closed connection 0
[task 2022-05-17T12:03:05.662Z] 12:03:05     INFO - PID 7492 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 379))
[task 2022-05-17T12:03:05.700Z] 12:03:05     INFO - PID 7492 | JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 81: AbortError: IOUtils: Shutting down and refusing additional I/O tasks
[task 2022-05-17T12:03:06.232Z] 12:03:06     INFO - PID 7492 | 1652788986232	geckodriver::browser	DEBUG	Browser process stopped: exit code: 0
[task 2022-05-17T12:03:06.233Z] 12:03:06     INFO - PID 7492 | 1652788986233	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-05-17T12:03:06.235Z] 12:03:06     INFO - PID 7492 | 1652788986234	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_165278501043466\\AppData\\Local\\Temp\\tmplx6l1m3w.mozrunner"], "binary": "Z:\\task_165278501043466\\build\\application\\firefox\\firefox.exe"}, "timeouts": {"implicit": 444, "pageLoad": 300000, "script": 30000}}}}
[task 2022-05-17T12:03:06.235Z] 12:03:06     INFO - PID 7492 | 1652788986234	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2022-05-17T12:03:06.236Z] 12:03:06     INFO - PID 7492 | 1652788986235	geckodriver::capabilities	DEBUG	Found version 102.0
[task 2022-05-17T12:03:06.295Z] 12:03:06     INFO - PID 7492 | 1652788986296	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_165278501043466\\AppData\\Local\\Temp\\tmplx6l1m3w.mozrunner\\user.geckodriver_backup"
[task 2022-05-17T12:03:06.310Z] 12:03:06     INFO - PID 7492 | 1652788986314	mozrunner::runner	INFO	Running command: "Z:\\task_165278501043466\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_165278501043466\\AppData\\Local\\Temp\\tmplx6l1m3w.mozrunner" "-no-remote"
[task 2022-05-17T12:03:06.326Z] 12:03:06     INFO - PID 7492 | 1652788986325	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-05-17T12:03:06.327Z] 12:03:06     INFO - PID 7492 | 1652788986325	geckodriver::browser	TRACE	Failed to open C:\Users\task_165278501043466\AppData\Local\Temp\tmplx6l1m3w.mozrunner\MarionetteActivePort
[task 2022-05-17T12:03:06.327Z] 12:03:06     INFO - PID 7492 | 1652788986325	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-17T12:03:06.434Z] 12:03:06     INFO - PID 7492 | 1652788986434	geckodriver::browser	TRACE	Failed to open C:\Users\task_165278501043466\AppData\Local\Temp\tmplx6l1m3w.mozrunner\MarionetteActivePort
[task 2022-05-17T12:03:06.435Z] 12:03:06     INFO - PID 7492 | 1652788986434	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-17T12:03:06.494Z] 12:03:06     INFO - PID 7492 | 1652788986502	Marionette	INFO	Marionette enabled
[task 2022-05-17T12:03:06.503Z] 12:03:06     INFO - PID 7492 | 1652788986503	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-05-17T12:03:06.504Z] 12:03:06     INFO - PID 7492 | 1652788986503	Marionette	INFO	Listening on port 64221
[task 2022-05-17T12:03:06.505Z] 12:03:06     INFO - PID 7492 | 1652788986503	Marionette	DEBUG	Marionette is listening
[task 2022-05-17T12:03:06.549Z] 12:03:06     INFO - PID 7492 | Read port: 64221
[task 2022-05-17T12:03:06.559Z] 12:03:06     INFO - PID 7492 | 1652788986559	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:64222
[task 2022-05-17T12:03:06.604Z] 12:03:06     INFO - PID 7492 | 1652788986612	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:64221.
[task 2022-05-17T12:03:06.622Z] 12:03:06     INFO - PID 7492 | 1652788986622	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"timeouts":{"implicit":444,"pageLoad":300000,"script":30000}}]
[task 2022-05-17T12:03:06.622Z] 12:03:06     INFO - PID 7492 | 1652788986622	Marionette	DEBUG	Waiting for initial application window
[task 2022-05-17T12:03:07.733Z] 12:03:07     INFO - PID 7492 | 1652788987734	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2022-05-17T12:03:07.736Z] 12:03:07     INFO - PID 7492 | 1652788987736	RemoteAgent	TRACE	[30] Document already finished loading: about:blank
[task 2022-05-17T12:03:07.742Z] 12:03:07     INFO - PID 7492 | 1652788987741	Marionette	DEBUG	0 <- [1,1,null,{"sessionId":"f0f99e5a-05b4-4c07-a206-1f8e204e9a0b","capabilities":{"browserName":"firefox","browserVersion":"102.0 ... ownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2022-05-17T12:03:07.746Z] 12:03:07     INFO - PID 7492 | 1652788987743	webdriver::server	DEBUG	<- 200 OK {"value":{"sessionId":"f0f99e5a-05b4-4c07-a206-1f8e204e9a0b","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"102.0","moz:accessibilityChecks":false,"moz:buildID":"20220517094814","moz:geckodriverVersion":"0.31.0","moz:headless":false,"moz:processID":8088,"moz:profile":"C:\\Users\\task_165278501043466\\AppData\\Local\\Temp\\tmplx6l1m3w.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"pageLoadStrategy":"normal","platformName":"windows","platformVersion":"10.0","proxy":{},"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":444,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
[task 2022-05-17T12:03:07.746Z] 12:03:07     INFO - STDOUT: PASSED
[task 2022-05-17T12:03:07.747Z] 12:03:07     INFO - PID 7492 | 1652788987744	webdriver::server	DEBUG	-> DELETE /session/f0f99e5a-05b4-4c07-a206-1f8e204e9a0b
[task 2022-05-17T12:03:07.748Z] 12:03:07     INFO - PID 7492 | 1652788987746	Marionette	DEBUG	0 -> [0,2,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-05-17T12:03:07.749Z] 12:03:07     INFO - PID 7492 | 1652788987747	Marionette	INFO	Stopped listening on port 64221
[task 2022-05-17T12:03:07.778Z] 12:03:07     INFO - PID 7492 | 1652788987781	Marionette	TRACE	Received observer notification quit-application
[task 2022-05-17T12:03:07.785Z] 12:03:07     INFO - PID 7492 | 1652788987783	Marionette	TRACE	Received observer notification quit-application
[task 2022-05-17T12:03:07.785Z] 12:03:07     INFO - PID 7492 | 1652788987784	Marionette	DEBUG	Marionette stopped listening
[task 2022-05-17T12:03:07.786Z] 12:03:07     INFO - PID 7492 | 1652788987784	Marionette	DEBUG	0 <- [1,2,null,{"cause":"shutdown","forced":false}]
[task 2022-05-17T12:03:07.798Z] 12:03:07     INFO - PID 7492 | 1652788987797	webdriver::server	DEBUG	Teardown session
[task 2022-05-17T12:03:07.799Z] 12:03:07     INFO - PID 7492 | 1652788987799	Marionette	DEBUG	Closed connection 0
[task 2022-05-17T12:03:08.003Z] 12:03:08     INFO - PID 7492 | 1652788988003	geckodriver::browser	DEBUG	Browser process stopped: exit code: 0
[task 2022-05-17T12:03:08.004Z] 12:03:08     INFO - PID 7492 | 1652788988004	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-05-17T12:03:08.007Z] 12:03:08     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/timeouts.py::test_timeouts[timeouts1] 
[task 2022-05-17T12:03:08.007Z] 12:03:08     INFO - PID 7492 | 1652788988007	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_165278501043466\\AppData\\Local\\Temp\\tmplx6l1m3w.mozrunner"], "binary": "Z:\\task_165278501043466\\build\\application\\firefox\\firefox.exe"}, "timeouts": {"implicit": 0, "pageLoad": 444, "script": 30000}}}}
[task 2022-05-17T12:03:08.008Z] 12:03:08     INFO - PID 7492 | 1652788988007	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2022-05-17T12:03:08.008Z] 12:03:08     INFO - PID 7492 | 1652788988007	geckodriver::capabilities	DEBUG	Found version 102.0
[task 2022-05-17T12:03:08.014Z] 12:03:08     INFO - PID 7492 | 1652788988014	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_165278501043466\\AppData\\Local\\Temp\\tmplx6l1m3w.mozrunner\\user.geckodriver_backup"
[task 2022-05-17T12:03:08.027Z] 12:03:08     INFO - PID 7492 | 1652788988029	mozrunner::runner	INFO	Running command: "Z:\\task_165278501043466\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_165278501043466\\AppData\\Local\\Temp\\tmplx6l1m3w.mozrunner" "-no-remote"
[task 2022-05-17T12:03:08.033Z] 12:03:08     INFO - PID 7492 | 1652788988033	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-05-17T12:03:08.034Z] 12:03:08     INFO - PID 7492 | 1652788988033	geckodriver::browser	TRACE	Failed to open C:\Users\task_165278501043466\AppData\Local\Temp\tmplx6l1m3w.mozrunner\MarionetteActivePort
[task 2022-05-17T12:03:08.035Z] 12:03:08     INFO - PID 7492 | 1652788988033	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-17T12:03:08.142Z] 12:03:08     INFO - PID 7492 | 1652788988142	geckodriver::browser	TRACE	Failed to open C:\Users\task_165278501043466\AppData\Local\Temp\tmplx6l1m3w.mozrunner\MarionetteActivePort
[task 2022-05-17T12:03:08.143Z] 12:03:08     INFO - PID 7492 | 1652788988142	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-17T12:03:08.187Z] 12:03:08     INFO - PID 7492 | 1652788988192	Marionette	INFO	Marionette enabled
[task 2022-05-17T12:03:08.193Z] 12:03:08     INFO - PID 7492 | 1652788988193	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-05-17T12:03:08.194Z] 12:03:08     INFO - PID 7492 | 1652788988194	Marionette	INFO	Listening on port 64238
[task 2022-05-17T12:03:08.195Z] 12:03:08     INFO - PID 7492 | 1652788988194	Marionette	DEBUG	Marionette is listening
[task 2022-05-17T12:03:08.255Z] 12:03:08     INFO - PID 7492 | Read port: 64238
[task 2022-05-17T12:03:08.283Z] 12:03:08     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/timeouts.py | expected OK
[task 2022-05-17T12:03:08.283Z] 12:03:08     INFO - TEST-INFO took 30023ms
[task 2022-05-17T12:03:08.502Z] 12:03:08     INFO - Closing logging queue
[task 2022-05-17T12:03:08.508Z] 12:03:08     INFO - queue closed
[task 2022-05-17T12:03:09.023Z] 12:03:09     INFO - PID 9768 | 1652788988522	geckodriver	INFO	Listening on 127.0.0.1:49844
[task 2022-05-17T12:03:09.025Z] 12:03:09     INFO - Starting runner
[task 2022-05-17T12:03:09.601Z] 12:03:09     INFO - TEST-START | /webdriver/tests/new_session/websocket_url.py

Comment 1

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

A test within this file sees a shutdown hang of Firefox:
https://treeherder.mozilla.org/logviewer?job_id=378339155&repo=try&lineNumber=56368-56378

[task 2022-05-17T12:02:39.887Z] 12:02:39     INFO - PID 7492 | 1652788959879	Marionette	DEBUG	0 -> [0,18,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-05-17T12:02:39.888Z] 12:02:39     INFO - PID 7492 | 1652788959879	Marionette	INFO	Stopped listening on port 64185
[task 2022-05-17T12:02:39.907Z] 12:02:39     INFO - PID 7492 | 1652788959912	Marionette	TRACE	Received observer notification quit-application
[task 2022-05-17T12:02:39.915Z] 12:02:39     INFO - PID 7492 | 1652788959914	Marionette	TRACE	Received observer notification quit-application
[task 2022-05-17T12:02:39.916Z] 12:02:39     INFO - PID 7492 | 1652788959914	Marionette	DEBUG	Marionette stopped listening
[task 2022-05-17T12:02:39.917Z] 12:02:39     INFO - PID 7492 | 1652788959915	Marionette	DEBUG	0 <- [1,18,null,{"cause":"shutdown","forced":false}]
[task 2022-05-17T12:02:39.929Z] 12:02:39     INFO - PID 7492 | 1652788959929	webdriver::server	DEBUG	Teardown session
[task 2022-05-17T12:02:39.931Z] 12:02:39     INFO - PID 7492 | 1652788959930	Marionette	DEBUG	Closed connection 0
[task 2022-05-17T12:03:05.662Z] 12:03:05     INFO - PID 7492 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 379))
[task 2022-05-17T12:03:05.700Z] 12:03:05     INFO - PID 7492 | JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 81: AbortError: IOUtils: Shutting down and refusing additional I/O tasks
[task 2022-05-17T12:03:06.232Z] 12:03:06     INFO - PID 7492 | 1652788986232	geckodriver::browser	DEBUG	Browser process stopped: exit code: 0

Dao, could this be related to SessionStore given the SessionFile is closed error message as printed nearly 30s later?

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform and build breakdown:

• windows10-64-2004-devedition-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1769749&startday=2022-05-16&endday=2022-05-22&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform and build breakdown:

• windows10-64-2004-devedition-qr: 1
  • opt: 1

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

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 1
  • opt: 1

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

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows10-64-2004-ccov-qr: 1
  • opt: 1

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

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows10-64-2004-ccov-qr: 1
  • opt: 1

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

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows10-64-2004-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1769749&startday=2022-09-12&endday=2022-09-18&tree=all

Comment 9

[BMO Automation]

Moving bug to Remote Protocol::Marionette component per bug 1815831.

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

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

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

Comment 11

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

The last intermittent failure was wrongly classified and is bug 1783217. Otherwise count it as a normal shutdown hang issue and dupe it to bug 1630162.

Comment 12

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

Lets make it a single tracking bug to have a better failure classification experience.

Recent failures for MacOS are all dependent on bug 1927416.

Comment 13

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

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