1760291 - Intermittent TEST-UNEXPECTED-TIMEOUT | Wd | expected OK (hang in WebDriver:Navigate when loading page via wptserve)

Reporter

Description

•

3 years ago

treeherder

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

[task 2022-03-18T11:38:08.877Z] 11:38:08     INFO - TEST-START | /webdriver/tests/take_screenshot/screenshot.py
[task 2022-03-18T11:38:08.937Z] 11:38:08     INFO - STDOUT: ============================= test session starts =============================
[task 2022-03-18T11:38:08.947Z] 11:38:08     INFO - STDOUT: platform win32 -- Python 3.9.5, pytest-6.1.1, py-1.5.2, pluggy-unknown -- Z:\task_164759494536844\build\venv\Scripts\python.exe
[task 2022-03-18T11:38:08.948Z] 11:38:08     INFO - STDOUT: rootdir: Z:\task_164759494536844\build
[task 2022-03-18T11:38:08.949Z] 11:38:08     INFO - STDOUT: plugins: asyncio-0.14.0
[task 2022-03-18T11:38:08.950Z] 11:38:08     INFO - STDOUT: collecting ... 
[task 2022-03-18T11:38:08.963Z] 11:38:08     INFO - STDOUT: collected 3 items
[task 2022-03-18T11:38:08.971Z] 11:38:08     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/take_screenshot/screenshot.py::test_no_top_browsing_context 
[task 2022-03-18T11:38:08.978Z] 11:38:08     INFO - PID 6392 | 1647603488977	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_164759494536844\\AppData\\Local\\Temp\\tmpev94s4hn.mozrunner"], "binary": "Z:\\task_164759494536844\\build\\application\\firefox\\firefox.exe"}}}}
[task 2022-03-18T11:38:08.978Z] 11:38:08     INFO - PID 6392 | 1647603488977	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2022-03-18T11:38:08.979Z] 11:38:08     INFO - PID 6392 | 1647603488977	geckodriver::capabilities	DEBUG	Found version 100.0a1
[task 2022-03-18T11:38:08.984Z] 11:38:08     INFO - PID 6392 | 1647603488983	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_164759494536844\\AppData\\Local\\Temp\\tmpev94s4hn.mozrunner\\user.geckodriver_backup"
[task 2022-03-18T11:38:08.997Z] 11:38:08     INFO - PID 6392 | 1647603488997	mozrunner::runner	INFO	Running command: "Z:\\task_164759494536844\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_164759494536844\\AppData\\Local\\Temp\\tmpev94s4hn.mozrunner" "-no-remote"
[task 2022-03-18T11:38:09.001Z] 11:38:09     INFO - PID 6392 | 1647603489000	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-03-18T11:38:09.002Z] 11:38:09     INFO - PID 6392 | 1647603489000	geckodriver::browser	TRACE	Failed to open C:\Users\task_164759494536844\AppData\Local\Temp\tmpev94s4hn.mozrunner\MarionetteActivePort
[task 2022-03-18T11:38:09.002Z] 11:38:09     INFO - PID 6392 | 1647603489000	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-18T11:38:09.106Z] 11:38:09     INFO - PID 6392 | 1647603489106	geckodriver::browser	TRACE	Failed to open C:\Users\task_164759494536844\AppData\Local\Temp\tmpev94s4hn.mozrunner\MarionetteActivePort
[task 2022-03-18T11:38:09.107Z] 11:38:09     INFO - PID 6392 | 1647603489106	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-18T11:38:09.199Z] 11:38:09     INFO - PID 6392 | 1647603489206	Marionette	INFO	Marionette enabled
[task 2022-03-18T11:38:09.215Z] 11:38:09     INFO - PID 6392 | 1647603489214	geckodriver::browser	TRACE	Failed to open C:\Users\task_164759494536844\AppData\Local\Temp\tmpev94s4hn.mozrunner\MarionetteActivePort
[task 2022-03-18T11:38:09.215Z] 11:38:09     INFO - PID 6392 | 1647603489214	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-18T11:38:09.322Z] 11:38:09     INFO - PID 6392 | 1647603489322	geckodriver::browser	TRACE	Failed to open C:\Users\task_164759494536844\AppData\Local\Temp\tmpev94s4hn.mozrunner\MarionetteActivePort
[task 2022-03-18T11:38:09.323Z] 11:38:09     INFO - PID 6392 | 1647603489322	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-18T11:38:09.430Z] 11:38:09     INFO - PID 6392 | 1647603489430	geckodriver::browser	TRACE	Failed to open C:\Users\task_164759494536844\AppData\Local\Temp\tmpev94s4hn.mozrunner\MarionetteActivePort
[task 2022-03-18T11:38:09.432Z] 11:38:09     INFO - PID 6392 | 1647603489430	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-18T11:38:09.541Z] 11:38:09     INFO - PID 6392 | 1647603489542	geckodriver::browser	TRACE	Failed to open C:\Users\task_164759494536844\AppData\Local\Temp\tmpev94s4hn.mozrunner\MarionetteActivePort
[task 2022-03-18T11:38:09.543Z] 11:38:09     INFO - PID 6392 | 1647603489542	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-18T11:38:09.657Z] 11:38:09     INFO - PID 6392 | 1647603489657	geckodriver::browser	TRACE	Failed to open C:\Users\task_164759494536844\AppData\Local\Temp\tmpev94s4hn.mozrunner\MarionetteActivePort
[task 2022-03-18T11:38:09.658Z] 11:38:09     INFO - PID 6392 | 1647603489657	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-18T11:38:09.773Z] 11:38:09     INFO - PID 6392 | 1647603489773	geckodriver::browser	TRACE	Failed to open C:\Users\task_164759494536844\AppData\Local\Temp\tmpev94s4hn.mozrunner\MarionetteActivePort
[task 2022-03-18T11:38:09.774Z] 11:38:09     INFO - PID 6392 | 1647603489773	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-18T11:38:09.889Z] 11:38:09     INFO - PID 6392 | 1647603489889	geckodriver::browser	TRACE	Failed to open C:\Users\task_164759494536844\AppData\Local\Temp\tmpev94s4hn.mozrunner\MarionetteActivePort
[task 2022-03-18T11:38:09.890Z] 11:38:09     INFO - PID 6392 | 1647603489889	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-18T11:38:10.004Z] 11:38:10     INFO - PID 6392 | 1647603490005	geckodriver::browser	TRACE	Failed to open C:\Users\task_164759494536844\AppData\Local\Temp\tmpev94s4hn.mozrunner\MarionetteActivePort
[task 2022-03-18T11:38:10.006Z] 11:38:10     INFO - PID 6392 | 1647603490005	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-18T11:38:10.120Z] 11:38:10     INFO - PID 6392 | 1647603490120	geckodriver::browser	TRACE	Failed to open C:\Users\task_164759494536844\AppData\Local\Temp\tmpev94s4hn.mozrunner\MarionetteActivePort
[task 2022-03-18T11:38:10.122Z] 11:38:10     INFO - PID 6392 | 1647603490120	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-18T11:38:10.242Z] 11:38:10     INFO - PID 6392 | 1647603490243	geckodriver::browser	TRACE	Failed to open C:\Users\task_164759494536844\AppData\Local\Temp\tmpev94s4hn.mozrunner\MarionetteActivePort
[task 2022-03-18T11:38:10.244Z] 11:38:10     INFO - PID 6392 | 1647603490243	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-18T11:38:10.358Z] 11:38:10     INFO - PID 6392 | 1647603490358	geckodriver::browser	TRACE	Failed to open C:\Users\task_164759494536844\AppData\Local\Temp\tmpev94s4hn.mozrunner\MarionetteActivePort
[task 2022-03-18T11:38:10.359Z] 11:38:10     INFO - PID 6392 | 1647603490358	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-18T11:38:10.403Z] 11:38:10     INFO - PID 6392 | 1647603490402	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2022-03-18T11:38:10.403Z] 11:38:10     INFO - PID 6392 | 1647603490402	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2022-03-18T11:38:10.416Z] 11:38:10     INFO - PID 6392 | 1647603490416	Marionette	TRACE	All scripts recorded.
[task 2022-03-18T11:38:10.417Z] 11:38:10     INFO - PID 6392 | 1647603490417	Marionette	INFO	Listening on port 50674
[task 2022-03-18T11:38:10.418Z] 11:38:10     INFO - PID 6392 | 1647603490417	Marionette	DEBUG	Marionette is listening
[task 2022-03-18T11:38:10.461Z] 11:38:10     INFO - PID 6392 | Read port: 50674
[task 2022-03-18T11:38:10.466Z] 11:38:10     INFO - PID 6392 | 1647603490465	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:50677
[task 2022-03-18T11:38:10.467Z] 11:38:10     INFO - PID 6392 | 1647603490466	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:50674.
[task 2022-03-18T11:38:10.469Z] 11:38:10     INFO - PID 6392 | 1647603490468	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{}]
[task 2022-03-18T11:38:10.473Z] 11:38:10     INFO - PID 6392 | 1647603490473	RemoteAgent	TRACE	[30] Document already finished loading: about:blank
[task 2022-03-18T11:38:10.477Z] 11:38:10     INFO - PID 6392 | 1647603490476	Marionette	DEBUG	0 <- [1,1,null,{"sessionId":"a1a26255-2356-434d-b97d-a59c72ffd7b4","capabilities":{"browserName":"firefox","browserVersion":"100.0 ... n.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2022-03-18T11:38:10.481Z] 11:38:10     INFO - PID 6392 | 1647603490479	webdriver::server	DEBUG	<- 200 OK {"value":{"sessionId":"a1a26255-2356-434d-b97d-a59c72ffd7b4","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"100.0a1","moz:accessibilityChecks":false,"moz:buildID":"20220318094822","moz:geckodriverVersion":"0.30.0","moz:headless":false,"moz:processID":2556,"moz:profile":"C:\\Users\\task_164759494536844\\AppData\\Local\\Temp\\tmpev94s4hn.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"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-03-18T11:38:10.482Z] 11:38:10     INFO - PID 6392 | 1647603490480	webdriver::server	DEBUG	-> POST /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/window/rect {"width": 800, "height": 600}
[task 2022-03-18T11:38:10.483Z] 11:38:10     INFO - PID 6392 | 1647603490482	Marionette	DEBUG	0 -> [0,2,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2022-03-18T11:38:10.483Z] 11:38:10     INFO - PID 6392 | 1647603490483	Marionette	DEBUG	0 <- [1,2,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-03-18T11:38:10.484Z] 11:38:10     INFO - PID 6392 | 1647603490483	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-03-18T11:38:10.485Z] 11:38:10     INFO - PID 6392 | 1647603490484	webdriver::server	DEBUG	-> POST /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/window/rect {"x": 100, "y": 100}
[task 2022-03-18T11:38:10.485Z] 11:38:10     INFO - PID 6392 | 1647603490485	Marionette	DEBUG	0 -> [0,3,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2022-03-18T11:38:10.486Z] 11:38:10     INFO - PID 6392 | 1647603490485	Marionette	DEBUG	0 <- [1,3,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-03-18T11:38:10.487Z] 11:38:10     INFO - PID 6392 | 1647603490485	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-03-18T11:38:10.487Z] 11:38:10     INFO - PID 6392 | 1647603490487	webdriver::server	DEBUG	-> GET /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/window
[task 2022-03-18T11:38:10.488Z] 11:38:10     INFO - PID 6392 | 1647603490487	Marionette	DEBUG	0 -> [0,4,"WebDriver:GetWindowHandle",{}]
[task 2022-03-18T11:38:10.489Z] 11:38:10     INFO - PID 6392 | 1647603490487	Marionette	DEBUG	0 <- [1,4,null,{"value":"3bd33e8b-ebb4-4f66-856a-840c010a1daf"}]
[task 2022-03-18T11:38:10.489Z] 11:38:10     INFO - PID 6392 | 1647603490488	webdriver::server	DEBUG	<- 200 OK {"value":"3bd33e8b-ebb4-4f66-856a-840c010a1daf"}
[task 2022-03-18T11:38:10.490Z] 11:38:10     INFO - PID 6392 | 1647603490489	webdriver::server	DEBUG	-> POST /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/window/new {"type": "tab"}
[task 2022-03-18T11:38:10.491Z] 11:38:10     INFO - PID 6392 | 1647603490489	Marionette	DEBUG	0 -> [0,5,"WebDriver:NewWindow",{"type":"tab"}]
[task 2022-03-18T11:38:10.495Z] 11:38:10     INFO - PID 6392 | 1647603490495	Marionette	TRACE	Received DOM event TabOpen for [object XULElement]
[task 2022-03-18T11:38:10.509Z] 11:38:10     INFO - PID 6392 | 1647603490516	RemoteAgent	TRACE	[39] ProgressListener state=start: about:newtab
[task 2022-03-18T11:38:10.528Z] 11:38:10     INFO - PID 6392 | 1647603490527	RemoteAgent	TRACE	[39] ProgressListener state=stop: about:blank
[task 2022-03-18T11:38:10.528Z] 11:38:10     INFO - PID 6392 | 1647603490528	Marionette	DEBUG	0 <- [1,5,null,{"handle":"d4a4b462-5b33-4ab5-8458-04e43fcd6a09","type":"tab"}]
[task 2022-03-18T11:38:10.529Z] 11:38:10     INFO - PID 6392 | 1647603490528	webdriver::server	DEBUG	<- 200 OK {"value":{"handle":"d4a4b462-5b33-4ab5-8458-04e43fcd6a09","type":"tab"}}
[task 2022-03-18T11:38:10.530Z] 11:38:10     INFO - PID 6392 | 1647603490529	webdriver::server	DEBUG	-> POST /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/window {"handle": "d4a4b462-5b33-4ab5-8458-04e43fcd6a09"}
[task 2022-03-18T11:38:10.530Z] 11:38:10     INFO - PID 6392 | 1647603490530	Marionette	DEBUG	0 -> [0,6,"WebDriver:SwitchToWindow",{"handle":"d4a4b462-5b33-4ab5-8458-04e43fcd6a09"}]
[task 2022-03-18T11:38:10.534Z] 11:38:10     INFO - PID 6392 | 1647603490534	Marionette	TRACE	Received DOM event TabSelect for [object XULElement]
[task 2022-03-18T11:38:10.537Z] 11:38:10     INFO - PID 6392 | 1647603490537	Marionette	DEBUG	0 <- [1,6,null,{"value":null}]
[task 2022-03-18T11:38:10.538Z] 11:38:10     INFO - PID 6392 | 1647603490538	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-18T11:38:10.540Z] 11:38:10     INFO - PID 6392 | 1647603490539	webdriver::server	DEBUG	-> POST /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/url {"url": "http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cinput+id%3D%27a%27+value%3D%27b%27%3E&mime=text%2Fhtml&charset=UTF-8"}
[task 2022-03-18T11:38:10.541Z] 11:38:10     INFO - PID 6392 | 1647603490539	Marionette	DEBUG	0 -> [0,7,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cinput+id%3D%27a%27+value%3D%27b%27%3E&mime=text%2Fhtml&charset=UTF-8"}]
[task 2022-03-18T11:38:10.543Z] 11:38:10     INFO - PID 6392 | 1647603490543	Marionette	TRACE	[39] Received event beforeunload for about:blank
[task 2022-03-18T11:38:10.551Z] 11:38:10     INFO - PID 6392 | 1647603490550	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 41
[task 2022-03-18T11:38:10.559Z] 11:38:10     INFO - PID 6392 | 1647603490559	Marionette	TRACE	[41] Received event beforeunload for about:blank
[task 2022-03-18T11:38:10.562Z] 11:38:10     INFO - PID 6392 | 1647603490562	Marionette	TRACE	[41] Received event pagehide for about:blank
[task 2022-03-18T11:38:10.574Z] 11:38:10     INFO - PID 6392 | 1647603490574	Marionette	TRACE	[41] Received event DOMContentLoaded for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cinput+id%3D%27a%27+value%3D%27b%27%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-03-18T11:38:10.575Z] 11:38:10     INFO - PID 6392 | 1647603490575	Marionette	TRACE	[41] Received event pageshow for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cinput+id%3D%27a%27+value%3D%27b%27%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-03-18T11:38:10.579Z] 11:38:10     INFO - PID 6392 | 1647603490579	Marionette	DEBUG	0 <- [1,7,null,{"value":null}]
[task 2022-03-18T11:38:10.582Z] 11:38:10     INFO - PID 6392 | 1647603490582	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-18T11:38:10.583Z] 11:38:10     INFO - PID 6392 | 1647603490583	webdriver::server	DEBUG	-> POST /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/element {"using": "css selector", "value": "input"}
[task 2022-03-18T11:38:10.584Z] 11:38:10     INFO - PID 6392 | 1647603490584	Marionette	DEBUG	0 -> [0,8,"WebDriver:FindElement",{"using":"css selector","value":"input"}]
[task 2022-03-18T11:38:10.587Z] 11:38:10     INFO - PID 6392 | 1647603490587	Marionette	TRACE	[41] MarionetteCommands actor created for window id 8589934593
[task 2022-03-18T11:38:10.594Z] 11:38:10     INFO - PID 6392 | 1647603490594	Marionette	DEBUG	0 <- [1,8,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"362e0364-e41f-4250-b83b-a218f80a3668"}}]
[task 2022-03-18T11:38:10.594Z] 11:38:10     INFO - PID 6392 | 1647603490594	webdriver::server	DEBUG	<- 200 OK {"value":{"element-6066-11e4-a52e-4f735466cecf":"362e0364-e41f-4250-b83b-a218f80a3668"}}
[task 2022-03-18T11:38:10.595Z] 11:38:10     INFO - PID 6392 | 1647603490595	webdriver::server	DEBUG	-> DELETE /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/window
[task 2022-03-18T11:38:10.596Z] 11:38:10     INFO - PID 6392 | 1647603490595	Marionette	DEBUG	0 -> [0,9,"WebDriver:CloseWindow",{}]
[task 2022-03-18T11:38:10.599Z] 11:38:10     INFO - PID 6392 | 1647603490599	Marionette	TRACE	Received DOM event TabClose for [object XULElement]
[task 2022-03-18T11:38:10.606Z] 11:38:10     INFO - PID 6392 | 1647603490605	Marionette	TRACE	Received observer notification message-manager-disconnect
[task 2022-03-18T11:38:10.606Z] 11:38:10     INFO - PID 6392 | 1647603490606	Marionette	TRACE	Received observer notification message-manager-disconnect
[task 2022-03-18T11:38:10.607Z] 11:38:10     INFO - PID 6392 | 1647603490606	Marionette	DEBUG	0 <- [1,9,null,["3bd33e8b-ebb4-4f66-856a-840c010a1daf"]]
[task 2022-03-18T11:38:10.608Z] 11:38:10     INFO - PID 6392 | 1647603490607	webdriver::server	DEBUG	<- 200 OK {"value":["3bd33e8b-ebb4-4f66-856a-840c010a1daf"]}
[task 2022-03-18T11:38:10.608Z] 11:38:10     INFO - PID 6392 | 1647603490608	webdriver::server	DEBUG	-> GET /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/window/handles
[task 2022-03-18T11:38:10.610Z] 11:38:10     INFO - PID 6392 | 1647603490610	Marionette	DEBUG	0 -> [0,10,"WebDriver:GetWindowHandles",{}]
[task 2022-03-18T11:38:10.611Z] 11:38:10     INFO - PID 6392 | 1647603490610	Marionette	DEBUG	0 <- [1,10,null,["3bd33e8b-ebb4-4f66-856a-840c010a1daf"]]
[task 2022-03-18T11:38:10.611Z] 11:38:10     INFO - PID 6392 | 1647603490610	webdriver::server	DEBUG	<- 200 OK {"value":["3bd33e8b-ebb4-4f66-856a-840c010a1daf"]}
[task 2022-03-18T11:38:10.612Z] 11:38:10     INFO - PID 6392 | 1647603490612	webdriver::server	DEBUG	-> GET /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/screenshot
[task 2022-03-18T11:38:10.612Z] 11:38:10     INFO - PID 6392 | 1647603490612	Marionette	DEBUG	0 -> [0,11,"WebDriver:TakeScreenshot",{"full":false,"highlights":[],"id":null}]
[task 2022-03-18T11:38:10.614Z] 11:38:10     INFO - PID 6392 | 1647603490613	Marionette	DEBUG	0 <- [1,11,{"error":"no such window","message":"Browsing context has been discarded","stacktrace":"WebDriverError@chrome://remote/ ... ote/content/marionette/server.js:253:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:500:20\n"},null]
[task 2022-03-18T11:38:10.615Z] 11:38:10     INFO - STDOUT: PASSED
[task 2022-03-18T11:38:10.616Z] 11:38:10     INFO - PID 6392 | 1647603490613	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such window","message":"Browsing context has been discarded","stacktrace":"WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm:183:5\nNoSuchWindowError@chrome://remote/content/shared/webdriver/Errors.jsm:437:5\nassert.that/<@chrome://remote/content/shared/webdriver/Assert.jsm:435:13\nassert.open@chrome://remote/content/shared/webdriver/Assert.jsm:143:4\nGeckoDriver.prototype.takeScreenshot@chrome://remote/content/marionette/driver.js:2180:10\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-03-18T11:38:10.617Z] 11:38:10     INFO - PID 6392 | 1647603490615	webdriver::server	DEBUG	-> POST /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/window {"handle": "3bd33e8b-ebb4-4f66-856a-840c010a1daf"}
[task 2022-03-18T11:38:10.618Z] 11:38:10     INFO - PID 6392 | 1647603490615	Marionette	DEBUG	0 -> [0,12,"WebDriver:SwitchToWindow",{"handle":"3bd33e8b-ebb4-4f66-856a-840c010a1daf"}]
[task 2022-03-18T11:38:10.619Z] 11:38:10     INFO - PID 6392 | 1647603490616	Marionette	DEBUG	0 <- [1,12,null,{"value":null}]
[task 2022-03-18T11:38:10.620Z] 11:38:10     INFO - PID 6392 | 1647603490616	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-18T11:38:10.620Z] 11:38:10     INFO - PID 6392 | 1647603490617	webdriver::server	DEBUG	-> POST /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/timeouts {"implicit": 0}
[task 2022-03-18T11:38:10.621Z] 11:38:10     INFO - PID 6392 | 1647603490618	Marionette	DEBUG	0 -> [0,13,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-03-18T11:38:10.621Z] 11:38:10     INFO - PID 6392 | 1647603490618	Marionette	DEBUG	0 <- [1,13,null,{"value":null}]
[task 2022-03-18T11:38:10.622Z] 11:38:10     INFO - PID 6392 | 1647603490618	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-18T11:38:10.622Z] 11:38:10     INFO - PID 6392 | 1647603490619	webdriver::server	DEBUG	-> POST /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/timeouts {"pageLoad": 300000}
[task 2022-03-18T11:38:10.623Z] 11:38:10     INFO - PID 6392 | 1647603490620	Marionette	DEBUG	0 -> [0,14,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-03-18T11:38:10.624Z] 11:38:10     INFO - PID 6392 | 1647603490620	Marionette	DEBUG	0 <- [1,14,null,{"value":null}]
[task 2022-03-18T11:38:10.624Z] 11:38:10     INFO - PID 6392 | 1647603490620	webdriver::server	DEBUG	<- 200 OK {"value":null}
<...>
[task 2022-03-18T11:38:38.254Z] 11:38:38     INFO - PID 6392 | 1647603518224	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-03-18T11:38:38.255Z] 11:38:38     INFO - PID 6392 | 1647603518224	webdriver::server	DEBUG	-> POST /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/frame {"id": null}
[task 2022-03-18T11:38:38.255Z] 11:38:38     INFO - PID 6392 | 1647603518225	Marionette	DEBUG	0 -> [0,77,"WebDriver:SwitchToFrame",{"id":null}]
[task 2022-03-18T11:38:38.255Z] 11:38:38     INFO - PID 6392 | 1647603518225	Marionette	DEBUG	0 <- [1,77,null,{"value":null}]
[task 2022-03-18T11:38:38.256Z] 11:38:38     INFO - PID 6392 | 1647603518226	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-18T11:38:38.256Z] 11:38:38     INFO - PID 6392 | 1647603518227	webdriver::server	DEBUG	-> DELETE /session/a1a26255-2356-434d-b97d-a59c72ffd7b4
[task 2022-03-18T11:38:38.257Z] 11:38:38     INFO - PID 6392 | 1647603518227	Marionette	DEBUG	0 -> [0,78,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-03-18T11:38:38.257Z] 11:38:38     INFO - PID 6392 | 1647603518228	Marionette	INFO	Stopped listening on port 50674
[task 2022-03-18T11:38:38.266Z] 11:38:38     INFO - PID 6392 | 1647603518266	Marionette	TRACE	Received observer notification quit-application
[task 2022-03-18T11:38:38.267Z] 11:38:38     INFO - PID 6392 | 1647603518266	Marionette	TRACE	Received observer notification quit-application
[task 2022-03-18T11:38:38.268Z] 11:38:38     INFO - PID 6392 | 1647603518266	Marionette	DEBUG	Marionette stopped listening
[task 2022-03-18T11:38:38.268Z] 11:38:38     INFO - PID 6392 | 1647603518268	Marionette	DEBUG	0 <- [1,78,null,{"cause":"shutdown","forced":false}]
[task 2022-03-18T11:38:38.282Z] 11:38:38     INFO - PID 6392 | 1647603518282	webdriver::server	DEBUG	Teardown session
[task 2022-03-18T11:38:38.285Z] 11:38:38     INFO - PID 6392 | 1647603518284	Marionette	DEBUG	Closed connection 0
[task 2022-03-18T11:38:38.890Z] 11:38:38     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/take_screenshot/screenshot.py | expected OK
[task 2022-03-18T11:38:38.890Z] 11:38:38     INFO - TEST-INFO took 30015ms
[task 2022-03-18T11:38:45.063Z] 11:38:45     INFO - Closing logging queue
[task 2022-03-18T11:38:45.071Z] 11:38:45     INFO - queue closed
[task 2022-03-18T11:38:45.577Z] 11:38:45     INFO - PID 7080 | 1647603525082	geckodriver	INFO	Listening on 127.0.0.1:49860
[task 2022-03-18T11:38:45.579Z] 11:38:45     INFO - Starting runner
[task 2022-03-18T11:38:46.170Z] 11:38:46     INFO - TEST-START | /webdriver/tests/take_screenshot/user_prompts.py

Comment hidden (Intermittent Failures Robot)

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

Comment 2

•

3 years ago

There is a visible long delay when loading a page as served by wptserve:

[task 2022-03-18T11:38:10.690Z] 11:38:10     INFO - PID 6392 | 1647603490690	webdriver::server	DEBUG	-> POST /session/a1a26255-2356-434d-b97d-a59c72ffd7b4/url {"url": "http://web-platform.test:8000/webdriver/tests/support/html/frames.html"}
[task 2022-03-18T11:38:10.691Z] 11:38:10     INFO - PID 6392 | 1647603490690	Marionette	DEBUG	0 -> [0,32,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/webdriver/tests/support/html/frames.html"}]
[task 2022-03-18T11:38:10.692Z] 11:38:10     INFO - PID 6392 | 1647603490692	Marionette	TRACE	[43] Received event beforeunload for about:blank
[task 2022-03-18T11:38:37.920Z] 11:38:37     INFO - PID 6392 | 1647603517924	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 45
[task 2022-03-18T11:38:37.935Z] 11:38:37     INFO - PID 6392 | 1647603517934	Marionette	TRACE	[45] Received event beforeunload for about:blank
[task 2022-03-18T11:38:37.939Z] 11:38:37     INFO - PID 6392 | 1647603517938	Marionette	TRACE	[45] Received event pagehide for about:blank
[task 2022-03-18T11:38:37.952Z] 11:38:37     INFO - PID 6392 | 1647603517953	Marionette	TRACE	[45] Received event DOMContentLoaded for http://web-platform.test:8000/webdriver/tests/support/html/frames.html
[task 2022-03-18T11:38:37.987Z] 11:38:37     INFO - PID 6392 | 1647603517992	Marionette	TRACE	[45] Received event pageshow for http://web-platform.test:8000/webdriver/tests/support/html/frames.html
[task 2022-03-18T11:38:37.996Z] 11:38:37     INFO - PID 6392 | 1647603517995	Marionette	DEBUG	0 <- [1,32,null,{"value":null}]

We could at least circumvent the test timeout by having a shorter timeout for navigations. See the request via bug 1760554.

Depends on: 1760554

BugBot [:suhaib / :marco/ :calixte]

Comment 3

•

3 years ago

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

Status: NEW → RESOLVED

Closed: 3 years ago

Resolution: --- → INCOMPLETE

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

Updated

•

2 years ago

Status: RESOLVED → REOPENED

Resolution: INCOMPLETE → ---

Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/take_screenshot/screenshot.py | expected OK → Intermittent TEST-UNEXPECTED-TIMEOUT | Wd | expected OK (hang in WebDriver:Navigate)

Comment hidden (Intermittent Failures Robot)

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

Updated

•

2 years ago

Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | Wd | expected OK (hang in WebDriver:Navigate) → Intermittent TEST-UNEXPECTED-TIMEOUT | Wd | expected OK (hang in WebDriver:Navigate when loading page via wptserve)

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

Updated

•

2 years ago

Blocks: 1774392

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

Updated

•

2 years ago

Blocks: 1775141

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

Updated

•

2 years ago

No longer blocks: 1775141

Comment hidden (Intermittent Failures Robot)

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

Comment 14

•

2 years ago

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

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

Repository breakdown:

mozilla-central: 3

Platform and build breakdown:

windows10-64-2004-ccov-qr: 3

opt: 3

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

All of these failures are related to bug 1783217. Can we please re-classify? Thanks.

Flags: needinfo?(sheriffs)

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

Updated

•

2 years ago

Flags: needinfo?(sheriffs)

Comment hidden (Intermittent Failures Robot)

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

Updated

•

2 years ago

Blocks: 1794076

Comment hidden (Intermittent Failures Robot)

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

Updated

•

2 years ago

See Also: → https://bugzilla.mozilla.org/show_bug.cgi?id=1801373

Comment hidden (Intermittent Failures Robot)

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

Updated

•

2 years ago

Duplicate of this bug: 1812418

Comment hidden (Intermittent Failures Robot)

BMO Automation

Comment 20

•

2 years ago

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

Component: geckodriver → Marionette

Product: Testing → Remote Protocol

Comment hidden (Intermittent Failures Robot)

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

Updated

•

2 years ago

Blocks: 1825858

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

Updated

•

2 years ago

No longer blocks: 1825858

Duplicate of this bug: 1825858

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

Updated

•

2 years ago

Depends on: 1826048

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

Updated

•

2 years ago

Depends on: 1664165

Comment hidden (Intermittent Failures Robot)

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

Updated

•

1 years ago

See Also: → https://bugzilla.mozilla.org/show_bug.cgi?id=1832294

Comment hidden (Intermittent Failures Robot)

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

Comment 29

•

1 years ago

Most of the failures from the last weeks are actually related to bug 1825501. I've corrected the classifications.

Comment hidden (Intermittent Failures Robot)

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

Updated

•

1 year ago

Duplicate of this bug: 1836006

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

Updated

•

1 year ago

Duplicate of this bug: 1832167

Comment hidden (Intermittent Failures Robot)

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

Comment 34

•

1 year ago

There might be a problem when we start a new navigation while a former navigation (e.g. the initial one for about:blank) hasn't been completed yet and we see an overlap of requests. Fixing bug 1837949 might help for this situation.

Depends on: 1837949

Comment hidden (Intermittent Failures Robot)

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

Updated

•

1 year ago

See Also: → https://bugzilla.mozilla.org/show_bug.cgi?id=1840470

Comment hidden (Intermittent Failures Robot)

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

Comment 38

•

1 year ago

Given that WebDriver Bidi has the same problem and is using the WebProgressListener bug 1664165 isn't actually a blocker.

No longer depends on: 1664165

Comment hidden (Intermittent Failures Robot)