Crash in AsyncShutdownTimeout | profile-before-change | Sqlite.jsm shutdown blocker

RESOLVED FIXED

Status

()

defect
P1
critical
RESOLVED FIXED
2 years ago
5 days ago

People

(Reporter: mak, Assigned: nanj)

Tracking

({crash, regression, topcrash})

Firefox Tracking Flags

(Not tracked)

Details

(crash signature)

Reporter

Description

2 years ago
+++ This bug was initially created as a clone of Bug #1376874 +++

This bug was filed from the Socorro interface and is 
report bp-30da927f-631a-4a75-89a1-4fb690170628.
=============================================================

these async shutdownhangs are spiking cross-platform on 56.0a1 after build 20170627030209.

Correlations for Firefox Nightly
(100.0% in signature vs 00.03% overall) abort_message = ###!!! ABORT: file resource://gre/modules/Sqlite.jsm, line 156
(100.0% in signature vs 03.62% overall) moz_crash_reason = MOZ_CRASH()
(100.0% in signature vs 05.54% overall) Module "twinapi.appcore.dll" = true
(100.0% in signature vs 05.63% overall) Module "twinapi.dll" = true
(83.33% in signature vs 07.64% overall) process_type = null [100.0% vs 06.75% if startup_crash = 0]
(100.0% in signature vs 08.29% overall) Module "explorerframe.dll" = true
(100.0% in signature vs 09.27% overall) Module "winsta.dll" = true
(100.0% in signature vs 09.40% overall) Module "FWPUCLNT.DLL" = true
(100.0% in signature vs 09.55% overall) Module "rasadhlp.dll" = true
(100.0% in signature vs 11.11% overall) shutdown_progress = profile-before-change
(83.33% in signature vs 08.50% overall) Module "ondemandconnroutehelper.dll" = true

graph from nightly: https://crash-stats.mozilla.com/signature/?release_channel=nightly&signature=AsyncShutdownTimeout%20%7C%20profile-before-change%20%7C%20Sqlite.jsm%20shutdown%20blocker&date=%3E%3D2017-03-01T00%3A00%3A00.000Z&date=%3C2017-06-28T18%3A25%3A45.000Z#graphs


From analysis in bug 1376874, metadata.sqlite was found as one of the problematic databases causing this.

See https://bugzilla.mozilla.org/show_bug.cgi?id=1376874#c12
Reporter

Updated

2 years ago
No longer depends on: 1376202
Reporter

Updated

2 years ago
No longer depends on: 1376874
See Also: → 1376874
Reporter

Comment 1

2 years ago
Tim, could you please have someone looking into this? it's a top crash on shutdown.
Flags: needinfo?(tspurway)
Assignee

Comment 3

2 years ago
Hey mak, I'm currently making a hotfix for this, and will cut a point release to fix it soon.
Reporter

Updated

2 years ago
Assignee: nobody → najiang
Status: NEW → ASSIGNED
Flags: needinfo?(tspurway)
Priority: -- → P1
Assignee

Comment 4

2 years ago
This is now fixed via this [commit](https://github.com/mozilla/activity-stream/commit/9f76080d97f5644d3cddd0dfe299a95d03cf6cc0).

We have cut a point release (1.14.1), though it'll most likely go out tomorrow as today is an American holiday.


Thanks for reporting it!
Status: ASSIGNED → RESOLVED
Last Resolved: 2 years ago
Resolution: --- → FIXED
Reporter

Comment 5

2 years ago
This crash report is on 1.14.1:
https://crash-stats.mozilla.com/report/index/f8760a66-b050-4ccc-8625-aab6b0170709#tab-extensions

{"phase":"profile-before-change","conditions":[{"name":"Sqlite.jsm shutdown blocker","state":{"description":"Waiting for connections to close","state":[{"name":"metadata.sqlite#0: waiting for shutdown","state":{"identifier":"metadata.sqlite#0","isCloseRequested":false,"hasDbConn":true,"hasInProgressTransaction":false,"pendingStatements":0,"statementCounter":11},"filename":"resource://gre/modules/Sqlite.jsm","lineNumber":258,"stack":["resource://gre/modules/Sqlite.jsm:ConnectionData:258","resource://gre/modules/Sqlite.jsm:OpenedConnection:1157","resource://gre/modules/Sqlite.jsm:openConnection/</<:967"]}]},"filename":"resource://gre/modules/Sqlite.jsm","lineNumber":156,"stack":["resource://gre/modules/Sqlite.jsm:null:156","resource://gre/modules/XPCOMUtils.jsm:get:198","resource://gre/modules/Sqlite.jsm:ConnectionData:258","resource://gre/modules/Sqlite.jsm:OpenedConnection:1157","resource://gre/modules/Sqlite.jsm:cloneStorageConnection/</<:1047"]}]}

looks like a connection where close() was not invoked at all ("isCloseRequested":false), that's strange, we should always close() now, according to the code.
Assignee

Comment 6

2 years ago
Hmm, that's odd.

As `asyncConnect` is the only entry point of `metadata.sql`, is it possible that `addBlocker` somehow failed to register it?

https://github.com/mozilla/activity-stream/blob/master/addon/MetadataStore.js#L170

The only difference between this implementation and mak's code snippet is that it uses `Task.asycn` other than `async function` in the `addBlocker`.

Will poke around it locally to see if it's reproducible.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Reporter

Comment 7

2 years ago
Just to be clear, so far there is only one report on 1.14.1, that compared to the previous situation is a big improvement, so the patch was a positive change.
It's possible there's an edge case that somehow slipped through the crack, it may be an issue in AsyncShutdown.jsm, Sqlite.jsm or AS itself. It's hard to tell off-hand.
Assignee

Comment 8

2 years ago
Yes, per crash-report, this only occurred once so far on 1.14.1. let's keep an eye on it for a bit longer.

A side note about the future impact of this issue. Since we're currently graduating A-S from Test Pilot to M-C as a system addon, and the new one no longer needs a separate sqlite database, eventually this issue should not appear in A-S at all.
Assignee

Comment 9

2 years ago
According to the crash-report, this seemed to be more silent, and only one issue was reported in the past week. Since A-S has graduated from Test Pilot, and no more new users will use it, I'll bravely mark this as resolved.
Status: REOPENED → RESOLVED
Last Resolved: 2 years ago2 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.