1238142 - Error collecting addons: TypeError: aString.substring is not a function (resource://gre/modules/TelemetryEnvironment.jsm:267:10

Status: VERIFIED FIXED

(Toolkit :: Telemetry, defect, P1)

Description

[Jared Wein [:jaws] (please needinfo? me)]

I found this error in my Browser Console when I started up my local build.

> 1452291074417 Toolkit.Telemetry ERROR TelemetryEnvironment::_checkForChanges:
> Error collecting addons: TypeError: aString.substring is not a function (resource://gre/modules/TelemetryEnvironment.jsm:267:10)
> JS Stack trace:
> [e-mail]:267:10 <
> EnvironmentAddonBuilder.prototype._getActiveAddons<@TelemetryEnvironment.jsm:525:18 <
> [e-mail]:315:40 <
> promise callback*[e-mail]:391:7 <
> [e-mail]:323:13 <
> [e-mail]:276:3 <
> createAsyncFunction/[e-mail]:250:14 <
> EnvironmentAddonBuilder.prototype._updateAddons<@TelemetryEnvironment.jsm:479:27 <
> [e-mail]:315:40 <
> [e-mail]:276:3 <
> createAsyncFunction/[e-mail]:250:14 <
> [e-mail]:437:25 <
> [e-mail]:428:5 <
> [e-mail]:1296:7 <
> [e-mail]:315:40 <
> [e-mail]:933:23 <
> [e-mail]:812:7 <
> Promise*[e-mail]:743:11 <
> [e-mail]:775:7 <
> [e-mail]:710:7 <
> this.BasePromiseWorker.prototype._worker/[e-mail]:231:9 <
> EventHandlerNonNull*[e-mail]:217:5 <
> [e-mail]:292:9 <
> [e-mail]:315:40 <
> [e-mail]:933:23 <
> [e-mail]:812:7 <
> Promise*[e-mail]:743:11 <
> [e-mail]:775:7 <
> [e-mail]:710:7 <
> onSuccess@osfile_native.jsm:63:7

These are the extensions I have installed,
DOM Inspector	2.0.16	true	[e-mail]
Firefox Hello	0.1	true	[e-mail]
Pocket	46.0a1	true	[e-mail]
Pocket	3.0.6.1-signed	false	[e-mail]

Comment 1

[Alessio Placitelli [:Dexter]]

That's a good catch, thanks.

How old is your local build?
Do you have any other addon/plugin installed?
Does it show as soon as FF starts?

I wasn't able to reproduce locally with the latest m-c and the extensions you posted.

Comment 2

[Jared Wein [:jaws] (please needinfo? me)]

My local build is based off ea01aa74be13, https://hg.mozilla.org/integration/fx-team/rev/ea01aa74be13

The list of addons/plugins in comment #0 is from about:support, so that should be exhaustive.

Yeah, it showed soon after Firefox started. I opened the Browser Console about 30 seconds after it started to check something I was working on.

Comment 3

[Jared Wein [:jaws] (please needinfo? me)]

I talked with Dexter on IRC and he asked me to put a `dump(JSON.stringify(addon))` statement at TelemetryEnvironment.jsm:516 and I saw the following:
a blank addon "{}",
a Google+ addon "{"manifest":{"author":"Google","description":"Quickly share [... redacted]},
then a Facebook addon "{"manifest":{"activities":{"share":{"disposition":"inline","filters":{"type":["*"]},"href":"https://www.facebook.com/sharer/s [... redacted]".

When I go to about:addons and click on the Services tab, it says "You don't have any addons of this type installed". Shane, do you know why these would be appearing in the Telemetry code but not in about:addons?

Comment 4

[Jared Wein [:jaws] (please needinfo? me)]

Oh whoops, I was using the wrong profile when I opened about:addons. Those are in about:addons and they show up in the share-plane.

Dexter found that Facebook was using a number for it's version and we expected a string.

Comment 5

[Alessio Placitelli [:Dexter]]

(In reply to Jared Wein [:jaws] (please needinfo? me) from comment #4)
> Oh whoops, I was using the wrong profile when I opened about:addons. Those
> are in about:addons and they show up in the share-plane.
> 
> Dexter found that Facebook was using a number for it's version and we
> expected a string.

We should probably be more effective in guarding against unexpected data loss on our Telemetry side.

However, it looks like the version returned from the addon manager should really be a string [0]. SocialService.jsm seems to assume [1] it is (see the "" part), but the Facebook social manifest has a number in it:

{
        ... other removed stuff ...
	"shareURL" : "https://www.facebook.com/sharer/sharer.php?u=%{url}",
	"version" : 2,
	"postActivationURL" : "https://activations.cdn.mozilla.net/en-US/activated/facebook.html",
	"updateDate" : 1452587419933,
	"installDate" : 1452534699655
}

The examples in the SocialAPI manifest documentation [2] seem to imply that version should be a number as well.

[0] - https://developer.mozilla.org/en-US/Add-ons/Add-on_Manager/Addon
[1] - https://dxr.mozilla.org/mozilla-central/rev/5acc2a44834ce0614f98466475e674517daf0041/toolkit/components/social/SocialService.jsm#1156
[2] - https://developer.mozilla.org/en-US/docs/Mozilla/Projects/Social_API/Manifest

Comment 6

[Georg Fritzsche [:gfritzsche]]

This affects all releases bug 1211404 is on.
Lets take the chance here to properly harden the addon collections so that we never lose more than the data for one addon.

Comment 7

[Alessio Placitelli [:Dexter]]

Attachment: part 1 - Harden addon data collection in TelemetryEnvironment

Collecting the data for each addon is wrapped in try/catch block so that, at most, one addon is lost if an exception is thrown.

This is also modifying limitStringLength to check for a valid "string" type.

Part 2 will add test coverage by adding an addon using the SocialAPI [0] with a broken manifest.

[0] - https://dxr.mozilla.org/mozilla-central/rev/5acc2a44834ce0614f98466475e674517daf0041/browser/modules/test/unit/social/head.js#115

Comment 8

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8706991 [details] [diff] [review]
part 1 - Harden addon data collection in TelemetryEnvironment

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

::: toolkit/components/telemetry/TelemetryEnvironment.jsm
@@ +263,5 @@
>   *        greater than the length of the input string, we return the whole input string.
>   * @return {String} The substring or null if the input string is null.
>   */
>  function limitStringToLength(aString, aMaxLength) {
> +  if (typeof aString !== "string") {

typeof(aString)

@@ +541,5 @@
> +        if (addon.signedState !== undefined)
> +          activeAddons[addon.id].signedState = addon.signedState;
> +
> +      } catch (ex) {
> +        this._environment._log.error("_getActiveAddons - An addon was discarded due to an error", ex);

Let's file a follow-up on error Telemetry here.

Comment 9

[Alessio Placitelli [:Dexter]]

Attachment: part 1 - Harden addon data collection in TelemetryEnvironment

Comment 10

[Alessio Placitelli [:Dexter]]

Attachment: part 2 - Add xpcshell test coverage

This uses the SocialAPI to break the addon collection:

1 - We install a "broken" manifest
2 - We install a legit addon
3 - We get the new environment
4 - We check that the broken addon is there (with the version being null) 
5 - And the legit addon is there as well

Comment 11

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8707428 [details] [diff] [review]
part 2 - Add xpcshell test coverage

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

::: toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js
@@ +1068,5 @@
> +    foreignInstall: false,
> +    hasBinaryComponents: false,
> +    installDay: ADDON_INSTALL_DATE,
> +    updateDay: ADDON_INSTALL_DATE,
> +    signedState: mozinfo.addon_signing ? AddonManager.SIGNEDSTATE_MISSING : AddonManager.SIGNEDSTATE_NOT_REQUIRED,

Nit: Line-break after ":".

@@ +1077,5 @@
> +
> +  let registerCheckpointPromise = (aExpected) => {
> +    gNow = futureDate(gNow, 10 * MILLISECONDS_PER_MINUTE);
> +    fakeNow(gNow);
> +    return new Promise(resolve => TelemetryEnvironment.registerChangeListener(

I think we really should consolidate all those manual approaches into one helper like `promiseEnvironmentChange()` later.
Or a class that gives you per-test-instances that allow waiting on changes and do the counting etc. for you.

@@ +1093,5 @@
> +
> +  // Make sure the valid addon is not already installed.
> +  let checkpointPromise = null;
> +  let addonInstalled = yield AddonTestUtils.getAddonById(ADDON_ID);
> +  if (addonInstalled) {

This seems complicated, we control the tests here.
Two cleaner options here:
(1) Figure out which previous test install it & make that clean up after itself
(2) If its already installed just leave it as-is

(1) seems preferrable.

@@ +1139,5 @@
> +  Assert.ok(ADDON_ID in activeAddons,
> +            "The valid addon must be reported.");
> +
> +  // We can't simply call checkEnvironmentData, as the addons data reported by
> +  // the broken addon is invalid and will not pass the test.

This doesn't seem great and is too easy to become outdated.
How about passing a flag or an options object to allow broken addon info?

Comment 12

[Alessio Placitelli [:Dexter]]

(In reply to Georg Fritzsche [:gfritzsche] from comment #8)
> @@ +541,5 @@
> > +        if (addon.signedState !== undefined)
> > +          activeAddons[addon.id].signedState = addon.signedState;
> > +
> > +      } catch (ex) {
> > +        this._environment._log.error("_getActiveAddons - An addon was discarded due to an error", ex);
> 
> Let's file a follow-up on error Telemetry here.

Filed bug 1239321.

Comment 13

[Alessio Placitelli [:Dexter]]

Attachment: part 2 - Add xpcshell test coverage

Comment 14

[Alessio Placitelli [:Dexter]]

(In reply to Georg Fritzsche [:gfritzsche] from comment #11)
> @@ +1077,5 @@
> > +
> > +  let registerCheckpointPromise = (aExpected) => {
> > +    gNow = futureDate(gNow, 10 * MILLISECONDS_PER_MINUTE);
> > +    fakeNow(gNow);
> > +    return new Promise(resolve => TelemetryEnvironment.registerChangeListener(
> 
> I think we really should consolidate all those manual approaches into one
> helper like `promiseEnvironmentChange()` later.
> Or a class that gives you per-test-instances that allow waiting on changes
> and do the counting etc. for you.

Filed bug 1239333.

Comment 15

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8707473 [details] [diff] [review]
part 2 - Add xpcshell test coverage

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

r=me with the below fixed.

::: toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js
@@ +572,5 @@
>    }
>  
>    // Check the active addons, if available.
> +  if (!expectBrokenAddons) {
> +    let activeAddons = data.addons.activeAddons;

We should just allow for null addon entries here instead of skipping all the checks.

@@ +1133,5 @@
> +            "The addon with the broken manifest must be reported.");
> +  Assert.equal(activeAddons[BROKEN_ADDON_ID].version, null,
> +               "null should be reported for invalid data.");
> +  Assert.ok(ADDON_ID in activeAddons,
> +            "The valid addon must be reported.");

This should not be null - at least check for one field like .description to assert that.

Comment 16

[Alessio Placitelli [:Dexter]]

Attachment: part 2 - Add xpcshell test coverage

Comment 17

[Alessio Placitelli [:Dexter]]

(In reply to Georg Fritzsche [:gfritzsche] from comment #15)
> ::: toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js
> @@ +572,5 @@
> >    }
> >  
> >    // Check the active addons, if available.
> > +  if (!expectBrokenAddons) {
> > +    let activeAddons = data.addons.activeAddons;
> 
> We should just allow for null addon entries here instead of skipping all the
> checks.

As discussed over IRC, the Social provider is not sending all the fields (e.g. signedState, hasBinaryComponents) so, instead of adding some special cases just for this test, let's keep things as they are.

Comment 18

[Alessio Placitelli [:Dexter]]

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

Comment 19

[Alessio Placitelli [:Dexter]]

https://hg.mozilla.org/integration/fx-team/rev/b875f45e9496a55bb364d6c0995fff8c782b3a25
Bug 1238142 - Harden Telemetry addon data collection. r=gfritzsche

https://hg.mozilla.org/integration/fx-team/rev/2d563b06b9076841084ae2ae9e0a61dfe411cdd9
Bug 1238142 - Add test coverage. r=gfritzsche

Comment 20

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/b875f45e9496
https://hg.mozilla.org/mozilla-central/rev/2d563b06b907

Comment 21

[Alessio Placitelli [:Dexter]]

Comment on attachment 8707427 [details] [diff] [review]
part 1 - Harden addon data collection in TelemetryEnvironment

Approval Request Comment
[Feature/regressing bug #]: 1211404
[User impact if declined]: None. Using the SocialAPI would compromise our ability to gather environment data through Telemetry, thus resulting in partial pings.
[Describe test coverage new/current, TreeHerder]: The Telemetry XPCSHELL test suit covers this. A new test was added to cover the specific interaction between the SocialAPI, broken addons and Telemetry.
[Risks and why]: Low risk. This patch wraps the collection of addon data, which is constrained to Telemetry, in a try catch block and logs any error.
[String/UUID change made/needed]: None.

Comment 22

[Alessio Placitelli [:Dexter]]

Comment on attachment 8707427 [details] [diff] [review]
part 1 - Harden addon data collection in TelemetryEnvironment

We know you need to stabilize, but if there is any chance for a trivial low-risk patch...

Comment 23

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

Comment on attachment 8707427 [details] [diff] [review]
part 1 - Harden addon data collection in TelemetryEnvironment

Firefox 44 release enters RC mode this week and the update bar continues to be high. We are only taking fixes for critical (recent) regressions, top crashes and sec-crit fixes. Given that criteria, this issue does not meet the bar for Beta44.

Comment 24

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

Comment on attachment 8707495 [details] [diff] [review]
part 2 - Add xpcshell test coverage

Does not meet Beta44 RC uplift bar, please see my last comment for more details.

Comment 26

[Alessio Placitelli [:Dexter]]

Alexandra, would you kindly check it's correctly fixed?

STR:

1 - Start Firefox, click on the "Burger" menu (right-most icon) and choose "Customize"
2 - Drag and drop "Share Page" somewhere so that you can use it
3 - Open a web page and use the "Share Page" content to share it using Facebook (You don't really need to share it, you just need it to install the Facebook provider)
4 - Restart Firefox.

Behaviour on the unfixed version: the error from comment 0 is displayed and about:telemetry displays a partial environment (does not show the Facebook provider in the active addons).

Behaviour on the fixed version: no error shown and the correct addons displayed in about:telemetry

Comment 27

[Ada [:adalucinet]]

Reproduced with Aurora 45.0a2 from 2016-01-16 under Windows 7 64-bit - the error is displayed in Browser console and the provider is not present in about:telemetry → Environment Data → activeAddons
Verified fixed with latest Nightly 46.0a1 (from 2016-01-18), across platforms [1] - the error is no longer displayed and all of the 6 providers are displayed in the designated area.

Although, noticed an error via Browser console: 
> TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_PAGE_LOAD_MS", key: "null" thrown by TelemetryStopwatch.jsm:297:0
which started to show up since bug 1205898 landed. Is this something we should worry about? 

[1] Windows 7 64-bit, Mac OS X 10.10.5 and Ubuntu 14.04 32-bit

Comment 28

[Alessio Placitelli [:Dexter]]

(In reply to Alexandra Lucinet, QA Mentor [:adalucinet] from comment #27)
> Although, noticed an error via Browser console: 
> > TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_PAGE_LOAD_MS", key: "null" thrown by TelemetryStopwatch.jsm:297:0
> which started to show up since bug 1205898 landed. Is this something we
> should worry about? 
> 
> [1] Windows 7 64-bit, Mac OS X 10.10.5 and Ubuntu 14.04 32-bit

Thank you for verifying!

No, we don't need to worry about that: bug 1205898 simply made the error show, the problem was already lurking in the code. Bug 1233004 was filed to investigate the issue.

Comment 29

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/ea4ce436a50c
https://hg.mozilla.org/releases/mozilla-aurora/rev/3ef0b9ecf2ee