1778104 - Intermittent TEST-UNEXPECTED-TIMEOUT Wd | expected OK [Ignoring event 'DOMContentLoaded' because document has an invalid readyState of 'complete']

Reporter

Description

•

3 years ago

treeherder

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

task 2022-07-05T11:04:28.862Z] 11:04:28     INFO - PID 11854 | [Parent 12906, Main Thread] WARNING: ContentParent: id=7f49e678bb00 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3688
[task 2022-07-05T11:04:28.865Z] 11:04:28     INFO - PID 11854 | [Parent 12906, Main Thread] WARNING: ContentParent: id=7f49e6790b00 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1825
[task 2022-07-05T11:04:28.866Z] 11:04:28     INFO - PID 11854 | [Parent 12906, Main Thread] WARNING: ContentParent: id=7f49e6790b00 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3688
[task 2022-07-05T11:04:28.868Z] 11:04:28     INFO - PID 11854 | [Parent 12906, Main Thread] WARNING: ContentParent: id=7f49e678b100 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1825
[task 2022-07-05T11:04:28.868Z] 11:04:28     INFO - PID 11854 | [Parent 12906, Main Thread] WARNING: ContentParent: id=7f49e678b100 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3688
[task 2022-07-05T11:04:30.852Z] 11:04:30     INFO - PID 11854 | 1657019070850	geckodriver::browser	DEBUG	Browser process stopped: exit status: 0
[task 2022-07-05T11:04:30.852Z] 11:04:30     INFO - PID 11854 | 1657019070851	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-07-05T11:04:30.854Z] 11:04:30     INFO - PID 11854 | 1657019070852	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmpzabi3tig.mozrunner"], "binary": "/builds/worker/workspace/build/application/firefox/firefox"}, "unhandledPromptBehavior": "ignore"}}}
[task 2022-07-05T11:04:30.855Z] 11:04:30     INFO - PID 11854 | 1657019070852	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2022-07-05T11:04:30.855Z] 11:04:30     INFO - PID 11854 | 1657019070852	geckodriver::capabilities	DEBUG	Found version 104.0a1
[task 2022-07-05T11:04:30.855Z] 11:04:30     INFO - PID 11854 | 1657019070853	geckodriver::browser	DEBUG	Backing up prefs to "/tmp/tmpzabi3tig.mozrunner/user.geckodriver_backup"
[task 2022-07-05T11:04:30.860Z] 11:04:30     INFO - PID 11854 | 1657019070858	mozrunner::runner	INFO	Running command: "/builds/worker/workspace/build/application/firefox/firefox" "--marionette" "--profile" "/tmp/tmpzabi3tig.mozrunner" "-no-remote"
[task 2022-07-05T11:04:30.860Z] 11:04:30     INFO - PID 11854 | 1657019070859	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-07-05T11:04:30.861Z] 11:04:30     INFO - PID 11854 | 1657019070859	geckodriver::browser	TRACE	Failed to open /tmp/tmpzabi3tig.mozrunner/MarionetteActivePort
[task 2022-07-05T11:04:30.861Z] 11:04:30     INFO - PID 11854 | 1657019070859	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-07-05T11:04:30.916Z] 11:04:30     INFO - PID 11854 | [CodeCoverage] Setting handlers for process 13152.
[task 2022-07-05T11:04:30.917Z] 11:04:30     INFO - PID 11854 | *** You are running in headless mode.
[task 2022-07-05T11:04:30.961Z] 11:04:30     INFO - PID 11854 | 1657019070959	geckodriver::browser	TRACE	Failed to open /tmp/tmpzabi3tig.mozrunner/MarionetteActivePort
[task 2022-07-05T11:04:30.961Z] 11:04:30     INFO - PID 11854 | 1657019070959	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-07-05T11:04:31.061Z] 11:04:31     INFO - PID 11854 | 1657019071059	geckodriver::browser	TRACE	Failed to open /tmp/tmpzabi3tig.mozrunner/MarionetteActivePort
[task 2022-07-05T11:04:31.061Z] 11:04:31     INFO - PID 11854 | 1657019071059	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-07-05T11:04:31.132Z] 11:04:31     INFO - PID 11854 | 1657019071130	Marionette	INFO	Marionette enabled
[task 2022-07-05T11:04:31.134Z] 11:04:31     INFO - PID 11854 | 1657019071132	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-07-05T11:04:31.138Z] 11:04:31     INFO - PID 11854 | 1657019071133	Marionette	INFO	Listening on port 46576
[task 2022-07-05T11:04:31.141Z] 11:04:31     INFO - PID 11854 | 1657019071133	Marionette	DEBUG	Marionette is listening
[task 2022-07-05T11:04:31.160Z] 11:04:31     INFO - PID 11854 | Read port: 46576
[task 2022-07-05T11:04:31.183Z] 11:04:31     INFO - PID 11854 | 1657019071181	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:33112
[task 2022-07-05T11:04:31.193Z] 11:04:31     INFO - PID 11854 | 1657019071192	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:46576.
[task 2022-07-05T11:04:31.306Z] 11:04:31     INFO - PID 11854 | 1657019071305	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"unhandledPromptBehavior":"ignore"}]
[task 2022-07-05T11:04:31.309Z] 11:04:31     INFO - PID 11854 | 1657019071308	Marionette	DEBUG	Waiting for initial application window
[task 2022-07-05T11:04:31.675Z] 11:04:31     INFO - PID 11854 | [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
[task 2022-07-05T11:04:31.819Z] 11:04:31     INFO - PID 11854 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpzabi3tig.mozrunner/search.json.mozlz4", (void 0)))
[task 2022-07-05T11:04:31.885Z] 11:04:31     INFO - PID 11854 | console.error: SearchEngineSelector: "Received empty search configuration!"
[task 2022-07-05T11:04:31.968Z] 11:04:31     INFO - PID 11854 | console.error: SearchEngineSelector: "Received empty search configuration!"
[task 2022-07-05T11:04:31.970Z] 11:04:31     INFO - PID 11854 | console.error: SearchService: "#init: failure initializing search:" ({})
[task 2022-07-05T11:04:31.972Z] 11:04:31     INFO - PID 11854 | JavaScript error: , line 0: uncaught exception: 2147549183
[task 2022-07-05T11:04:31.973Z] 11:04:31     INFO - PID 11854 | JavaScript error: , line 0: uncaught exception: 2147549183
[task 2022-07-05T11:04:31.975Z] 11:04:31     INFO - PID 11854 | JavaScript error: , line 0: uncaught exception: 2147549183
[task 2022-07-05T11:04:31.976Z] 11:04:31     INFO - PID 11854 | JavaScript error: resource://gre/modules/SearchService.jsm, line 1205: NS_ERROR_UNEXPECTED: SearchService previously failed to initialize
[task 2022-07-05T11:04:31.979Z] 11:04:31     INFO - PID 11854 | JavaScript error: , line 0: uncaught exception: 2147549183
[task 2022-07-05T11:04:32.172Z] 11:04:32     INFO - PID 11854 | [CodeCoverage] Setting handlers for process 13211.
[task 2022-07-05T11:04:32.544Z] 11:04:32     INFO - PID 11854 | [CodeCoverage] Setting handlers for process 13221.
[task 2022-07-05T11:04:32.635Z] 11:04:32     INFO - PID 11854 | 1657019072633	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2022-07-05T11:04:32.640Z] 11:04:32     INFO - PID 11854 | 1657019072639	RemoteAgent	TRACE	[18] ProgressListener state=start: about:blank
[task 2022-07-05T11:04:32.898Z] 11:04:32     INFO - PID 11854 | console.error: SearchSettings: "_write: Could not write to settings file:" (new Error("cannot write without any engine.", "resource://gre/modules/SearchSettings.jsm", 218))
[task 2022-07-05T11:09:31.868Z] 11:09:31     INFO - PID 11854 | JavaScript error: , line 0: uncaught exception: 2147549183
[task 2022-07-05T11:10:06.834Z] 11:10:06     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/find_elements_from_element/user_prompts.py | expected OK
[task 2022-07-05T11:10:06.834Z] 11:10:06     INFO - TEST-INFO took 365003ms
[task 2022-07-05T11:10:06.835Z] 11:10:06     INFO - Restarting browser for new test group
[task 2022-07-05T11:10:06.980Z] 11:10:06     INFO - Closing logging queue
[task 2022-07-05T11:10:06.980Z] 11:10:06     INFO - queue closed
[task 2022-07-05T11:10:06.991Z] 11:10:06     INFO - PID 13293 | 1657019406990	geckodriver	INFO	Listening on 127.0.0.1:45261
[task 2022-07-05T11:10:06.992Z] 11:10:06     INFO - Starting runner
[task 2022-07-05T11:10:07.227Z] 11:10:07     INFO - TEST-START | /webdriver/tests/get_active_element/get.py

Comment hidden (Intermittent Failures Robot)

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

Comment 2

•

3 years ago

Looks like that we never got a progress state of stop for the initial page load and as such WebDriver:NewSession doesn't return:

[task 2022-07-05T11:04:32.635Z] 11:04:32     INFO - PID 11854 | 1657019072633	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2022-07-05T11:04:32.640Z] 11:04:32     INFO - PID 11854 | 1657019072639	RemoteAgent	TRACE	[18] ProgressListener state=start: about:blank
[task 2022-07-05T11:04:32.898Z] 11:04:32     INFO - PID 11854 | console.error: SearchSettings: "_write: Could not write to settings file:" (new Error("cannot write without any engine.", "resource://gre/modules/SearchSettings.jsm", 218))
[task 2022-07-05T11:09:31.868Z] 11:09:31     INFO - PID 11854 | JavaScript error: , line 0: uncaught exception: 2147549183

Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/find_elements_from_element/user_prompts.py | expected OK → Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/find_elements_from_element/user_prompts.py | expected OK [initial tab doesn't finish loading]

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

Comment 3

•

3 years ago

The problem here is actually the following line:

Ignoring event 'DOMContentLoaded' because document has an invalid readyState of 'complete'.

Most likely we have an overlapping navigation here because we do not wait long enough for the initial tab to be finished loading.

Depends on: 1767295

Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/find_elements_from_element/user_prompts.py | expected OK [initial tab doesn't finish loading] → Intermittent TEST-UNEXPECTED-TIMEOUT Wd | expected OK [Ignoring event 'DOMContentLoaded' because document has an invalid readyState of 'complete']

Comment hidden (Intermittent Failures Robot)

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

Comment 6

•

3 years ago

No more failures since bug 1767295 has been fixed. Marking as fixed as well.

Assignee: nobody → jdescottes

Status: NEW → RESOLVED

Closed: 3 years ago

status-firefox104: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → 104 Branch

Comment hidden (Intermittent Failures Robot)

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

Comment 8

•

3 years ago

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

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

All of these failures were wrongly classified and are actually bug 1790325 or bug 1790329. I fixed them.

Comment hidden (Intermittent Failures Robot)

BMO Automation

Comment 13

•

3 years ago

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

Component: geckodriver → Marionette

Product: Testing → Remote Protocol

Comment hidden (Intermittent Failures Robot)

Bugzilla

Intermittent TEST-UNEXPECTED-TIMEOUT Wd | expected OK [Ignoring event 'DOMContentLoaded' because document has an invalid readyState of 'complete']

Categories

(Remote Protocol :: Marionette, defect, P5)

Tracking

(firefox104 fixed)

People

(Reporter: intermittent-bug-filer, Assigned: jdescottes)

References

Details

(Keywords: intermittent-failure)

Crash Data

Security

(public)

User Story

Description

Comment 1

Comment 2

Comment 3

Comment 5

Comment 6

Comment 7

Comment 8

Comment 9

Comment 10

Comment 11

Comment 12

Comment 13

Comment 14

Comment 15