Closed Bug 1238142 Opened 4 years ago Closed 4 years ago

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

Categories

(Toolkit :: Telemetry, defect, P1)

defect
Points:
2

Tracking

()

VERIFIED FIXED
mozilla46
Tracking Status
firefox43 --- wontfix
firefox44 --- wontfix
firefox45 --- fixed
firefox46 --- verified

People

(Reporter: jaws, Assigned: Dexter)

References

Details

(Whiteboard: [measurement:client])

Attachments

(2 files, 3 obsolete files)

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:
> limitStringToLength@TelemetryEnvironment.jsm:267:10 <
> EnvironmentAddonBuilder.prototype._getActiveAddons<@TelemetryEnvironment.jsm:525:18 <
> TaskImpl_run@Task.jsm:315:40 <
> promise callback*TaskImpl_handleResultValue@Task.jsm:391:7 <
> TaskImpl_run@Task.jsm:323:13 <
> TaskImpl@Task.jsm:276:3 <
> createAsyncFunction/asyncFunction@Task.jsm:250:14 <
> EnvironmentAddonBuilder.prototype._updateAddons<@TelemetryEnvironment.jsm:479:27 <
> TaskImpl_run@Task.jsm:315:40 <
> TaskImpl@Task.jsm:276:3 <
> createAsyncFunction/asyncFunction@Task.jsm:250:14 <
> EnvironmentAddonBuilder.prototype._checkForChanges@TelemetryEnvironment.jsm:437:25 <
> EnvironmentAddonBuilder.prototype.observe@TelemetryEnvironment.jsm:428:5 <
> Experiments.Experiments.prototype._evaluateExperiments@Experiments.jsm:1296:7 <
> TaskImpl_run@Task.jsm:315:40 <
> Handler.prototype.process@Promise-backend.js:933:23 <
> this.PromiseWalker.walkerLoop@Promise-backend.js:812:7 <
> Promise*this.PromiseWalker.scheduleWalkerLoop@Promise-backend.js:743:11 <
> this.PromiseWalker.schedulePromise@Promise-backend.js:775:7 <
> this.PromiseWalker.completePromise@Promise-backend.js:710:7 <
> this.BasePromiseWorker.prototype._worker/worker.onmessage@PromiseWorker.jsm:231:9 <
> EventHandlerNonNull*this.BasePromiseWorker.prototype._worker@PromiseWorker.jsm:217:5 <
> postMessage@PromiseWorker.jsm:292:9 <
> TaskImpl_run@Task.jsm:315:40 <
> Handler.prototype.process@Promise-backend.js:933:23 <
> this.PromiseWalker.walkerLoop@Promise-backend.js:812:7 <
> Promise*this.PromiseWalker.scheduleWalkerLoop@Promise-backend.js:743:11 <
> this.PromiseWalker.schedulePromise@Promise-backend.js:775:7 <
> this.PromiseWalker.completePromise@Promise-backend.js:710:7 <
> onSuccess@osfile_native.jsm:63:7

These are the extensions I have installed,
DOM Inspector	2.0.16	true	inspector@mozilla.org
Firefox Hello	0.1	true	loop@mozilla.org
Pocket	46.0a1	true	firefox@getpocket.com
Pocket	3.0.6.1-signed	false	isreaditlater@ideashower.com
Flags: needinfo?(alessio.placitelli)
Priority: -- → P2
Whiteboard: [measurement:client]
Flags: needinfo?(alessio.placitelli)
Priority: P2 → P1
Assignee: nobody → alessio.placitelli
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.
Flags: needinfo?(jaws)
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.
Flags: needinfo?(jaws)
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?
Flags: needinfo?(mixedpuppy)
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.
Flags: needinfo?(mixedpuppy)
(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
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.
Points: --- → 2
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
Attachment #8706991 - Flags: review?(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.
Attachment #8706991 - Flags: review?(gfritzsche) → review+
Status: NEW → ASSIGNED
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
Attachment #8707428 - Flags: review?(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?
Attachment #8707428 - Flags: review?(gfritzsche)
(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.
Attachment #8707428 - Attachment is obsolete: true
Attachment #8707473 - Flags: review?(gfritzsche)
(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 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.
Attachment #8707473 - Flags: review?(gfritzsche) → review+
Attachment #8707473 - Attachment is obsolete: true
Attachment #8707495 - Flags: review+
(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.
Flags: qe-verify+
https://hg.mozilla.org/mozilla-central/rev/b875f45e9496
https://hg.mozilla.org/mozilla-central/rev/2d563b06b907
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla46
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.
Attachment #8707427 - Flags: approval-mozilla-aurora?
Attachment #8707495 - Flags: approval-mozilla-aurora?
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...
Attachment #8707427 - Flags: approval-mozilla-beta?
Attachment #8707495 - Flags: approval-mozilla-beta?
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.
Attachment #8707427 - Flags: approval-mozilla-beta? → approval-mozilla-beta-
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.
Attachment #8707495 - Flags: approval-mozilla-beta? → approval-mozilla-beta-
Duplicate of this bug: 1234169
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
Flags: needinfo?(alexandra.lucinet)
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
Status: RESOLVED → VERIFIED
Flags: qe-verify+
Flags: needinfo?(alexandra.lucinet)
Flags: needinfo?(alessio.placitelli)
(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.
Flags: needinfo?(alessio.placitelli)
Depends on: 1240868
Attachment #8707427 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Attachment #8707495 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Duplicate of this bug: 1235463
You need to log in before you can comment on or make changes to this bug.