Telemetry experiments: invalid timer scheduling when addon & experiment id don't match

RESOLVED FIXED in Firefox 31

Status

defect
RESOLVED FIXED
5 years ago
9 months ago

People

(Reporter: benjamin, Assigned: gfritzsche)

Tracking

unspecified
Firefox 31
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(2 attachments, 1 obsolete attachment)

I'm having an issue running manual QA on the experiment system. More details coming in a sec.
Steps to reproduce:

* set experiments.logging.level=0
* set experiments.manifest.cert.checkAttributes=false
* set experiments.uri="http://benjamin.smedbergs.us/telex-bug985670/manifest/Firefox/3"
* set experiments.enabled=true

Expected:
readable-closable-tabs was installed as an experiment

Actual:
The experiment was not installed, and I got this output in the browser console:

1395262386548	Browser.Experiments	TRACE	Experiments::httpGetRequest(http://benjamin.smedbergs.us/telex-bug985670/manifest/Firefox/30)

GET http://benjamin.smedbergs.us/telex-bug985670/manifest/Firefox/30 [HTTP/1.1 200 OK 132ms]
1395262387152	Browser.Experiments	TRACE	Experiments::updateManifest::updateTask() - responseText="{"experiments": [{"startTime": 0, "xpiHash": "sha256:e661508263fd1f949481cc79408a9806c0dade27225fcf5e6c211861fd5e7656", "maxActiveSeconds": 20160, "xpiURL": "http://benjamin.smedbergs.us/telex-bug985670/experiment.xpi", "endTime": 2234567890, "appName": ["Firefox"], "id": "closable-tabs", "channel": ["default"]}], "version": 1}"

1395262387154	Browser.Experiments	TRACE	Experiments::updateExperiments() - experiments: {"experiments":[{"startTime":0,"xpiHash":"sha256:e661508263fd1f949481cc79408a9806c0dade27225fcf5e6c211861fd5e7656","maxActiveSeconds":20160,"xpiURL":"http://benjamin.smedbergs.us/telex-bug985670/experiment.xpi","endTime":2234567890,"appName":["Firefox"],"id":"closable-tabs","channel":["default"]}],"version":1}

1395262387155	Browser.Experiments	TRACE	ExperimentEntry::isManifestDataValid() - data: {"startTime":0,"xpiHash":"sha256:e661508263fd1f949481cc79408a9806c0dade27225fcf5e6c211861fd5e7656","maxActiveSeconds":20160,"xpiURL":"http://benjamin.smedbergs.us/telex-bug985670/experiment.xpi","endTime":2234567890,"appName":["Firefox"],"id":"closable-tabs","channel":["default"]}

1395262387159	Browser.Experiments	TRACE	Experiments::evaluateExperiments()

1395262387163	Browser.Experiments	TRACE	ExperimentEntry::isApplicable() - now=1395262387.162, data={"startTime":0,"xpiHash":"sha256:e661508263fd1f949481cc79408a9806c0dade27225fcf5e6c211861fd5e7656","maxActiveSeconds":20160,"xpiURL":"http://benjamin.smedbergs.us/telex-bug985670/experiment.xpi","endTime":2234567890,"appName":["Firefox"],"id":"closable-tabs","channel":["default"]}

1395262387176	Browser.Experiments	DEBUG	Experiments::evaluateExperiments() - activating experiment closable-tabs

1395262387177	Browser.Experiments	TRACE	ExperimentEntry::start() for closable-tabs

GET http://benjamin.smedbergs.us/telex-bug985670/experiment.xpi [HTTP/1.1 200 OK 173ms]
1395262388183	Browser.Experiments	TRACE	ExperimentEntry::start() - onDownloadEnded for closable-tabs

1395262388185	Browser.Experiments	ERROR	ExperimentEntry::start() - id mismatch: 'closable-tabs' vs. 'readable-closable-tabs@benjamin.smedbergs.us'

1395262388188	Browser.Experiments	ERROR	ExperimentEntry::start() - AddonInstall onDownloadCancelled for closable-tabs, state=8, error=0

1395262388192	Browser.Experiments	TRACE	Experiments::scheduleExperimentEvaluation() - scheduling for 2777958522000000, now: 1395262388191

1395262389458	Browser.Experiments	DEBUG	Experiments::saveToCache::fileTask() saved to: /home/bsmedberg/test-profile/experiments.json


There's a couple things here that I didn't expect:

* it looks like the experiment ID is supposed to match the addon ID. This wasn't in the spec and I don't think it's documented anywhere. Is this really a necessary requirement? I'd like to avoid this requirement if possible.
* The message about rescheduling is surprising; it appears that we have a second/millisecond mismatch in there at least.
Assignee: nobody → georg.fritzsche
(In reply to Benjamin Smedberg  [:bsmedberg] from comment #1)
> * it looks like the experiment ID is supposed to match the addon ID. This
> wasn't in the spec and I don't think it's documented anywhere. Is this
> really a necessary requirement? I'd like to avoid this requirement if
> possible.

Happy to drop this, i probably "just assumed".

> * The message about rescheduling is surprising; it appears that we have a
> second/millisecond mismatch in there at least.

Investigating.
Along the way i noticed that in ExperimentEntry.start(), we are missing a check if an addon is already installed.

From running tests on this it looks like when trying to install an addon via getInstallForURL(), it just succeeds when the addon is already installed.
Can i differentiate this case (without knowing the addon id)?
Flags: needinfo?(bmcbride)
WIP with the above question unsolved.
So, let's not schedule timers for a default year 9000 when there are no pending experiments.
Attachment #8394226 - Flags: review?(felipc)
Moved the above, non-blocking issue to bug 986040, so this can be reviewed.
Attachment #8394163 - Attachment is obsolete: true
Attachment #8394296 - Flags: review?(felipc)
Flags: needinfo?(bmcbride)
Blocks: 986530
Summary: Telemetry experiments: error with mismatched IDs or something? → Telemetry experiments: invalid timer scheduling on when addon & experiment id don't match
Attachment #8394226 - Flags: review?(felipc) → review+
Attachment #8394296 - Flags: review?(felipc) → review+
https://hg.mozilla.org/integration/mozilla-inbound/rev/c5586b13d243
https://hg.mozilla.org/integration/mozilla-inbound/rev/cbc4e35edfc5
Status: NEW → ASSIGNED
OS: Linux → All
Hardware: x86_64 → All
Summary: Telemetry experiments: invalid timer scheduling on when addon & experiment id don't match → Telemetry experiments: invalid timer scheduling when addon & experiment id don't match
https://hg.mozilla.org/mozilla-central/rev/c5586b13d243
https://hg.mozilla.org/mozilla-central/rev/cbc4e35edfc5
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 31
Product: Firefox Health Report → Firefox Health Report Graveyard
You need to log in before you can comment on or make changes to this bug.