Treeherder Bug Filer Reporter
	Description • 6 years ago
treeherder

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

	Henrik Skupin [:whimboo][⌚️UTC+1] Assignee
	Comment 1 • 6 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.

	Henrik Skupin [:whimboo][⌚️UTC+1] Assignee
	Comment 11 • 6 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

	Henrik Skupin [:whimboo][⌚️UTC+1] Assignee
	Comment 15 • 6 years ago

Those two tests will be disabled by the next wptsync merge as covered by bug 1453105.

	Henrik Skupin [:whimboo][⌚️UTC+1] Assignee
	Comment 17 • 6 years ago

Both tests have been disabled based on the wptsync merge from bug 1453105.

	Henrik Skupin [:whimboo][⌚️UTC+1] Assignee
	Comment 21 • 6 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.

	Andreas Tolfsen ❲:ato❳
	Comment 24 • 6 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

	Pulsebot
	Comment 25 • 6 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

	Andrei Ciure[:aciure]
	Comment 26 • 6 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/f5cb209a849d

	BMO Automation
	Comment 28 • 1 year ago

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