1380267 - Crash in AsyncShutdownTimeout | profile-change-teardown | Extension Shutdown: jid0-GXjLLfbCoAx0LcltEdFrEkQdQPI@jetpack (Awesome Screenshot - Capture, Annotate & More)

Status: RESOLVED FIXED

(Firefox :: Screenshots, defect)

Description

[Calixte Denizet (:calixte)]

This bug was filed from the Socorro interface and is 
report bp-c44e4d7c-321a-400f-b6f2-391a00170711.
=============================================================

There are 95 crashes in nightly 56 with buildid 20170711030203.
This signature is ranked #14 on topcrashers.

Comment 1

[Wil Clouser [:clouserw]]

It looks like this issue is about Awesome Screenshots, an unrelated 3rd-party add-on (https://addons.mozilla.org/en-US/firefox/addon/screenshot-capture-annotate/?src=ss I think?).  Andy -- does the add-on team track these crashes on bugzilla?

Total number of crashes is growing:  http://bit.ly/2uf3UvT

Comment 2

[Kris Maglione [:kmag]]

I've also seen this in some talos runs from Screenshots.

This is a shutdown hang. The issue is that we're now waiting for extensions to fully startup and shutdown before continuing with browser shutdown, and that sometimes results in timeouts. I'm still looking into it.

Comment 3

[Kris Maglione [:kmag]]

Attachment: Bug 1380267: Fix shutdown blocker corner cases.

Review commit: https://reviewboard.mozilla.org/r/156742/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/156742/

Comment 4

[Andrew Swan [:aswan]]

Comment on attachment 8885958 [details]
Bug 1380267: Fix shutdown blocker corner cases.

https://reviewboard.mozilla.org/r/156742/#review161864

::: toolkit/components/extensions/Extension.jsm:1204
(Diff revision 1)
> +    if (shutdownPromises.has(this.id)) {
> +      await shutdownPromises.get(this.id);
> +    }

Please add a comment at least explaining the scenario this code is meant to handle.  I think its quite likely that somebody will come along and misunderstand the purpose of this code otherwise.

Comment 5

[Kris Maglione [:kmag]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/a4490a86f11f183c48d603340d23725abe6d750c
Bug 1380267: Fix shutdown blocker corner cases. r=aswan

Comment 6

[Carsten Book [:Tomcat]]

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

Comment 7

[Nicholas Nethercote [inactive]]

kmag: this doesn't appear to be fixed. Your patch landed on mozilla-central 3 days ago, making it into Nightly 20170714030205, but there are still *many* AsyncShutdownTimeout crashes in that build and the two subsequent Nightly builds. Please investigate ASAP.

Comment 8

[Kris Maglione [:kmag]]

In the particular case of "Awesome Screenshots", it seems that the problem is that its background page tries to load scripts that don't actually exist in its extension, which apparently prevents DOMContentLoaded from firing (which is odd), and therefore prevents the extension startup from ever completing, and therefore prevents the extension shutdown from ever starting.

Comment 9

[Kris Maglione [:kmag]]

(In reply to Kris Maglione [:kmag] from comment #8)
> which apparently prevents DOMContentLoaded from firing (which is odd)

Apparently this is because of the moz-extension remoting code. With remoting
turned off, it doesn't happen.

Comment 10

[Kris Maglione [:kmag]]

Andreas, can you contact the Awesome Screenshots team about the nonexistent scripts they're trying to load from their background page?

Also, the fact that they needlessly inject ~140KB of content scripts (and 12K of CSS) into every page is... definitely less than ideal. And the weird things that they do with OAuth2 tokens on https://www.google.com/cookies.txt, and similar things for Facebook and so forth, are a bit concerning. Oh, and the fact that they have webRequest and webRequestBlocking and webNavigation and idle and storage permissions that they never use.

Comment 11

[Andreas Wagner [:TheOne] [use NI]]

The developer has been notified.

Comment 12

[Ekanan Ketunuti]

I got crash [@ AsyncShutdownTimeout | profile-change-teardown | Extension Shutdown: [e-mail] (uBlock Origin) ] while testing bug 1382190.

bp-9a2d7eb0-ba5c-41a2-ba16-00dd80170720

1500533787009   addons.update-checker   WARN    Update manifest for [e-mail] did not contain an updates property
1500533787039   addons.update-checker   WARN    Update manifest for {972ce4c6-7e08-4474-a285-3208198ce6fd} did not contain an updates property
[GFX1-]: Could not get a DXGI adapter
1500533794636   addons.xpi      WARN    Please specify whether you want browser_style or not in your options_ui options.
1500533795522   addons.xpi      WARN    Failed to remove temporary file C:\Users\Ek\AppData\Local\Temp\tmp-w9g.xpi for addon https://addons.cdn.mozilla.net/user-media/addons/607454/ublock_origin-1.13.9b0-an+fx.xpi?filehash=sha256%3A0275a6789f79afaa54e937ee6545b805e66144f54d8501dedfbae5be61308915: [Exception... "Component returned failure code: 0x80520015 (NS_ERROR_FILE_ACCESS_DENIED) [nsIFile.remove]"  nsresult: "0x80520015 (NS_ERROR_FILE_ACCESS_DENIED)"  location: "JS frame :: resource://gre/modules/addons/XPIInstall.jsm :: removeTemporaryFile :: line 1596"  data: no] Stack trace: removeTemporaryFile()@resource://gre/modules/addons/XPIInstall.jsm:1596 < startInstall/<()@resource://gre/modules/addons/XPIInstall.jsm:1964
[Child 3508] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
[GFX1-]: Could not get a DXGI adapter

###!!! [Parent][MessageChannel] Error: (msgtype=0x28008A,name=PBrowser::Msg_UpdateNativeWindowHandle) Channel error: cannot send/recv


###!!! [Parent][MessageChannel] Error: (msgtype=0x28007E,name=PBrowser::Msg_Destroy) Channel error: cannot send/recv

WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"Extension Shutdown: [e-mail] (uBlock Origin)","state":"(none)","filename":"resource://gre/modules/Extension.jsm","lineNumber":1192,"stack":["resource://gre/modules/Extension.jsm:shutdown:1192"]}] Barrier: profile-change-teardown
console.error:
  Message: Error: SessionFile is closed
  Stack:
    write@resource:///modules/sessionstore/SessionFile.jsm:338:29
write@resource:///modules/sessionstore/SessionFile.jsm:73:12
_writeState@resource:///modules/sessionstore/SessionSaver.jsm:343:12
_saveState@resource:///modules/sessionstore/SessionSaver.jsm:281:12
_saveStateAsync@resource:///modules/sessionstore/SessionSaver.jsm:327:5
runDelayed/this._timeoutID<@resource:///modules/sessionstore/SessionSaver.jsm:184:40
setTimeout_timer@resource://gre/modules/Timer.jsm:30:5
observe@resource://gre/modules/AsyncShutdown.jsm:534:9

FATAL ERROR: AsyncShutdown timeout in profile-change-teardown Conditions: [{"name":"Extension Shutdown: [e-mail] (uBlock Origin)","state":"(none)","filename":"resource://gre/modules/Extension.jsm","lineNumber":1192,"stack":["resource://gre/modules/Extension.jsm:shutdown:1192"]}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources.
[Parent 7772] ###!!! ABORT: file resource://gre/modules/Extension.jsm, line 1192

Comment 13

[Andrew McCreight [:mccr8]]

#3 top Windows crash in the 7-19 Nightly, with 5.3% of all crashes.

Comment 14

[Marcia Knous [:marcia]]

wil: philipp mentioned to me on IRC that the firefox screenshots system addon also seems to be a big factor contributing to these shutdown crashes - can someone take a look?

Comment 15

[Nicholas Nethercote [inactive]]

#2 Windows topcrash in Nightly 20170721030204.

Comment 16

[Nicholas Nethercote [inactive]]

(In reply to Nicholas Nethercote [:njn] from comment #15)
> #2 Windows topcrash in Nightly 20170721030204.

Oh, and a different signature that matches this bug is the #3 topcrash in the same Nightly :(

Comment 17

[Wil Clouser [:clouserw]]

Hi Philipp.  (re: comment 14)  can you give any more information on a relationship with Screenshots?  Thanks

Comment 18

[[:philipp]]

different philipp :-)

there are at least 500 async shutdown crash reports on nightly last week referencing firefox screenshots:
https://crash-stats.mozilla.com/signature/?signature=AsyncShutdownTimeout%20%7C%20profile-change-teardown%20%7C%20Extension%20Shutdown%3A%20screenshots%40mozilla.org%20(Firefox%20Screenshots)

Comment 19

[[:philipp]]

working link: http://bit.ly/2uZAzpj

Comment 20

[Jared Hirsch [:jhirsch] (he/him) (Needinfo please)]

Guessing this is an OOP webextensions thing. Kris, any thoughts on the source of these crashes?

Comment 21

[Jared Hirsch [:jhirsch] (he/him) (Needinfo please)]

I'm not familiar with the crash-stats site. Can you tell if these crashes are happening on beta as well?

Comment 22

[[:philipp]]

it's not an issue on 55.0b - these crashes started when the separate process for webextensions was switched on in 56.0a1 (bug 1357486).

Comment 23

[Kris Maglione [:kmag]]

This has nothing to do with the separate content process.

When we landed the pref change to turn OOP by default, we also added a shutdown blocker to make sure add-on shutdown completed before app shutdown, and more startup/shutdown consistency checks to make sure we didn't start shutting down an extension before it finished starting up. Those were issues prior to turning on OOP, but OOP changed the timing enough to make test failures more common, so we landed them at the same time.

In the case of the Awesome Screenshots shutdown hangs, the main issue is in the web-extension: protocol remoting, which doesn't handle the extension's attempts to load nonexistent scripts properly.

In the case of the Screenshots system add-on, it's more likely a race in add-on's own embedded extension startup/shutdown code.

Comment 24

[Kris Maglione [:kmag]]

Attachment: Bug 1380267: Add 1s max delay to extension shutdown blocker.

Review commit: https://reviewboard.mozilla.org/r/163118/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/163118/

Comment 25

[Andrew Swan [:aswan]]

Comment on attachment 8892127 [details]
Bug 1380267: Add 1s max delay to extension shutdown blocker.

https://reviewboard.mozilla.org/r/163118/#review168544

::: toolkit/components/extensions/Extension.jsm:1216
(Diff revision 1)
>      let promise = this._shutdown(reason);
>  
> +    let blocker = () => {
> +      return Promise.race([
> +        promise,
> +        new Promise(resolve => setTimeout(resolve, SHUTDOWN_BLOCKER_MAX_MS)),

Can you log or reportError() something here so we know this is happening?  Its a reasonable safety net but it shouldn't happen unless we have other bugs like 1382271

Comment 26

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

Tracked for 56, this is a top crasher on Nightly56. Let's make sure the fix lands in Nightly pre-merge. If not, let's uplift a fix to Beta56 after it stabilizes a bit.

Comment 27

[Kris Maglione [:kmag]]

Comment on attachment 8892127 [details]
Bug 1380267: Add 1s max delay to extension shutdown blocker.

https://reviewboard.mozilla.org/r/163118/#review168544

> Can you log or reportError() something here so we know this is happening?  Its a reasonable safety net but it shouldn't happen unless we have other bugs like 1382271

reportError wouldn't show up anywhere, since the error console is already closed at this point. We could log to the console, but this is only a short term workaround until we figure out what's causing this to happen so often for Screenshots.

Comment 28

[Kris Maglione [:kmag]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/f23f75bc9d39980d863e4d3d845dbd97d9de8f5c
Bug 1380267: Add 1s max delay to extension shutdown blocker. r=aswan

Comment 29

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

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