1110681 - HealthReporter AsyncShutdownTimeout due to blocking provider

Status: RESOLVED WONTFIX

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

Description

[Georg Fritzsche [:gfritzsche]]

From bp-552aac00-cfc6-48b1-9631-1fd372141212, the AsyncShutdownTimeout data is:
{"phase":"Metrics Storage Backend","conditions":[{"name":"FHR: Flushing storage shutdown","state":{"shutdownInitiated":false,"initialized":false,"shutdownRequested":true,"initializeHadError":false,"providerManagerInProgress":true,"storageInProgress":false,"hasProviderManager":true,"hasStorage":true,"shutdownComplete":false},"filename":"resource://gre/modules/HealthReport.jsm","lineNumber":4335,"stack":["resource://gre/modules/HealthReport.jsm:AbstractHealthReporter.prototype<.init/<:4335",""]}]}

That shows that we got to the provider manager shutdown here:
http://hg.mozilla.org/mozilla-central/annotate/5288b15d22de/services/healthreport/healthreporter.jsm#l580
... but returned because the provider manager is still initializing - i.e. we're still waiting on the init here:
http://hg.mozilla.org/mozilla-central/annotate/5288b15d22de/services/healthreport/healthreporter.jsm#l430

Now, in the shutdown blocker here:
http://hg.mozilla.org/mozilla-central/annotate/5288b15d22de/services/healthreport/healthreporter.jsm#l398
... we won't retry _initiateShutdown() in this scenario and hence hang indefinitely.

I think we have to either
* have the _initiateShutdown() wait on initialization to be finished
* or add another check for _shutdownRequested after initialization finished around here:
  http://hg.mozilla.org/mozilla-central/annotate/5288b15d22de/services/healthreport/healthreporter.jsm#l433
  ... similar to here:
  http://hg.mozilla.org/mozilla-central/annotate/5288b15d22de/services/healthreport/healthreporter.jsm#l433

Comment 1

[Georg Fritzsche [:gfritzsche]]

Attachment: Fix potential hang

This seems the simplest possible solution:
Retry shutdown after finishing initialization.

gps, what do you think?

Comment 2

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8535635 [details] [diff] [review]
Fix potential hang

This is the AsyncShutdownTimeout top-crash cause per bug 1035290, comment 15.
Trying rnewman as gps is on PTO.

Comment 3

[Gregory Szorc [:gps]]

Comment on attachment 8535635 [details] [diff] [review]
Fix potential hang

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

Looks OK-ish. But this doesn't get r+ until there is a test. See test_healthreporter.js.

::: services/healthreport/healthreporter.jsm
@@ +434,5 @@
>  
>          yield this._initializeProviderManager();
>          yield this._onProviderManagerInitialized();
>          this._initializedDeferred.resolve();
> +        yield this.onInit();

This change shouldn't matter. The API here is a bit wonky. init() is returning a Task that formerly resolved to a promise (this._initializedDeferred) that resolves to nothing (see line above). That's kinda wonky.

Unless someone is actually waiting on this promise, this line can be removed.

@@ +443,5 @@
> +        // We may have tried to shutdown during provider manager
> +        // initialization and skipped it; check for it now.
> +        if (this._shutdownRequested) {
> +          this._initiateShutdown();
> +        }

I don't think this needs to be in a finally block. Instead, it can be in-lined before |this._initializedDeferred.resolve()|

Comment 4

[Georg Fritzsche [:gfritzsche]]

Actually, rereading the code to evaluate testability... i don't think i identified the issue correctly.

Given |"hasProviderManager":true| and the other state information:
{
  "shutdownInitiated":false,
  "initialized":false,
  "shutdownRequested":true,
  "initializeHadError":false,
  "providerManagerInProgress":true,
  "storageInProgress":false,
  "hasProviderManager":true,
  "hasStorage":true,
  "shutdownComplete":false
}

That means we still have to be in _initializeProviderManager() [0], as _onProviderManagerInitialized() sets |providerManagerInProgress=true| [1].

Which means that we probably hang waiting on a provider to start up.
I wonder if we can break anything provider startups depend on by hitting _initiateShutdown() too early (i.e. setting this._initialized=false and this._shutdownRequested=false).

gps, can you sanity check my reading above?
Any input/ideas?

[0] http://hg.mozilla.org/mozilla-central/annotate/5288b15d22de/services/healthreport/healthreporter.jsm#l430
[1] http://hg.mozilla.org/mozilla-central/annotate/5288b15d22de/services/healthreport/healthreporter.jsm#l507

Comment 5

[Georg Fritzsche [:gfritzsche]]

I was still logged in to the wrong bugzilla account while trying to merge them.
Resending needinfo from correct account.

Comment 6

[Georg Fritzsche [:gfritzsche]]

(In reply to cygmatic from comment #4)
> That means we still have to be in _initializeProviderManager() [0], as
> _onProviderManagerInitialized() sets |providerManagerInProgress=true| [1].
> 
> Which means that we probably hang waiting on a provider to start up.

Ok, just checked this by making ExperimentsProvider.postInit() just return a non-resolving promise. I ended up with the same AsyncShutdownTimeout state as here.

Comment 7

[Georg Fritzsche [:gfritzsche]]

Attachment: AsyncShutdownTimeout diagnostic for FHR provider init

Adding diagnostics for this.

Comment 8

[Gregory Szorc [:gps]]

Promises from providers "hanging" is a known issue in FHR. See also bug 1030270 and bug 989788. This bug is just a variant that occurs during provider init/shutdown instead of collection. Same outcome.

Quite frankly, I'm surprised it took so long for this kind of issue to surface as a top crasher. Your forensics will likely indicate a failure and legitimate bug in some other component. That other component should be fixed. However, I still think FHR should practice defense in depth and implement timers for promise resolution when dealing with external systems. The chances that a client will encounter this class of error will increase as the number of providers increases. The problem will only get worse over time.

Comment 9

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

Comment on attachment 8537853 [details] [diff] [review]
AsyncShutdownTimeout diagnostic for FHR provider init

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

Looks good, thanks.
Also, gps is right, we should probably add a timeout, see e.g. PromiseUtils.resolveOrTimeout.

::: services/metrics/providermanager.jsm
@@ +126,5 @@
>          Cu.import(uri, ns);
>  
>          let promise = this.registerProviderFromType(ns[entry]);
>          if (promise) {
> +          promiseMap.set(entry, promise);

Are we sure that `entry` is unique?
If not, we should rather store an array of {entry, promise}, shouldn't we?

@@ +136,5 @@
>          continue;
>        }
>      }
>  
>      return Task.spawn(function wait() {

`function*`, btw

Comment 10

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

Side-note: we still want data on providers that don't terminate. Perhaps we should crash in DEBUG mode and timeout in non-DEBUG? Or can we upload such data meaningfully using FHR itself?

Comment 11

[Georg Fritzsche [:gfritzsche]]

(In reply to David Rajchenbach-Teller [:Yoric] (hard to reach until January 10th - use "needinfo") from comment #10)
> Side-note: we still want data on providers that don't terminate. Perhaps we
> should crash in DEBUG mode and timeout in non-DEBUG? Or can we upload such
> data meaningfully using FHR itself?

Hm, this is a little interesting as this basically means to submit data into FHR while its shutting down.

Comment 12

[Georg Fritzsche [:gfritzsche]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/02b168bd2232

Comment 13

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8537853 [details] [diff] [review]
AsyncShutdownTimeout diagnostic for FHR provider init

Approval Request Comment
[Feature/regressing bug #]: Some FHR provider is timing out.
[User impact if declined]: No info on which provider is at fault.
[Describe test coverage new/current, TBPL]: Automated test-coverage.
[Risks and why]: Low-risk, just adding some diagnostics.
[String/UUID change made/needed]: None.

Comment 14

[Georg Fritzsche [:gfritzsche]]

(In reply to Gregory Szorc [:gps] from comment #8)
> Quite frankly, I'm surprised it took so long for this kind of issue to
> surface as a top crasher. Your forensics will likely indicate a failure and
> legitimate bug in some other component. That other component should be
> fixed. However, I still think FHR should practice defense in depth and
> implement timers for promise resolution when dealing with external systems.

Ok, but then we also need to cross-check all FHR code to properly fail when accessed late in each respective scenarios, which might open up another bucket of problems.
And we definitely need to figure out how to submit the offending providers via FHR and Telemetry, which may be hard during/after shutdown of these systems.
Shutdown ordering between the two might then also be a concern.

Comment 15

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/02b168bd2232

Comment 16

[Georg Fritzsche [:gfritzsche]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/888ab5f9e567
https://hg.mozilla.org/releases/mozilla-beta/rev/0c82d41ff213

Comment 17

[Ryan VanderMeulen [:RyanVM]]

This isn't fixed on 37 IIUC.

Comment 18

[Georg Fritzsche [:gfritzsche]]

We do have some data in "are we shutting down yet" now that has currentProviderInInit and currentProviderInShutdown.
There is already quite some reports with "currentProviderInInit":"SearchesProvider".

Given the spike for these in 34, this points to bug 1029031 ("Record the currently selected search provider in FHR"):
http://hg.mozilla.org/mozilla-central/rev/b77106f50779

However, that bug was uplifted to 33 & 32 and apparently we didn't have a spike there.

Comment 19

[Georg Fritzsche [:gfritzsche]]

I quickly sampled "Are we shutting down yet" for this today again [0] manually - most of the timeouts for 35+ are still with "currentProviderInInit":"SearchesProvider".

Florian, it looks like you are good to ask on SearchService issues?

We apparently have the FHR SearchesProvider hanging around here:
https://hg.mozilla.org/mozilla-central/annotate/2a193b7f395c/services/healthreport/providers.jsm#l1626

... which would mean that we don't get called back from SearchService.init():
https://hg.mozilla.org/mozilla-central/annotate/2a193b7f395c/toolkit/components/search/nsSearchService.js#l3998

The first thing that stands out is that we don't seem to call back the observer when |this._initStarted| is true.
Am i missing something here? Any other failure points you can think of?

[0] http://yoric.github.io/are-we-shutting-down-yet-/?signature=~FHR%3A+Flushing+storage+shutdown#

Comment 20

[:Gavin Sharp [email: [e-mail]]]

(In reply to Georg Fritzsche [:gfritzsche] from comment #19)
> The first thing that stands out is that we don't seem to call back the
> observer when |this._initStarted| is true.
> Am i missing something here?

Yoric wrote this code, but I think you might be. If _initStarted is true, then we should fall directly into the if (observer) case, and this._initObservers.promise will either already be resolved, or be in the process of resolving itself.

From a quick skim I don't see any code paths that can lead to _initObservers.promise not being resolved, but maybe there are some...

Comment 21

[Georg Fritzsche [:gfritzsche]]

(In reply to :Gavin Sharp [email: [e-mail]] from comment #20)
> Yoric wrote this code, but I think you might be. If _initStarted is true,
> then we should fall directly into the if (observer) case, and
> this._initObservers.promise will either already be resolved, or be in the
> process of resolving itself.

Ah, indeed, i missed that .then() handlers are still called when the promise is already resolved.

Yoric, any ideas here?

Comment 22

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

I have looked at SearchService initialization. I believe that the asynchronous initialization never completes. This may be due to a bug in the code (the loading of search engines, in particular, is way too complicated to be easy to trust) or in a notification observer that could be spinning the event loop and causing havoc.

To find out more, I believe that the best solution is to make the asynchronous initialization an AsyncShutdown blocker, and use its `fetchState` to determine how far we have managed to go in the initialization.

Comment 23

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

https://tbpl.mozilla.org/?tree=Try&rev=cdda26ec865b

Comment 24

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

Attachment: AsyncShutdown diagnostics for SearchService

This should give us more details about what's going wrong.

Comment 25

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

Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=2bfb9a5e6579

Comment 26

[:Felipe Gomes (needinfo for replies!)]

Comment on attachment 8550274 [details] [diff] [review]
AsyncShutdown diagnostics for SearchService

Adding Florian in case he wants to take a look or can get to this before myself, as he has worked a lot on this recently

Comment 27

[Florian Quèze [:florian]]

Comment on attachment 8550274 [details] [diff] [review]
AsyncShutdown diagnostics for SearchService

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

::: toolkit/components/search/nsSearchService.js
@@ +240,5 @@
>   */
>  const SEARCH_LOG_PREFIX = "*** Search: ";
>  
>  /**
> + * The latest entries to the log.

Isn't there a word missing in this comment?

@@ +278,5 @@
>  /**
>   * Otherwise, don't log at all by default. This can be overridden at startup
>   * by the pref, see SearchService's _init method.
>   */
> +var LOG = function(aText){

nit: space between ) and {.

@@ +3106,5 @@
> +   * part of a crash report in case of AsyncShutdown timeout.
> +   */
> +  debugState: {
> +    get initStarted() {
> +      return SearchService.prototype._initStarted;

Isn't this (on the prototype, rather than on the SearchService instance) always null?

Comment 28

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

Could someone take over this patch? I won't have time to work on it in January.

Comment 29

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

Attachment: MozReview Request: bz://1110681/Yoric

Comment 30

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

/r/2695 - Bug 1110681 - Instrumenting SearchService;r=felipe

Pull down this commit:

hg pull review -r 4e368c82aab468e20bf0acd56349b6124a4e594e

Comment 31

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

/r/2695 - Bug 1110681 - Instrumenting SearchService;r=felipe
/r/2697 - Bug 1110681 - Instrumenting SearchService;r=florian

Pull down these commits:

hg pull review -r 6ff1375352e785841ade4aea530a72afa5ae1735

Comment 32

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

/r/2695 - Bug 1110681 - Instrumenting SearchService;r=felipe
/r/2697 - Bug 1110681 - Instrumenting SearchService;r=florian

Pull down these commits:

hg pull review -r 6ff1375352e785841ade4aea530a72afa5ae1735

Comment 33

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

Applied feedback.

Comment 34

[Florian Quèze [:florian]]

https://reviewboard.mozilla.org/r/2695/#review1787

::: toolkit/components/search/nsSearchService.js
(Diff revision 1)
> +      return this._initStarted;

It seems to me that "this" here points to the 'debugState' object, so I'm afraid _initStarted and _initRV will be undefined.

Comment 35

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

/r/2695 - Bug 1110681 - Instrumenting SearchService;r=felipe
/r/2697 - Bug 1110681 - Instrumenting SearchService;r=florian
/r/2699 - Bug 1110681 - Instrumenting SearchService;r=florian

Pull down these commits:

hg pull review -r b94aa40682472d51a42f4b6709597a98e0fe6cc7

Comment 36

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

https://reviewboard.mozilla.org/r/2695/#review1789

> It seems to me that "this" here points to the 'debugState' object, so I'm afraid _initStarted and _initRV will be undefined.

You are, of course, right. My bad.

Comment 37

[Georg Fritzsche [:gfritzsche]]

(In reply to David Rajchenbach-Teller [:Yoric] (away until Febrary - use "needinfo") from comment #28)
> Could someone take over this patch? I won't have time to work on it in
> January.

Benjamin, do you know who could?

Comment 38

[Florian Quèze [:florian]]

https://reviewboard.mozilla.org/r/2693/#review1791

::: toolkit/components/search/nsSearchService.js
(Diff revision 3)
> -var LOG = function(){};
> +var LOG = function (aText){

I noted in comment 27 that a space was missing between ) and {, you added one between "function" and "(".

::: toolkit/components/search/nsSearchService.js
(Diff revision 3)
> +      return !!self._batchTaskl

nit: missing ; here.

::: toolkit/components/search/nsSearchService.js
(Diff revision 3)
> +  this.debugState = {

It seems this object and the gLatestLogEntries array become useless once _initObservers.promise has resolved (and the search service init is no longer blocking shutdown). Should we set them to null so that they are gc'ed?

Comment 39

[Benjamin Smedberg]

Georg, if this is indeed important, then it's something that you and Alessio will need to do. But as I said earlier, I'm not convinced that spending time on this is worthwhile since we're planning on sunsetting all this FHR code in the 38 cycle anyway.

Comment 40

[Florian Quèze [:florian]]

Comment on attachment 8551512 [details]
MozReview Request: bz://1110681/Yoric

Clearing the review flag (my review comments are in comment 38) and needinfo per comment 39.

Comment 41

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

https://treeherder.mozilla.org/#/jobs?repo=try&revision=d1baa28e7614

Comment 42

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

Comment on attachment 8551512 [details]
MozReview Request: bz://1110681/Yoric

/r/2695 - Bug 1110681 - Instrumenting nsSearchService;r=florian

Pull down this commit:

hg pull review -r d1baa28e7614a44315ede5101472a789f6cb75b3

Comment 43

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

Ah, right, my bad, I forgot to click "publish" in mozReview, so Florian had never received my updated review request. Here we go.

Comment 44

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

Florian?

Comment 45

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

Ah, good offline point: the blocked bug has been WONTFIXed, canceling review.

Comment 46

[Firefox Bug Husbandry Bot]

Removing leave-open keyword from resolved bugs, per :sylvestre.