Closed Bug 1456641 Opened 2 years ago Closed 1 month ago

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

Categories

(Testing :: geckodriver, defect, P5)

Version 3
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure)

Shutdownhang which is blocked on bug 1449538.
Depends on: 1449538
Fixed by bug 1449538.
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
No longer blocks: 1459916
Duplicate of this bug: 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: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 2 years ago2 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: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 2 years ago9 months 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: 9 months ago7 months 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: 7 months ago1 month ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.