981556 - Shutdown warning: Condition: OS.File: flush pending requests, warn about unclosed files, shut down service. Phase: web-workers-shutdown State: (none)

Status: RESOLVED FIXED

(Toolkit Graveyard :: OS.File, defect)

Description

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

Mozilla/5.0 (X11; Linux x86_64; rv:30.0) Gecko/20100101 Firefox/30.0 ID:20140309030204 CSet: 21f293fc8d34

Over the weekend some code has been landed in Nightly which is causing the following warning to appear in the console:

WARNING: A completion condition encountered an error while we were spinning the event loop. Condition: OS.File: flush pending requests, warn about unclosed files, shut down service. Phase: web-workers-shutdown State: (none)
WARNING: Error: OS.File has been shut down.
WARNING: Scheduler.push/promise<@resource://gre/modules/osfile/osfile_async_front.jsm:206:9
Handler.prototype.process@resource://gre/modules/Promise.jsm:782:11
this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm:661:7
Spinner.prototype.observe@resource://gre/modules/AsyncShutdown.jsm:446:7

Given the state 'web-workers-shutdown' I assume that this is part of the web workers component?

Someone should try to find the regression range.

Comment 1

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

With our Mozmill tests we see this across all of our platforms. Looks like it has been started between 20140307030202 and 20140308030203.

PASS: https://hg.mozilla.org/mozilla-central/rev/b0e7f63c2138
FAIL: https://hg.mozilla.org/mozilla-central/rev/d01bf8596d3b

Pushlog: http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=b0e7f63c2138&tochange=d01bf8596d3b

Comment 2

[David Teller [:Yoric] - still alive but not very active]

So, some client of OS.File is attempting to use OS.File after the OS.File thread has been shutdown.

Most likely culprits:
- http://hg.mozilla.org/mozilla-central/rev/9a5b7ed8dae4 (Bug 965527 - Intermittent B2G desktop Shutdown | application crashed [@ mozalloc_abort(char const*)]);
- http://hg.mozilla.org/mozilla-central/rev/f0cf7cdc0301 (Bug 967192 - Bookmarks restore and import should use OS.File).

Comment 3

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

Does it mean we have a dataloss situation here?

Comment 4

[David Teller [:Yoric] - still alive but not very active]

This is quite possible.

Comment 5

[Marco Bonardo [:mak]]

(In reply to David Rajchenbach Teller [:Yoric] (currently away from bugzilla – ETA March 11th – please use "needinfo?") from comment #2)
> So, some client of OS.File is attempting to use OS.File after the OS.File
> thread has been shutdown.

does this mean we start an OS.File request after shutdown? since I expect requests done before the thread is shutdown to complete.
the only thing we do on shutdown in some case is bookmarks.html export, but you must set a pref for it to happen and it's using AsyncShutdown, I'd expect any work blocking AsyncShutdown to happen before OS.File is gone (otherwise it's pretty pointless). Is that the case?

Henrik do you set browser.bookmarks.autoExportHTML in the harness?

Comment 6

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

(In reply to Marco Bonardo [:mak] from comment #5)
> Henrik do you set browser.bookmarks.autoExportHTML in the harness?

Marco, I have to say that this happens also with a blank profile and shutting down Firefox yourself. There is nothing you would need a test harness for. Sorry, that I missed to give this additional information.

Steps:
1. Start Firefox with an existing or new profile from the command line
2. Close Firefox after a couple of seconds
3. Observe the console output on the command line

You will notice those lines each time you close the browser.

Comment 7

[Marco Bonardo [:mak]]

Then I'm not sure, the autoExportBookmarks case is the only one we use AsyncShutdown for and in a blank profile that code doesn't run. if this happens due to AsyncShutdown I don't think that code is related.

The only thing to do is try to backout Bug 967192 locally and see if the warning goes away, though it looks strange, that bug only fixed code to avoid doing nsIFile->OS.File dance

Comment 8

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

Attachment: js stack

I tried to get the JS stack but it looks like this code is getting called from C++. 

I will backout the bookmark patch and check if this is the cause.

Comment 9

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

Sadly. I cannot remove that patch because it doesn't apply cleanly anymore. So I did a further check with tinderbox builds and nailed down the problem even more:

http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=b0e7f63c2138&tochange=b9fc2eb18bd1

Not sure how to continue here. What kind of merge was that, Carsten?

Comment 10

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

Ok, so the given stack and the reduced pushlog I can see bug 965527 as reason why we are seeing those issues now. So the underlying issue could already exist even longer and should not be related at all to the bookmark backup code.

Comment 11

[Marco Bonardo [:mak]]

Thanks, that makes sense if I just look at the backups changed code, it should not really run that late...

Comment 12

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

David, I think we have to put this back onto your plate. There is nothing else I could do here. Some devs should really look into that code and figure out which component sends those late requests.

Comment 13

[David Teller [:Yoric] - still alive but not very active]

Ok, that makes sense. In bug 965527, I have added more careful checking for shutdown races, so that's probably what causes the error message. I'll look into it.

Comment 14

[David Teller [:Yoric] - still alive but not very active]

Backed out the (almost certainly) offending patch. This should solve the issue.

Comment 15

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

Yes, I don't see it anymore with Mozilla/5.0 (X11; Linux x86_64; rv:30.0) Gecko/20100101 Firefox/30.0 ID:20140312030201 CSet: 44ae8462d6ab. Thanks!