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

Status: RESOLVED INCOMPLETE

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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/

Comment 1

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

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.

Comment 2

[Intermittent Failures Robot]

1 failures in 4182 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1590740&startday=2019-10-21&endday=2019-10-27&tree=all

Comment 3

[Intermittent Failures Robot]

1 failures in 4331 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• macosx1014-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1590740&startday=2019-11-25&endday=2019-12-01&tree=all

Comment 4

[Bogdan Tara[:bogdan_tara | bogdant]]

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

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 7

Platform breakdown:

• windows10-64-ccov: 6
• linux1804-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1590740&startday=2020-01-06&endday=2020-01-12&tree=all

Comment 6

[Intermittent Failures Robot]

24 failures in 3773 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 24

Platform breakdown:

• windows10-64-ccov: 24

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1590740&startday=2020-01-13&endday=2020-01-19&tree=all

Comment 7

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

(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.

Comment 8

[Intermittent Failures Robot]

3 failures in 4004 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 3

Platform breakdown:

• windows10-64-ccov: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1590740&startday=2020-01-20&endday=2020-01-26&tree=all

Comment 9

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

No more failures since 8 months. Closing as incomplete.

Comment 10

[BMO Automation]

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