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

Status: RESOLVED FIXED

(Firefox Graveyard :: Activity Streams: General, defect, P1)

Description

[Marco Bonardo [:mak]]

+++ 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

Comment 1

[Marco Bonardo [:mak]]

Tim, could you please have someone looking into this? it's a top crash on shutdown.

Comment 2

[Mathieu Leplatre [:leplatrem]]

I guess the same snippet with `Sqlite.shutdown.addBlocker()` should be added here:
https://github.com/mozilla/activity-stream/blob/8517560b4450a9aaf4c9df94077075154fe246a7/addon/MetadataStore.js#L167

Comment 3

[Nan Jiang [:nanj]]

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

Comment 4

[Nan Jiang [:nanj]]

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!

Comment 5

[Marco Bonardo [:mak]]

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.

Comment 6

[Nan Jiang [:nanj]]

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.

Comment 7

[Marco Bonardo [:mak]]

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.

Comment 8

[Nan Jiang [:nanj]]

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.

Comment 9

[Nan Jiang [:nanj]]

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.