Closed Bug 1134700 Opened 9 years ago Closed 9 years ago

TelemetryEnvironment tries to collect addon data after AddonManager shutdown

Categories

(Toolkit :: Telemetry, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla39
Tracking Status
firefox39 --- fixed

People

(Reporter: gfritzsche, Assigned: gfritzsche)

References

Details

(Whiteboard: [ready])

Attachments

(1 file, 3 obsolete files)

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>
Summary: TelemetryEnvironment tries to collect addon data after it is shutdown → TelemetryEnvironment tries to collect addon data after AddonManager shutdown
Assignee: nobody → gfritzsche
Status: NEW → ASSIGNED
* 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+
(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?
Attachment #8567908 - Attachment is obsolete: true
Attachment #8568582 - Flags: review?(dteller)
Comment on attachment 8568582 [details] [diff] [review]
Cache addons on AddonManager shutdown

Rerouting.
Attachment #8568582 - Flags: review?(dteller) → review?(vdjeric)
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)
(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.
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+
(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.
Attachment #8568582 - Attachment is obsolete: true
Attachment #8569225 - Flags: review+
Whiteboard: [ready]
Attachment #8569225 - Attachment is obsolete: true
Attachment #8569287 - Flags: review+
https://hg.mozilla.org/mozilla-central/rev/6a9b785640d1
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla39
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: