Closed Bug 1456641 Opened 6 years ago Closed 2 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/close_window/close.py | expected OK

Categories

(Remote Protocol :: Marionette, defect, P5)

Version 3
defect

Tracking

(Not tracked)

RESOLVED DUPLICATE of bug 1630162

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Shutdownhang which is blocked on bug 1449538.
Depends on: 1449538
Fixed by bug 1449538.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
No longer blocks: 1459916
As it looks like this hasn't been fixed yet:

https://treeherder.mozilla.org/logviewer.html#?job_id=175381923&repo=autoland&lineNumber=17898

> [task 2018-04-24T18:08:11.521Z] 18:08:11     INFO - PID 1171 | 1524593291515	Marionette	TRACE	0 -> [0,45,"WebDriver:CloseWindow",{}]
> [task 2018-04-24T18:08:11.522Z] 18:08:11     INFO - PID 1171 | 1524593291517	Marionette	TRACE	0 <- [1,45,null,[]]
> [task 2018-04-24T18:08:11.523Z] 18:08:11     INFO - PID 1171 | 1524593291518	geckodriver::marionette	TRACE	<- [1,45,null,[]]
> [task 2018-04-24T18:08:11.524Z] 18:08:11     INFO - PID 1171 | 1524593291518	webdriver::server	DEBUG	Last window was closed, deleting session
> [task 2018-04-24T18:08:11.525Z] 18:08:11     INFO - PID 1171 | 1524593291518	webdriver::server	DEBUG	Deleting session
> [task 2018-04-24T18:08:11.526Z] 18:08:11     INFO - PID 1171 | 1524593291518	geckodriver::marionette	TRACE	-> 49:[0,46,"Marionette:Quit",{"flags":["eForceQuit"]}]
> [task 2018-04-24T18:08:11.527Z] 18:08:11     INFO - PID 1171 | 1524593291519	Marionette	TRACE	0 -> [0,46,"Marionette:Quit",{"flags":["eForceQuit"]}]
> [task 2018-04-24T18:08:11.528Z] 18:08:11     INFO - PID 1171 | 1524593291522	Marionette	DEBUG	New connections will no longer be accepted
> [task 2018-04-24T18:08:11.584Z] 18:08:11     INFO - PID 1171 | 1524593291578	Marionette	TRACE	0 <- [1,46,null,{"cause":"shutdown"}]
> [task 2018-04-24T18:08:11.607Z] 18:08:11     INFO - PID 1171 | 1524593291599	geckodriver::marionette	TRACE	<- [1,46,null,{"cause":"shutdown"}]
> [task 2018-04-24T18:08:11.623Z] 18:08:11     INFO - PID 1171 | 1524593291611	Marionette	DEBUG	Closed connection 0
> [task 2018-04-24T18:08:37.962Z] 18:08:37     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/close_window/close.py | expected OK
> [task 2018-04-24T18:08:37.963Z] 18:08:37     INFO - TEST-INFO took 30016ms

So there is clearly a different hang during shutdown. Sadly this is an opt build and there is no way to get more details.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Target Milestone: mozilla61 → ---
Low intermittent failure and only seems to happen for qr builds now. It should be blocked on bug 1464756.
Depends on: 1464756
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 6 years ago6 years ago
Resolution: --- → INCOMPLETE
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 6 years ago6 years ago
Resolution: --- → INCOMPLETE
Recent log failure:
https://treeherder.mozilla.org/logviewer.html#?job_id=211027828&repo=mozilla-inbound&lineNumber=1103
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 6 years ago6 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 6 years ago5 years ago
Resolution: --- → INCOMPLETE

Why is this "INCOMPLETE" and not "WONTFIX"?

Never mind. I see it was done by a robot.

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=280343018&repo=autoland&lineNumber=1684

[task 2019-12-09T19:18:15.592Z] 19:18:15 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/close_window/close.py::test_close_last_browsing_context
[task 2019-12-09T19:18:15.592Z] 19:18:15 INFO - PID 1182 | 1575919095437 webdriver::server DEBUG -> POST /session/c66372b3-db94-403a-abf1-257ec0123005/window/rect {"width": 800, "height": 600}
[task 2019-12-09T19:18:15.593Z] 19:18:15 INFO - PID 1182 | 1575919095439 Marionette DEBUG 0 -> [0,84,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2019-12-09T19:18:15.593Z] 19:18:15 INFO - PID 1182 | 1575919095443 Marionette DEBUG 0 <- [1,84,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2019-12-09T19:18:15.595Z] 19:18:15 INFO - PID 1182 | 1575919095445 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2019-12-09T19:18:15.595Z] 19:18:15 INFO - PID 1182 | 1575919095454 webdriver::server DEBUG -> POST /session/c66372b3-db94-403a-abf1-257ec0123005/window/rect {"y": 100, "x": 100}
[task 2019-12-09T19:18:15.596Z] 19:18:15 INFO - PID 1182 | 1575919095455 Marionette DEBUG 0 -> [0,85,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2019-12-09T19:18:15.596Z] 19:18:15 INFO - PID 1182 | 1575919095470 Marionette DEBUG 0 <- [1,85,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2019-12-09T19:18:15.598Z] 19:18:15 INFO - PID 1182 | 1575919095471 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2019-12-09T19:18:15.598Z] 19:18:15 INFO - PID 1182 | 1575919095473 webdriver::server DEBUG -> GET /session/c66372b3-db94-403a-abf1-257ec0123005/window/handles
[task 2019-12-09T19:18:15.599Z] 19:18:15 INFO - PID 1182 | 1575919095474 Marionette DEBUG 0 -> [0,86,"WebDriver:GetWindowHandles",{}]
[task 2019-12-09T19:18:15.599Z] 19:18:15 INFO - PID 1182 | 1575919095474 Marionette DEBUG 0 <- [1,86,null,["17"]]
[task 2019-12-09T19:18:15.600Z] 19:18:15 INFO - PID 1182 | 1575919095474 webdriver::server DEBUG <- 200 OK {"value":["17"]}
[task 2019-12-09T19:18:15.601Z] 19:18:15 INFO - PID 1182 | 1575919095475 webdriver::server DEBUG -> DELETE /session/c66372b3-db94-403a-abf1-257ec0123005/window
[task 2019-12-09T19:18:15.601Z] 19:18:15 INFO - PID 1182 | 1575919095475 Marionette DEBUG 0 -> [0,87,"WebDriver:CloseWindow",{}]
[task 2019-12-09T19:18:15.602Z] 19:18:15 INFO - PID 1182 | 1575919095476 Marionette DEBUG 0 <- [1,87,null,[]]
[task 2019-12-09T19:18:15.603Z] 19:18:15 INFO - PID 1182 | 1575919095476 webdriver::server DEBUG Last window was closed, deleting session
[task 2019-12-09T19:18:15.604Z] 19:18:15 INFO - PID 1182 | 1575919095476 webdriver::server DEBUG Deleting session
[task 2019-12-09T19:18:15.604Z] 19:18:15 INFO - PID 1182 | 1575919095477 Marionette DEBUG 0 -> [0,88,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2019-12-09T19:18:15.605Z] 19:18:15 INFO - PID 1182 | 1575919095477 Marionette INFO Stopped listening on port 2828
[task 2019-12-09T19:18:15.653Z] 19:18:15 INFO - PID 1182 | 1575919095577 Marionette TRACE Received observer notification quit-application
[task 2019-12-09T19:18:15.653Z] 19:18:15 INFO - PID 1182 | 1575919095583 Marionette DEBUG 0 <- [1,88,null,{"cause":"shutdown"}]
[task 2019-12-09T19:18:15.653Z] 19:18:15 INFO - PID 1182 | 1575919095622 Marionette DEBUG Closed connection 0
[task 2019-12-09T19:18:16.072Z] 19:18:16 INFO - PID 1182 | JavaScript error: resource://gre/modules/UrlClassifierListManager.jsm, line 680: TypeError: this.tablesData[table] is undefined
[task 2019-12-09T19:18:30.587Z] 19:18:30 INFO - PID 1182 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 433))
[task 2019-12-09T19:18:38.130Z] 19:18:38 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/close_window/close.py | expected OK
[task 2019-12-09T19:18:38.130Z] 19:18:38 INFO - TEST-INFO took 30015ms
[task 2019-12-09T19:18:38.196Z] 19:18:38 INFO - Closing logging queue
[task 2019-12-09T19:18:38.197Z] 19:18:38 INFO - queue closed
[task 2019-12-09T19:18:38.198Z] 19:18:38 INFO - Starting runner
[task 2019-12-09T19:18:38.218Z] 19:18:38 INFO - PID 1373 | 1575919118213 geckodriver DEBUG Listening on 127.0.0.1:54181
[task 2019-12-09T19:18:38.718Z] 19:18:38 INFO - WebDriver HTTP server listening at http://127.0.0.1:54181/
[task 2019-12-09T19:18:38.718Z] 19:18:38 INFO - TEST-START | /webdriver/tests/close_window/user_prompts.py
[task 2019-12-09T19:18:39.062Z] 19:18:39 INFO - STDOUT: ============================= test session starts ==============================
[task 2019-12-09T19:18:39.062Z] 19:18:39 INFO - STDOUT: platform linux2 -- Python 2.7.12, pytest-unknown, py-1.5.2, pluggy-0.5.3.dev -- /builds/worker/workspace/build/venv/bin/python
[task 2019-12-09T19:18:39.063Z] 19:18:39 INFO - STDOUT: rootdir: /builds/worker/workspace/build, inifile:
[task 2019-12-09T19:18:39.063Z] 19:18:39 INFO - STDOUT: collecting ...
[task 2019-12-09T19:18:39.112Z] 19:18:39 INFO - STDOUT: collected 18 items
[task 2019-12-09T19:18:39.112Z] 19:18:39 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/close_window/user_prompts.py::test_accept[capabilities0-alert]

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
See Also: → 1608956

Looks like the shutdown phase for profile-before-change gets finished but profile-before-change-telemetry is never started:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=296180058&repo=mozilla-release&lineNumber=1151-1153

Maybe this happens due to the following session file error?

[task 2020-04-03T19:17:22.151Z] 19:17:22 INFO - PID 1597 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 433))

In working cases this failure doesn't appear:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=296180058&repo=mozilla-release&lineNumber=32805-32817

Chris, do you have any idea? We see this across a lot of different Marionette and Wdspec tests. So if that is a telemetry problem we should file a new bug for it, and mark all known failures dependent o nit.

Flags: needinfo?(chutten)

Here actually another failure from a different test:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=296180553&repo=mozilla-release&lineNumber=61442-61447

[task 2020-04-03T19:32:08.395Z] 19:32:08     INFO - PID 7332 | DEBUG: Finished phase profile-before-change
[task 2020-04-03T19:32:08.433Z] 19:32:08     INFO - PID 7332 | 
[task 2020-04-03T19:32:08.433Z] 19:32:08     INFO - PID 7332 | ###!!! [Parent][DispatchAsyncMessage] Error: PBackgroundIDBFactory::Msg_PBackgroundIDBFactoryRequestConstructor Value error: message was deserialized, but contained an illegal value
[task 2020-04-03T19:32:08.433Z] 19:32:08     INFO - PID 7332 | 
[task 2020-04-03T19:32:23.220Z] 19:32:23     INFO - PID 7332 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 433))
[task 2020-04-03T19:32:38.411Z] 19:32:38     INFO - PID 7332 | DEBUG: Starting phase profile-before-change-telemetry

So this problem might happen in-between those phases?

Flags: needinfo?(florian)

This is all beta and release. So lets move the discussion over to bug 1623007.

Flags: needinfo?(florian)
Flags: needinfo?(chutten)
Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

(In reply to Alexandru Michis [:malexandru] from comment #60)

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=330845141&repo=autoland&lineNumber=2087

This is actually a timeout because of bug 1676582. There is no activity of Firefox after marionette got enabled.

Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=355997267&repo=autoland&lineNumber=1916

[task 2021-10-25T22:42:00.053Z] 22:42:00     INFO - STDOUT: PASSED
[task 2021-10-25T22:42:00.055Z] 22:42:00     INFO - PID 2584 | 1635201720053	webdriver::server	DEBUG	-> POST /session/None/timeouts {"implicit": 0}
[task 2021-10-25T22:42:00.056Z] 22:42:00     INFO - STDERR: Ignored exception invalid session id (404): Tried to run command without establishing a connection
[task 2021-10-25T22:42:00.057Z] 22:42:00     INFO - PID 2584 | 1635201720053	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"invalid session id","message":"Tried to run command without establishing a connection","stacktrace":""}}
[task 2021-10-25T22:42:00.058Z] 22:42:00     INFO - PID 2584 | 1635201720055	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_163519815348501\\AppData\\Local\\Temp\\tmpwcbet7k6.mozrunner"], "binary": "Z:\\task_163519815348501\\build\\application\\firefox\\firefox.exe"}}}}
[task 2021-10-25T22:42:00.059Z] 22:42:00     INFO - PID 2584 | 1635201720055	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2021-10-25T22:42:00.061Z] 22:42:00     INFO - PID 2584 | 1635201720056	geckodriver::capabilities	DEBUG	Found version 95.0a1
[task 2021-10-25T22:42:00.062Z] 22:42:00     INFO - PID 2584 | 1635201720057	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_163519815348501\\AppData\\Local\\Temp\\tmpwcbet7k6.mozrunner\\user.geckodriver_backup"
[task 2021-10-25T22:42:00.071Z] 22:42:00     INFO - PID 2584 | 1635201720069	mozrunner::runner	INFO	Running command: "Z:\\task_163519815348501\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_163519815348501\\AppData\\Local\\Temp\\tmpwcbet7k6.mozrunner" "-no-remote"
[task 2021-10-25T22:42:00.073Z] 22:42:00     INFO - PID 2584 | 1635201720071	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1:2828
[task 2021-10-25T22:42:00.258Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker AddonManager: shutting down. for phase profile-before-change
[task 2021-10-25T22:42:00.273Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase profile-before-change
[task 2021-10-25T22:42:00.274Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker IOUtils Blocker (xpcom-will-shutdown) for phase xpcom-will-shutdown
[task 2021-10-25T22:42:00.276Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker XPIProvider shutdown for phase quit-application-granted
[task 2021-10-25T22:42:00.277Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2021-10-25T22:42:00.277Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker ServiceWorkerRegistrar: Flushing data for phase profile-before-change
[task 2021-10-25T22:42:00.278Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2021-10-25T22:42:00.283Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2021-10-25T22:42:00.293Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2021-10-25T22:42:00.298Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change
[task 2021-10-25T22:42:00.300Z] 22:42:00     INFO - PID 2584 | 1635201720299	Marionette	INFO	Marionette enabled
[task 2021-10-25T22:42:00.308Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2021-10-25T22:42:00.321Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker OS.File: flush pending requests, warn about unclosed files, shut down service. for phase xpcom-will-shutdown
[task 2021-10-25T22:42:00.334Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker OS.File: flush I/O queued before profileBeforeChange for phase profile-before-change
[task 2021-10-25T22:42:00.336Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker ClientManagerService: start destroying IPC actors early for phase xpcom-will-shutdown
[task 2021-10-25T22:42:00.395Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker MediaShutdownManager: shutdown for phase profile-before-change
[task 2021-10-25T22:42:00.414Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker Remote Settings profile-before-change for phase profile-before-change
[task 2021-10-25T22:42:00.521Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker GMPProvider for phase AddonManager: Waiting for providers to shut down.
[task 2021-10-25T22:42:00.535Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker ContentParent: id=221f3c00 for phase xpcom-will-shutdown
[task 2021-10-25T22:42:00.536Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker ContentParent: id=221f3c00 for phase profile-before-change
[task 2021-10-25T22:42:00.542Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker ServiceWorkerShutdownBlocker: shutting down Service Workers for phase profile-change-teardown
[task 2021-10-25T22:42:00.586Z] 22:42:00     INFO - PID 2584 | DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2021-10-25T22:42:01.357Z] 22:42:01     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/close_window/close.py | expected OK
[task 2021-10-25T22:42:01.357Z] 22:42:01     INFO - TEST-INFO took 30014ms
[task 2021-10-25T22:42:01.896Z] 22:42:01     INFO - Closing logging queue
[task 2021-10-25T22:42:01.910Z] 22:42:01     INFO - queue closed
[task 2021-10-25T22:42:01.912Z] 22:42:01     INFO - Starting runner
[task 2021-10-25T22:42:03.206Z] 22:42:03     INFO - PID 6200 | 1635201722702	geckodriver	INFO	Listening on 127.0.0.1:49961
[task 2021-10-25T22:42:03.209Z] 22:42:03     INFO - WebDriver HTTP server listening at http://127.0.0.1:49961/
[task 2021-10-25T22:42:03.211Z] 22:42:03     INFO - TEST-START | /webdriver/tests/close_window/user_prompts.py
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Latest failure here happens because of a missing toplevel-window-ready notification.

Depends on: 1382162
Status: REOPENED → RESOLVED
Closed: 3 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

All the recent failures are about hangs during shutdown. As such lets dupe over to bug 1630162.

Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → DUPLICATE
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
You need to log in before you can comment on or make changes to this bug.