Closed Bug 1431081 Opened 2 years ago Closed 2 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_async_script/user_prompts.py, /webdriver/tests/execute_script/user_prompts.py | expected OK

Categories

(Testing :: geckodriver, defect, P5)

Version 3
defect

Tracking

(firefox61 disabled, firefox62 fixed)

RESOLVED FIXED
mozilla62
Tracking Status
firefox61 --- disabled
firefox62 --- fixed

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
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.
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
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
Those two tests will be disabled by the next wptsync merge as covered by bug 1453105.
Depends on: 1453105
Both tests have been disabled based on the wptsync merge from bug 1453105.
See Also: → 1457244
Duplicate of this bug: 1457593
See Also: 1457244
Depends on: 1449538
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.
Attachment #8973670 - Flags: review?(ato)
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+
Attachment #8973670 - Flags: review?(mjzffr)
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
https://hg.mozilla.org/mozilla-central/rev/f5cb209a849d
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla62
Assignee: nobody → hskupin
You need to log in before you can comment on or make changes to this bug.