Closed Bug 1831965 Opened 2 years ago Closed 1 year ago

Intermittent [tier 2] Wd TEST-UNEXPECTED-TIMEOUT | expected OK (hang in WebDriver:NewSession)

Categories

(Remote Protocol :: Marionette, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure)

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


[task 2023-05-08T18:46:37.786Z] 18:46:37     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/take_screenshot/user_prompts.py::test_accept_and_notify[capabilities0-alert-None] 
[task 2023-05-08T18:46:37.788Z] 18:46:37     INFO - PID 2254 | 1683571597785	Marionette	DEBUG	0 -> [0,77,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2023-05-08T18:46:37.789Z] 18:46:37     INFO - PID 2254 | 1683571597785	Marionette	INFO	Stopped listening on port 40992
[task 2023-05-08T18:46:37.790Z] 18:46:37     INFO - PID 2254 | 1683571597787	Marionette	TRACE	[11] MarionetteCommands actor destroyed for window id 8589934595
[task 2023-05-08T18:46:37.827Z] 18:46:37     INFO - PID 2254 | [Child 2949, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-08T18:46:37.829Z] 18:46:37     INFO - PID 2254 | [Child 2949, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-08T18:46:37.850Z] 18:46:37     INFO - PID 2254 | [Child 2949, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-08T18:46:37.851Z] 18:46:37     INFO - PID 2254 | [Child 2949, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-08T18:46:37.854Z] 18:46:37     INFO - PID 2254 | [Child 2949, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-08T18:46:37.855Z] 18:46:37     INFO - PID 2254 | [Child 2949, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-08T18:46:37.857Z] 18:46:37     INFO - PID 2254 | [Child 2949, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-08T18:46:37.876Z] 18:46:37     INFO - PID 2254 | [CodeCoverage] Setting handlers for process 3079.
[task 2023-05-08T18:46:37.889Z] 18:46:37     INFO - PID 2254 | 1683571597888	Marionette	TRACE	Received observer notification quit-application
[task 2023-05-08T18:46:37.894Z] 18:46:37     INFO - PID 2254 | 1683571597893	Marionette	TRACE	Received observer notification quit-application
[task 2023-05-08T18:46:37.895Z] 18:46:37     INFO - PID 2254 | 1683571597893	Marionette	DEBUG	Marionette stopped listening
[task 2023-05-08T18:46:37.896Z] 18:46:37     INFO - PID 2254 | 1683571597895	Marionette	DEBUG	0 <- [1,77,null,{"cause":"shutdown","forced":false,"in_app":true}]
[task 2023-05-08T18:46:37.928Z] 18:46:37     INFO - PID 2254 | [Child 3043, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (MarionetteCommands, MarionetteCommandsParent:executeScript) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-08T18:46:37.933Z] 18:46:37     INFO - PID 2254 | 1683571597932	webdriver::server	DEBUG	Teardown session
[task 2023-05-08T18:46:37.941Z] 18:46:37     INFO - PID 2254 | 1683571597940	Marionette	DEBUG	Closed connection 0
[task 2023-05-08T18:46:38.013Z] 18:46:38     INFO - PID 2254 | [CodeCoverage] Setting handlers for process 3080.
[task 2023-05-08T18:46:40.335Z] 18:46:40     INFO - PID 2254 | 1683571600334	geckodriver::browser	DEBUG	Browser process stopped: exit status: 0
[task 2023-05-08T18:46:40.336Z] 18:46:40     INFO - PID 2254 | 1683571600335	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-05-08T18:46:40.337Z] 18:46:40     INFO - PID 2254 | 1683571600336	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmp51mmv57y.mozrunner"], "binary": "/builds/worker/workspace/build/application/firefox/firefox"}, "unhandledPromptBehavior": "accept and notify"}}}
[task 2023-05-08T18:46:40.338Z] 18:46:40     INFO - PID 2254 | 1683571600336	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2023-05-08T18:46:40.339Z] 18:46:40     INFO - PID 2254 | 1683571600336	geckodriver::capabilities	DEBUG	Found version 115.0a1
[task 2023-05-08T18:46:40.339Z] 18:46:40     INFO - PID 2254 | 1683571600337	geckodriver::browser	DEBUG	Backing up prefs to "/tmp/tmp51mmv57y.mozrunner/user.geckodriver_backup"
[task 2023-05-08T18:46:40.343Z] 18:46:40     INFO - PID 2254 | 1683571600342	mozrunner::runner	INFO	Running command: MOZ_CRASHREPORTER="1" MOZ_CRASHREPORTER_NO_REPORT="1" MOZ_CRASHREPORTER_SHUTDOWN="1" MOZ_NO_REMOTE="1" "/builds/worker/workspace/build/application/firefox/firefox" "--marionette" "--profile" "/tmp/tmp51mmv57y.mozrunner" "-no-remote"
[task 2023-05-08T18:46:40.345Z] 18:46:40     INFO - PID 2254 | 1683571600343	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2023-05-08T18:46:40.345Z] 18:46:40     INFO - PID 2254 | 1683571600343	geckodriver::browser	TRACE	Failed to open /tmp/tmp51mmv57y.mozrunner/MarionetteActivePort
[task 2023-05-08T18:46:40.345Z] 18:46:40     INFO - PID 2254 | 1683571600343	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-05-08T18:46:40.402Z] 18:46:40     INFO - PID 2254 | [CodeCoverage] Setting handlers for process 3155.
[task 2023-05-08T18:46:40.403Z] 18:46:40     INFO - PID 2254 | *** You are running in headless mode.
[task 2023-05-08T18:46:40.444Z] 18:46:40     INFO - PID 2254 | 1683571600443	geckodriver::browser	TRACE	Failed to open /tmp/tmp51mmv57y.mozrunner/MarionetteActivePort
[task 2023-05-08T18:46:40.445Z] 18:46:40     INFO - PID 2254 | 1683571600443	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-05-08T18:46:40.545Z] 18:46:40     INFO - PID 2254 | 1683571600543	geckodriver::browser	TRACE	Failed to open /tmp/tmp51mmv57y.mozrunner/MarionetteActivePort
[task 2023-05-08T18:46:40.545Z] 18:46:40     INFO - PID 2254 | 1683571600543	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-05-08T18:46:40.615Z] 18:46:40     INFO - PID 2254 | 1683571600614	Marionette	INFO	Marionette enabled
[task 2023-05-08T18:46:40.616Z] 18:46:40     INFO - PID 2254 | 1683571600615	Marionette	TRACE	Received observer notification final-ui-startup
[task 2023-05-08T18:46:40.618Z] 18:46:40     INFO - PID 2254 | 1683571600616	Marionette	INFO	Listening on port 46538
[task 2023-05-08T18:46:40.618Z] 18:46:40     INFO - PID 2254 | 1683571600617	Marionette	DEBUG	Marionette is listening
[task 2023-05-08T18:46:40.644Z] 18:46:40     INFO - PID 2254 | Read port: 46538
[task 2023-05-08T18:46:40.663Z] 18:46:40     INFO - PID 2254 | 1683571600662	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:44124
[task 2023-05-08T18:46:40.671Z] 18:46:40     INFO - PID 2254 | 1683571600671	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:46538.
[task 2023-05-08T18:46:40.789Z] 18:46:40     INFO - PID 2254 | 1683571600788	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"unhandledPromptBehavior":"accept and notify"}]
[task 2023-05-08T18:46:40.792Z] 18:46:40     INFO - PID 2254 | 1683571600791	Marionette	DEBUG	Waiting for initial application window
[task 2023-05-08T18:46:40.802Z] 18:46:40     INFO - PID 2254 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-05-08T18:46:40.804Z] 18:46:40     INFO - PID 2254 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-05-08T18:46:41.090Z] 18:46:41     INFO - PID 2254 | [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
[task 2023-05-08T18:46:41.152Z] 18:46:41     INFO - PID 2254 | console.error: ({})
[task 2023-05-08T18:46:41.281Z] 18:46:41     INFO - PID 2254 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-05-08T18:46:41.283Z] 18:46:41     INFO - PID 2254 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-05-08T18:46:41.304Z] 18:46:41     INFO - PID 2254 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-05-08T18:46:41.308Z] 18:46:41     INFO - PID 2254 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-05-08T18:46:41.328Z] 18:46:41     INFO - PID 2254 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-05-08T18:46:41.442Z] 18:46:41     INFO - PID 2254 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-05-08T18:46:41.528Z] 18:46:41     INFO - PID 2254 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-05-08T18:46:41.660Z] 18:46:41     INFO - PID 2254 | [CodeCoverage] Setting handlers for process 3211.
[task 2023-05-08T18:46:41.702Z] 18:46:41     INFO - PID 2254 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-05-08T18:46:41.973Z] 18:46:41     INFO - PID 2254 | [CodeCoverage] Setting handlers for process 3224.
[task 2023-05-08T18:46:42.082Z] 18:46:42     INFO - PID 2254 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-05-08T18:46:42.083Z] 18:46:42     INFO - PID 2254 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-05-08T18:46:42.084Z] 18:46:42     INFO - PID 2254 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-05-08T18:46:42.128Z] 18:46:42     INFO - PID 2254 | 1683571602127	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2023-05-08T18:46:42.135Z] 18:46:42     INFO - PID 2254 | 1683571602133	RemoteAgent	TRACE	[3] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=3200 waitForExplicitStart=false
[task 2023-05-08T18:46:42.135Z] 18:46:42     INFO - PID 2254 | 1683571602134	RemoteAgent	TRACE	[3] ProgressListener Document already loading about:blank
[task 2023-05-08T18:46:42.136Z] 18:46:42     INFO - PID 2254 | 1683571602134	RemoteAgent	TRACE	[3] ProgressListener Check loading state: isStart=true isStop=false
[task 2023-05-08T18:46:42.136Z] 18:46:42     INFO - PID 2254 | 1683571602134	RemoteAgent	TRACE	[3] ProgressListener state=start: about:blank
[task 2023-05-08T18:47:11.419Z] 18:47:11     INFO - PID 2254 | console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 324))
[task 2023-05-08T18:52:38.485Z] 18:52:38     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/take_screenshot/user_prompts.py | expected OK
[task 2023-05-08T18:52:38.485Z] 18:52:38     INFO - TEST-INFO took 365003ms
[task 2023-05-08T18:52:38.487Z] 18:52:38     INFO - Restarting browser for new test group
[task 2023-05-08T18:52:38.674Z] 18:52:38     INFO - Closing logging queue
[task 2023-05-08T18:52:38.676Z] 18:52:38     INFO - queue closed
[task 2023-05-08T18:52:38.685Z] 18:52:38     INFO - PID 3303 | 1683571958684	geckodriver	INFO	Listening on 127.0.0.1:37006
[task 2023-05-08T18:52:38.686Z] 18:52:38     INFO - Starting runner
[task 2023-05-08T18:52:38.920Z] 18:52:38     INFO - TEST-START | /_mozilla/webdriver/bidi/script/exception_details.py

The WebDriver:NewSession command is timing out because our progress listener seems to have not seen any further navigation related activity from the WebProgress. Lets see how often that happens.

Status: NEW → RESOLVED
Closed: 1 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

All the recent failures in the last 2 weeks were wrongly classified. I've corrected it.

Status: REOPENED → RESOLVED
Closed: 1 years ago1 year ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.