1114567 - AsyncShutdown crashes in Experiments.jsm shutdown with Flash protected mode experiment

Status: RESOLVED WORKSFORME

(Firefox Health Report Graveyard :: Client: Desktop, defect)

Description

[Robert Kaiser]

This bug was filed from the Socorro interface and is 
report bp-f2eb01a6-370f-4a97-808f-12b532141222.
=============================================================

Since we activated the Flash protected mode experiment on beta, we're seeing a jump in AsyncShutdown crashes in 35, the ones I checked are all once again in Experiments.jsm shutdown (this is the full AsyncShutdownTimeout field of the reports linked above, other reports look similar):

{"phase":"AddonManager: Waiting for providers to shut down.","conditions":[{"name":"Experiments.jsm shutdown","state":{"isShutdown":true,"isEnabled":true,"isRefresh":false,"isDirty":false,"isFirstEvaluate":true,"hasLoadTask":false,"hasMainTask":true,"hasTimer":false,"hasAddonProvider":false,"latestLogs":[null,"10: constructor","10: enabled=true, true","10: Registering instance with Addon Manager.","10: Registering previous experiment add-on provider.","10: _loadFromCache","10: populateFromCache() - data: {\"version\":1,\"data\":[{\"_enabled\":false,\"_manifestData\":{\"xpiURL\":\"https://telemetry-experiment.cdn.mozilla.net/flash-protectedmode-beta35%40experiments.mozilla.org/experiment.xpi\",\"xpiHash\":\"sha256:bdcb193dc5971ebf227120a470b955b9048a2556b94ad2044efabe75e210c759\",\"appName\":[\"Firefox\"],\"maxActiveSeconds\":2764800,\"maxVersion\":\"37.*\",\"sample\":0.1,\"minBuildID\":\"20141215000000\",\"startTime\":1418601600,\"minVersion\":\"35.0\",\"endTime\":1421280000,\"os\":[\"WINNT\"],\"id\":\"[e-mail]\",\"channel\":[\"beta\"]},\"_needsUpdate\":false,\"_randomValue\":0.962550273391916,\"_failedStart\":false,\"_name\":null,\"_description\":null,\"_homepageURL\":null,\"_addonId\":null,\"_branch\":null},{\"_enabled\":true,\"_manifestData\":{\"xpiURL\":\"https://telemetry-experiment.cdn.mozilla.net/newtab-data-beta%40experiments.mozilla.org/experiment.xpi\",\"xpiHash\":\"sha256:e296f69f6a175c123f0e7d547154da46d95b9b65af7df2174af803bfacedde93\",\"appName\":[\"Firefox\"],\"maxActiveSeconds\":604800,\"maxVersion\":\"37.*\",\"sample\":0.25,\"startTime\":1418169600,\"minVersion\":\"33.0\",\"endTime\":1420848000,\"id\":\"[e-mail]\",\"channel\":[\"beta\"]},\"_needsUpdate\":false,\"_randomValue\":0.1692913596528135,\"_failedStart\":false,\"_name\":\"New Tab Data\",\"_description\":\"An experiment to analyze the data on about:newtab, see bug 1062708.\",\"_homepageURL\":\"\",\"_addonId\":\"[e-mail]\",\"_branch\":null,\"_startDate\":1419045164215}]}","10: _loadTask finished ok","10: _run","10: _main iteration","10: _evaluateExperiments","10: uninit: started","10: uninit: finished with _loadTask","10: uninit: no previous shutdown","10: Unregistering instance with Addon Manager.","10: Removing install listener from add-on manager.","10: Removing addon listener from add-on manager.","10: Finished unregistering with addon manager.","10: Unregistering previous experiment add-on provider.","10: uninit: waiting on _mainTask"],"experiments":{},"terminateReason":null},"filename":"resource://app/modules/experiments/Experiments.jsm","lineNumber":435,"stack":["resource://app/modules/experiments/Experiments.jsm:Experiments.Experiments.prototype.init:435","resource://app/modules/experiments/Experiments.jsm:Experiments.Experiments:416","resource://app/modules/experiments/Experiments.jsm:Experiments.instance:250","resource://app/components/ExperimentsService.js:ExperimentsService.prototype.observe:79","null:null:0"]}]}

For more details, see the metadata tabs of reports in https://crash-stats.mozilla.com/report/list?product=Firefox&version=Firefox:35.0b&signature=mozalloc_abort%28char%20const%2A%20const%29%20%7C%20NS_DebugBreak%20%7C%20nsDebugImpl%3A%3AAbort%28char%20const%2A%2C%20int%29#tab-reports

Comment 1

[Benjamin Smedberg]

So something in _evaluateExperiments is getting stuck: https://hg.mozilla.org/releases/mozilla-beta/annotate/FIREFOX_35_0b5_RELEASE/browser/experiments/Experiments.jsm#l1200

The promise could be in any of these subfuncs:
yield installedExperimentAddons()
yield activeExperiment.shouldStop() ... very unlikely because it calls isApplicable which logs
yield activeExperiment.stop ... very unlikely because it logs
yield experiment.isApplicable() ... very unlikely because it logs

Which leaves us with installedExperimentAddons which seems like the most likely culprit: https://hg.mozilla.org/releases/mozilla-beta/annotate/FIREFOX_35_0b5_RELEASE/browser/experiments/Experiments.jsm#l200

AddonManager.getAddonsByTypes() isn't a promise function and could be throwing or even just failing to do its callback at all.

Comment 2

[Georg Fritzsche [:gfritzsche]]

There are definitely issues around AddonManager missing callbacks in some scenarios (like e.g. bug 1074135, can't find the actual discussions/bugs with irving i was thinking about).
Especially races of shutdown vs. querying the AM API seem still to be around.

If that issue continues we could either:
* put time into investigating/fixing the AddonManager
* possibly short-term go for timing-out on the AddonManager API (needs lower timeout then AsyncShutdownTimeout waits for and sanity-review of the Experiments recovery code path for this)

Comment 3

[Georg Fritzsche [:gfritzsche]]

(In reply to Georg Fritzsche [:gfritzsche] from comment #2)
> There are definitely issues around AddonManager missing callbacks in some
> scenarios (like e.g. bug 1074135, can't find the actual discussions/bugs
> with irving i was thinking about).

Ok, i was thinking of bug 1075625 - given the shutdown flag in the AsyncShutdownTimeout state here, that seems to be a likely culprit.

Comment 4

[Danial Horton]

i've been submitting the crash log every time i experience this one,  turning off telemetry the crash doesn't occur, but with it on, the process hangs around with minimal cpu activity after exiting or restarting and eventually pops up the crash reporter.

started occuring after i updated to beta 5, but might have been introduced prior (i'm not sure) but its still occuring in beta 8.

Comment 5

[Danial Horton]

"{"phase":"AddonManager: Waiting for providers to shut down.","conditions":[{"name":"Experiments.jsm shutdown","state":{"isShutdown":true,"isEnabled":true,"isRefresh":false,"isDirty":false,"isFirstEvaluate":true,"hasLoadTask":false,"hasMainTask":true,"hasTimer":false,"hasAddonProvider":false,"latestLogs":["10: enabled=true, true","10: Registering instance with Addon Manager.","10: Registering previous experiment add-on provider.","10: _loadFromCache","10: populateFromCache() - data: {\"version\":1,\"data\":[{\"_enabled\":false,\"_manifestData\":{\"xpiURL\":\"https://telemetry-experiment.cdn.mozilla.net/flash-protectedmode-beta35%40experiments.mozilla.org/experiment.xpi\",\"xpiHash\":\"sha256:bdcb193dc5971ebf227120a470b955b9048a2556b94ad2044efabe75e210c759\",\"appName\":[\"Firefox\"],\"maxActiveSeconds\":2764800,\"maxVersion\":\"37.*\",\"sample\":0.1,\"minBuildID\":\"20141215000000\",\"startTime\":1418601600,\"minVersion\":\"35.0\",\"endTime\":1421280000,\"os\":[\"WINNT\"],\"id\":\"[e-mail]\",\"channel\":[\"beta\"]},\"_needsUpdate\":false,\"_randomValue\":0.08365563149460609,\"_failedStart\":false,\"_name\":null,\"_description\":null,\"_homepageURL\":null,\"_addonId\":null,\"_branch\":null}]}","10: _loadTask finished ok","10: _run","10: _main iteration","10: _evaluateExperiments","20: evaluateExperiments() - activating experiment [e-mail]","10: onInstallStarted() - [e-mail]","10: uninit: started","10: uninit: finished with _loadTask","10: uninit: no previous shutdown","10: Unregistering instance with Addon Manager.","10: Removing install listener from add-on manager.","10: Removing addon listener from add-on manager.","10: Finished unregistering with addon manager.","10: Unregistering previous experiment add-on provider.","10: uninit: waiting on _mainTask"],"experiments":{},"terminateReason":null},"filename":"resource://app/modules/experiments/Experiments.jsm","lineNumber":435,"stack":["resource://app/modules/experiments/Experiments.jsm:Experiments.Experiments.prototype.init:435","resource://app/modules/experiments/Experiments.jsm:Experiments.Experiments:416","resource://app/modules/experiments/Experiments.jsm:Experiments.instance:250","resource://app/components/ExperimentsService.js:ExperimentsService.prototype.observe:90","chrome://mozapps/content/extensions/extensions.js:initialize:134","null:null:0"]}]}"

Comment 6

[Blair McBride [:Unfocused] (UNAVAILABLE)]

(In reply to Georg Fritzsche [:gfritzsche] [slow to respond until Jan 19] from comment #3)
> Ok, i was thinking of bug 1075625 - given the shutdown flag in the
> AsyncShutdownTimeout state here, that seems to be a likely culprit.

FYI, I just landed the fix for bug 1075625 on fx-team. Providers are now only accessed through AddonManager's APIs if they're considered to be in a safe state (ie, its startup has completed & its shutdown hasn't begun).

Comment 7

[Georg Fritzsche [:gfritzsche]]

Some bugs were fixed in the mean-time, lets investigate further issues in new bugs.