1348097 - Intermittent browser/components/search/test/browser_yahoo_behavior.js | A promise chain failed to handle a rejection: - at resource://app/modules/experiments/Experiments.jsm:840 - Error: experiments are disabled

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect)

Description

[Treeherder Bug Filer]

Filed by: wkocher [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=84391731&repo=autoland

https://queue.taskcluster.net/v1/task/IOq83LNIQEW6mv9MCb4gEQ/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[Intermittent Failures Robot]

5 failures in 898 pushes (0.006 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* try: 4
* mozilla-inbound: 1

Platform breakdown:
* linux64: 4
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1348097&startday=2017-03-20&endday=2017-03-26&tree=all

Comment 2

[Mark Banner (:standard8)]

Although this is reporting a test failure against browser/components/search/test/browser_yahoo_behavior.js, I think this is actually an issue in the Experiments code:

20:34:12     INFO - TEST-UNEXPECTED-FAIL | browser/components/search/test/browser_yahoo_behavior.js | A promise chain failed to handle a rejection:  - at resource://app/modules/experiments/Experiments.jsm:840 - Error: experiments are disabled
20:34:12     INFO - Stack trace:
20:34:12     INFO - updateManifest@resource://app/modules/experiments/Experiments.jsm:840:29
20:34:12     INFO - notify@resource://app/components/ExperimentsService.js:66:7
20:34:12     INFO - TM_notify/<@resource://gre/components/nsUpdateTimerManager.js:218:11
20:34:12     INFO - TM_notify@resource://gre/components/nsUpdateTimerManager.js:263:7
20:34:12     INFO - GECKO(2802) | Completed ShutdownLeaks collections in process 2802

AFAICT we're not touching anything relating to enabling/disabling experiments in browser_yahoo_behavior.js. This implies another test has triggered the timer in ExperimentsService.js, but it hasn't been disabled properly.

There's several things that I think are wrong here:

1) `ExperimentsService:notify` calls `instance.updateManifest()`. However, the function is returning a promise. So this should possibly have a catch on it, or some other handling if required.

2) `gExperimentsEnabled` in ExperimentsService.js is defined as (some constants replaced for clarity):

```
    const IS_UNIFIED_TELEMETRY = Preferences.get("toolkit.telemetry.unified", false);
    return gPrefs.get("experiments.enabled", false) &&
           IS_UNIFIED_TELEMETRY && gPrefs.get(PREF_TELEMETRY_ENABLED, false);
```

In Experiments.jsm it is:

```
    gExperimentsEnabled = gPrefs.get("experiments.enabled", false) && TelemetryUtils.isTelemetryEnabled;
```

So `gExperimentsEnabled` is based on two different values.

3) Experiments.jsm watches the telemetry preference status, but ExperimentsService.jsm doesn't. This will mean that the Experiments.jsm version will get an update, whereas the ExperimentsService.jsm might not (it depends on exactly how the lazy getter works).

My theory then, is that the timer within ExperimentsService.js has been triggered, and when it activates it calls `instance.updateManifest()` in Experiments.jsm, but that one has been updated to think that the experiments service is not enabled, and hence the promise blows up.

Comment 3

[Joel Maher ( :jmaher ) (UTC -8)]

in working on migrating the tests to run on Ubuntu 16.04 (instead of 12.04) we hit this root cause failure often:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=c4fb0bf102f76c3458b477cabc63a8820960e4f4&filter-searchStr=linux%20bc5%20e10s%20debug

is there a recommended fix for this or some general direction of what we should be doing to fix this?

Comment 4

[Mark Banner (:standard8)]

(In reply to Joel Maher ( :jmaher) from comment #3)
> in working on migrating the tests to run on Ubuntu 16.04 (instead of 12.04)
> we hit this root cause failure often:
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=c4fb0bf102f76c3458b477cabc63a8820960e4f4&filter-
> searchStr=linux%20bc5%20e10s%20debug

That's interesting, especially as it fails with the same errors but in different tests.

> is there a recommended fix for this or some general direction of what we
> should be doing to fix this?

I've taken a bit more of a look. The more I get into this, the more I think that there is something to do with timing going on in Experiments/ExperimentsService.jsm. I'm not quite sure what yet though.

browser_oneOffContextMenu.js does stuff which triggers some Experiments activity, it then turns it off again later. On my opt setup, I'm not able to repeat this, but that's probably unsurprising, as this seems to be timing related.

There's a few timers about, and my suspicion is that one of them is somehow triggered at just the wrong time to upset the tests. My guess would be that the Ubuntu 16.04 builders are slightly slower and therefore triggering this more often.

With all the debug I've turned on and added, I've now pushed a try build. Hopefully that'll show up an explanation as to what is happening:

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

I'll take another look in the morning.

Comment 5

[Joel Maher ( :jmaher ) (UTC -8)]

I see a failure in bc3:
https://public-artifacts.taskcluster.net/SMemd-6KSXqza_Cl_7ZBvw/0/public/logs/live_backing.log

and I see:
[task 2017-04-18T22:57:06.022006Z] 22:57:06     INFO - GECKO(1531) | --DOMWINDOW == 13 (0xc9111400) [pid = 1531] [serial = 86] [outer = (nil)] [url = about:blank]
[task 2017-04-18T22:57:06.326319Z] 22:57:06     INFO - GECKO(1531) | 1492556226319	Browser.Experiments.Experiments	TRACE	Experiments #0::updateManifest()
[task 2017-04-18T22:57:12.295604Z] 22:57:12     INFO - GECKO(1531) | Completed ShutdownLeaks collections in process 1664
[task 2017-04-18T22:57:12.701353Z] 22:57:12     INFO - GECKO(1531) | Completed ShutdownLeaks collections in process 1618
[task 2017-04-18T22:57:13.385353Z] 22:57:13     INFO - GECKO(1531) | Completed ShutdownLeaks collections in process 1642
[task 2017-04-18T22:57:14.031587Z] 22:57:14     INFO - GECKO(1531) | Completed ShutdownLeaks collections in process 1584
[task 2017-04-18T22:57:17.421945Z] 22:57:17     INFO - GECKO(1531) | --DOMWINDOW == 12 (0xe842cc00) [pid = 1531] [serial = 76] [outer = (nil)] [url = chrome://mochitests/content/browser/browser/components/search/test/opensearch.html]
[task 2017-04-18T22:57:17.424246Z] 22:57:17     INFO - GECKO(1531) | --DOMWINDOW == 11 (0xc8d33400) [pid = 1531] [serial = 79] [outer = (nil)] [url = chrome://mochitests/content/browser/browser/components/search/test/opensearch.html]
[task 2017-04-18T22:57:17.426257Z] 22:57:17     INFO - GECKO(1531) | --DOMWINDOW == 10 (0xc928fc00) [pid = 1531] [serial = 82] [outer = (nil)] [url = chrome://mochitests/content/browser/browser/components/search/test/tooManyEnginesOffered.html]
[task 2017-04-18T22:57:22.309864Z] 22:57:22     INFO - Console message: [JavaScript Error: "notify CALLLED123" {file: "jar:file:///home/worker/workspace/build/application/firefox/browser/omni.ja!/components/ExperimentsService.js" line: 58}]
[task 2017-04-18T22:57:22.312343Z] 22:57:22     INFO - notify@jar:file:///home/worker/workspace/build/application/firefox/browser/omni.ja!/components/ExperimentsService.js:58:5
[task 2017-04-18T22:57:22.313753Z] 22:57:22     INFO - TM_notify/<@jar:file:///home/worker/workspace/build/application/firefox/omni.ja!/components/nsUpdateTimerManager.js:218:11
[task 2017-04-18T22:57:22.315424Z] 22:57:22     INFO - TM_notify@jar:file:///home/worker/workspace/build/application/firefox/omni.ja!/components/nsUpdateTimerManager.js:263:7
[task 2017-04-18T22:57:22.315643Z] 22:57:22     INFO - 
[task 2017-04-18T22:57:22.317015Z] 22:57:22     INFO - Console message: 1492556226319	Browser.Experiments.Experiments	TRACE	Experiments #0::updateManifest()
[task 2017-04-18T22:57:22.374244Z] 22:57:22     INFO - TEST-INFO | started process screentopng
[task 2017-04-18T22:57:22.456099Z] 22:57:22     INFO - Failed to start /home/worker/workspace/build/tests/bin/screentopng for screenshot: No such file or directory
[task 2017-04-18T22:57:22.461320Z] 22:57:22     INFO - TEST-UNEXPECTED-FAIL | browser/components/search/test/browser_yahoo_behavior.js | A promise chain failed to handle a rejection:  - at resource:///modules/experiments/Experiments.jsm:843 - Error: experiments are disabled
[task 2017-04-18T22:57:22.461635Z] 22:57:22     INFO - Stack trace:
[task 2017-04-18T22:57:22.464118Z] 22:57:22     INFO - updateManifest@resource:///modules/experiments/Experiments.jsm:843:29
[task 2017-04-18T22:57:22.465671Z] 22:57:22     INFO - notify@jar:file:///home/worker/workspace/build/application/firefox/browser/omni.ja!/components/ExperimentsService.js:67:7
[task 2017-04-18T22:57:22.467080Z] 22:57:22     INFO - TM_notify/<@jar:file:///home/worker/workspace/build/application/firefox/omni.ja!/components/nsUpdateTimerManager.js:218:11
[task 2017-04-18T22:57:22.468522Z] 22:57:22     INFO - TM_notify@jar:file:///home/worker/workspace/build/application/firefox/omni.ja!/components/nsUpdateTimerManager.js:263:7
[task 2017-04-18T22:57:31.839255Z] 22:57:31     INFO - GECKO(1531) | Completed ShutdownLeaks collections in process 1531
[task 2017-04-18T22:57:31.839664Z] 22:57:31     INFO - TEST-START | Shutdown


what looks interesting is:
[task 2017-04-18T22:57:06.326319Z] 22:57:06     INFO - GECKO(1531) | 1492556226319	Browser.Experiments.Experiments	TRACE	Experiments #0::updateManifest()
...
[task 2017-04-18T22:57:22.309864Z] 22:57:22     INFO - Console message: [JavaScript Error: "notify CALLLED123" {file: "jar:file:///home/worker/workspace/build/application/firefox/browser/omni.ja!/components/ExperimentsService.js" line: 58}]

I assume that is related to this call:
https://dxr.mozilla.org/mozilla-central/source/browser/experiments/ExperimentsService.js?q=path%3AExperimentsService.js&redirect_type=single#58

I am not really sure if that helps at all, but thought I would take a look.

Comment 6

[Mark Banner (:standard8)]

So, from the try builds, and today's investigations so far:

- ExperimentsService.notify() is being triggered because it is an update-timer defined in Experiments.manifest:

https://dxr.mozilla.org/mozilla-central/rev/722fdbff1efc308a22060e75b603311d23541bb5/browser/experiments/Experiments.manifest#3

The update-timers are triggered with one timer every 30 seconds, there are a few of them, so this could indeed be firing at any time (probably worse on slow builds, e.g. the debug ones).


Now comes the interesting bit:

- When the browser/components/search tests start, both ExperimentsService and Experiments see the various preferences as being true, i.e. they are enabled. In particular, "toolkit.telemetry.enabled" is true.

- browser_oneOffContextMenu.js changes "toolkit.telemetry.enabled" to false

=> Experiments picks this up, and changes its gExperimentsEnabled state to false. ExperimentsService stays as true, as it doesn't look for pref changes (see comment 2).

- browser_oneOffContextMenu.js then changes "toolkit.telemetry.enabled" to true

=> Experiments picks this up, but doesn't change its gExperimentsEnabled state - _telemetryStatusChanged calls _toggleExperimentsEnabled with the current value of gExperimentsEnabled (false), and then passes that enabled value to:

gExperimentsEnabled = enabled && TelemetryUtils.isTelemetryEnabled;

which is always going to return false...

- At some time later the update-timer kicks in, and triggers ExperimentsService.

=> ExperimentsService has its original recorded value of gExperimentsEnabled = true, so fires Experiments.updateManifest() which rejects a promise due to Experiments thinking that it is disabled, and bang: test fail.


I can reproduce this (5/5) on an opt build on my local mac by editing nsUpdateTimerManager.js and in TimerManager.observe forcing `this._timerMinimumDelay` and `firstInterval` to be `5000`.

These intervals are normally 30s, so I'd guess these tests are taking longer on the newer ubuntu machines.

Comment 7

[Mark Banner (:standard8)]

Attachment: Bug 1348097 - Fix intermittent failures caused by Experiments.jsm by ensuring the preference monitoring is in sync.

Change the ExperimentsService to get the current value of the preferences (since it only uses them once or twice), so that they match the values in Experiments, and avoid differences causing promises to be rejected in the updateManifest call.
Also fix Experiments to correctly re-enable itself when toolkit.telemetry.enabled is changed from false to true (also fixes bug 1232648).
Finally, add a catch for a promise when calling updateManifest so that we don't get an uncaught promise exception.

Review commit: https://reviewboard.mozilla.org/r/131538/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/131538/

Comment 8

[Mark Banner (:standard8)]

Comment on attachment 8859535 [details]
Bug 1348097 - Fix intermittent failures caused by Experiments.jsm by ensuring the preference monitoring is in sync.

I'm currently investigating the issues raised by try server.

Comment 9

[Mark Banner (:standard8)]

Comment on attachment 8859535 [details]
Bug 1348097 - Fix intermittent failures caused by Experiments.jsm by ensuring the preference monitoring is in sync.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/131538/diff/1-2/

Comment 10

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8859535 [details]
Bug 1348097 - Fix intermittent failures caused by Experiments.jsm by ensuring the preference monitoring is in sync.

https://reviewboard.mozilla.org/r/131538/#review134444

Thanks for figuring this out!

::: browser/experiments/Experiments.jsm:124
(Diff revision 2)
>  function configureLogging() {
>    if (!gLogger) {
>      gLogger = Log.repository.getLogger("Browser.Experiments");
>      gLogger.addAppender(new Log.ConsoleAppender(new Log.BasicFormatter()));
>    }
> -  gLogger.level = gPrefs.get(PREF_LOGGING_LEVEL, Log.Level.Warn);
> +  gLogger.level = gPrefs.get(PREF_LOGGING_LEVEL, Log.Level.Trace);

Left-over? Please undo this.

::: browser/experiments/ExperimentsService.js:53
(Diff revision 2)
>  
> +  get _experimentsEnabled() {
> +    // We can enable experiments if either unified Telemetry or FHR is on, and the user
> +    // has opted into Telemetry.
> +    return gPrefs.get(PREF_EXPERIMENTS_ENABLED, false) &&
> +           IS_UNIFIED_TELEMETRY && gPrefs.get(PREF_TELEMETRY_ENABLED, false);

Please use `TelemetryUtils.isTelemetryEnabled()`.
This handles an actual type issue we have seen before.

Comment 11

[Mark Banner (:standard8)]

Comment on attachment 8859535 [details]
Bug 1348097 - Fix intermittent failures caused by Experiments.jsm by ensuring the preference monitoring is in sync.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/131538/diff/2-3/

Comment 12

[Mark Banner (:standard8)]

Comment on attachment 8859535 [details]
Bug 1348097 - Fix intermittent failures caused by Experiments.jsm by ensuring the preference monitoring is in sync.

https://reviewboard.mozilla.org/r/131538/#review134444

> Please use `TelemetryUtils.isTelemetryEnabled()`.
> This handles an actual type issue we have seen before.

Thanks, I've changed it. I also dropped the IS_UNIFIED_TELEMETRY check so that it was consistent with Experiments.jsm

Comment 13

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8859535 [details]
Bug 1348097 - Fix intermittent failures caused by Experiments.jsm by ensuring the preference monitoring is in sync.

https://reviewboard.mozilla.org/r/131538/#review134950

Thanks for getting this fixed!

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e1c9c6e89f50
Fix intermittent failures caused by Experiments.jsm by ensuring the preference monitoring is in sync. r=gfritzsche

Comment 15

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

This caused failures like https://treeherder.mozilla.org/logviewer.html#?job_id=93077770&repo=autoland to start up on at least linux asan builds

Backed out in https://hg.mozilla.org/integration/autoland/rev/bc65b6aff361

Comment 16

[Mark Banner (:standard8)]

I knew I should have done the experiments.enabled setting for the whole of that test directory :-(

I'll get that fixed.

Comment 17

[Mark Banner (:standard8)]

Comment on attachment 8859535 [details]
Bug 1348097 - Fix intermittent failures caused by Experiments.jsm by ensuring the preference monitoring is in sync.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/131538/diff/3-4/

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b2c250009e4b
Fix intermittent failures caused by Experiments.jsm by ensuring the preference monitoring is in sync. r=gfritzsche

Comment 19

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

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