Closed Bug 1848314 Opened 4 months ago Closed 4 months ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/session/unsubscribe/invalid.py | expected OK

Categories

(Remote Protocol :: WebDriver BiDi, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED DUPLICATE of bug 1630162

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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


[task 2023-08-11T10:20:40.971Z] 10:20:40     INFO - TEST-START | /webdriver/tests/bidi/session/unsubscribe/invalid.py
[task 2023-08-11T10:20:41.027Z] 10:20:41     INFO - STDOUT: ============================= test session starts ==============================
[task 2023-08-11T10:20:41.029Z] 10:20:41     INFO - STDOUT: platform linux -- Python 3.7.5, pytest-7.0.1, pluggy-unknown -- /builds/worker/workspace/build/venv/bin/python
[task 2023-08-11T10:20:41.030Z] 10:20:41     INFO - STDOUT: rootdir: /builds/worker/workspace/build
[task 2023-08-11T10:20:41.030Z] 10:20:41     INFO - STDOUT: plugins: asyncio-0.19.0
[task 2023-08-11T10:20:41.030Z] 10:20:41     INFO - STDOUT: asyncio: mode=strict
[task 2023-08-11T10:20:41.031Z] 10:20:41     INFO - STDOUT: collecting ... 
[task 2023-08-11T10:20:41.050Z] 10:20:41     INFO - STDOUT: collected 34 items
[task 2023-08-11T10:20:41.050Z] 10:20:41     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/session/unsubscribe/invalid.py::test_params_empty 
[task 2023-08-11T10:20:41.052Z] 10:20:41     INFO - PID 6397 | 1691749241050	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmp_batu529.mozrunner"]}, "webSocketUrl": true}}}
[task 2023-08-11T10:20:41.052Z] 10:20:41     INFO - PID 6397 | 1691749241051	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2023-08-11T10:20:41.053Z] 10:20:41     INFO - PID 6397 | 1691749241051	geckodriver::capabilities	DEBUG	Found version 118.0a1
[task 2023-08-11T10:20:41.053Z] 10:20:41     INFO - PID 6397 | 1691749241052	geckodriver::browser	DEBUG	Backing up prefs to "/tmp/tmp_batu529.mozrunner/user.geckodriver_backup"
[task 2023-08-11T10:20:41.059Z] 10:20:41     INFO - PID 6397 | 1691749241057	mozrunner::runner	INFO	Running command: MOZ_CRASHREPORTER="1" MOZ_CRASHREPORTER_NO_REPORT="1" MOZ_CRASHREPORTER_SHUTDOWN="1" MOZ_NO_REMOTE="1" "/bui ... te" "--profile" "/tmp/tmp_batu529.mozrunner" "--remote-debugging-port" "9222" "--remote-allow-hosts" "localhost" "-no-remote"
[task 2023-08-11T10:20:41.059Z] 10:20:41     INFO - PID 6397 | 1691749241058	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2023-08-11T10:20:41.060Z] 10:20:41     INFO - PID 6397 | 1691749241058	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:41.061Z] 10:20:41     INFO - PID 6397 | 1691749241058	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:41.106Z] 10:20:41     INFO - PID 6397 | *** You are running in headless mode.
[task 2023-08-11T10:20:41.159Z] 10:20:41     INFO - PID 6397 | 1691749241158	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:41.160Z] 10:20:41     INFO - PID 6397 | 1691749241158	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:41.259Z] 10:20:41     INFO - PID 6397 | 1691749241258	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:41.259Z] 10:20:41     INFO - PID 6397 | 1691749241258	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:41.359Z] 10:20:41     INFO - PID 6397 | 1691749241358	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:41.360Z] 10:20:41     INFO - PID 6397 | 1691749241358	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:41.459Z] 10:20:41     INFO - PID 6397 | 1691749241458	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:41.461Z] 10:20:41     INFO - PID 6397 | 1691749241458	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:41.559Z] 10:20:41     INFO - PID 6397 | 1691749241558	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:41.560Z] 10:20:41     INFO - PID 6397 | 1691749241558	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:41.659Z] 10:20:41     INFO - PID 6397 | 1691749241659	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:41.660Z] 10:20:41     INFO - PID 6397 | 1691749241659	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:41.759Z] 10:20:41     INFO - PID 6397 | 1691749241759	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:41.760Z] 10:20:41     INFO - PID 6397 | 1691749241759	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:41.859Z] 10:20:41     INFO - PID 6397 | 1691749241859	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:41.860Z] 10:20:41     INFO - PID 6397 | 1691749241859	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:41.960Z] 10:20:41     INFO - PID 6397 | 1691749241959	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:41.960Z] 10:20:41     INFO - PID 6397 | 1691749241959	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:42.060Z] 10:20:42     INFO - PID 6397 | 1691749242059	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:42.060Z] 10:20:42     INFO - PID 6397 | 1691749242059	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:42.160Z] 10:20:42     INFO - PID 6397 | 1691749242159	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:42.160Z] 10:20:42     INFO - PID 6397 | 1691749242159	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:42.260Z] 10:20:42     INFO - PID 6397 | 1691749242259	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:42.261Z] 10:20:42     INFO - PID 6397 | 1691749242259	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:42.360Z] 10:20:42     INFO - PID 6397 | 1691749242359	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:42.361Z] 10:20:42     INFO - PID 6397 | 1691749242359	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:42.461Z] 10:20:42     INFO - PID 6397 | 1691749242460	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:42.461Z] 10:20:42     INFO - PID 6397 | 1691749242460	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:42.561Z] 10:20:42     INFO - PID 6397 | 1691749242560	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:42.561Z] 10:20:42     INFO - PID 6397 | 1691749242560	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:42.661Z] 10:20:42     INFO - PID 6397 | 1691749242660	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:42.662Z] 10:20:42     INFO - PID 6397 | 1691749242660	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:42.681Z] 10:20:42     INFO - PID 6397 | 1691749242681	RemoteAgent	DEBUG	WebDriver BiDi enabled
[task 2023-08-11T10:20:42.683Z] 10:20:42     INFO - PID 6397 | 1691749242682	RemoteAgent	DEBUG	CDP enabled
[task 2023-08-11T10:20:42.685Z] 10:20:42     INFO - PID 6397 | 1691749242684	Marionette	INFO	Marionette enabled
[task 2023-08-11T10:20:42.689Z] 10:20:42     INFO - PID 6397 | 1691749242688	Marionette	TRACE	Received observer notification final-ui-startup
[task 2023-08-11T10:20:42.692Z] 10:20:42     INFO - PID 6397 | 1691749242691	RemoteAgent	TRACE	Received observer notification final-ui-startup
[task 2023-08-11T10:20:42.761Z] 10:20:42     INFO - PID 6397 | 1691749242760	geckodriver::browser	TRACE	Failed to open /tmp/tmp_batu529.mozrunner/MarionetteActivePort
[task 2023-08-11T10:20:42.761Z] 10:20:42     INFO - PID 6397 | 1691749242760	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-08-11T10:20:42.833Z] 10:20:42     INFO - PID 6397 | 1691749242832	Marionette	INFO	Listening on port 45597
[task 2023-08-11T10:20:42.835Z] 10:20:42     INFO - PID 6397 | 1691749242834	Marionette	DEBUG	Marionette is listening
[task 2023-08-11T10:20:42.861Z] 10:20:42     INFO - PID 6397 | Read port: 45597
[task 2023-08-11T10:20:42.868Z] 10:20:42     INFO - PID 6397 | 1691749242867	RemoteAgent	TRACE	Available local IP addresses: 127.0.0.1, [::1]
[task 2023-08-11T10:20:42.879Z] 10:20:42     INFO - PID 6397 | WebDriver BiDi listening on ws://127.0.0.1:9222
[task 2023-08-11T10:20:42.881Z] 10:20:42     INFO - PID 6397 | 1691749242880	CDP	DEBUG	Waiting for initial application window
[task 2023-08-11T10:20:42.901Z] 10:20:42     INFO - PID 6397 | 1691749242900	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:56846
[task 2023-08-11T10:20:42.915Z] 10:20:42     INFO - PID 6397 | 1691749242914	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:45597.
[task 2023-08-11T10:20:42.936Z] 10:20:42     INFO - PID 6397 | 1691749242935	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"webSocketUrl":true}]
[task 2023-08-11T10:20:42.950Z] 10:20:42     INFO - PID 6397 | 1691749242949	WebDriver BiDi	DEBUG	Waiting for initial application window
[task 2023-08-11T10:20:43.513Z] 10:20:43     INFO - PID 6397 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-08-11T10:20:43.518Z] 10:20:43     INFO - PID 6397 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-08-11T10:20:44.853Z] 10:20:44     INFO - PID 6397 | Crash Annotation GraphicsCriticalError: |[0][GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt (t=3.78749) [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
[task 2023-08-11T10:20:44.971Z] 10:20:44     INFO - PID 6397 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-08-11T10:20:45.230Z] 10:20:45     INFO - PID 6397 | console.error: ({})
<...>
[task 2023-08-11T10:20:55.640Z] 10:20:55     INFO - PID 6397 | 1691749255637	RemoteAgent	TRACE	Received command log._applySessionData for destination WINDOW_GLOBAL
[task 2023-08-11T10:20:55.640Z] 10:20:55     INFO - PID 6397 | 1691749255637	RemoteAgent	TRACE	Module windowglobal-in-root/log.sys.mjs found for WINDOW_GLOBAL
[task 2023-08-11T10:20:55.641Z] 10:20:55     INFO - PID 6397 | 1691749255637	RemoteAgent	TRACE	Module windowglobal/log.sys.mjs found for WINDOW_GLOBAL
[task 2023-08-11T10:20:55.642Z] 10:20:55     INFO - PID 6397 | 1691749255639	RemoteAgent	TRACE	Received command log._applySessionData for destination WINDOW_GLOBAL
[task 2023-08-11T10:20:55.642Z] 10:20:55     INFO - PID 6397 | 1691749255639	RemoteAgent	TRACE	Module windowglobal/log.sys.mjs found for WINDOW_GLOBAL
[task 2023-08-11T10:20:55.643Z] 10:20:55     INFO - PID 6397 | 1691749255642	RemoteAgent	TRACE	Module root/log.sys.mjs found for ROOT
[task 2023-08-11T10:20:55.644Z] 10:20:55     INFO - PID 6397 | 1691749255644	RemoteAgent	DEBUG	WebDriverBiDiConnection 135b1677-b076-4c17-92ce-14ecba1e1c4c <- {"type":"success","id":58,"result":{}}
[task 2023-08-11T10:20:55.646Z] 10:20:55     INFO - PID 6397 | 1691749255646	RemoteAgent	DEBUG	WebDriverBiDiConnection 135b1677-b076-4c17-92ce-14ecba1e1c4c closed
[task 2023-08-11T10:20:55.648Z] 10:20:55     INFO - PID 6397 | 1691749255647	webdriver::server	DEBUG	-> POST /session/e4abeeed-3935-451d-b41b-a73409d08d2c/timeouts {"implicit": 0}
[task 2023-08-11T10:20:55.650Z] 10:20:55     INFO - PID 6397 | 1691749255649	Marionette	DEBUG	0 -> [0,532,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2023-08-11T10:20:55.653Z] 10:20:55     INFO - PID 6397 | 1691749255650	Marionette	DEBUG	0 <- [1,532,null,{"value":null}]
[task 2023-08-11T10:20:55.654Z] 10:20:55     INFO - PID 6397 | 1691749255653	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-08-11T10:20:55.655Z] 10:20:55     INFO - PID 6397 | 1691749255654	webdriver::server	DEBUG	-> POST /session/e4abeeed-3935-451d-b41b-a73409d08d2c/timeouts {"pageLoad": 300000}
[task 2023-08-11T10:20:55.656Z] 10:20:55     INFO - PID 6397 | 1691749255656	Marionette	DEBUG	0 -> [0,533,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2023-08-11T10:20:55.657Z] 10:20:55     INFO - PID 6397 | 1691749255656	Marionette	DEBUG	0 <- [1,533,null,{"value":null}]
[task 2023-08-11T10:20:55.659Z] 10:20:55     INFO - PID 6397 | 1691749255657	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-08-11T10:20:55.661Z] 10:20:55     INFO - PID 6397 | 1691749255658	webdriver::server	DEBUG	-> POST /session/e4abeeed-3935-451d-b41b-a73409d08d2c/timeouts {"script": 30000}
[task 2023-08-11T10:20:55.662Z] 10:20:55     INFO - PID 6397 | 1691749255660	Marionette	DEBUG	0 -> [0,534,"WebDriver:SetTimeouts",{"script":30000}]
[task 2023-08-11T10:20:55.663Z] 10:20:55     INFO - PID 6397 | 1691749255660	Marionette	DEBUG	0 <- [1,534,null,{"value":null}]
[task 2023-08-11T10:20:55.663Z] 10:20:55     INFO - PID 6397 | 1691749255661	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-08-11T10:20:55.664Z] 10:20:55     INFO - PID 6397 | 1691749255662	webdriver::server	DEBUG	-> GET /session/e4abeeed-3935-451d-b41b-a73409d08d2c/window
[task 2023-08-11T10:20:55.664Z] 10:20:55     INFO - PID 6397 | 1691749255663	Marionette	DEBUG	0 -> [0,535,"WebDriver:GetWindowHandle",{}]
[task 2023-08-11T10:20:55.665Z] 10:20:55     INFO - PID 6397 | 1691749255664	Marionette	DEBUG	0 <- [1,535,null,{"value":"52783e49-cc6f-42a2-ad00-050ea6101bbb"}]
[task 2023-08-11T10:20:55.666Z] 10:20:55     INFO - PID 6397 | 1691749255665	webdriver::server	DEBUG	<- 200 OK {"value":"52783e49-cc6f-42a2-ad00-050ea6101bbb"}
[task 2023-08-11T10:20:55.667Z] 10:20:55     INFO - PID 6397 | 1691749255666	webdriver::server	DEBUG	-> GET /session/e4abeeed-3935-451d-b41b-a73409d08d2c/window
[task 2023-08-11T10:20:55.668Z] 10:20:55     INFO - PID 6397 | 1691749255667	Marionette	DEBUG	0 -> [0,536,"WebDriver:GetWindowHandle",{}]
[task 2023-08-11T10:20:55.669Z] 10:20:55     INFO - PID 6397 | 1691749255668	Marionette	DEBUG	0 <- [1,536,null,{"value":"52783e49-cc6f-42a2-ad00-050ea6101bbb"}]
[task 2023-08-11T10:20:55.670Z] 10:20:55     INFO - PID 6397 | 1691749255669	webdriver::server	DEBUG	<- 200 OK {"value":"52783e49-cc6f-42a2-ad00-050ea6101bbb"}
[task 2023-08-11T10:20:55.672Z] 10:20:55     INFO - PID 6397 | 1691749255669	webdriver::server	DEBUG	-> GET /session/e4abeeed-3935-451d-b41b-a73409d08d2c/window/handles
[task 2023-08-11T10:20:55.673Z] 10:20:55     INFO - PID 6397 | 1691749255670	Marionette	DEBUG	0 -> [0,537,"WebDriver:GetWindowHandles",{}]
[task 2023-08-11T10:20:55.673Z] 10:20:55     INFO - PID 6397 | 1691749255672	Marionette	DEBUG	0 <- [1,537,null,["52783e49-cc6f-42a2-ad00-050ea6101bbb"]]
[task 2023-08-11T10:20:55.674Z] 10:20:55     INFO - PID 6397 | 1691749255673	webdriver::server	DEBUG	<- 200 OK {"value":["52783e49-cc6f-42a2-ad00-050ea6101bbb"]}
[task 2023-08-11T10:20:55.676Z] 10:20:55     INFO - PID 6397 | 1691749255675	webdriver::server	DEBUG	-> POST /session/e4abeeed-3935-451d-b41b-a73409d08d2c/window {"handle": "52783e49-cc6f-42a2-ad00-050ea6101bbb"}
[task 2023-08-11T10:20:55.677Z] 10:20:55     INFO - PID 6397 | 1691749255676	Marionette	DEBUG	0 -> [0,538,"WebDriver:SwitchToWindow",{"handle":"52783e49-cc6f-42a2-ad00-050ea6101bbb"}]
[task 2023-08-11T10:20:55.680Z] 10:20:55     INFO - PID 6397 | 1691749255679	Marionette	DEBUG	0 <- [1,538,null,{"value":null}]
[task 2023-08-11T10:20:55.681Z] 10:20:55     INFO - PID 6397 | 1691749255680	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-08-11T10:20:55.682Z] 10:20:55     INFO - PID 6397 | 1691749255681	webdriver::server	DEBUG	-> POST /session/e4abeeed-3935-451d-b41b-a73409d08d2c/alert/dismiss {}
[task 2023-08-11T10:20:55.684Z] 10:20:55     INFO - PID 6397 | 1691749255683	Marionette	DEBUG	0 -> [0,539,"WebDriver:DismissAlert",{}]
[task 2023-08-11T10:20:55.687Z] 10:20:55     INFO - PID 6397 | 1691749255685	Marionette	DEBUG	0 <- [1,539,{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... ote/content/marionette/server.sys.mjs:263:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:494:20\n"},null]
[task 2023-08-11T10:20:55.689Z] 10:20:55     INFO - PID 6397 | 1691749255687	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/Remo ... ontent/marionette/server.sys.mjs:263:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:494:20\n"}}
[task 2023-08-11T10:20:55.689Z] 10:20:55     INFO - PID 6397 | 1691749255687	webdriver::server	DEBUG	-> POST /session/e4abeeed-3935-451d-b41b-a73409d08d2c/window {"handle": "52783e49-cc6f-42a2-ad00-050ea6101bbb"}
[task 2023-08-11T10:20:55.692Z] 10:20:55     INFO - PID 6397 | 1691749255691	Marionette	DEBUG	0 -> [0,540,"WebDriver:SwitchToWindow",{"handle":"52783e49-cc6f-42a2-ad00-050ea6101bbb"}]
[task 2023-08-11T10:20:55.694Z] 10:20:55     INFO - PID 6397 | 1691749255693	Marionette	DEBUG	0 <- [1,540,null,{"value":null}]
[task 2023-08-11T10:20:55.695Z] 10:20:55     INFO - PID 6397 | 1691749255694	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-08-11T10:20:55.696Z] 10:20:55     INFO - PID 6397 | 1691749255695	webdriver::server	DEBUG	-> GET /session/e4abeeed-3935-451d-b41b-a73409d08d2c/window
[task 2023-08-11T10:20:55.698Z] 10:20:55     INFO - PID 6397 | 1691749255697	Marionette	DEBUG	0 -> [0,541,"WebDriver:GetWindowHandle",{}]
[task 2023-08-11T10:20:55.699Z] 10:20:55     INFO - PID 6397 | 1691749255697	Marionette	DEBUG	0 <- [1,541,null,{"value":"52783e49-cc6f-42a2-ad00-050ea6101bbb"}]
[task 2023-08-11T10:20:55.700Z] 10:20:55     INFO - PID 6397 | 1691749255698	webdriver::server	DEBUG	<- 200 OK {"value":"52783e49-cc6f-42a2-ad00-050ea6101bbb"}
[task 2023-08-11T10:20:55.701Z] 10:20:55     INFO - PID 6397 | 1691749255700	webdriver::server	DEBUG	-> GET /session/e4abeeed-3935-451d-b41b-a73409d08d2c/window/handles
[task 2023-08-11T10:20:55.703Z] 10:20:55     INFO - PID 6397 | 1691749255701	Marionette	DEBUG	0 -> [0,542,"WebDriver:GetWindowHandles",{}]
[task 2023-08-11T10:20:55.705Z] 10:20:55     INFO - PID 6397 | 1691749255702	Marionette	DEBUG	0 <- [1,542,null,["52783e49-cc6f-42a2-ad00-050ea6101bbb"]]
[task 2023-08-11T10:20:55.706Z] 10:20:55     INFO - PID 6397 | 1691749255703	webdriver::server	DEBUG	<- 200 OK {"value":["52783e49-cc6f-42a2-ad00-050ea6101bbb"]}
[task 2023-08-11T10:20:55.707Z] 10:20:55     INFO - PID 6397 | 1691749255704	webdriver::server	DEBUG	-> POST /session/e4abeeed-3935-451d-b41b-a73409d08d2c/window {"handle": "52783e49-cc6f-42a2-ad00-050ea6101bbb"}
[task 2023-08-11T10:20:55.708Z] 10:20:55     INFO - PID 6397 | 1691749255705	Marionette	DEBUG	0 -> [0,543,"WebDriver:SwitchToWindow",{"handle":"52783e49-cc6f-42a2-ad00-050ea6101bbb"}]
[task 2023-08-11T10:20:55.709Z] 10:20:55     INFO - PID 6397 | 1691749255707	Marionette	DEBUG	0 <- [1,543,null,{"value":null}]
[task 2023-08-11T10:20:55.710Z] 10:20:55     INFO - PID 6397 | 1691749255708	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-08-11T10:20:55.711Z] 10:20:55     INFO - PID 6397 | 1691749255708	webdriver::server	DEBUG	-> POST /session/e4abeeed-3935-451d-b41b-a73409d08d2c/window/rect {"width": 800, "height": 600}
[task 2023-08-11T10:20:55.713Z] 10:20:55     INFO - PID 6397 | 1691749255710	Marionette	DEBUG	0 -> [0,544,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2023-08-11T10:20:55.714Z] 10:20:55     INFO - PID 6397 | 1691749255711	Marionette	TRACE	Requested window geometry matches
[task 2023-08-11T10:20:55.715Z] 10:20:55     INFO - PID 6397 | 1691749255711	Marionette	DEBUG	0 <- [1,544,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2023-08-11T10:20:55.717Z] 10:20:55     INFO - PID 6397 | 1691749255712	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2023-08-11T10:20:55.718Z] 10:20:55     INFO - PID 6397 | 1691749255713	webdriver::server	DEBUG	-> POST /session/e4abeeed-3935-451d-b41b-a73409d08d2c/frame {"id": null}
[task 2023-08-11T10:20:55.719Z] 10:20:55     INFO - PID 6397 | 1691749255714	Marionette	DEBUG	0 -> [0,545,"WebDriver:SwitchToFrame",{"id":null}]
[task 2023-08-11T10:20:55.721Z] 10:20:55     INFO - PID 6397 | 1691749255720	Marionette	DEBUG	0 <- [1,545,null,{"value":null}]
[task 2023-08-11T10:20:55.723Z] 10:20:55     INFO - PID 6397 | 1691749255721	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-08-11T10:20:55.726Z] 10:20:55     INFO - PID 6397 | 1691749255725	webdriver::server	DEBUG	-> DELETE /session/e4abeeed-3935-451d-b41b-a73409d08d2c
[task 2023-08-11T10:20:55.727Z] 10:20:55     INFO - PID 6397 | 1691749255726	Marionette	DEBUG	0 -> [0,546,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2023-08-11T10:20:55.730Z] 10:20:55     INFO - PID 6397 | 1691749255729	Marionette	INFO	Stopped listening on port 45597
[task 2023-08-11T10:20:55.749Z] 10:20:55     INFO - PID 6397 | 1691749255748	Marionette	TRACE	[3] MarionetteCommands actor destroyed for window id 4294967297
[task 2023-08-11T10:20:55.756Z] 10:20:55     INFO - PID 6397 | 1691749255754	WebDriver BiDi	DEBUG	Unregistered session handler: /session/e4abeeed-3935-451d-b41b-a73409d08d2c
[task 2023-08-11T10:20:55.767Z] 10:20:55     INFO - PID 6397 | 1691749255766	RemoteAgent	TRACE	MessageHandler ROOT for session e4abeeed-3935-451d-b41b-a73409d08d2c is being destroyed
[task 2023-08-11T10:20:55.768Z] 10:20:55     INFO - PID 6397 | 1691749255767	RemoteAgent	TRACE	Unregistered MessageHandler ROOT for session e4abeeed-3935-451d-b41b-a73409d08d2c
[task 2023-08-11T10:20:56.069Z] 10:20:56     INFO - PID 6397 | 1691749256068	Marionette	TRACE	Received observer notification quit-application
[task 2023-08-11T10:20:56.090Z] 10:20:56     INFO - PID 6397 | 1691749256089	Marionette	TRACE	Received observer notification quit-application
[task 2023-08-11T10:20:56.090Z] 10:20:56     INFO - PID 6397 | 1691749256089	RemoteAgent	TRACE	Received observer notification quit-application
[task 2023-08-11T10:20:56.096Z] 10:20:56     INFO - PID 6397 | 1691749256096	Marionette	DEBUG	Marionette stopped listening
[task 2023-08-11T10:20:56.098Z] 10:20:56     INFO - PID 6397 | 1691749256097	Marionette	DEBUG	0 <- [1,546,null,{"cause":"shutdown","forced":false,"in_app":true}]
[task 2023-08-11T10:20:56.223Z] 10:20:56     INFO - PID 6397 | 1691749256222	RemoteAgent	TRACE	MessageHandler WINDOW_GLOBAL for session e4abeeed-3935-451d-b41b-a73409d08d2c is being destroyed
[task 2023-08-11T10:20:56.227Z] 10:20:56     INFO - PID 6397 | 1691749256225	RemoteAgent	TRACE	Unregistered MessageHandler WINDOW_GLOBAL for session e4abeeed-3935-451d-b41b-a73409d08d2c
[task 2023-08-11T10:20:56.234Z] 10:20:56     INFO - PID 6397 | 1691749256232	RemoteAgent	DEBUG	Resetting recommended pref browser.contentblocking.features.standard
[task 2023-08-11T10:20:56.234Z] 10:20:56     INFO - PID 6397 | 1691749256233	RemoteAgent	DEBUG	Resetting recommended pref network.cookie.cookieBehavior
[task 2023-08-11T10:20:56.236Z] 10:20:56     INFO - PID 6397 | 1691749256235	webdriver::server	DEBUG	Teardown session
[task 2023-08-11T10:20:56.246Z] 10:20:56     INFO - PID 6397 | 1691749256245	Marionette	DEBUG	Closed connection 0
[task 2023-08-11T10:20:56.395Z] 10:20:56     INFO - PID 6397 | console.error: ({})
[task 2023-08-11T10:20:57.949Z] 10:20:57     INFO - PID 6397 | [Parent 7016, IPC I/O Parent] WARNING: Process 7188 may be hanging at shutdown; will wait for up to 40000ms: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/process_watcher_posix_sigchld.cc:184
[task 2023-08-11T10:21:37.967Z] 10:21:37     INFO - PID 6397 | [Parent 7016, IPC I/O Parent] WARNING: Process 7188 hanging at shutdown; attempting crash report (fatal error).: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/process_watcher_posix_sigchld.cc:207
[task 2023-08-11T10:22:00.973Z] 10:22:00     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/session/unsubscribe/invalid.py | expected OK
[task 2023-08-11T10:22:00.973Z] 10:22:00     INFO - TEST-INFO took 80003ms
[task 2023-08-11T10:22:00.974Z] 10:22:00     INFO - Restarting browser for new test group
[task 2023-08-11T10:22:07.030Z] 10:22:07     INFO - Closing logging queue
[task 2023-08-11T10:22:07.032Z] 10:22:07     INFO - queue closed
[task 2023-08-11T10:22:07.038Z] 10:22:07     INFO - PID 7292 | 1691749327037	geckodriver	INFO	Listening on 127.0.0.1:56232
[task 2023-08-11T10:22:07.039Z] 10:22:07     INFO - Starting runner
[task 2023-08-11T10:22:07.278Z] 10:22:07     INFO - TEST-START | /webdriver/tests/classic/dismiss_alert/dismiss.py

Shutdown hang of Firefox

Status: NEW → RESOLVED
Closed: 4 months ago
Duplicate of bug: 1630162
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.