1040761 - Re-add state info for async shutdown blocker in Experiments.jsm

Status: RESOLVED FIXED

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

Description

[Georg Fritzsche [:gfritzsche]]

Not sure what happened without further look, but we lost the additional state information from the Experiments.jsm async shutdown that Yoric added here:
http://hg.mozilla.org/mozilla-central/annotate/99f694d1b50c/browser/experiments/Experiments.jsm#l408

Comment 1

[Georg Fritzsche [:gfritzsche]]

The state info was added in bug 1012924.

Comment 2

[Georg Fritzsche [:gfritzsche]]

The patch never landed on m-c, only on Aurora. We should get a patch ready so we can get this landed and uplifted quickly after branching.

Comment 3

[Georg Fritzsche [:gfritzsche]]

This bug requires taking the instrumentation patch in bug 1012924, make it apply to the current source and take it for quick testing.

Comment 4

[David Teller [:Yoric] - still alive but not very active]

Can you handle this or do you need me to?

Comment 5

[Georg Fritzsche [:gfritzsche]]

I can handle it when i have time or mentor someone to do it, i was assuming you are away.

Comment 6

[Marco Mucci [:MarcoM]]

For a contributor, I'll add the Iteration ID when the bug lands.

Comment 7

[Qeole]

I am under the impression that even though
  1)  AsyncShutdown.profileBeforeChange.addBlocker("Experiments.jsm shutdown", this.uninit.bind(this));

was turned into
  2)  AddonManager.shutdown.addBlocker("Experiments.jsm shutdown", this.uninit.bind(this));

the |addBlocker| method which is called in the end is the same − I think it's called on a |AsyncShutdown.Barrier().client| in both cases:

 * in 1), on a |client| of |this._barrier| in |Spinner.prototype|, this Spinner being created by |getPhase| which is in turn called by |AsyncShutdown.profileBeforeChange| (see respectively [1], [2] and [3]);
 * in 2), |AddonManager.shutdown| returns |gShutdownBarrier.client|, where |gShutdownBarrier| is an |AsyncShutdown.Barrier()| (in [4] and [5]).

Hence the two calls would accept the same arguments (these arguments are explained in [6]), and I'd be tempted to patch with the line which was added in bug 1012924, i.e. to have:

  AddonManager.shutdown.addBlocker("Experiments.jsm shutdown",
    this.uninit.bind(this),
    this._getState.bind(this)
  );

But I've got a problem for testing this: I don't know how to keep logs from web console (or from another way) when Firefox closes, nor do I know if it is possible to shut down addon manager without closing Firefox. Georg, could you give me hints about this please?

[1] https://hg.mozilla.org/mozilla-central/annotate/e5ced39f443b/toolkit/modules/AsyncShutdown.jsm#l312
[2] https://hg.mozilla.org/mozilla-central/annotate/e5ced39f443b/toolkit/modules/AsyncShutdown.jsm#l246
[3] https://hg.mozilla.org/mozilla-central/annotate/e5ced39f443b/toolkit/modules/AsyncShutdown.jsm#l775
[4] https://hg.mozilla.org/mozilla-central/annotate/e5ced39f443b/toolkit/mozapps/extensions/AddonManager.jsm#l2811
[5] https://hg.mozilla.org/mozilla-central/annotate/e5ced39f443b/toolkit/mozapps/extensions/AddonManager.jsm#l2811
[6] https://hg.mozilla.org/mozilla-central/annotate/e5ced39f443b/toolkit/modules/AsyncShutdown.jsm#l409

Comment 8

[Georg Fritzsche [:gfritzsche]]

Great - if that is the only conflict, adding the _getState() function as before should work fine.

I can't think of a clean way for automatic tests here, but verifying manually should be fine.
The easiest way would be to check on the console/terminal, you should see the messages from AsyncShutdown.jsm there [1] when you set the preference browser.dom.window.dump.enabled to true.

You should see this trigger by blocking Experiments.uninit(), e.g. with something like this:
> let deferred = Promise.defer();
> yield deferred.promise;

... then the async shutdown timeout handling should kick in with a warning [2] and finally a crash [3] and dump the messages including the state to the terminal.

[1] https://hg.mozilla.org/mozilla-central/annotate/e5ced39f443b/toolkit/modules/AsyncShutdown.jsm#l93
[2] https://hg.mozilla.org/mozilla-central/annotate/e5ced39f443b/toolkit/modules/AsyncShutdown.jsm#l675
[3] https://hg.mozilla.org/mozilla-central/annotate/e5ced39f443b/toolkit/modules/AsyncShutdown.jsm#l710

Comment 9

[Qeole]

Attachment: updatedFromBug1012924.patch

Thanks Georg, I got the logs.

I realized that just patching as described in comment #7 was obviously not enough, as the |_getState()| method is lacking: it was also implemented in bug 1012924.

So I took the whole patch of bug 1012924 [1] and tried to adapt. There were two failing hooks:
1) first one on |AddonManager.shutdown.addBlocker()|, of course, since it has changed;
2) second one at bottom of patch, for |_unregisterWithAddonManager()| method: but code instructions weren't changed, only reversed, so it was easy to fix.

Now I have an up-to-date version of patch used in bug 1012924. I ran Firefox, made it crash, and could read following message: 

> FATAL ERROR: AsyncShutdown timeout in AddonManager: Waiting for clients to shut down. Conditions:
> [{"name":"Experiments.jsm shutdown","state":{"isShutdown":true,"isEnabled":true,"isRefresh":false,
> "isDirty":false,"isFirstEvaluate":false,"hasLoadTask":false,"hasMainTask":false,"hasTimer":false,
> "hasAddonProvider":false,"latestLogs":[null,null,null],"experiments":{},"terminateReason":null},
> "filename":"resource:///modules/experiments/Experiments.jsm","lineNumber":425,"stack":[ … ]}]
> At least one completion condition failed to complete within a reasonable amount of time.
> Causing a crash to ensure that we do not leave the user with an unresponsive process draining
> resources.
> [16482] ###!!! ABORT: file resource:///modules/experiments/Experiments.jsm, line 425
> [16482] ###!!! ABORT: file resource:///modules/experiments/Experiments.jsm, line 425

I enclose updated patch for feedback. I don't know if you wish to keep all of it, Georg, or to dismiss some log data/error handling.

[1] https://bug1012924.bugzilla.mozilla.org/attachment.cgi?id=8451645

Comment 10

[Qeole]

Attachment: updatedFromBug1012924.patch

Forgot to remove instructions for crashing Firefox from previous version of patch :s …
Updating.

Comment 11

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8462246 [details] [diff] [review]
updatedFromBug1012924.patch

Review of attachment 8462246 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks for checking into this, this looks good!

Comment 12

[Georg Fritzsche [:gfritzsche]]

https://hg.mozilla.org/integration/fx-team/rev/7c7c65151eaf

Comment 13

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/7c7c65151eaf

Comment 14

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8462246 [details] [diff] [review]
updatedFromBug1012924.patch

We currently are missing this on Firefox 33 / Aurora, so i'm hoping for an early uplift.

Approval Request Comment
[Feature/regressing bug #]: -
[User impact if declined]: No additional async shutdown timeout details for our dashboard.
[Describe test coverage new/current, TBPL]: Manual testing done by Qeole & the original patch from bug 1012924 was fine so far on 32.
[Risks and why]: Low as this is only the instrumentation patch from bug 1012924 rebased.
[String/UUID change made/needed]: None.

Comment 15

[Georg Fritzsche [:gfritzsche]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/e7d4238dd075