1463489 - ScriptCache.delete in ExtensionContent.Script does not close the open channel of the AsyncScriptCompiler

Status: RESOLVED WONTFIX

(WebExtensions :: General, defect)

Description

[Rob Wu [:robwu]]

Bug 1399348 is an intermittent test failure in browser_ext_tabs_executeScript_bad.js .

The test features two tabs.executeScript({file}) calls.
Before my patch, these calls ran in parallel (and only the second call's result was checked).
After my patch, these calls were sequential: https://searchfox.org/mozilla-central/rev/d9d4c8d8521e6e41d8a4cf804ee33ac336342668/browser/components/extensions/test/browser/browser_ext_tabs_executeScript_bad.js

With this change, all intermittent failures disappeared: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2018-04-25&endday=2018-05-22&tree=trunk&bug=1399348

This shows that there is a problem with extension resource locks upon shutdown.
Specifically, content script resources of pending script executions are not immediately released.

This bug might have a similar cause as bug 1435100.

I guess that the following happens (see step 3-5 for the race condition):

1. Extension:Execute called, which instantiates a Script
  https://searchfox.org/mozilla-central/rev/2aa42f2cab4a110edf21dd7281ac23a1ea8901f9/toolkit/components/extensions/extension-process-script.js#134-152

   We only need to look at the Script constructor (and not at ExtensionContent.handleExtensionExecute), because script.matchesWindow is always false in the test case:
   - Old (parallel) test case: https://searchfox.org/mozilla-central/rev/a71d99bc3e717b16a979957ec20b809c128505ae/browser/components/extensions/test/browser/browser_ext_tabs_executeScript_bad.js#26-29
   - New (sequential) test case: https://searchfox.org/mozilla-central/rev/d9d4c8d8521e6e41d8a4cf804ee33ac336342668/browser/components/extensions/test/browser/browser_ext_tabs_executeScript_bad.js#16-18
   - Source : https://searchfox.org/mozilla-central/rev/2aa42f2cab4a110edf21dd7281ac23a1ea8901f9/toolkit/components/extensions/ExtensionContent.jsm#860-861,864,869-870,876,882

2. The Script constructor preloads (compiles) the script (since wantReturnValue is set).
   https://searchfox.org/mozilla-central/rev/2aa42f2cab4a110edf21dd7281ac23a1ea8901f9/toolkit/components/extensions/ExtensionContent.jsm#299-300,323

3. The ScriptCache getter calls ChromeUtils.compileScript, which opens a new channel in AsyncScriptCompiler:
   - ChromeUtils::CompileScript: https://searchfox.org/mozilla-central/rev/2aa42f2cab4a110edf21dd7281ac23a1ea8901f9/js/xpconnect/loader/ChromeScriptLoader.cpp#276-278
   - AsyncScriptCompiler::Start https://searchfox.org/mozilla-central/rev/2aa42f2cab4a110edf21dd7281ac23a1ea8901f9/js/xpconnect/loader/ChromeScriptLoader.cpp#95-113

4. Meanwhile, "Extension:Shutdown" is called, which flushes the script caches (since bug 1435100).
   Some ping-pong happens with the parent process, and then the file is removed:
   - Extension:Shutdown broadcast: https://searchfox.org/mozilla-central/rev/2aa42f2cab4a110edf21dd7281ac23a1ea8901f9/toolkit/components/extensions/Extension.jsm#1831,1837
   - File removal: https://searchfox.org/mozilla-central/rev/2aa42f2cab4a110edf21dd7281ac23a1ea8901f9/toolkit/components/extensions/Extension.jsm#1731-1748

   Since the AsyncScriptCompiler has still opened the channel, Windows refuses to release the file lock, and consequently the file cannot be removed.

5. The AsyncScriptCompiler completes and closes the channel.



If this race condition happens often enough, then we will experience issues like bug 1399348:

> [Exception... "Component returned failure code: 0x80520015 (NS_ERROR_FILE_ACCESS_DENIED) [nsIFile.createUnique]"

Comment 1

[Kris Maglione [:kmag]]

There's no way to cancel an async script compile, and I don't intend to change that. We could conceivably wait for pending compiles to finish before shutting down, but there are all sorts of other async IO operations that would cause the same problem.

(In reply to Rob Wu [:robwu] from comment #0)
> If this race condition happens often enough, then we will experience issues
> like bug 1399348:
> 
> > [Exception... "Component returned failure code: 0x80520015 (NS_ERROR_FILE_ACCESS_DENIED) [nsIFile.createUnique]"

If you can reliably reproduce this, please file a bug describing how. CreateUnique shouldn't fail in this circumstance.

Comment 2

[Rob Wu [:robwu]]

> (In reply to Rob Wu [:robwu] from comment #0)
> > If this race condition happens often enough, then we will experience issues
> > like bug 1399348:
> > 
> > > [Exception... "Component returned failure code: 0x80520015 (NS_ERROR_FILE_ACCESS_DENIED) [nsIFile.createUnique]"
> 
> If you can reliably reproduce this, please file a bug describing how.
> CreateUnique shouldn't fail in this circumstance.

Apparently createUnique has also changed in the past three months (bug 1443651).
The impact of this "bug" is now reduced to a file being left behind instead of being deleted.

While not ideal, it's not going to cause big issues, so I'll close this bug.

Comment 3

[Rob Wu [:robwu]]

(In reply to Kris Maglione [:kmag] (long backlog; ping on IRC if you're blocked) from comment #1)
> If you can reliably reproduce this, please file a bug describing how.
> CreateUnique shouldn't fail in this circumstance.

FYI bug 1394863 also has an intermittent createUnique error on Windows.