Closed Bug 1590740 Opened 5 years ago Closed 4 years ago

Perma Tier 2 Central TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/minimize_window/user_prompts.py | expected OK (due to shutdown hang)

Categories

(Remote Protocol :: Marionette, defect, P5)

Product:
Remote Protocol
Component:
Marionette
Version:
Version 3
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=272521075&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/EA2VPT30T1Sdd_8UTiKDAg/runs/0/artifacts/public/logs/live_backing.log

[task 2019-10-23T06:02:36.311Z] 06:02:36 INFO - TEST-START | /webdriver/tests/minimize_window/user_prompts.py
[task 2019-10-23T06:02:36.447Z] 06:02:36 INFO - STDOUT: ============================= test session starts =============================
[task 2019-10-23T06:02:36.448Z] 06:02:36 INFO - STDOUT: platform win32 -- Python 2.7.11, pytest-unknown, py-1.5.2, pluggy-0.5.3.dev -- Z:\task_1571807174\build\venv\Scripts\python.exe
[task 2019-10-23T06:02:36.449Z] 06:02:36 INFO - STDOUT: rootdir: Z:\task_1571807174\build, inifile:
[task 2019-10-23T06:02:36.449Z] 06:02:36 INFO - STDOUT: collecting ...
[task 2019-10-23T06:02:36.530Z] 06:02:36 INFO - STDOUT: collected 18 items
[task 2019-10-23T06:02:36.531Z] 06:02:36 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/minimize_window/user_prompts.py::test_accept[capabilities0-alert-None]
[task 2019-10-23T06:02:36.531Z] 06:02:36 INFO - PID 3724 | 1571810556520 webdriver::server DEBUG -> DELETE /session/da8d637e-b187-4b3d-93be-3cb9f7d0b123
[task 2019-10-23T06:02:36.532Z] 06:02:36 INFO - PID 3724 | 1571810556518 Marionette DEBUG 0 -> [0,443,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2019-10-23T06:02:36.533Z] 06:02:36 INFO - PID 3724 | 1571810556519 Marionette INFO Stopped listening on port 2828
[task 2019-10-23T06:02:36.653Z] 06:02:36 INFO - PID 3724 | 1571810556635 Marionette TRACE Received observer notification quit-application
[task 2019-10-23T06:02:36.667Z] 06:02:36 INFO - PID 3724 | 1571810556644 Marionette DEBUG 0 <- [1,443,null,{"cause":"shutdown"}]
[task 2019-10-23T06:02:36.728Z] 06:02:36 INFO - PID 3724 | 1571810556718 webdriver::server DEBUG Deleting session
[task 2019-10-23T06:02:36.761Z] 06:02:36 INFO - PID 3724 | [Child 4356, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 1571810556740 Marionette

[task 2019-10-23T06:05:41.037Z] 06:05:41 INFO - PID 3724 | 1571810741015 Marionette DEBUG 0 -> [0,133,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2019-10-23T06:05:41.037Z] 06:05:41 INFO - PID 3724 | 1571810741021 Marionette DEBUG 0 <- [1,133,null,{"value":false}]
[task 2019-10-23T06:05:41.038Z] 06:05:41 INFO - PID 3724 | 1571810741023 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2019-10-23T06:05:41.139Z] 06:05:41 INFO - PID 3724 | 1571810741114 webdriver::server DEBUG -> POST /session/64df0127-1068-4ac2-ad20-4f5617a9ab89/execute/sync {"args": [], "script": "return document.hidden"}
[task 2019-10-23T06:05:41.140Z] 06:05:41 INFO - PID 3724 | 1571810741114 Marionette DEBUG 0 -> [0,134,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2019-10-23T06:05:41.140Z] 06:05:41 INFO - PID 3724 | 1571810741120 Marionette DEBUG 0 <- [1,134,null,{"value":false}]
[task 2019-10-23T06:05:41.141Z] 06:05:41 INFO - PID 3724 | 1571810741122 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2019-10-23T06:05:41.236Z] 06:05:41 INFO - PID 3724 | 1571810741213 webdriver::server DEBUG -> POST /session/64df0127-1068-4ac2-ad20-4f5617a9ab89/execute/sync {"args": [], "script": "return document.hidden"}
[task 2019-10-23T06:05:41.237Z] 06:05:41 INFO - PID 3724 | 1571810741213 Marionette DEBUG 0 -> [0,135,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2019-10-23T06:05:41.237Z] 06:05:41 INFO - PID 3724 | 1571810741218 Marionette DEBUG 0 <- [1,135,null,{"value":false}]
[task 2019-10-23T06:05:41.238Z] 06:05:41 INFO - PID 3724 | 1571810741221 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2019-10-23T06:05:41.323Z] 06:05:41 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/minimize_window/user_prompts.py | expected OK
[task 2019-10-23T06:05:41.324Z] 06:05:41 INFO - TEST-INFO took 185015ms
[task 2019-10-23T06:05:41.491Z] 06:05:41 INFO - PID 3724 | 1571810741312 webdriver::server DEBUG -> POST /session/64df0127-1068-4ac2-ad20-4f5617a9ab89/execute/sync {"args": [], "script": "return document.hidden"}
[task 2019-10-23T06:05:41.493Z] 06:05:41 INFO - PID 3724 | 1571810741312 Marionette DEBUG 0 -> [0,136,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2019-10-23T06:05:41.494Z] 06:05:41 INFO - PID 3724 | 1571810741317 Marionette DEBUG 0 <- [1,136,null,{"value":false}]
[task 2019-10-23T06:05:41.494Z] 06:05:41 INFO - PID 3724 | 1571810741319 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2019-10-23T06:05:41.495Z] 06:05:41 INFO - PID 3724 | Exiting due to channel error.
[task 2019-10-23T06:05:41.496Z] 06:05:41 INFO - PID 3724 | Exiting due to channel error.
[task 2019-10-23T06:05:41.496Z] 06:05:41 INFO - Closing logging queue
[task 2019-10-23T06:05:41.496Z] 06:05:41 INFO - queue closed
[task 2019-10-23T06:05:41.497Z] 06:05:41 INFO - Starting runner
[task 2019-10-23T06:05:43.229Z] 06:05:43 INFO - PID 4952 | 1571810743212 geckodriver DEBUG Listening on 127.0.0.1:53693
[task 2019-10-23T06:05:43.693Z] 06:05:43 INFO - WebDriver HTTP server listening at http://127.0.0.1:53693/

There is an about 30s hang during shutdown:

[task 2019-10-23T06:04:50.638Z] 06:04:50     INFO - PID 3724 | dThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-10-23T06:04:50.855Z] 06:04:50     INFO - PID 3724 | [Parent 6124, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-10-23T06:04:50.889Z] 06:04:50     INFO - PID 3724 | [Child 4556, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium[Parent 6124, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 160
[task 2019-10-23T06:04:50.929Z] 06:04:50     INFO - PID 3724 | JavaScript error: resource://gre/modules/JSONFile.jsm, line 173: Error: Data is not ready.
[task 2019-10-23T06:04:50.976Z] 06:04:50     INFO - PID 3724 | console.error: (new Error("IndexedDB list() The operation failed for reasons unrelated to the database itself and not covered by any other error code.", "resource://services-common/kinto-offline-client.js", 603))
[task 2019-10-23T06:05:05.614Z] 06:05:05     INFO - PID 3724 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 433))
[task 2019-10-23T06:05:21.237Z] 06:05:21     INFO - PID 3724 | 1571810721207	Marionette	TRACE	Received observer notification xpcom-will-shutdown

Kris, could this somehow be related to Kinto? Also sessionstore seem to be affected given that it cannot store the state.

Flags: needinfo?(kmaglione+bmo)
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/minimize_window/user_prompts.py | expected OK → Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/minimize_window/user_prompts.py | expected OK (due to shutdown hang)

Seems to perma fail on Windows 10 Ccov Tier 2 Central.

https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&searchStr=windows%2C10%2Cx64%2Cccov%2Copt%2Cweb%2Cplatform%2Ctests%2Ctest-windows10-64-ccov%2Fopt-web-platform-tests-wdspec-e10s-4%2Cw%28wd4%29&tochange=1536cf66a302811c1e302118e0d356c6c7545fab&fromchange=408f6c0f98146da1f540d5b6759e4d9a787db8ab&selectedJob=284604324

Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/minimize_window/user_prompts.py | expected OK (due to shutdown hang) → Perma Tier 2 Central TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/minimize_window/user_prompts.py | expected OK (due to shutdown hang)

(In reply to Bogdan Tara[:bogdan_tara] from comment #4)

Seems to perma fail on Windows 10 Ccov Tier 2 Central.

This ramped up recently, but warrants its own bug. See bug 1495002 for details about the ccov specific failure.

No more failures since 8 months. Closing as incomplete.

Status: NEW → RESOLVED
Closed: 4 years ago
Flags: needinfo?(kmaglione+bmo)
Resolution: --- → INCOMPLETE
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.