1774392 - Intermittent Wd | <random> - asyncio.exceptions.CancelledError

Status: REOPENED

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-06-15T10:54:14.960Z] 10:54:14     INFO - STDOUT: PASSED
[task 2022-06-15T10:54:14.960Z] 10:54:14     INFO - PID 6980 | 1655290454959	webdriver::server	DEBUG	-> POST /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/window {"handle": "64f2fd5b-da15-448d-a7c5-53433e5c6a47"}
[task 2022-06-15T10:54:14.961Z] 10:54:14     INFO - PID 6980 | 1655290454959	Marionette	DEBUG	0 -> [0,227,"WebDriver:SwitchToWindow",{"handle":"64f2fd5b-da15-448d-a7c5-53433e5c6a47"}]
[task 2022-06-15T10:54:14.964Z] 10:54:14     INFO - PID 6980 | 1655290454963	RemoteAgent	TRACE	Received DOM event TabSelect for [object XULElement]
[task 2022-06-15T10:54:14.969Z] 10:54:14     INFO - PID 6980 | 1655290454969	Marionette	DEBUG	0 <- [1,227,null,{"value":null}]
[task 2022-06-15T10:54:14.970Z] 10:54:14     INFO - PID 6980 | 1655290454970	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-15T10:54:14.972Z] 10:54:14     INFO - PID 6980 | 1655290454971	WebDriver BiDi	DEBUG	f4348031-ea44-46bb-9f67-5fcd6a0cbf9c -> {"id":41,"method":"browsingContext.close","params":{"context":"30f1dd43-274d-47b7-bb79-2e3da132b68a"}}
[task 2022-06-15T10:54:14.972Z] 10:54:14     INFO - PID 6980 | 1655290454971	RemoteAgent	TRACE	Received command browsingContext.close for destination ROOT
[task 2022-06-15T10:54:14.974Z] 10:54:14     INFO - PID 6980 | 1655290454973	RemoteAgent	TRACE	[61] ProgressListener state=stop: error=0x80004004 (NS_ERROR_ABORT)
[task 2022-06-15T10:54:14.974Z] 10:54:14     INFO - PID 6980 | 1655290454974	WebDriver BiDi	DEBUG	f4348031-ea44-46bb-9f67-5fcd6a0cbf9c <- {"id":41,"result":{}}
[task 2022-06-15T10:54:14.975Z] 10:54:14     INFO - PID 6980 | 1655290454974	WebDriver BiDi	DEBUG	f4348031-ea44-46bb-9f67-5fcd6a0cbf9c <- {"id":39,"error":"unknown error","message":"Error: NS_ERROR_ABORT","stacktrace":"#checkLoadingState@chrome://remote/content/s ... mote/content/server/WebSocketTransport.jsm:91:18\nhandleEvent@chrome://remote/content/server/WebSocketTransport.jsm:73:14\n"}
[task 2022-06-15T10:54:14.976Z] 10:54:14     INFO - PID 6980 | 1655290454974	RemoteAgent	TRACE	MessageHandler WINDOW_GLOBAL for session f4348031-ea44-46bb-9f67-5fcd6a0cbf9c is being destroyed
[task 2022-06-15T10:54:14.977Z] 10:54:14     INFO - PID 6980 | 1655290454974	RemoteAgent	TRACE	Unregistered MessageHandler WINDOW_GLOBAL for session f4348031-ea44-46bb-9f67-5fcd6a0cbf9c
[task 2022-06-15T10:54:14.977Z] 10:54:14     INFO - PID 6980 | JavaScript error: chrome://remote/content/shared/Navigate.jsm, line 216: Error: NS_ERROR_ABORT
[task 2022-06-15T10:54:14.978Z] 10:54:14     INFO - PID 6980 | 1655290454976	RemoteAgent	DEBUG	WebDriverBiDiConnection 9fd9d228-9dc0-43d9-9efb-88193736c943 closed
[task 2022-06-15T10:54:14.979Z] 10:54:14     INFO - PID 6980 | 1655290454977	webdriver::server	DEBUG	-> POST /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/timeouts {"implicit": 0}
[task 2022-06-15T10:54:14.980Z] 10:54:14     INFO - PID 6980 | 1655290454978	Marionette	DEBUG	0 -> [0,228,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-06-15T10:54:14.980Z] 10:54:14     INFO - PID 6980 | 1655290454978	Marionette	DEBUG	0 <- [1,228,null,{"value":null}]
[task 2022-06-15T10:54:14.981Z] 10:54:14     INFO - PID 6980 | 1655290454978	RemoteAgent	TRACE	MessageHandler WINDOW_GLOBAL for session f4348031-ea44-46bb-9f67-5fcd6a0cbf9c is being destroyed
[task 2022-06-15T10:54:14.982Z] 10:54:14     INFO - PID 6980 | 1655290454978	RemoteAgent	TRACE	Unregistered MessageHandler WINDOW_GLOBAL for session f4348031-ea44-46bb-9f67-5fcd6a0cbf9c
[task 2022-06-15T10:54:14.982Z] 10:54:14     INFO - PID 6980 | 1655290454978	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-15T10:54:14.983Z] 10:54:14     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206da761e00 | BlockShutdown: ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1806
[task 2022-06-15T10:54:14.984Z] 10:54:14     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206da761e00 | BlockShutdown: ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1840
[task 2022-06-15T10:54:14.985Z] 10:54:14     INFO - PID 6980 | 1655290454979	webdriver::server	DEBUG	-> POST /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/timeouts {"pageLoad": 300000}
[task 2022-06-15T10:54:14.985Z] 10:54:14     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206da761e00 | BlockShutdown: ShutDownProcess: Close already called.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1847
[task 2022-06-15T10:54:14.986Z] 10:54:14     INFO - PID 6980 | 1655290454980	Marionette	DEBUG	0 -> [0,229,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-06-15T10:54:14.986Z] 10:54:14     INFO - PID 6980 | 1655290454980	Marionette	DEBUG	0 <- [1,229,null,{"value":null}]
[task 2022-06-15T10:54:14.987Z] 10:54:14     INFO - PID 6980 | 1655290454980	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-15T10:54:14.988Z] 10:54:14     INFO - PID 6980 | 1655290454981	webdriver::server	DEBUG	-> POST /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/timeouts {"script": 30000}
[task 2022-06-15T10:54:14.989Z] 10:54:14     INFO - PID 6980 | 1655290454981	Marionette	DEBUG	0 -> [0,230,"WebDriver:SetTimeouts",{"script":30000}]
[task 2022-06-15T10:54:14.990Z] 10:54:14     INFO - PID 6980 | 1655290454982	Marionette	DEBUG	0 <- [1,230,null,{"value":null}]
[task 2022-06-15T10:54:14.990Z] 10:54:14     INFO - PID 6980 | 1655290454982	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-15T10:54:14.991Z] 10:54:14     INFO - PID 6980 | 1655290454982	webdriver::server	DEBUG	-> GET /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/window
[task 2022-06-15T10:54:14.992Z] 10:54:14     INFO - PID 6980 | 1655290454983	Marionette	DEBUG	0 -> [0,231,"WebDriver:GetWindowHandle",{}]
[task 2022-06-15T10:54:14.993Z] 10:54:14     INFO - PID 6980 | 1655290454983	Marionette	DEBUG	0 <- [1,231,null,{"value":"64f2fd5b-da15-448d-a7c5-53433e5c6a47"}]
[task 2022-06-15T10:54:14.993Z] 10:54:14     INFO - PID 6980 | 1655290454983	webdriver::server	DEBUG	<- 200 OK {"value":"64f2fd5b-da15-448d-a7c5-53433e5c6a47"}
[task 2022-06-15T10:54:14.994Z] 10:54:14     INFO - PID 6980 | 1655290454984	webdriver::server	DEBUG	-> GET /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/window
[task 2022-06-15T10:54:14.995Z] 10:54:14     INFO - PID 6980 | 1655290454984	Marionette	DEBUG	0 -> [0,232,"WebDriver:GetWindowHandle",{}]
[task 2022-06-15T10:54:14.995Z] 10:54:14     INFO - PID 6980 | 1655290454984	Marionette	DEBUG	0 <- [1,232,null,{"value":"64f2fd5b-da15-448d-a7c5-53433e5c6a47"}]
[task 2022-06-15T10:54:14.996Z] 10:54:14     INFO - PID 6980 | 1655290454984	webdriver::server	DEBUG	<- 200 OK {"value":"64f2fd5b-da15-448d-a7c5-53433e5c6a47"}
[task 2022-06-15T10:54:14.996Z] 10:54:14     INFO - PID 6980 | 1655290454985	webdriver::server	DEBUG	-> GET /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/window/handles
[task 2022-06-15T10:54:14.997Z] 10:54:14     INFO - PID 6980 | 1655290454985	Marionette	DEBUG	0 -> [0,233,"WebDriver:GetWindowHandles",{}]
[task 2022-06-15T10:54:14.998Z] 10:54:14     INFO - PID 6980 | 1655290454986	Marionette	DEBUG	0 <- [1,233,null,["64f2fd5b-da15-448d-a7c5-53433e5c6a47"]]
[task 2022-06-15T10:54:14.998Z] 10:54:14     INFO - PID 6980 | 1655290454986	webdriver::server	DEBUG	<- 200 OK {"value":["64f2fd5b-da15-448d-a7c5-53433e5c6a47"]}
[task 2022-06-15T10:54:14.999Z] 10:54:14     INFO - PID 6980 | 1655290454986	webdriver::server	DEBUG	-> POST /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/window {"handle": "64f2fd5b-da15-448d-a7c5-53433e5c6a47"}
[task 2022-06-15T10:54:15.000Z] 10:54:15     INFO - PID 6980 | 1655290454987	Marionette	DEBUG	0 -> [0,234,"WebDriver:SwitchToWindow",{"handle":"64f2fd5b-da15-448d-a7c5-53433e5c6a47"}]
[task 2022-06-15T10:54:15.001Z] 10:54:15     INFO - PID 6980 | 1655290454987	Marionette	DEBUG	0 <- [1,234,null,{"value":null}]
[task 2022-06-15T10:54:15.001Z] 10:54:15     INFO - PID 6980 | 1655290454987	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-15T10:54:15.002Z] 10:54:15     INFO - PID 6980 | 1655290454988	webdriver::server	DEBUG	-> POST /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/alert/dismiss {}
[task 2022-06-15T10:54:15.002Z] 10:54:15     INFO - PID 6980 | 1655290454990	Marionette	DEBUG	0 -> [0,235,"WebDriver:DismissAlert",{}]
[task 2022-06-15T10:54:15.003Z] 10:54:15     INFO - PID 6980 | 1655290454990	Marionette	DEBUG	0 <- [1,235,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm ... ote/content/marionette/server.js:251:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:502:20\n"},null]
[task 2022-06-15T10:54:15.006Z] 10:54:15     INFO - PID 6980 | 1655290454991	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm:188:5\nNoSuchAlertError@chrome://remote/content/shared/webdriver/Errors.jsm:389:5\nGeckoDriver.prototype._checkIfAlertIsPresent@chrome://remote/content/marionette/driver.js:2600:11\nGeckoDriver.prototype.dismissDialog@chrome://remote/content/marionette/driver.js:2511:8\ndespatch@chrome://remote/content/marionette/server.js:304:40\nexecute@chrome://remote/content/marionette/server.js:277:16\nonPacket/<@chrome://remote/content/marionette/server.js:250:20\nonPacket@chrome://remote/content/marionette/server.js:251:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:502:20\n"}}
[task 2022-06-15T10:54:15.006Z] 10:54:15     INFO - PID 6980 | 1655290454992	webdriver::server	DEBUG	-> POST /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/window {"handle": "64f2fd5b-da15-448d-a7c5-53433e5c6a47"}
[task 2022-06-15T10:54:15.007Z] 10:54:15     INFO - PID 6980 | 1655290454992	Marionette	DEBUG	0 -> [0,236,"WebDriver:SwitchToWindow",{"handle":"64f2fd5b-da15-448d-a7c5-53433e5c6a47"}]
[task 2022-06-15T10:54:15.008Z] 10:54:15     INFO - PID 6980 | 1655290454992	Marionette	DEBUG	0 <- [1,236,null,{"value":null}]
[task 2022-06-15T10:54:15.008Z] 10:54:15     INFO - PID 6980 | 1655290454993	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-15T10:54:15.009Z] 10:54:15     INFO - PID 6980 | 1655290454993	webdriver::server	DEBUG	-> GET /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/window
[task 2022-06-15T10:54:15.010Z] 10:54:15     INFO - PID 6980 | 1655290454994	Marionette	DEBUG	0 -> [0,237,"WebDriver:GetWindowHandle",{}]
[task 2022-06-15T10:54:15.011Z] 10:54:15     INFO - PID 6980 | 1655290454994	Marionette	DEBUG	0 <- [1,237,null,{"value":"64f2fd5b-da15-448d-a7c5-53433e5c6a47"}]
[task 2022-06-15T10:54:15.011Z] 10:54:15     INFO - PID 6980 | 1655290454994	webdriver::server	DEBUG	<- 200 OK {"value":"64f2fd5b-da15-448d-a7c5-53433e5c6a47"}
[task 2022-06-15T10:54:15.012Z] 10:54:15     INFO - PID 6980 | 1655290454994	webdriver::server	DEBUG	-> GET /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/window/handles
[task 2022-06-15T10:54:15.013Z] 10:54:15     INFO - PID 6980 | 1655290454995	Marionette	DEBUG	0 -> [0,238,"WebDriver:GetWindowHandles",{}]
[task 2022-06-15T10:54:15.014Z] 10:54:15     INFO - PID 6980 | 1655290454995	Marionette	DEBUG	0 <- [1,238,null,["64f2fd5b-da15-448d-a7c5-53433e5c6a47"]]
[task 2022-06-15T10:54:15.014Z] 10:54:15     INFO - PID 6980 | 1655290454995	webdriver::server	DEBUG	<- 200 OK {"value":["64f2fd5b-da15-448d-a7c5-53433e5c6a47"]}
[task 2022-06-15T10:54:15.015Z] 10:54:15     INFO - PID 6980 | 1655290454996	webdriver::server	DEBUG	-> POST /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/window {"handle": "64f2fd5b-da15-448d-a7c5-53433e5c6a47"}
[task 2022-06-15T10:54:15.016Z] 10:54:15     INFO - PID 6980 | 1655290454996	Marionette	DEBUG	0 -> [0,239,"WebDriver:SwitchToWindow",{"handle":"64f2fd5b-da15-448d-a7c5-53433e5c6a47"}]
[task 2022-06-15T10:54:15.017Z] 10:54:15     INFO - PID 6980 | 1655290454996	Marionette	DEBUG	0 <- [1,239,null,{"value":null}]
[task 2022-06-15T10:54:15.018Z] 10:54:15     INFO - PID 6980 | 1655290454997	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-15T10:54:15.019Z] 10:54:15     INFO - PID 6980 | 1655290454997	webdriver::server	DEBUG	-> POST /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/window/rect {"width": 800, "height": 600}
[task 2022-06-15T10:54:15.021Z] 10:54:15     INFO - PID 6980 | 1655290454998	Marionette	DEBUG	0 -> [0,240,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2022-06-15T10:54:15.022Z] 10:54:15     INFO - PID 6980 | 1655290454998	Marionette	TRACE	Requested window geometry matches
[task 2022-06-15T10:54:15.023Z] 10:54:15     INFO - PID 6980 | 1655290454998	Marionette	DEBUG	0 <- [1,240,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-06-15T10:54:15.024Z] 10:54:15     INFO - PID 6980 | 1655290454998	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-06-15T10:54:15.024Z] 10:54:15     INFO - PID 6980 | 1655290454999	webdriver::server	DEBUG	-> POST /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c/frame {"id": null}
[task 2022-06-15T10:54:15.025Z] 10:54:15     INFO - PID 6980 | 1655290454999	Marionette	DEBUG	0 -> [0,241,"WebDriver:SwitchToFrame",{"id":null}]
[task 2022-06-15T10:54:15.026Z] 10:54:15     INFO - PID 6980 | 1655290455000	Marionette	DEBUG	0 <- [1,241,null,{"value":null}]
[task 2022-06-15T10:54:15.026Z] 10:54:15     INFO - PID 6980 | 1655290455000	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-15T10:54:15.027Z] 10:54:15     INFO - PID 6980 | 1655290455003	webdriver::server	DEBUG	-> DELETE /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c
[task 2022-06-15T10:54:15.027Z] 10:54:15     INFO - PID 6980 | 1655290455003	Marionette	DEBUG	0 -> [0,242,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-06-15T10:54:15.028Z] 10:54:15     INFO - PID 6980 | 1655290455003	Marionette	INFO	Stopped listening on port 52433
[task 2022-06-15T10:54:15.029Z] 10:54:15     INFO - PID 6980 | 1655290455005	WebDriver BiDi	DEBUG	Unregistered session handler: /session/f4348031-ea44-46bb-9f67-5fcd6a0cbf9c
[task 2022-06-15T10:54:15.029Z] 10:54:15     INFO - PID 6980 | 1655290455007	RemoteAgent	TRACE	MessageHandler ROOT for session f4348031-ea44-46bb-9f67-5fcd6a0cbf9c is being destroyed
[task 2022-06-15T10:54:15.030Z] 10:54:15     INFO - PID 6980 | 1655290455007	RemoteAgent	TRACE	Unregistered MessageHandler ROOT for session f4348031-ea44-46bb-9f67-5fcd6a0cbf9c
[task 2022-06-15T10:54:15.040Z] 10:54:15     INFO - PID 6980 | 1655290455040	Marionette	TRACE	Received observer notification quit-application
[task 2022-06-15T10:54:15.042Z] 10:54:15     INFO - PID 6980 | 1655290455041	Marionette	TRACE	Received observer notification quit-application
[task 2022-06-15T10:54:15.042Z] 10:54:15     INFO - PID 6980 | 1655290455041	Marionette	DEBUG	Marionette stopped listening
[task 2022-06-15T10:54:15.043Z] 10:54:15     INFO - PID 6980 | 1655290455041	RemoteAgent	TRACE	Received observer notification quit-application
[task 2022-06-15T10:54:15.044Z] 10:54:15     INFO - PID 6980 | 1655290455042	Marionette	DEBUG	0 <- [1,242,null,{"cause":"shutdown","forced":false}]
[task 2022-06-15T10:54:15.045Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206d8e27700 | BlockShutdown: ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1806
[task 2022-06-15T10:54:15.056Z] 10:54:15     INFO - PID 6980 | 1655290455056	RemoteAgent	DEBUG	Resetting recommended pref browser.contentblocking.features.standard
[task 2022-06-15T10:54:15.057Z] 10:54:15     INFO - PID 6980 | 1655290455056	RemoteAgent	DEBUG	Resetting recommended pref network.cookie.cookieBehavior
[task 2022-06-15T10:54:15.058Z] 10:54:15     INFO - PID 6980 | 1655290455056	webdriver::server	DEBUG	Teardown session
[task 2022-06-15T10:54:15.059Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206d8e27700 | BlockShutdown: ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1840
[task 2022-06-15T10:54:15.060Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206d8e27700 | BlockShutdown: ShutDownProcess: Close already called.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1847
[task 2022-06-15T10:54:15.060Z] 10:54:15     INFO - PID 6980 | 1655290455060	Marionette	DEBUG	Closed connection 0
[task 2022-06-15T10:54:15.061Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206d912c600 | BlockShutdown: ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1806
[task 2022-06-15T10:54:15.062Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206d912c600 | BlockShutdown: ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1840
[task 2022-06-15T10:54:15.063Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206d912c600 | BlockShutdown: ShutDownProcess: Close already called.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1847
[task 2022-06-15T10:54:15.079Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206d72a7100 | BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3600
[task 2022-06-15T10:54:15.080Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206d72a7100 | BlockShutdown: ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1806
[task 2022-06-15T10:54:15.081Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206db18a400 | BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3600
[task 2022-06-15T10:54:15.081Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206db18a400 | BlockShutdown: ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1806
[task 2022-06-15T10:54:15.082Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206db18ae00 | BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3600
[task 2022-06-15T10:54:15.083Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206db18ae00 | BlockShutdown: ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1806
[task 2022-06-15T10:54:15.083Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206db189a00 | BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3600
[task 2022-06-15T10:54:15.084Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206db189a00 | BlockShutdown: ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1806
[task 2022-06-15T10:54:15.091Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206d72a7100 | BlockShutdown: ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1840
[task 2022-06-15T10:54:15.092Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206d72a7100 | BlockShutdown: ShutDownProcess: Close already called.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1847
[task 2022-06-15T10:54:15.093Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206db18a400 | BlockShutdown: ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1840
[task 2022-06-15T10:54:15.094Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206db18a400 | BlockShutdown: ShutDownProcess: Close already called.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1847
[task 2022-06-15T10:54:15.094Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206db18ae00 | BlockShutdown: ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1840
[task 2022-06-15T10:54:15.095Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206db18ae00 | BlockShutdown: ShutDownProcess: Close already called.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1847
[task 2022-06-15T10:54:15.096Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206db189a00 | BlockShutdown: ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1840
[task 2022-06-15T10:54:15.097Z] 10:54:15     INFO - PID 6980 | [Parent 6384, Main Thread] WARNING: ContentParent: id=206db189a00 | BlockShutdown: ShutDownProcess: Close already called.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1847
[task 2022-06-15T10:54:15.256Z] 10:54:15     INFO - PID 6980 | [2022-06-15T10:54:15Z ERROR xulstore::persist] removeDocument error: unavailable
[task 2022-06-15T10:54:15.388Z] 10:54:15     INFO - PID 6980 | 1655290455388	geckodriver::browser	DEBUG	Browser process stopped: exit code: 0
[task 2022-06-15T10:54:15.389Z] 10:54:15     INFO - PID 6980 | 1655290455389	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-15T10:54:15.393Z] 10:54:15     INFO - STDOUT: ================================== FAILURES ===================================
[task 2022-06-15T10:54:15.393Z] 10:54:15     INFO - STDOUT: _____________________ test_slow_image[interactive-False] ______________________
[task 2022-06-15T10:54:15.394Z] 10:54:15     INFO - STDOUT: self = <webdriver.bidi.modules.browsing_context.BrowsingContext object at 0x0000018480836970>
[task 2022-06-15T10:54:15.395Z] 10:54:15     INFO - STDOUT: kwargs = {'context': '15d3dbe7-8c8c-4436-9562-b22bca5f5ea6', 'url': 'http://web-platform.test:8000/webdriver/tests/support/inli...Fnavigate%2Fsupport%2Fempty.svg%3Fpipe%3Dtrickle%28d10%29%27%3E&mime=text%2Fhtml&charset=UTF-8', 'wait': 'interactive'}
[task 2022-06-15T10:54:15.407Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.407Z] 10:54:15     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/wait.py | test_expected_url[none] 
[task 2022-06-15T10:54:15.407Z] 10:54:15     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/wait.py | test_expected_url[interactive] 
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/wait.py | test_expected_url[complete] 
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/wait.py | test_slow_image[none-False] 
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/browsing_context/navigate/wait.py | test_slow_image[interactive-False] - asyncio.exceptions.CancelledError
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO - self = <webdriver.bidi.modules.browsing_context.BrowsingContext object at 0x0000018480836970>
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO - kwargs = {'context': '15d3dbe7-8c8c-4436-9562-b22bca5f5ea6', 'url': 'http://web-platform.test:8000/webdriver/tests/support/inli...Fnavigate%2Fsupport%2Fempty.svg%3Fpipe%3Dtrickle%28d10%29%27%3E&mime=text%2Fhtml&charset=UTF-8', 'wait': 'interactive'}
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO - params = {'context': '15d3dbe7-8c8c-4436-9562-b22bca5f5ea6', 'url': 'http://web-platform.test:8000/webdriver/tests/support/inli...Fnavigate%2Fsupport%2Fempty.svg%3Fpipe%3Dtrickle%28d10%29%27%3E&mime=text%2Fhtml&charset=UTF-8', 'wait': 'interactive'}
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO - mod_name = 'browsingContext', cmd_name = 'browsingContext.navigate'
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO - future = <Future cancelled>
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO -     @functools.wraps(params_fn)
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO -     async def inner(self: Any, **kwargs: Any) -> Any:
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO -         params = params_fn(self, **kwargs)
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO -         # Convert the classname and the method name to a bidi command name
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO -         mod_name = owner.__name__[0].lower() + owner.__name__[1:]
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO -         if hasattr(owner, "prefix"):
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO -             mod_name = f"{owner.prefix}:{mod_name}"
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO -         cmd_name = f"{mod_name}.{to_camelcase(name)}"
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.411Z] 10:54:15     INFO -         future = await self.session.send_command(cmd_name, params)
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - >       result = await future
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - E       asyncio.exceptions.CancelledError
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - cmd_name   = 'browsingContext.navigate'
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - future     = <Future cancelled>
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - kwargs     = {'context': '15d3dbe7-8c8c-4436-9562-b22bca5f5ea6',
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO -  'url': 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cimg+src%3D%27%2Fwebdriver%2Ftests%2Fbidi%2Fbrowsing_context%2Fnavigate%2Fsupport%2Fempty.svg%3Fpipe%3Dtrickle%28d10%29%27%3E&mime=text%2Fhtml&charset=UTF-8',
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO -  'wait': 'interactive'}
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - mod_name   = 'browsingContext'
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - name       = 'navigate'
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - owner      = <class 'webdriver.bidi.modules.browsing_context.BrowsingContext'>
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - params     = {'context': '15d3dbe7-8c8c-4436-9562-b22bca5f5ea6',
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO -  'url': 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cimg+src%3D%27%2Fwebdriver%2Ftests%2Fbidi%2Fbrowsing_context%2Fnavigate%2Fsupport%2Fempty.svg%3Fpipe%3Dtrickle%28d10%29%27%3E&mime=text%2Fhtml&charset=UTF-8',
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO -  'wait': 'interactive'}
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - params_fn  = <function BrowsingContext.navigate at 0x00000184FF879280>
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - result_fn  = <function BrowsingContext._navigate at 0x00000184FF879310>
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - self       = <webdriver.bidi.modules.browsing_context.BrowsingContext object at 0x0000018480836970>
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - tests\web-platform\tests\tools\webdriver\webdriver\bidi\modules\_module.py:62: CancelledError
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - During handling of the above exception, another exception occurred:
[task 2022-06-15T10:54:15.412Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO - fut = <Task cancelled name='Task-1064' coro=<BrowsingContext.navigate() done, defined at Z:\task_165528568133414\build\tests\web-platform\tests\tools\webdriver\webdriver\bidi\modules\_module.py:51>>
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO - timeout = 1
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -     async def wait_for(fut, timeout, *, loop=None):
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -         """Wait for the single Future or coroutine to complete, with timeout.
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -         Coroutine will be wrapped in Task.
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -         Returns result of the Future or coroutine.  When a timeout occurs,
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -         it cancels the task and raises TimeoutError.  To avoid the task
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -         cancellation, wrap it in shield().
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -         If the wait is cancelled, the task is also cancelled.
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -         This function is a coroutine.
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -         """
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -         if loop is None:
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -             loop = events.get_running_loop()
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -         else:
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -             warnings.warn("The loop argument is deprecated since Python 3.8, "
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -                           "and scheduled for removal in Python 3.10.",
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -                           DeprecationWarning, stacklevel=2)
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -         if timeout is None:
[task 2022-06-15T10:54:15.413Z] 10:54:15     INFO -             return await fut
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -         if timeout <= 0:
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -             fut = ensure_future(fut, loop=loop)
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -             if fut.done():
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -                 return fut.result()
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -             await _cancel_and_wait(fut, loop=loop)
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -             try:
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -                 fut.result()
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -             except exceptions.CancelledError as exc:
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -                 raise exceptions.TimeoutError() from exc
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -             else:
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -                 raise exceptions.TimeoutError()
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -         waiter = loop.create_future()
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -         timeout_handle = loop.call_later(timeout, _release_waiter, waiter)
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -         cb = functools.partial(_release_waiter, waiter)
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -         fut = ensure_future(fut, loop=loop)
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -         fut.add_done_callback(cb)
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -         try:
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -             # wait until the future completes or the timeout
[task 2022-06-15T10:54:15.414Z] 10:54:15     INFO -             try:
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                 await waiter
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -             except exceptions.CancelledError:
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                 if fut.done():
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                     return fut.result()
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                 else:
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                     fut.remove_done_callback(cb)
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                     # We must ensure that the task is not running
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                     # after wait_for() returns.
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                     # See https://bugs.python.org/issue32751
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                     await _cancel_and_wait(fut, loop=loop)
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                     raise
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -             if fut.done():
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                 return fut.result()
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -             else:
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                 fut.remove_done_callback(cb)
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                 # We must ensure that the task is not running
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                 # after wait_for() returns.
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                 # See https://bugs.python.org/issue32751
[task 2022-06-15T10:54:15.415Z] 10:54:15     INFO -                 await _cancel_and_wait(fut, loop=loop)
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO -                 # In case task cancellation failed with some
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO -                 # exception, we should re-raise it
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO -                 # See https://bugs.python.org/issue40607
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO -                 try:
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - >                   fut.result()
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - E                   asyncio.exceptions.CancelledError
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - cb         = functools.partial(<function _release_waiter at 0x00000184FF7B5E50>, <Future finished result=None>)
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - fut        = <Task cancelled name='Task-1064' coro=<BrowsingContext.navigate() done, defined at Z:\task_165528568133414\build\tests\web-platform\tests\tools\webdriver\webdriver\bidi\modules\_module.py:51>>
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - loop       = <ProactorEventLoop running=False closed=False debug=False>
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - timeout    = 1
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - timeout_handle = <TimerHandle cancelled when=499.64>
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - waiter     = <Future finished result=None>
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - c:\mozilla-build\python3\lib\asyncio\tasks.py:492: CancelledError
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - The above exception was the direct cause of the following exception:
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x0000018480836490>
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - inline = <function inline.<locals>.inline at 0x00000184FFE21F70>
[task 2022-06-15T10:54:15.416Z] 10:54:15     INFO - new_tab = {'children': None, 'context': '15d3dbe7-8c8c-4436-9562-b22bca5f5ea6', 'parent': None, 'url': 'about:blank'}
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO - wait = 'interactive', expect_timeout = False
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -     @pytest.mark.parametrize(
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -         "wait, expect_timeout",
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -         [
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -             ("none", False),
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -             ("interactive", False),
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -             ("complete", True),
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -         ],
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -     )
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -     async def test_slow_image(bidi_session, inline, new_tab, wait, expect_timeout):
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -         script_url = "/webdriver/tests/bidi/browsing_context/navigate/support/empty.svg"
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -         url = inline(f"<img src='{script_url}?pipe=trickle(d10)'>")
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -         # Ultimately, "interactive" and "complete" should support a timeout argument.
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -         # See https://github.com/w3c/webdriver-bidi/issues/188.
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -         wait_for_navigation = asyncio.wait_for(
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -             bidi_session.browsing_context.navigate(
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -                 context=new_tab["context"], url=url, wait=wait
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -             ),
[task 2022-06-15T10:54:15.417Z] 10:54:15     INFO -             timeout=1,
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO -         )
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO -     
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO -         if expect_timeout:
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO -             with pytest.raises(asyncio.TimeoutError):
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO -                 await wait_for_navigation
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO -         else:
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO - >           await wait_for_navigation
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x0000018480836490>
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO - expect_timeout = False
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO - inline     = <function inline.<locals>.inline at 0x00000184FFE21F70>
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO - new_tab    = {'children': None,
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO -  'context': '15d3dbe7-8c8c-4436-9562-b22bca5f5ea6',
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO -  'parent': None,
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO -  'url': 'about:blank'}
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO - script_url = '/webdriver/tests/bidi/browsing_context/navigate/support/empty.svg'
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO - url        = 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cimg+src%3D%27%2Fwebdriver%2Ftests%2Fbidi%2Fbrowsing_context%2Fnavigate%2Fsupport%2Fempty.svg%3Fpipe%3Dtrickle%28d10%29%27%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO - wait       = 'interactive'
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO - wait_for_navigation = <coroutine object wait_for at 0x00000184FFD3FF40>
[task 2022-06-15T10:54:15.418Z] 10:54:15     INFO - 
[task 2022-06-15T10:54:15.419Z] 10:54:15     INFO - tests\web-platform\tests\webdriver\tests\bidi\browsing_context\navigate\wait.py:46: 

Comment 1

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

The failure is actually in these lines:
https://treeherder.mozilla.org/logviewer?job_id=381394549&repo=autoland&lineNumber=16473-16481

1655290449342	WebDriver BiDi	DEBUG	f4348031-ea44-46bb-9f67-5fcd6a0cbf9c -> {"id":19,"method":"browsingContext.navigate","params":{"context":"22d97bc4-de7f-470d-9201-b324282ce42d","url":"http://web-pla ... _context%2Fnavigate%2Fsupport%2Fempty.svg%3Fpipe%3Dtrickle%28d10%29%27%3E&mime=text%2Fhtml&charset=UTF-8","wait":"complete"}}
1655290449343	RemoteAgent	TRACE	Received command browsingContext.navigate for destination ROOT
1655290449343	RemoteAgent	TRACE	Received command browsingContext._getBaseURL for destination WINDOW_GLOBAL
1655290449343	RemoteAgent	TRACE	Received command browsingContext._getBaseURL for destination WINDOW_GLOBAL
1655290449343	RemoteAgent	TRACE	Module windowglobal/browsingContext.jsm found for WINDOW_GLOBAL
1655290449347	RemoteAgent	TRACE	[43] ProgressListener state=start: http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ci ... sts%2Fbidi%2Fbrowsing_context%2Fnavigate%2Fsupport%2Fempty.svg%3Fpipe%3Dtrickle%28d10%29%27%3E&mime=text%2Fhtml&charset=UTF-8
1655290450348	WebDriver BiDi	DEBUG	f4348031-ea44-46bb-9f67-5fcd6a0cbf9c -> {"id":20,"method":"browsingContext.getTree","params":{"maxDepth":0,"root":"22d97bc4-de7f-470d-9201-b324282ce42d"}}
1655290450348	RemoteAgent	TRACE	Received command browsingContext.getTree for destination ROOT
1655290450348	WebDriver BiDi	DEBUG	f4348031-ea44-46bb-9f67-5fcd6a0cbf9c <- {"id":20,"result":{"contexts":[{"context":"22d97bc4-de7f-470d-9201-b324282ce42d","url":"about:blank","children":null,"parent":null}]}}

So we send the browsingContext.getTree command while the navigation hasn't been finished yet but run into a timeout of 1s. Then we check the returned URL to be the URL the navigation should have gone to. Sadly this fails because the current browsing context still has about:blank loaded. Maybe we should update the test to use Poll.wait() for a couple of seconds to wait until the new page has actually been loaded.

Julian, what do you think?

Comment 2

[Julian Descottes [:jdescottes]]

I am not sure. The 1s timeout comes from the asyncio.wait at https://searchfox.org/mozilla-central/rev/ec3889f74d6b5695833280f4370ca0e9ba59a3e4/testing/web-platform/tests/webdriver/tests/bidi/browsing_context/navigate/wait.py#35-40

    wait_for_navigation = asyncio.wait_for(
        bidi_session.browsing_context.navigate(
            context=new_tab["context"], url=url, wait=wait
        ),
        timeout=1,
    )

When we initially landed the tests I remember we wondered what would be a safe timeout to use here. 1s seemed to be fine, but I think here we just hit a case where the browser could not perform "enough" navigation in that second. Which means that the interactive test fails with an unexpected timeout/cancelled error (CancelledError gets reported, but it really ends up as a asyncio.TimeoutError in the test).

I can actually reproduce the exact same failure logs locally if I drastically reduce the timeout, all the way down to 0.01s. IMO waiting after the navigation will not help here. Let's monitor, and if that seems to happen frequently we should increase the delay in asyncio.wait_for

Comment 3

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

Hm, thinking more about this case what is the exact reason why we have to use wait_for at all? Why can't we wait until the navigate command has been returned? Is it for the unlikely case that due to a missing timeout argument this won't happen at all? If yes, I wonder if it wouldn't be safer to just remove this async wait for then and let the test module run into a timeout instead.

Comment 4

[Julian Descottes [:jdescottes]]

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

Hm, thinking more about this case what is the exact reason why we have to use wait_for at all? Why can't we wait until the navigate command has been returned? Is it for the unlikely case that due to a missing timeout argument this won't happen at all? If yes, I wonder if it wouldn't be safer to just remove this async wait for then and let the test module run into a timeout instead.

We are explicitly testing scenarios where navigate will not return due to slow loading resources. So by design some of those calls will timeout. If the navigate command implemented a timeout parameter, we would use that (that's mentioned in the test itself), but instead we use wait_for. Here.

Should we really wait until the test module times out here? That would really slow down the test I think? In this test file, we have 5 scenarios which are expected to timeout: "complete" navigation for a slow image, slow script and slow page, as well as "interactive" navigation for slow script and slow page. How would the assertion look like if we rely on the test module timeout?

Comment 5

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

Oh right. We have a delay of 10s for each of these pages that get loaded. I was completely masking that fact, sorry. By removing this asyncio timeout we probably would have to split the test file given that after 2 tests we run into a timeout.

But for this specific test we actually do not delay the load of the page but of an image source. That means that DOMContentLoaded should still be fired immediately and only load is delayed until the actual image has been fully loaded. With exactly interactive failing it feels like that there was an issue with wptserve serving the page at all. So I now wonder if that particular issue is maybe just bug 1760291?

Comment 6

[Julian Descottes [:jdescottes]]

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

So I now wonder if that particular issue is maybe just bug 1760291?

That's really possible. I agree that 1s to wait for interactive should be plenty of time, especially considering this failed on a regular optimized build. So an issue with wptserve would make a lot of sense. It would be great if we could detect that.

Comment 7

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

Lets add the dependency so that we do not forget about it. Sadly this failure is so seldom that it will be very hard to catch and experiment with possible solution. :/

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1774392&startday=2022-06-13&endday=2022-06-19&tree=all

Comment 9

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

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

Comment 10

[BMO Automation]

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

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

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

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

Comment 13

[Intermittent Failures Robot]

9 failures in 3791 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 3
• autoland: 2
• try: 2
• mozilla-central: 2

Platform and build breakdown:

• windows11-32-2009-qr: 2
  • debug: 2
• windows11-32-2009-shippable-qr: 2
  • opt: 2
• windows11-64-2009-devedition-qr: 2
  • opt: 2
• windows11-64-2009-qr: 2
  • opt: 2
• windows11-64-2009-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1774392&startday=2024-03-18&endday=2024-03-24&tree=all

Comment 14

[Intermittent Failures Robot]

8 failures in 3590 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3
• try: 3
• mozilla-beta: 2

Platform and build breakdown:

• windows11-32-2009-qr: 2
  • opt: 2
• windows11-64-2009-qr: 1
  • opt: 1
• windows11-64-2009-devedition-qr: 3
  • opt: 3
• windows11-64-2009-shippable-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1774392&startday=2024-03-25&endday=2024-03-31&tree=all

Comment 15

[Intermittent Failures Robot]

11 failures in 3805 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-beta: 6
• mozilla-central: 4

Platform and build breakdown:

• windows11-64-2009-qr: 1
  • opt: 1
• windows11-64-2009-shippable-qr: 6
  • opt: 6
• windows11-32-2009-shippable-qr: 1
  • opt: 1
• windows11-64-2009-devedition-qr: 3
  • opt: 3

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

Comment 16

[Intermittent Failures Robot]

12 failures in 3235 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 5
• try: 1
• mozilla-central: 6

Platform and build breakdown:

• windows11-64-2009-qr: 3
  • opt: 2
  • debug: 1
• windows11-32-2009-qr: 3
  • opt: 3
• windows11-64-2009-shippable-qr: 2
  • opt: 2
• windows11-64-2009-ccov-qr: 2
  • opt: 2
• windows11-32-2009-shippable-qr: 2
  • opt: 2

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

Comment 17

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 3
• try: 1
• mozilla-central: 1

Platform and build breakdown:

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

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

Comment 18

[Intermittent Failures Robot]

10 failures in 4336 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 3
• mozilla-central: 4
• autoland: 2
• try: 1

Platform and build breakdown:

• windows11-64-2009-devedition-qr: 2
  • opt: 2
• windows11-64-2009-shippable-qr: 5
  • opt: 5
• windows11-32-2009-shippable-qr: 1
  • opt: 1
• windows11-32-2009-qr: 2
  • opt: 2

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

Comment 19

[Intermittent Failures Robot]

15 failures in 4059 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 4
• autoland: 7
• mozilla-central: 3
• try: 1

Platform and build breakdown:

• windows11-32-2009-shippable-qr: 4
  • opt: 4
• windows11-32-2009-qr: 3
  • opt: 3
• windows11-64-2009-qr: 4
  • opt: 4
• windows11-64-2009-shippable-qr: 2
  • opt: 2
• windows11-64-2009-devedition-qr: 1
  • opt: 1
• windows11-64-2009-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1774392&startday=2024-04-29&endday=2024-05-05&tree=all

Comment 20

[Intermittent Failures Robot]

15 failures in 3649 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 8
• mozilla-central: 4
• try: 3

Platform and build breakdown:

• windows11-64-2009-qr: 5
  • debug: 1
  • opt: 4
• windows11-32-2009-shippable-qr: 5
  • opt: 5
• windows11-32-2009-qr: 3
  • opt: 2
  • debug: 1
• windows11-64-2009-ccov-qr: 1
  • opt: 1
• windows11-64-2009-shippable-qr: 1
  • opt: 1

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

Comment 21

[Intermittent Failures Robot]

7 failures in 4547 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2
• mozilla-beta: 3
• try: 1
• autoland: 1

Platform and build breakdown:

• windows11-64-2009-ccov-qr: 1
  • opt: 1
• windows11-32-2009-qr: 1
  • debug: 1
• linux1804-64-tsan-qr: 1
  • opt: 1
• windows11-32-2009-shippable-qr: 3
  • opt: 3
• windows11-64-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1774392&startday=2024-05-13&endday=2024-05-19&tree=all

Comment 22

[Intermittent Failures Robot]

15 failures in 722 pushes (0.021 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 14
• mozilla-beta: 1

Platform and build breakdown:

• windows11-32-2009-qr: 7
  • debug: 4
  • opt: 3
• windows11-64-2009-qr: 7
  • opt: 5
  • debug: 2
• windows11-64-2009-devedition-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1774392&startday=2024-05-23&endday=2024-05-23&tree=all

Comment 23

[Julian Descottes [:jdescottes]]

All the recent failures (starting on the 23rd) are with the test /webdriver/tests/bidi/network/add_intercept/url_patterns.py | test_string_patterns_matching, so maybe that's related to the changes from Bug 1850680 ?

Comment 24

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

Looks like this is caused by a call to wait_for_future_safe() and that specifically in line 176 of the test:

https://searchfox.org/mozilla-central/rev/0529464f0d2981347ef581f7521ace8b7af7f7ac/testing/web-platform/tests/webdriver/tests/bidi/network/add_intercept/url_patterns.py#176

Does it mean that we do not get a network.beforeRequestSent event?

Comment 25

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

Probably we should file a new regression bug to get this fixed, and which should block this bug.

Comment 26

[Julian Descottes [:jdescottes]]

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

Probably we should file a new regression bug to get this fixed, and which should block this bug.

I'll wait until I get confirmation from try, and then I will file.

Comment 27

[Intermittent Failures Robot]

17 failures in 829 pushes (0.021 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 8
• try: 2
• autoland: 7

Platform and build breakdown:

• windows11-64-2009-shippable-qr: 4
  • opt: 4
• windows11-32-2009-qr: 4
  • debug: 3
  • opt: 1
• windows11-64-2009-qr: 7
  • debug: 4
  • opt: 3
• windows11-32-2009-shippable-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1774392&startday=2024-05-24&endday=2024-05-24&tree=all

Comment 28

[Intermittent Failures Robot]

43 failures in 3995 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #44 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 11
• autoland: 27
• mozilla-beta: 3
• try: 2

Platform and build breakdown:

• windows11-64-2009-shippable-qr: 5
  • opt: 5
• windows11-32-2009-qr: 12
  • debug: 7
  • opt: 5
• windows11-64-2009-qr: 20
  • debug: 7
  • opt: 13
• windows11-64-2009-devedition-qr: 3
  • opt: 3
• windows11-32-2009-shippable-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1774392&startday=2024-05-20&endday=2024-05-26&tree=all

Comment 29

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1
• mozilla-beta: 1
• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • debug: 1
• windows11-32-2009-qr: 1
  • debug: 1
• linux1804-64-tsan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1774392&startday=2024-05-27&endday=2024-06-02&tree=all

Comment 30

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1
• autoland: 1

Platform and build breakdown:

• windows11-64-2009-qr: 1
  • debug: 1
• linux1804-64-tsan-qr: 1
  • opt: 1

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