Closed
Bug 1134700
Opened 9 years ago
Closed 9 years ago
TelemetryEnvironment tries to collect addon data after AddonManager shutdown
Categories
(Toolkit :: Telemetry, defect)
Toolkit
Telemetry
Tracking
()
RESOLVED
FIXED
mozilla39
Tracking | Status | |
---|---|---|
firefox39 | --- | fixed |
People
(Reporter: gfritzsche, Assigned: gfritzsche)
References
Details
(Whiteboard: [ready])
Attachments
(1 file, 3 obsolete files)
9.50 KB,
patch
|
gfritzsche
:
review+
|
Details | Diff | Splinter Review |
On shutdown we try to collect the addons data from the addon manager, which doesn't work (it shuts down before us). We need to at least store the last addon state before AM shuts down (using AddonManager.shutdown.addBlocker()). 1424366218491 Toolkit.Telemetry TRACE TelemetryPing::shutdown 1424366218493 Toolkit.Telemetry TRACE TelemetrySession::savePendingPings 1424366218494 Toolkit.Telemetry TRACE TelemetrySession::getSessionPayload - reason: saved-session, clearSubsession: true 1424366218495 Toolkit.Telemetry TRACE TelemetrySession::getSimpleMeasurements 1424366218509 Toolkit.Telemetry TRACE TelemetrySession::getMetadata - Reason saved-session 1424366218514 Toolkit.Telemetry TRACE TelemetrySession::getFlashVersion 1424366218516 Toolkit.Telemetry TRACE TelemetrySession::assemblePayloadWithMeasurements - reason: saved-session, submitting subsession data: false 1424366218517 Toolkit.Telemetry TRACE TelemetrySession::getHistograms - subsession: false, clearSubsession: true 1424366218707 Toolkit.Telemetry TRACE TelemetrySession::getKeyedHistograms - subsession: false, clearSubsession: true 1424366218714 Toolkit.Telemetry TRACE TelemetrySession::getThreadHangStats 1424366218716 Toolkit.Telemetry TRACE TelemetrySession::getAddonHistograms 1424366218718 Toolkit.Telemetry TRACE TelemetrySession::_scheduleDailyTimer - now: Thu Feb 19 2015 18:16:58 GMT+0100 (CET), scheduled: Fri Feb 20 2015 00:00:00 GMT+0100 (CET) 1424366218719 Toolkit.Telemetry TRACE TelemetryPing::savePendingPings - Type main, Server http://localhost:8080, aOptions {"retentionDays":14,"addClientId":true,"addEnvironment":true} 1424366218720 Toolkit.Telemetry TRACE TelemetryPing::assemblePing - Type main, Server http://localhost:8080, aOptions {"retentionDays":14,"addClientId":true,"addEnvironment":true} 1424366218725 Toolkit.Telemetry TRACE TelemetryEnvironment::getEnvironmentData 1424366218726 Toolkit.Telemetry TRACE TelemetryEnvironment::getEnvironmentData 1424366218780 Toolkit.Telemetry TRACE TelemetryEnvironment::_getGFXData - Only one display adapter detected. 1424366218789 Toolkit.Telemetry ERROR TelemetryEnvironment::_doGetEnvironmentData - There was an exception collecting addons: [Exception... "AddonManager is not initialized" nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)" location: "JS frame :: resource://gre/modules/AddonManager.jsm :: AMI_getAddonsByTypes :: line 2183" data: no] Stack trace: AMI_getAddonsByTypes()@resource://gre/modules/AddonManager.jsm:2183 < AM_getAddonsByTypes()@resource://gre/modules/AddonManager.jsm:2835 < promiseGetAddonsByTypes/<()@resource://gre/modules/TelemetryEnvironment.jsm:95 < promiseGetAddonsByTypes()@resource://gre/modules/TelemetryEnvironment.jsm:94 < this.TelemetryEnvironment._getActiveAddons<()@resource://gre/modules/TelemetryEnvironment.jsm:580 < InterpretGeneratorResume()@self-hosted:702 < next()@self-hosted:610 < TaskImpl_run()@resource://gre/modules/Task.jsm:314 < TaskImpl()@resource://gre/modules/Task.jsm:275 < createAsyncFunction/asyncFunction()@resource://gre/modules/Task.jsm:249 < this.TelemetryEnvironment._getAddons<()@resource://gre/modules/TelemetryEnvironment.jsm:725 < next()@self-hosted:610 < TaskImpl_run()@resource://gre/modules/Task.jsm:314 < TaskImpl()@resource://gre/modules/Task.jsm:275 < createAsyncFunction/asyncFunction()@resource://gre/modules/Task.jsm:249 < this.TelemetryEnvironment._doGetEnvironmentData</sections.addons()@resource://gre/modules/TelemetryEnvironment.jsm:861 < this.TelemetryEnvironment._doGetEnvironmentData<()@resource://gre/modules/TelemetryEnvironment.jsm:870 < next()@self-hosted:610 < TaskImpl_run()@resource://gre/modules/Task.jsm:314 < TaskImpl_handleResultValue()@resource://gre/modules/Task.jsm:393 < TaskImpl_run()@resource://gre/modules/Task.jsm:322 < TaskImpl_handleResultValue()@resource://gre/modules/Task.jsm:393 < TaskImpl_run()@resource://gre/modules/Task.jsm:322 < Handler.prototype.process()@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:867 < this.PromiseWalker.walkerLoop()@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:746 < this.PromiseWalker.scheduleWalkerLoop/<()@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:688 < Spinner.prototype.observe()@resource://gre/modules/AsyncShutdown.jsm:464 < <file:unknown>
Assignee | ||
Updated•9 years ago
|
Summary: TelemetryEnvironment tries to collect addon data after it is shutdown → TelemetryEnvironment tries to collect addon data after AddonManager shutdown
Assignee | ||
Updated•9 years ago
|
Assignee: nobody → gfritzsche
Assignee | ||
Updated•9 years ago
|
Status: NEW → ASSIGNED
Assignee | ||
Comment 1•9 years ago
|
||
* cache addons on AM shutdown * use cached addon data if we have any * minor test-fixup
Attachment #8567908 -
Flags: review?(vdjeric)
Comment on attachment 8567908 [details] [diff] [review] Cache addons on AddonManager shutdown Review of attachment 8567908 [details] [diff] [review]: ----------------------------------------------------------------- ::: toolkit/components/telemetry/TelemetryEnvironment.jsm @@ +237,5 @@ > > // The Addons change listener, init by |_startWatchingAddons| . > _addonsListener: null, > > + // AddonManager may shut down before us, in which case we cache the addons here. Nit: What's the type of this? Is it non-null only if AddonManager shuts down before us? @@ +831,5 @@ > + let addons = this._cachedAddons || {}; > + if (!this._cachedAddons) { > + addons.activeAddons = yield this._getActiveAddons(); > + addons.activeTheme = yield this._getActiveTheme(); > + addons.activeGMPlugins = yield this._getActiveGMPlugins(); Are we sure that AddonManager may not shutdown during these `yield`? If so, please document it. Otherwise, we have a race condition. @@ +1005,5 @@ > }, > + > + /** > + * This blocks the AddonManager shutdown barrier, it caches addons we might need later. > + * It also lets an active collect task finish first as it may still access the AM. So shouldn't the collect tasks finish before we compute `this._cachedAddons`? @@ +1007,5 @@ > + /** > + * This blocks the AddonManager shutdown barrier, it caches addons we might need later. > + * It also lets an active collect task finish first as it may still access the AM. > + */ > + _onAddonManagerShutdown: Task.async(function*() { Nit: I'm a big fan of giving different names to methods that return some value and methods that return a promise. Doubly-so if this is meant to be a blocker. @@ +1027,5 @@ > + */ > + _getState: function() { > + return { > + shutdown: this._shutdown, > + collectTask: !!this._collectTask, Nit: `hasCollectTask`, `hasAddonsListener`, `hasCachedAddons`.
Attachment #8567908 -
Flags: review?(vdjeric) → feedback+
Assignee | ||
Comment 3•9 years ago
|
||
(In reply to David Rajchenbach-Teller [:Yoric] (away until Febrary - use "needinfo") from comment #2) > > // The Addons change listener, init by |_startWatchingAddons| . > > _addonsListener: null, > > > > + // AddonManager may shut down before us, in which case we cache the addons here. > > Nit: What's the type of this? Is it non-null only if AddonManager shuts down > before us? Yes, non-null only if AddonManager shuts down before us. It's an object containing the addon information, suitable for use in the environment data. Document this? > @@ +831,5 @@ > > + let addons = this._cachedAddons || {}; > > + if (!this._cachedAddons) { > > + addons.activeAddons = yield this._getActiveAddons(); > > + addons.activeTheme = yield this._getActiveTheme(); > > + addons.activeGMPlugins = yield this._getActiveGMPlugins(); > > Are we sure that AddonManager may not shutdown during these `yield`? If so, > please document it. Otherwise, we have a race condition. Yes, we are running this from a blocker of the AddonManagers shutdown barrier. > @@ +1005,5 @@ > > }, > > + > > + /** > > + * This blocks the AddonManager shutdown barrier, it caches addons we might need later. > > + * It also lets an active collect task finish first as it may still access the AM. > > So shouldn't the collect tasks finish before we compute `this._cachedAddons`? It doesn't really matter whether it finishes before or after. It will either pick up the cached addons or collect some itself (may already be actively collecting). > @@ +1007,5 @@ > > + /** > > + * This blocks the AddonManager shutdown barrier, it caches addons we might need later. > > + * It also lets an active collect task finish first as it may still access the AM. > > + */ > > + _onAddonManagerShutdown: Task.async(function*() { > > Nit: I'm a big fan of giving different names to methods that return some > value and methods that return a promise. Doubly-so if this is meant to be a > blocker. What are you suggesting?
(In reply to Georg Fritzsche [:gfritzsche] [away Feb 27 - March 15] from comment #3) > > Nit: What's the type of this? Is it non-null only if AddonManager shuts down > > before us? > > Yes, non-null only if AddonManager shuts down before us. It's an object > containing the addon information, suitable for use in the environment data. > Document this? Yes, please. > Yes, we are running this from a blocker of the AddonManagers shutdown > barrier. In that case, please document it. > It doesn't really matter whether it finishes before or after. It will either > pick up the cached addons or collect some itself (may already be actively > collecting). ok > > > @@ +1007,5 @@ > > > + /** > > > + * This blocks the AddonManager shutdown barrier, it caches addons we might need later. > > > + * It also lets an active collect task finish first as it may still access the AM. > > > + */ > > > + _onAddonManagerShutdown: Task.async(function*() { > > > > Nit: I'm a big fan of giving different names to methods that return some > > value and methods that return a promise. Doubly-so if this is meant to be a > > blocker. > > What are you suggesting? _blockAddonManagerShutdown, maybe?
Assignee | ||
Comment 5•9 years ago
|
||
Attachment #8567908 -
Attachment is obsolete: true
Attachment #8568582 -
Flags: review?(dteller)
Assignee | ||
Comment 6•9 years ago
|
||
Comment on attachment 8568582 [details] [diff] [review] Cache addons on AddonManager shutdown Rerouting.
Attachment #8568582 -
Flags: review?(dteller) → review?(vdjeric)
Comment 7•9 years ago
|
||
Comment on attachment 8568582 [details] [diff] [review] Cache addons on AddonManager shutdown Review of attachment 8568582 [details] [diff] [review]: ----------------------------------------------------------------- > 1424366218494 Toolkit.Telemetry TRACE TelemetrySession::getSessionPayload - > reason: saved-session, clearSubsession: true why are we clearing the subsession when fetching a saved-session ping? won't that interfere with gathering the subsession shutdown ping? > 1424366218718 Toolkit.Telemetry TRACE TelemetrySession::_scheduleDailyTimer > - now: Thu Feb 19 2015 18:16:58 GMT+0100 (CET), scheduled: Fri Feb 20 2015 > 00:00:00 GMT+0100 (CET) why is a 24hr timer being scheduled at shutdown? (In reply to Georg Fritzsche [:gfritzsche] [away Feb 27 - March 15] from comment #3) > (In reply to David Rajchenbach-Teller [:Yoric] (away until Febrary - use > "needinfo") from comment #2) > > > + let addons = this._cachedAddons || {}; > > > + if (!this._cachedAddons) { > > > + addons.activeAddons = yield this._getActiveAddons(); > > > + addons.activeTheme = yield this._getActiveTheme(); > > > + addons.activeGMPlugins = yield this._getActiveGMPlugins(); > > > > Are we sure that AddonManager may not shutdown during these `yield`? If so, > > please document it. Otherwise, we have a race condition. > > Yes, we are running this from a blocker of the AddonManagers shutdown > barrier. This is the _getAddons() method -- doesn't it get called during reason=daily and environment-changed? And _cachedAddons is null until _blockAddonManagerShutdown is called. So isn't it possible this _getAddons() code will execute during the daily ping collection and the addon manager will begin shutting down at the same time?
Attachment #8568582 -
Flags: review?(vdjeric)
Assignee | ||
Comment 8•9 years ago
|
||
(In reply to Vladan Djeric (:vladan) -- please needinfo! from comment #7) > > 1424366218494 Toolkit.Telemetry TRACE TelemetrySession::getSessionPayload - > > reason: saved-session, clearSubsession: true > > why are we clearing the subsession when fetching a saved-session ping? won't > that interfere with gathering the subsession shutdown ping? > > > 1424366218718 Toolkit.Telemetry TRACE TelemetrySession::_scheduleDailyTimer > > - now: Thu Feb 19 2015 18:16:58 GMT+0100 (CET), scheduled: Fri Feb 20 2015 > > 00:00:00 GMT+0100 (CET) > > why is a 24hr timer being scheduled at shutdown? Sorting those out separately in a bit, unrelated to the bug at hand. > (In reply to Georg Fritzsche [:gfritzsche] [away Feb 27 - March 15] from > comment #3) > > (In reply to David Rajchenbach-Teller [:Yoric] (away until Febrary - use > > "needinfo") from comment #2) > > > > + let addons = this._cachedAddons || {}; > > > > + if (!this._cachedAddons) { > > > > + addons.activeAddons = yield this._getActiveAddons(); > > > > + addons.activeTheme = yield this._getActiveTheme(); > > > > + addons.activeGMPlugins = yield this._getActiveGMPlugins(); > > > > > > Are we sure that AddonManager may not shutdown during these `yield`? If so, > > > please document it. Otherwise, we have a race condition. > > > > Yes, we are running this from a blocker of the AddonManagers shutdown > > barrier. > > This is the _getAddons() method -- doesn't it get called during reason=daily > and environment-changed? And _cachedAddons is null until > _blockAddonManagerShutdown is called. So isn't it possible this _getAddons() > code will execute during the daily ping collection and the addon manager > will begin shutting down at the same time? Yes - but we will block AddonManager shutdown until the collection task finished.
Assignee | ||
Comment 9•9 years ago
|
||
Comment on attachment 8568582 [details] [diff] [review] Cache addons on AddonManager shutdown And back to Yoric so we can get this finished today.
Attachment #8568582 -
Flags: review?(dteller)
Comment on attachment 8568582 [details] [diff] [review] Cache addons on AddonManager shutdown Review of attachment 8568582 [details] [diff] [review]: ----------------------------------------------------------------- r=me, provided you convince Vlad and myself that _getAddons can only be called from within a shutdown blocker. If so, please document it. ::: toolkit/components/telemetry/TelemetryEnvironment.jsm @@ +837,5 @@ > + if (!this._cachedAddons) { > + addons.activeAddons = yield this._getActiveAddons(); > + addons.activeTheme = yield this._getActiveTheme(); > + addons.activeGMPlugins = yield this._getActiveGMPlugins(); > + } I am interested in your answer to Vlad's reply, too. @@ +1032,5 @@ > + */ > + _getState: function() { > + return { > + shutdown: this._shutdown, > + collectTask: !!this._collectTask, Nit: hasCollectTask, hasAddonsListener, hasCachedAddons.
Attachment #8568582 -
Flags: review?(dteller) → review+
Assignee | ||
Comment 11•9 years ago
|
||
(In reply to David Rajchenbach-Teller [:Yoric] (away until Febrary - use "needinfo") from comment #10) > r=me, provided you convince Vlad and myself that _getAddons can only be > called from within a shutdown blocker. If so, please document it. > > ::: toolkit/components/telemetry/TelemetryEnvironment.jsm > @@ +837,5 @@ > > + if (!this._cachedAddons) { > > + addons.activeAddons = yield this._getActiveAddons(); > > + addons.activeTheme = yield this._getActiveTheme(); > > + addons.activeGMPlugins = yield this._getActiveGMPlugins(); > > + } > > I am interested in your answer to Vlad's reply, too. Ok, i thought we cleared that up before. This is part of _getAddons(), which only called from _doGetEnvironmentData(), which is part of the _collectTask. When addon manager is shutting down, it runs our blocker function, _blockAddonManagerShutdown. If _collectTask is _running, we're waiting on it there. Later calls will instead hit the cached addon data.
Thanks for explaining over IRC the code paths that can lead to calling _getAddons. I believe that this needs to be documented for future generations, as any attempt to call _getAddons from a different code path could lead to a race condition.
Assignee | ||
Comment 13•9 years ago
|
||
Attachment #8568582 -
Attachment is obsolete: true
Attachment #8569225 -
Flags: review+
Assignee | ||
Updated•9 years ago
|
Whiteboard: [ready]
Assignee | ||
Comment 14•9 years ago
|
||
Attachment #8569225 -
Attachment is obsolete: true
Attachment #8569287 -
Flags: review+
Assignee | ||
Comment 15•9 years ago
|
||
Pushed in: https://hg.mozilla.org/integration/fx-team/pushloghtml?changeset=b83c3fa8c80f
Comment 16•9 years ago
|
||
https://hg.mozilla.org/mozilla-central/rev/6a9b785640d1
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
status-firefox39:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla39
You need to log in
before you can comment on or make changes to this bug.
Description
•