1021002 - Nightly test experiment logging doesn't show failures due to incompatible extensions: because the jsfilter isn't working!

Status: VERIFIED FIXED

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

Description

[Benjamin Smedberg]

Looking through the dashboard for the nightly deployment of the tile-switcher experiment, I expected to see activations that were rejected because the user had tree-style-tabs or classic-theme-restorer, but I don't see any indication of that.

Visit http://bsmedberg.github.io/telemetry-experiments-dashboard/ and add "first date: 2014-04-25" and nightly release channel

Failed Activations

Reason	#
REJECTED,endTime	3882459
REJECTED,sample	3224130
INSTALL_FAILURE	12069
REJECTED,failedStart	3559
REJECTED,startTime	1316
REJECTED,Error: Service failed to initialize.	250
REJECTED,Error: Error(s) encountered during statement execution.	101
REJECTED,maxActiveSeconds	47
REJECTED,TypeError: this._providerManager is null	34
REJECTED,Error: Not initialized.	11
REJECTED,channel	11
REJECTED,TypeError: reporter is null	10
REJECTED,TypeError: this.log is not a function	1
REJECTED,TypeError: this._storage is null	1

I would expect to see some entries like

REJECTED,jsfilter-false
REJECTED,jsfilter-threw,Error: Tree-style tabs present

Kamil, do you have time to try this and see what actually shows up in the telemetry log?

STR:
* Clone and adjust the experiment manifest to get rid of the sample and change the dates to the present
* Run the browser and force check for experiment updates. In the browser console:

Cu.import("resource:///modules/experiments/Experiments.jsm");
Experiments.instance().updateManifest();

* After the update is finished, get the telemetry log entries by running this in the browser console:

Cu.import("resource://gre/modules/TelemetryLog.jsm");
TelemetryLog.entries();

Comment 1

[Kamil Jozwiak [:kjozwiak]]

- Installed the "tree-style-tabs" add-on (same results using the classic-theme-restorer add-on)
- Followed the instructions from comment #0 (removing the sample rate, etc..)
- Once the experiment was installed, typed in "TelemetryLog.entries().toSource();" into the Browser Console. Received the following log entries:

- ["EXPERIMENT_ACTIVATION", 52487, "ACTIVATED", "[e-mail]"]
- ["EXPERIMENT_TERMINATION", 389463, "ADDON_UNINSTALLED", "[e-mail]"]
- ["EXPERIMENT_ACTIVATION", 400009, "ACTIVATED", "[e-mail] #2"]
- ["EXPERIMENT_TERMINATION", 692040, "ADDON_UNINSTALLED", "[e-mail] #2"]
- ["EXPERIMENT_ACTIVATION", 731416, "ACTIVATED", "[e-mail] #3"]

I never received an error message indicating that "tree-style-tabs" or "classic-theme-restorer" have been installed. I tried it a few times with the same results. (Installing/Removing/Installing)

Benjamin, let me know if these are the correct log entries that you were looking for!

Comment 2

[Benjamin Smedberg]

Crap, that means that the jsfilter isn't working for some reason. Thanks Kamil, this is an important bug. This will also affect 31, but it may not matter because we don't have any planned experiments for 31.

Comment 3

[Kamil Jozwiak [:kjozwiak]]

I'll keep my eye on this bug and test it as soon as it's fixed. I'll also add this case into "Important things to check" under the wiki and will personally start testing this case every time I go through experiments testing!

Comment 4

[Georg Fritzsche [:gfritzsche]]

Attachment: Fix FHR JSON payload handling

healthreporter.collectAndObtainJSONPayload() returns a stringified payload, which meant we were double-stringifying that payload.

Of course this didn't show up in the tests because we mocked it to return an object payload instead...

I threw in two minor bonus fixups (unused code + task return handling).

Comment 5

[Georg Fritzsche [:gfritzsche]]

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

Comment 6

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

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

Comment 7

[[SV Manager] Florin Mezei, QA (:FlorinMezei)]

Assigning this to Kamil based on comment 3.

Comment 8

[Kamil Jozwiak [:kjozwiak]]

Used the following build for verification:
- http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014-06-17-03-02-03-mozilla-central/

Logs received using "experiments.logging.level;0" once "Experiments.instance().updateManifest();" is run:

* 1403015002143	Browser.Experiments.Experiments	TRACE	Experiments #0::evaluateExperiments() - added EXPERIMENT_ACTIVATION to TelemetryLog: ["REJECTED","[e-mail]","jsfilter-threw","Tree-style tabs present"]
* 1403015279358	Browser.Experiments.Experiments	TRACE	Experiments #0::evaluateExperiments() - added EXPERIMENT_ACTIVATION to TelemetryLog: ["REJECTED","[e-mail]","jsfilter-threw","Tree-style tabs present"]
* 1403016034200	Browser.Experiments.Experiments	TRACE	Experiments #0::evaluateExperiments() - added EXPERIMENT_ACTIVATION to TelemetryLog: ["REJECTED","[e-mail]","jsfilter-false"]

Logs received using "TelemetryLog.entries().toSource();"

* ["EXPERIMENT_ACTIVATION", 67515, "REJECTED", "[e-mail]", "jsfilter-threw", "Tree-style tabs present"]
* ["EXPERIMENT_ACTIVATION", 344734, "REJECTED", "[e-mail]", "jsfilter-threw", "Tree-style tabs present"]
* ["EXPERIMENT_ACTIVATION", 74578, "REJECTED", "[e-mail]", "jsfilter-false"]
* ["EXPERIMENT_ACTIVATION", 251437, "REJECTED", "[e-mail]", "jsfilter-false"]]"

I also ensured that once "tree-style-tabs" or "classic-theme-restorer" are removed, the current experiment is installed and logged correctly.

The one thing that I noticed is that the logs don't indicate why the experiment was terminated while using "classic-theme-restorer". Not sure if this is an issue but it would be useful to have that information logged the same way it's being done for "tree-style-tabs".

Benjamin, should we fix the above to indicate that it was terminated because of "classic-theme-restorer present"??

Comment 9

[Benjamin Smedberg]

That was an intentional choice when implementing this first filter function so that we could test both the "throw" and "return false" codepaths. This is working as expected. Future experiements will probably just use the throw codepath for the extra logging detail.

Comment 10

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8439479 [details] [diff] [review]
Fix FHR JSON payload handling

[Approval Request Comment]
Bug caused by (feature/regressing bug #): Telemetry experiments.
User impact if declined: jsfilters broken for telemetry experiments.
Testing completed (on m-c, etc.): Verified on Nightly.
Risk to taking this patch (and alternatives if risky): Low-risk - well-understood once the underlying issue was located. 
String or IDL/UUID changes made by this patch: None.

Comment 11

[Sylvestre Ledru [:Sylvestre]]

Not tracking since it won't be a problem with 31.

Comment 12

[Georg Fritzsche [:gfritzsche]]

Any update on the approval here?

Comment 13

[Lawrence Mandel [:lmandel] (use needinfo)]

Comment on attachment 8439479 [details] [diff] [review]
Fix FHR JSON payload handling

Aurora approval granted.

Comment 14

[Georg Fritzsche [:gfritzsche]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/e8300a04ed60

Comment 15

[Kamil Jozwiak [:kjozwiak]]

Went through verification for fx32 using the following build:
- http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014-06-25-00-40-01-mozilla-aurora/

I went through the same test cases outlined in comment # 8 without any issues. Ensured when either "tree-style-tabs" or "classic-theme-restorer" are installed, the experiment is NOT installed and is correctly logged. Extracted the logs using (from comment #0):

Cu.import("resource://gre/modules/TelemetryLog.jsm");
TelemetryLog.entries().toSource();

The correct errors also appeared in the browser console when installing the experiment. I also ensured that the following is being logged:

- ["EXPERIMENT_TERMINATION", 31011, "EXPIRED", "[e-mail] #3"]
- ["EXPERIMENT_ACTIVATION to TelemetryLog: ["REJECTED","[e-mail] #4","jsfilter-threw","Tree-style tabs present"]
- ["EXPERIMENT_ACTIVATION", 31640, "REJECTED", "[e-mail] #6", "jsfilter-false"] (classic-theme-restorer)
- ["EXPERIMENT_ACTIVATION", 107781, "ACTIVATED", "[e-mail] #5"]]"
- ["EXPERIMENT_TERMINATION", 5922, "ADDON_UNINSTALLED", "[e-mail] #4"]