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

RESOLVED FIXED in Firefox 33

Status

defect
RESOLVED FIXED
5 years ago
9 months ago

People

(Reporter: gfritzsche, Assigned: qeole, Mentored)

Tracking

unspecified
Firefox 34
Dependency tree / graph
Bug Flags:
firefox-backlog +

Firefox Tracking Flags

(firefox33 fixed, firefox34 fixed)

Details

(Whiteboard: [diamond][lang=js])

Attachments

(1 attachment, 1 obsolete attachment)

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
Flags: firefox-backlog+
Assignee: georg.fritzsche → nobody
Points: 2 → 3
The state info was added in bug 1012924.
Blocks: 1012924
Keywords: regression
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.
Mentor: georg.fritzsche
Flags: needinfo?(dteller)
Whiteboard: [diamond][lang=js]
Flags: needinfo?(dteller)
Keywords: regression
QA Whiteboard: [qa-]
This bug requires taking the instrumentation patch in bug 1012924, make it apply to the current source and take it for quick testing.
Can you handle this or do you need me to?
Flags: needinfo?(georg.fritzsche)
Keywords: checkin-needed
I can handle it when i have time or mentor someone to do it, i was assuming you are away.
Flags: needinfo?(georg.fritzsche)
Assignee: nobody → qeole
Iteration: --- → 33.3
For a contributor, I'll add the Iteration ID when the bug lands.
Iteration: 33.3 → ---
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
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
Posted patch updatedFromBug1012924.patch (obsolete) — Splinter Review
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
Attachment #8462102 - Flags: feedback?(georg.fritzsche)
Attachment #8462102 - Attachment filename: updatedFromBug1012924.patch → updatedFromBug1012924_bugged.patch
Attachment #8462102 - Attachment is obsolete: true
Attachment #8462102 - Flags: feedback?(georg.fritzsche)
Forgot to remove instructions for crashing Firefox from previous version of patch :s …
Updating.
Attachment #8462246 - Flags: feedback?(georg.fritzsche)
Comment on attachment 8462246 [details] [diff] [review]
updatedFromBug1012924.patch

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

Thanks for checking into this, this looks good!
Attachment #8462246 - Flags: feedback?(georg.fritzsche) → review+
https://hg.mozilla.org/mozilla-central/rev/7c7c65151eaf
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 34
Iteration: --- → 34.1
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.
Attachment #8462246 - Flags: approval-mozilla-aurora?
Attachment #8462246 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Product: Firefox Health Report → Firefox Health Report Graveyard
You need to log in before you can comment on or make changes to this bug.