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

RESOLVED FIXED in Firefox 56

Status

()

Firefox
Screenshots
--
critical
RESOLVED FIXED
8 months ago
5 months ago

People

(Reporter: calixte, Assigned: kmag)

Tracking

({crash, regression, topcrash})

unspecified
Firefox 56
Unspecified
Windows 7
crash, regression, topcrash
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox-esr52 unaffected, firefox54 unaffected, firefox55 unaffected, firefox56+ fixed)

Details

(crash signature)

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(1 attachment, 1 obsolete attachment)

(Reporter)

Description

8 months ago
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.
(Reporter)

Updated

8 months ago
Crash Signature: [@ AsyncShutdownTimeout | profile-change-teardown | Extension Shutdown: jid0-GXjLLfbCoAx0LcltEdFrEkQdQPI@jetpack (Awesome Screenshot - Capture, Annotate & More)] → [@ AsyncShutdownTimeout | profile-change-teardown | Extension Shutdown: jid0-GXjLLfbCoAx0LcltEdFrEkQdQPI@jetpack (Awesome Screenshot - Capture, Annotate & More)] [@ AsyncShutdownTimeout | profile-change-teardown | Extension Shutdown: screenshots@m…
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
Flags: needinfo?(amckay)
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.
Flags: needinfo?(amckay)
Comment hidden (mozreview-request)

Comment 4

8 months ago
mozreview-review
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.
Attachment #8885958 - Flags: review?(aswan) → review+

Comment 6

8 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/a4490a86f11f
Status: NEW → RESOLVED
Last Resolved: 8 months ago
status-firefox56: affected → fixed
Resolution: --- → FIXED
Assignee: nobody → kmaglione+bmo
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.
Flags: needinfo?(kmaglione+bmo)
Status: RESOLVED → REOPENED
Flags: needinfo?(kmaglione+bmo)
Resolution: FIXED → ---
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.
(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.
Blocks: 1334550
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.
Flags: needinfo?(awagner)
The developer has been notified.
Flags: needinfo?(awagner)

Comment 12

7 months ago
I got crash [@ AsyncShutdownTimeout | profile-change-teardown | Extension Shutdown: uBlock0@raymondhill.net (uBlock Origin) ] while testing bug 1382190.

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

1500533787009   addons.update-checker   WARN    Update manifest for onboarding@mozilla.org 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: uBlock0@raymondhill.net (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: uBlock0@raymondhill.net (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
Crash Signature: [@ AsyncShutdownTimeout | profile-change-teardown | Extension Shutdown: jid0-GXjLLfbCoAx0LcltEdFrEkQdQPI@jetpack (Awesome Screenshot - Capture, Annotate & More)] [@ AsyncShutdownTimeout | profile-change-teardown | Extension Shutdown: screenshots@m&hellip; → [@ AsyncShutdownTimeout | profile-change-teardown | Extension Shutdown: jid0-GXjLLfbCoAx0LcltEdFrEkQdQPI@jetpack (Awesome Screenshot - Capture, Annotate & More)] [@ AsyncShutdownTimeout | profile-change-teardown | Extension Shutdown: screenshots@m&hellip;
status-firefox56: fixed → affected
#3 top Windows crash in the 7-19 Nightly, with 5.3% of all crashes.
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?
Flags: needinfo?(wclouser)

Updated

7 months ago
Blocks: 1383489
#2 Windows topcrash in Nightly 20170721030204.
(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 :(
Hi Philipp.  (re: comment 14)  can you give any more information on a relationship with Screenshots?  Thanks
Flags: needinfo?(wclouser) → needinfo?(philipp)

Comment 18

7 months ago
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)
Flags: needinfo?(philipp)

Comment 19

7 months ago
working link: http://bit.ly/2uZAzpj
Guessing this is an OOP webextensions thing. Kris, any thoughts on the source of these crashes?
Flags: needinfo?(kmaglione+bmo)
I'm not familiar with the crash-stats site. Can you tell if these crashes are happening on beta as well?
Flags: needinfo?(madperson)

Comment 22

7 months ago
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).
Flags: needinfo?(madperson)
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.
Flags: needinfo?(kmaglione+bmo)
Comment hidden (mozreview-request)
Attachment #8885958 - Attachment is obsolete: true

Comment 25

7 months ago
mozreview-review
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
Attachment #8892127 - Flags: review?(aswan) → review+

Comment 26

7 months ago
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.
tracking-firefox56: --- → +
(Assignee)

Comment 27

7 months ago
mozreview-review-reply
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 29

7 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/f23f75bc9d39
Status: REOPENED → RESOLVED
Last Resolved: 8 months ago7 months ago
status-firefox56: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla56
Duplicate of this bug: 1379994
Target Milestone: mozilla56 → Firefox 56

Updated

5 months ago
Product: Cloud Services → Firefox
You need to log in before you can comment on or make changes to this bug.