Closed
Bug 1431081
Opened 7 years ago
Closed 7 years ago
Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_async_script/user_prompts.py, /webdriver/tests/execute_script/user_prompts.py | expected OK
Categories
(Remote Protocol :: Marionette, defect, P5)
Tracking
(firefox61 disabled, firefox62 fixed)
RESOLVED
FIXED
mozilla62
People
(Reporter: intermittent-bug-filer, Assigned: whimboo)
References
Details
(Keywords: intermittent-failure, test-disabled)
Attachments
(1 file)
Filed by: csabou [at] mozilla.com
https://treeherder.mozilla.org/logviewer.html#?job_id=156849268&repo=autoland
https://queue.taskcluster.net/v1/task/XYh6YJuKRBGED0sSWuvMIQ/runs/0/artifacts/public/logs/live_backing.log
[task 2018-01-17T12:39:38.383Z] 12:39:38 INFO - PID 4161 | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping
[task 2018-01-17T12:39:38.794Z] 12:39:38 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/execute_async_script/user_prompts.py::test_handle_prompt_twice
[task 2018-01-17T12:39:38.798Z] 12:39:38 INFO - PID 4161 | 1516192778796 mozrunner::runner INFO Running command: "/builds/worker/workspace/build/application/firefox/firefox" "-marionette" "-profile" "/tmp/rust_mozprofile.FxkXge9KyeCJ"
[task 2018-01-17T12:39:39.686Z] 12:39:39 INFO - PID 4161 | 1516192779684 Marionette INFO Enabled via --marionette
[task 2018-01-17T12:39:42.867Z] 12:39:42 INFO - PID 4161 | GLib-GIO-Message: Using the 'memory' GSettings backend. Your settings will not be saved or shared with other applications.
[task 2018-01-17T12:39:43.650Z] 12:39:43 INFO - PID 4161 | 1516192783646 Marionette INFO Listening on port 2828
[task 2018-01-17T12:39:43.879Z] 12:39:43 INFO - STDOUT: FAILED
[task 2018-01-17T12:39:43.917Z] 12:39:43 INFO - PID 4161 | 1516192783911 addons.xpi WARN Exception running bootstrap method shutdown on activity-stream@mozilla.org: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver]" nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: resource://activity-stream/lib/SnippetsFeed.jsm :: uninit :: line 125" data: no] Stack trace: uninit()@resource://activity-stream/lib/SnippetsFeed.jsm:125 < onAction()@resource://activity-stream/lib/SnippetsFeed.jsm:141 < _middleware/</<()@resource://activity-stream/lib/Store.jsm:51 < Store/this[method]()@resource://activity-stream/lib/Store.jsm:30 < uninit()@resource://activity-stream/lib/Store.jsm:153 < uninit()@resource://activity-stream/lib/ActivityStream.jsm:274 < uninit()@resource://gre/modules/addons/XPIProvider.jsm -> jar:file:///builds/worker/workspace/build/application/firefox/browser/features/activity-stream@mozilla.org.xpi!/bootstrap.js:80 < shutdown()@resource://gre/modules/addons/XPIProvider.jsm -> jar:file:///builds/worker/workspace/build/application/firefox/browser/features/activity-stream@mozilla.org.xpi!/bootstrap.js:196 < callBootstrapMethod()@resource://gre/modules/addons/XPIProvider.jsm:4422 < observe()@resource://gre/modules/addons/XPIProvider.jsm:2282 < GeckoDriver.prototype.quit()@driver.js:3268
[task 2018-01-17T12:39:43.994Z] 12:39:43 INFO - PID 4161 | JavaScript error: chrome://marionette/content/error.js, line 172: Error: Document was unloaded
[task 2018-01-17T12:39:46.730Z] 12:39:46 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_async_script/user_prompts.py | expected OK
[task 2018-01-17T12:39:46.730Z] 12:39:46 INFO - TEST-INFO took 30002ms
Assignee | ||
Comment 1•7 years ago
|
||
Please note that with bug 1403923 we get longer execution times of tests. And as it looks like here, the `execute_async_script/user_prompts.py` test is working close on it's timeout limit of 30s in random cases for opt builds:
[task 2018-01-17T12:39:16.730Z] 12:39:16 INFO - TEST-START | /webdriver/tests/execute_async_script/user_prompts.py
[..]
[task 2018-01-17T12:39:46.730Z] 12:39:46 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_async_script/user_prompts.py | expected OK
[task 2018-01-17T12:39:46.730Z] 12:39:46 INFO - TEST-INFO took 30002ms
Those tests are forcing a couple of restarts of Firefox due to the @new_session decorator. And watching the timing across all subtests I cannot see a hang somewhere. So the only thing I see here is to request for a longer timeout.
But lets see how often this failure actually happens.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 11•7 years ago
|
||
The underlying issue for this problem seems to manifest for the `test_handle_prompt_twice` subtest. Here the "sessionstore-windows-restored" notification is massively delayed or doesn't happen at all.
https://treeherder.mozilla.org/logviewer.html#?job_id=170286388&repo=mozilla-inbound&lineNumber=39356-39386
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Updated•7 years ago
|
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_async_script/user_prompts.py | expected OK → Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_async_script/user_prompts.py, /webdriver/tests/execute_script/user_prompts.py | expected OK
Assignee | ||
Comment 15•7 years ago
|
||
Those two tests will be disabled by the next wptsync merge as covered by bug 1453105.
Depends on: 1453105
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 17•7 years ago
|
||
Both tests have been disabled based on the wptsync merge from bug 1453105.
status-firefox61:
--- → disabled
Keywords: test-disabled
Comment hidden (Intermittent Failures Robot) |
Comment hidden (mozreview-request) |
Assignee | ||
Comment 21•7 years ago
|
||
Bug 1449538 has been fixed. So the timeout should no longer appear for normal builds. For webrender we have to keep the test disabled given that Marionette takes a bit with its initialization, which might be related to the gfx window. But that's clearly a different bug.
Comment hidden (mozreview-request) |
Comment hidden (mozreview-request) |
Assignee | ||
Updated•7 years ago
|
Attachment #8973670 -
Flags: review?(ato)
Comment 24•7 years ago
|
||
mozreview-review |
Comment on attachment 8973670 [details]
Bug 1431081 - [wdspec] Unskip user prompt tests for execute (async) script tests.
https://reviewboard.mozilla.org/r/242042/#review248204
Attachment #8973670 -
Flags: review?(ato) → review+
Assignee | ||
Updated•7 years ago
|
Attachment #8973670 -
Flags: review?(mjzffr)
Comment 25•7 years ago
|
||
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/f5cb209a849d
[wdspec] Unskip user prompt tests for execute (async) script tests. r=ato
Comment 26•7 years ago
|
||
bugherder |
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox62:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla62
Updated•7 years ago
|
Assignee: nobody → hskupin
Comment hidden (Intermittent Failures Robot) |
Comment 28•2 years ago
|
||
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.
Description
•