952543 - Report startup exceptions in AddonManager and XPIProvider through telemetry

Status: RESOLVED FIXED

(Toolkit :: Add-ons Manager, defect)

Description

[:Irving Reid (No longer working on Firefox)]

Telemetry review of the simple measures AMI_startup_end, XPI_startup_end, and XPI_bootstrap_end show that in roughly 1 in 10 000 Firefox Nightly / Windows sessions, one of these phases of the start up process does not complete - the _end timestamp is not in the telemetry packet, even though other later timestamps are present.

A triage pass over bugs in the Add-on Manager component didn't find any obvious reports of problems, so I'd like to record an exception summary in the simpleMeasures/addonManager section to see if we can identify any problems based on reports from the field.

Open question: do we record a one line entry, exception text and file/line, or a full stack? Note that Android telemetry does include some stacks (e.g. bug 826053, for Application Not Responding events) but these are Java, not JS.

Comment 1

[:Irving Reid (No longer working on Firefox)]

Attachment: Catch exceptions in several places and record in telemetry

Comment 2

[Dave Townsend [:mossop]]

Comment on attachment 8350731 [details] [diff] [review]
Catch exceptions in several places and record in telemetry

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

::: toolkit/mozapps/extensions/AddonManager.jsm
@@ +469,5 @@
>     * Initializes the AddonManager, loading any known providers and initializing
>     * them.
>     */
>    startup: function AMI_startup() {
> +   try {

Nice for review but before landing make the indent right

@@ +576,5 @@
>          Components.utils.import(url, {});
>        }
>        catch (e) {
> +        AddonManagerPrivate.recordSimpleMeasure("exception",
> +          LogManager.formatLogMessage("ERROR", "AMI", "provider " + url + " load failed", e));

These exceptions are already caught, doesn't that mean they can't be the cause of problems?

@@ +599,5 @@
>          delete this.startupChanges[type];
>      }
>  
> +      this.foo.bar();
> +    

I suspect you didn't mean to include this in the patch

Comment 3

[Vladan Djeric (:vladan)]

Comment on attachment 8350731 [details] [diff] [review]
Catch exceptions in several places and record in telemetry

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

Aside from dtownsend's remarks, looks good

Comment 4

[:Irving Reid (No longer working on Firefox)]

Attachment: Record exceptions in telemetry, without depending on AddonLogging.jsm

I was just wrapping up testing my cleanup from these comments when I remembered bug 661982, and figured that if I'm helping to get rid of AddonLogging.jsm I'd better not add a new dependency on it in this patch. I changed things to record the exception details as a JSON blob rather than a string.

(In reply to Dave Townsend (:Mossop) from comment #2)
> Review of attachment 8350731 [details] [diff] [review]:
> -----------------------------------------------------------------
> @@ +576,5 @@
> >          Components.utils.import(url, {});
> >        }
> >        catch (e) {
> > +        AddonManagerPrivate.recordSimpleMeasure("exception",
> > +          LogManager.formatLogMessage("ERROR", "AMI", "provider " + url + " load failed", e));
> 
> These exceptions are already caught, doesn't that mean they can't be the
> cause of problems?

Yes, but I figured an exception here is serious enough that we'd be interested to find out about it.

> @@ +599,5 @@
> >          delete this.startupChanges[type];
> >      }
> >  
> > +      this.foo.bar();
> > +    
> 
> I suspect you didn't mean to include this in the patch

Oops, that was how I caused the exceptions for manual testing...

Comment 5

[Dave Townsend [:mossop]]

Comment on attachment 8356781 [details] [diff] [review]
Record exceptions in telemetry, without depending on AddonLogging.jsm

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

::: toolkit/mozapps/extensions/AddonManager.jsm
@@ +2239,5 @@
> +        report.file = aException.fileName;
> +        report.line = aException.lineNumber;
> +      }
> +    }
> +      

Nit: Trailing whitespace

Comment 6

[:Irving Reid (No longer working on Firefox)]

Attachment: Telemetry for add-on manager exceptions, nit fixed for check-in

Carrying forward Dave's r+ in comment 5

Comment 7

[:Irving Reid (No longer working on Firefox)]

This doesn't need a build of its own

Comment 8

[Ryan VanderMeulen [:RyanVM]]

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

Comment 9

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

Backed out in https://hg.mozilla.org/integration/fx-team/rev/2645530519bb for xpcshell failures:

https://tbpl.mozilla.org/php/getParsedLog.php?id=32720598&tree=Fx-Team

Comment 10

[:Irving Reid (No longer working on Firefox)]

Attachment: Record exceptions in telemetry, test failure fixed

Bah, test_shutdown.js / test_functions() assumes that every method in AddonManager and AddonManagerPrivate should throw a NOT_INITIALIZED exception, unless the method is explicitly ignored in the test. This is the n+1'th time I've been burned by this.

Updated patch just adds AddonManagerPrivate.recordException() to the ignore list in test_shutdown.js; rs=mossop in IRC #fx-team.

Comment 11

[Ryan VanderMeulen [:RyanVM]]

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

Comment 12

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/e977e3694048