1462013 - Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/minimize_window/user_prompts.py | expected OK

Status: RESOLVED INCOMPLETE

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: archaeopteryx [at] coole-files.de

https://treeherder.mozilla.org/logviewer.html#?job_id=178636585&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/N42SMCikRGKEtvgRswneKA/runs/0/artifacts/public/logs/live_backing.log

Comment 1

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

First, there are startup delays of 5s based on bug 1460193, but there is also a long shutdown time of 7s:

https://treeherder.mozilla.org/logviewer.html#?job_id=178636585&repo=mozilla-inbound&lineNumber=45072-45196

> [task 2018-05-15T22:59:42.643Z] 22:59:42     INFO - PID 4653 | 1526425182634	Marionette	TRACE	0 -> [0,8,"Marionette:Quit",{"flags":["eForceQuit"]}]
> [..]
> [task 2018-05-15T22:59:45.514Z] 22:59:45     INFO - PID 4653 | 1526425185509	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
> [..]
> [task 2018-05-15T22:59:49.060Z] 22:59:49     INFO - PID 4653 | 1526425189057	geckodriver::marionette	DEBUG	Browser process stopped: exit code: 0

Andrea, do you have an idea based on the logs from the debug build?

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* linux64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1462013&startday=2018-05-14&endday=2018-05-20&tree=trunk

Comment 3

[Oana Pop-Rus]

New occurrences on beta simulation: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=229430304&repo=try&lineNumber=73055

Comment 4

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

There is a delayed shutdown of about 20s between the quit request and the xpcom-will-shutdown notification is send:

14:15:23 INFO - PID 2736 | 1550672123966 Marionette DEBUG 0 -> [0,159,"Marionette:Quit",{"flags":["eForceQuit"]}]
14:15:23 INFO - PID 2736 | 1550672123966 Marionette DEBUG 0 <- [1,159,{"error":"invalid session id","message":"Tried to run command without establishing a connection","stacktrace":"WebDriv ... t@chrome://marionette/content/server.js:236:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:492:20\n"},null]
14:15:23 INFO - PID 2736 | [Parent 2740, Gecko_IOThread] WARNING: pipe error: 109: file z:/task_1550663791/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
14:15:23 INFO - PID 2736 | [Child 8224, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1550663791/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
14:15:23 INFO - PID 2736 | [Child 8224, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_15501550672123976 Marionette DEBUG Closed connection 0
14:15:27 INFO - PID 2736 | console.error:
14:15:27 INFO - PID 2736 | [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIAppShellService.hiddenDOMWindow]" nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: resource://activity-stream/lib/DownloadsManager.jsm :: init :: line 44" data: no]: init@resource://activity-stream/lib/DownloadsManager.jsm:44:5
14:15:27 INFO - PID 2736 | postInit@resource://activity-stream/lib/HighlightsFeed.jsm:60:27
14:15:27 INFO - PID 2736 | handler@resource://gre/modules/EventEmitter.jsm:94:11
14:15:27 INFO - PID 2736 | emit@resource://gre/modules/EventEmitter.jsm:149:20
14:15:27 INFO - PID 2736 | init@resource://activity-stream/lib/SectionsManager.jsm:119:10
14:15:27 INFO - PID 2736 | observe@resource://gre/modules/AsyncShutdown.jsm:532:16
14:15:27 INFO - PID 2736 |
14:15:35 INFO - PID 2736 | [Parent 2740, Gecko_IOThread] WARNING: pipe error: 109: file z:/task_1550663791/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
14:15:35 INFO - PID 2736 | [Parent 2740, Gecko_IOThread] WARNING: pipe error: 109: file z:/task_1550663791/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
14:15:35 INFO - PID 2736 | [Child 8576, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1550663791/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
14:15:35 INFO - PID 2736 | [Child 8576, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task[Child 6280, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1550663791/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
14:15:44 INFO - PID 2736 | [Child 6280, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1550663791/build/src1550672144643 Marionette TRACE Received observer notification xpcom-will-shutdown

Not sure if that might be related to the activity stream error. Mike do you know whom we could ask here?

Comment 5

[Mike Conley (:mconley) (:⚙️)]

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #4)

Not sure if that might be related to the activity stream error. Mike do you know whom we could ask here?

This frame:

14:15:27 INFO - PID 2736 | observe@resource://gre/modules/AsyncShutdown.jsm:532:16

is from AsyncShutdown, which is spinning the event loop waiting for some component to finish shutting down. The error from Activity Stream being reported is, I believe, a spurious error that occurs while spinning the event loop, but is not the cause of the timeout.

This stack is more important:

14:07:39 INFO - PID 4712 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"Extension shutdown: [e-mail]","state":{"state":"Shutdown: Storage"},"filename":"resource://gre/modules/addons/XPIProvider.jsm","lineNumber":2297,"stack":["resource://gre/modules/addons/XPIProvider.jsm:startup/<:2297","resource://gre/modules/AsyncShutdown.jsm:observe:532","chrome://marionette/content/driver.js:GeckoDriver.prototype.quit:3376","chrome://marionette/content/server.js:despatch:289","chrome://marionette/content/server.js:execute:262","chrome://marionette/content/server.js:onPacket/<:235","chrome://marionette/content/server.js:onPacket:236","chrome://marionette/content/transport.js:_onJSONObjectReady/<:492"]}] Barrier: profile-change-teardown

So it looks like this has to do with the add-on manager shutting down.

There are a few more:

14:16:44 INFO - PID 2700 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"CrashMonitor: Writing notifications to file after receiving profile-before-change","state":"(none)","filename":"resource://gre/modules/CrashMonitor.jsm","lineNumber":168,"stack":["resource://gre/modules/CrashMonitor.jsm:init:168","resource://gre/modules/nsCrashMonitor.jsm:observe:19"]}] Barrier: OS.File: Waiting for clients before profileBeforeChange

14:16:44 INFO - PID 2700 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"OS.File: flush I/O queued before profileBeforeChange","state":{"launched":true,"shutdown":false,"worker":true,"pendingReset":false,"latestSent":["Wed Feb 20 2019 14:16:44 GMT+0000 (Greenwich Mean Time)","writeAtomic"],"latestReceived":["Wed Feb 20 2019 14:16:44 GMT+0000 (Greenwich Mean Time)",804],"messagesSent":25,"messagesReceived":25,"messagesQueued":27,"DEBUG":false,"clients":[{"name":"CrashMonitor: Writing notifications to file after receiving profile-before-change","state":"(none)","filename":"resource://gre/modules/CrashMonitor.jsm","lineNumber":168,"stack":["resource://gre/modules/CrashMonitor.jsm:init:168","resource://gre/modules/nsCrashMonitor.jsm:observe:19"]}]},"filename":"resource://gre/modules/osfile/osfile_async_front.jsm","lineNumber":1459,"stack":["resource://gre/modules/osfile/osfile_async_front.jsm:setupShutdown:1459","resource://gre/modules/osfile/osfile_async_front.jsm:null:1479","resource://gre/modules/osfile.jsm:null:11","resource://gre/modules/addons/GMPProvider.jsm:null:13","resource://gre/modules/AddonManager.jsm:startup:787","resource://gre/modules/AddonManager.jsm:startup:2794","resource://gre/modules/addonManager.js:observe:65"]},{"name":"Flush WebExtension StartupCache","state":"(none)","filename":"resource://gre/modules/ExtensionParent.jsm","lineNumber":1659,"stack":["resource://gre/modules/ExtensionParent.jsm:save:1659","resource://gre/modules/ExtensionParent.jsm:get:1762","resource://gre/modules/addons/XPIProvider.jsm:awaitPromise:187","resource://gre/modules/addons/XPIInstall.jsm:syncLoadManifestFromFile:611","resource://gre/modules/addons/XPIDatabase.jsm:addMetadata:2349","resource://gre/modules/addons/XPIDatabase.jsm:processFileChanges:2719","resource://gre/modules/addons/XPIProvider.jsm:checkForChanges:2640","resource://gre/modules/addons/XPIProvider.jsm:startup:2224","resource://gre/modules/AddonManager.jsm:callProvider:204","resource://gre/modules/AddonManager.jsm:_startProvider:653","resource://gre/modules/AddonManager.jsm:startup:806","resource://gre/modules/AddonManager.jsm:startup:2794","resource://gre/modules/addonManager.js:observe:65"]}] Barrier: profile-before-change

These two are waiting for some off main thread IO to flush...

14:17:18 INFO - PID 2700 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"Extension shutdown: [e-mail]","state":{"state":"Shutdown: Storage"},"filename":"resource://gre/modules/addons/XPIProvider.jsm","lineNumber":2297,"stack":["resource://gre/modules/addons/XPIProvider.jsm:startup/<:2297","resource://gre/modules/AsyncShutdown.jsm:observe:532","chrome://marionette/content/driver.js:GeckoDriver.prototype.quit:3376","chrome://marionette/content/server.js:despatch:289","chrome://marionette/content/server.js:execute:262","chrome://marionette/content/server.js:onPacket/<:235","chrome://marionette/content/server.js:onPacket:236","chrome://marionette/content/transport.js:_onJSONObjectReady/<:492"]}] Barrier: profile-change-teardown

There's XPIProvider again... seems to have to do with Storage...

and finally:

14:19:18 INFO - PID 928 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"CrashMonitor: Writing notifications to file after receiving profile-before-change","state":"(none)","filename":"resource://gre/modules/CrashMonitor.jsm","lineNumber":168,"stack":["resource://gre/modules/CrashMonitor.jsm:init:168","resource://gre/modules/nsCrashMonitor.jsm:observe:19"]}] Barrier: OS.File: Waiting for clients before profileBeforeChange
14:19:18 INFO - PID 928 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"OS.File: flush I/O queued before profileBeforeChange","state":{"launched":true,"shutdown":false,"worker":true,"pendingReset":false,"latestSent":["Wed Feb 20 2019 14:19:18 GMT+0000 (Greenwich Mean Time)","exists"],"latestReceived":["Wed Feb 20 2019 14:19:18 GMT+0000 (Greenwich Mean Time)",null],"messagesSent":29,"messagesReceived":29,"messagesQueued":30,"DEBUG":false,"clients":[{"name":"CrashMonitor: Writing notifications to file after receiving profile-before-change","state":"(none)","filename":"resource://gre/modules/CrashMonitor.jsm","lineNumber":168,"stack":["resource://gre/modules/CrashMonitor.jsm:init:168","resource://gre/modules/nsCrashMonitor.jsm:observe:19"]}]},"filename":"resource://gre/modules/osfile/osfile_async_front.jsm","lineNumber":1459,"stack":["resource://gre/modules/osfile/osfile_async_front.jsm:setupShutdown:1459","resource://gre/modules/osfile/osfile_async_front.jsm:null:1479","resource://gre/modules/osfile.jsm:null:11","resource://gre/modules/addons/GMPProvider.jsm:null:13","resource://gre/modules/AddonManager.jsm:startup:787","resource://gre/modules/AddonManager.jsm:startup:2794","resource://gre/modules/addonManager.js:observe:65"]}] Barrier: profile-before-change

So it all looks like we're stuck waiting for stuff to write to disk and it's never finishing.

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform breakdown:

• windows10-64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1462013&startday=2019-02-18&endday=2019-02-24&tree=all

Comment 7

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

So I only see Shutdown: Storage at one single place which is:
https://searchfox.org/mozilla-central/rev/dbddac86aadf1d4871fb350bbe66db43728a9f81/toolkit/components/extensions/Extension.jsm#1997

It would mean the await for ExtensionStorageIDB.selectedBackendPromises.get(this) never completes, and that for the screenshots extension. But hard to see without debugging output from which WeakRef it actually comes from.

Also this failure happened only once so far, so I don't see a chance to get it into a debugger. Lets wait if something changes in the future.

Comment 8

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 9

[BMO Automation]

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