Closed Bug 1396180 Opened 8 years ago Closed 7 years ago

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

Categories

(Remote Protocol :: Marionette, defect, P5)

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

Tracking

(firefox61 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla61
Tracking Flags:
Tracking Status
firefox61 --- fixed

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

Timed out in handling the alert prompt: Z] 23:04:26 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/get_window_rect.py::test_get_window_rect_prompt_accept [task 2017-09-01T23:04:26.947366Z] 23:04:26 INFO - PID 1525 | 1504307066942 Marionette INFO New connections will no longer be accepted [task 2017-09-01T23:04:27.056154Z] 23:04:27 INFO - PID 1525 | [Child 1828] WARNING: pipe error (16): Connection reset by peer: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353 [task 2017-09-01T23:04:27.056543Z] 23:04:27 INFO - PID 1525 | [Child 1828] WARNING: pipe error (3): Connection reset by peer: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353 [task 2017-09-01T23:04:27.072551Z] 23:04:27 INFO - PID 1525 | 1504307067068 geckodriver::marionette INFO Starting browser /builds/worker/workspace/build/application/firefox/firefox with args ["-marionette"] [task 2017-09-01T23:04:27.351664Z] 23:04:27 INFO - PID 1525 | 1504307067343 addons.xpi WARN Error parsing extensions state: [Exception... "Component returned failure code: 0x80520012 (NS_ERROR_FILE_NOT_FOUND) [amIAddonManagerStartup.readStartupData]" nsresult: "0x80520012 (NS_ERROR_FILE_NOT_FOUND)" location: "JS frame :: resource://gre/modules/addons/XPIProvider.jsm :: loadExtensionState :: line 1515" data: no] Stack trace: loadExtensionState()@resource://gre/modules/addons/XPIProvider.jsm:1515 < getInstallState()@resource://gre/modules/addons/XPIProvider.jsm:1550 < checkForChanges()@resource://gre/modules/addons/XPIProvider.jsm:3085 < startup()@resource://gre/modules/addons/XPIProvider.jsm:2152 < callProvider()@resource://gre/modules/AddonManager.jsm:263 < _startProvider()@resource://gre/modules/AddonManager.jsm:731 < startup()@resource://gre/modules/AddonManager.jsm:898 < startup()@resource://gre/modules/AddonManager.jsm:3082 < observe()@jar:file:///builds/worker/workspace/build/application/firefox/omni.ja!/components/addonManager.js:65 [task 2017-09-01T23:04:27.795610Z] 23:04:27 INFO - PID 1525 | 1504307067789 Marionette INFO Enabled via --marionette [task 2017-09-01T23:04:30.071636Z] 23:04:30 INFO - PID 1525 | 1504307070062 Marionette INFO Listening on port 2828 [task 2017-09-01T23:04:30.148647Z] 23:04:30 INFO - PID 1525 | 1504307070138 Marionette DEBUG Register listener.js for window 2147483649 [task 2017-09-01T23:04:30.185167Z] 23:04:30 INFO - PID 1525 | 1504307070172 Marionette DEBUG Received DOM event "beforeunload" for "about:blank" [task 2017-09-01T23:04:30.185523Z] 23:04:30 INFO - PID 1525 | 1504307070177 Marionette DEBUG Received DOM event "pagehide" for "about:blank" [task 2017-09-01T23:04:30.186178Z] 23:04:30 INFO - PID 1525 | 1504307070177 Marionette DEBUG Received DOM event "unload" for "about:blank" [task 2017-09-01T23:04:30.188762Z] 23:04:30 INFO - PID 1525 | 1504307070183 Marionette DEBUG Received DOM event "DOMContentLoaded" for "data:text/html;charset=utf-8,%3Ctitle%3EWD%20doc%20title%3C/title%3E" [task 2017-09-01T23:04:30.189756Z] 23:04:30 INFO - PID 1525 | 1504307070187 Marionette DEBUG Received DOM event "pageshow" for "data:text/html;charset=utf-8,%3Ctitle%3EWD%20doc%20title%3C/title%3E" [task 2017-09-01T23:04:56.735338Z] 23:04:56 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/get_window_rect.py | expected OK [task 2017-09-01T23:04:56.735416Z] 23:04:56 INFO - TEST-INFO took 30002ms
https://wiki.mozilla.org/Bugmasters#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → INCOMPLETE
This happened again: https://treeherder.mozilla.org/logviewer.html#?job_id=155186947&repo=autoland [task 2018-01-10T00:47:06.204Z] 00:47:06 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/get_window_rect.py::test_handle_prompt_accept [task 2018-01-10T00:47:35.805Z] 00:47:35 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/get_window_rect.py | expected OK Here `get_window_rect.py::test_handle_prompt_accept` caused a timeout.
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Debug builds show a shutdown hang which most likely also looks like bug 1425559. [task 2018-01-12T17:40:48.051Z] 17:40:48 INFO - PID 5816 | [Parent 6120, IPDL Background] WARNING: Some storage operations are taking longer than expected during shutdown and will be aborted!: file /builds/worker/workspace/build/src/dom/quota/ActorsParent.cpp, line 5824 [task 2018-01-12T17:41:06.869Z] 17:41:06 INFO - PID 5816 | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping [task 2018-01-12T17:41:10.887Z] 17:41:10 INFO - PID 5816 | [Parent 6120, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/dom/xhr/XMLHttpRequestMainThread.cpp, line 2772 [task 2018-01-12T17:41:10.888Z] 17:41:10 INFO - PID 5816 | [Parent 6120, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/dom/xhr/XMLHttpRequestMainThread.cpp, line 2772 [task 2018-01-12T17:41:10.889Z] 17:41:10 INFO - PID 5816 | [Parent 6120, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/dom/xhr/XMLHttpRequestMainThread.cpp, line 2772 [task 2018-01-12T17:41:10.889Z] 17:41:10 INFO - PID 5816 | [Parent 6120, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/dom/xhr/XMLHttpRequestMainThread.cpp, line 2772 [task 2018-01-12T17:41:10.890Z] 17:41:10 INFO - PID 5816 | [Parent 6120, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/dom/xhr/XMLHttpRequestMainThread.cpp, line 2772 [task 2018-01-12T17:41:10.890Z] 17:41:10 INFO - PID 5816 | [Parent 6120, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/dom/xhr/XMLHttpRequestMainThread.cpp, line 2772 [task 2018-01-12T17:41:21.006Z] 17:41:21 INFO - PID 5816 | Hit MOZ_CRASH(Workers Hanging - A:3|S:0|Q:0-BC:0|WorkerHolderToken-BC:0|WorkerHolderToken-BC:0|WorkerHolderToken) at /builds/worker/workspace/build/src/dom/workers/RuntimeService.cpp:2187 [task 2018-01-12T17:41:21.010Z] 17:41:21 INFO - PID 5816 | ExceptionHandler::GenerateDump cloned child 6269 [task 2018-01-12T17:41:21.010Z] 17:41:21 INFO - PID 5816 | ExceptionHandler::SendContinueSignalToChild sent continue signal to child [task 2018-01-12T17:41:21.011Z] 17:41:21 INFO - PID 5816 | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
Flags: needinfo?(amarchesini)
Whiteboard: [stockwell unknown]
There are 35 failures in the past week. Platforms: linux64-qr opt and one debug; Linux opt and one debug Recent log failure: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=170684525&lineNumber=40892 Relevant part of the log: [task 2018-03-27T23:12:34.364Z] 23:12:34 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/get_window_rect.py | expected OK [task 2018-03-27T23:12:34.364Z] 23:12:34 INFO - TEST-INFO took 30002ms [task 2018-03-27T23:12:34.426Z] 23:12:34 WARNING - u'runner_teardown': () [task 2018-03-27T23:12:34.427Z] 23:12:34 INFO - Starting runner [task 2018-03-27T23:12:34.458Z] 23:12:34 INFO - PID 4566 | 1522192354452 geckodriver INFO geckodriver 0.20.0 ( 'b9de00749ad9' '2018-03-21 11:52 -0500') [task 2018-03-27T23:12:34.458Z] 23:12:34 INFO - PID 4566 | 1522192354453 webdriver::httpapi DEBUG Creating routes [task 2018-03-27T23:12:34.460Z] 23:12:34 INFO - PID 4566 | 1522192354456 geckodriver INFO Listening on 127.0.0.1:4447 [task 2018-03-27T23:12:34.961Z] 23:12:34 INFO - WebDriver HTTP server listening at http://127.0.0.1:4447/ [task 2018-03-27T23:12:34.962Z] 23:12:34 INFO - TEST-START | /webdriver/tests/interaction/element_clear.py [task 2018-03-27T23:12:35.148Z] 23:12:35 INFO - STDOUT: ============================= test session starts ============================== [task 2018-03-27T23:12:35.148Z] 23:12:35 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 2018-03-27T23:12:35.150Z] 23:12:35 INFO - STDOUT: rootdir: /builds/worker/workspace/build, inifile: [task 2018-03-27T23:12:35.150Z] 23:12:35 INFO - STDOUT: collecting ... [task 2018-03-27T23:12:35.210Z] 23:12:35 INFO - STDOUT: collected 80 items [task 2018-03-27T23:12:35.212Z] 23:12:35 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/interaction/element_clear.py::test_closed_context :whimboo Can you please take a look?
Status: REOPENED → RESOLVED
Closed: 8 years ago → 7 years ago
Flags: needinfo?(hskupin)
Resolution: --- → FIXED
There is nothing fixed here yet. So reopening the bug. Here an example from a log of an opt build: https://taskcluster-artifacts.net/IW_mHx0YTO-EL8WqAgvoew/0/public/logs/live_backing.log > [task 2018-03-27T23:12:04.412Z] 23:12:04 INFO - TEST-START | /webdriver/tests/get_window_rect.py [..] > [task 2018-03-27T23:12:04.913Z] 23:12:04 INFO - PID 4079 | 1522192324904 Marionette DEBUG Closed connection 0 > [task 2018-03-27T23:12:34.364Z] 23:12:34 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/get_window_rect.py | expected OK > [task 2018-03-27T23:12:34.364Z] 23:12:34 INFO - TEST-INFO took 30002ms You can see that there is a massively delayed shutdown and that the test gets aborted after 30s. This is for `get_window_rect.py::test_handle_prompt_accept`. It creates dialogs for alert, confirm, and prompt. But that happens after a restart of Firefox, and requesting that triggers the slow shutdown. So that means one of the previous sub tests of this module or even a formerly run module didn't clean-up correctly. The only test in question for `get_window_rect.py` is actually `test_no_browsing_context`: https://dxr.mozilla.org/mozilla-central/rev/b906009d875d1f5d29b0d1252cdb43a9b1a5889c/testing/web-platform/tests/webdriver/tests/get_window_rect.py#16-25 It creates a new window, close it, and tries to retrieve window rect details for the non-existent window. All looks proper to me. The test module as run before is fullscreen_window.py. Here I see some interesting failures in the log: > javascript error (500): ReferenceError: accept1 is not defined Which means that a dialog which should have been created was maybe failing and its references was never added as `session.accept1`. So I assume we try to shutdown Firefox from within fullscreen mode. Maybe this causes the slowness?
Status: RESOLVED → REOPENED
Flags: needinfo?(hskupin)
Resolution: FIXED → ---
I'm fairly sure now that the fullscreen window test is causing this brokeness. I filed bug 1449499 to get this fixed in the test. Andrea, it would still be great to investigate why we have such a long shutdown when it is getting triggered from within the fullscreen mode.
Depends on: 1449499
Ok, so even with my patch on bug 1449499 the hang is still present: https://treeherder.mozilla.org/#/jobs?repo=try&revision=f16233e0a5c4ab2fbe6354efea9bc0d2be610b7f&selectedJob=170755623 Related lines from the log viewer: https://treeherder.mozilla.org/logviewer.html#?job_id=170755623&repo=try&lineNumber=40512-40526 There is a hang when shutting down Firefox to create a new session. So we are blocked on bug 1449538.
Depends on: 1449538
Over the last 7 days there are 34 failures present on this bug. These happen on Linux, Linux x64 and linux64-qr. Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=173584826&lineNumber=40897 Here is the relevant part of that log: [task 2018-04-13T19:46:05.544Z] 19:46:05 INFO - PID 4319 | 1523648765537 geckodriver::marionette TRACE <- [1,91,{"error":"invalid session id","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:178:5\nInvalidSessionIDError@chrome://marionette/content/error.js:347:5\nassert.that/<@chrome://marionette/content/assert.js:405:13\nassert.session@chrome://marionette/content/assert.js:79:3\ndespatch@chrome://marionette/content/server.js:290:7\nasync*execute@chrome://marionette/content/server.js:267:11\nasync*onPacket/<@chrome://marionette/content/server.js:242:15\nasync*onPacket@chrome://marionette/content/server.js:241:8\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:500:9\n"},null] [task 2018-04-13T19:46:05.559Z] 19:46:05 INFO - PID 4319 | 1523648765548 Marionette DEBUG Closed connection 0 [task 2018-04-13T19:46:35.030Z] 19:46:35 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/get_window_rect.py | expected OK [task 2018-04-13T19:46:35.031Z] 19:46:35 INFO - TEST-INFO took 30002ms [task 2018-04-13T19:46:35.063Z] 19:46:35 WARNING - u'runner_teardown': () [task 2018-04-13T19:46:35.064Z] 19:46:35 INFO - Starting runner
Flags: needinfo?(hskupin)
(In reply to Stefan Hindli [:stefan_hindli] from comment #24) > Over the last 7 days there are 34 failures present on this bug. These happen > on Linux, Linux x64 and linux64-qr. Not sure what else I should add compared to what I already mentioned in comment 21. We are still blocked.
Flags: needinfo?(hskupin)
Fixed by bug 1449538.
Status: REOPENED → RESOLVED
Closed: 7 years ago → 7 years ago
status-firefox61: --- → fixed
Flags: needinfo?(amarchesini)
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
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.