Closed Bug 1613994 Opened 2 months ago Closed 2 months ago

Intermittent browser/extensions/doh-rollout/test/browser/browser_rollback.js | TRR mode changed when it shouldn't have! -

Categories

(Firefox :: Security, defect, P5)

defect

Tracking

()

RESOLVED FIXED
Firefox 75
Tracking Status
firefox73 --- fixed
firefox74 --- fixed
firefox75 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: nhnt11)

References

(Regression)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Filed by: rmaries [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=287957193&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/fOrBDZDrQEeoF6Sj2S2bXg/runs/0/artifacts/public/logs/live_backing.log


[task 2020-02-07T18:07:09.268Z] 18:07:09 INFO - TEST-START | browser/extensions/doh-rollout/test/browser/browser_rollback.js
[task 2020-02-07T18:07:16.493Z] 18:07:16 INFO - TEST-INFO | started process screenshot
[task 2020-02-07T18:07:16.720Z] 18:07:16 INFO - TEST-INFO | screenshot: exit 0
[task 2020-02-07T18:07:16.721Z] 18:07:16 INFO - Buffered messages logged at 18:07:09
[task 2020-02-07T18:07:16.721Z] 18:07:16 INFO - Entering test bound setup
[task 2020-02-07T18:07:16.722Z] 18:07:16 INFO - Leaving test bound setup
[task 2020-02-07T18:07:16.722Z] 18:07:16 INFO - Entering test bound testRollback
[task 2020-02-07T18:07:16.723Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | Breadcrumb saved. -
[task 2020-02-07T18:07:16.723Z] 18:07:16 INFO - Buffered messages logged at 18:07:10
[task 2020-02-07T18:07:16.724Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | Doorhanger shown pref undefined before user interaction. -
[task 2020-02-07T18:07:16.724Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | TRR mode is 2 -
[task 2020-02-07T18:07:16.725Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | Found the expected heuristics event. -
[task 2020-02-07T18:07:16.725Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | The event records the expected decision -
[task 2020-02-07T18:07:16.725Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | Got the expected reason. -
[task 2020-02-07T18:07:16.726Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | Doorhanger shown pref saved. -
[task 2020-02-07T18:07:16.726Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | Doorhanger decision saved. -
[task 2020-02-07T18:07:16.727Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | Breadcrumb not cleared. -
[task 2020-02-07T18:07:16.727Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | TRR mode is 0 -
[task 2020-02-07T18:07:16.727Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | Found the expected heuristics event. -
[task 2020-02-07T18:07:16.727Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | The event records the expected decision -
[task 2020-02-07T18:07:16.728Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | Got the expected reason. -
[task 2020-02-07T18:07:16.728Z] 18:07:16 INFO - Buffered messages logged at 18:07:16
[task 2020-02-07T18:07:16.728Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | No change in TRR mode -
[task 2020-02-07T18:07:16.728Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | Found the expected heuristics event. -
[task 2020-02-07T18:07:16.728Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | The event records the expected decision -
[task 2020-02-07T18:07:16.728Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | Got the expected reason. -
[task 2020-02-07T18:07:16.728Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | TRR mode is 0 -
[task 2020-02-07T18:07:16.728Z] 18:07:16 INFO - TEST-PASS | browser/extensions/doh-rollout/test/browser/browser_rollback.js | Found no heuristics events. -
[task 2020-02-07T18:07:16.728Z] 18:07:16 INFO - Buffered messages finished
[task 2020-02-07T18:07:16.729Z] 18:07:16 INFO - TEST-UNEXPECTED-FAIL | browser/extensions/doh-rollout/test/browser/browser_rollback.js | TRR mode changed when it shouldn't have! -
[task 2020-02-07T18:07:16.729Z] 18:07:16 INFO - Stack trace:
[task 2020-02-07T18:07:16.729Z] 18:07:16 INFO - chrome://mochikit/content/browser-test.js:test_ok:1292
[task 2020-02-07T18:07:16.729Z] 18:07:16 INFO - chrome://mochitests/content/browser/browser/extensions/doh-rollout/test/browser/head.js:ensureNoTRRModeChange:190
[task 2020-02-07T18:07:16.729Z] 18:07:16 INFO - chrome://mochitests/content/browser/browser/extensions/doh-rollout/test/browser/browser_rollback.js:testRollback:73
[task 2020-02-07T18:07:16.729Z] 18:07:16 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1062
[task 2020-02-07T18:07:16.729Z] 18:07:16 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
[task 2020-02-07T18:07:16.729Z] 18:07:16 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:925
[task 2020-02-07T18:07:16.729Z] 18:07:16 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:808
[task 2020-02-07T18:07:16.729Z] 18:07:16 INFO - Not taking screenshot here: see the one that was previously logged

Flags: needinfo?(nhnt11)
Regressed by: 1613659

This issue is happening because:

  1. We are at TRR mode = 0
  2. We reset the enabled pref (and don't wait for the add-on to react to this)
  3. We check that the TRR mode is now 0, which it will be without delay, because of 1.
  4. We simulate a network change

Now, sometimes at this point, we've arrived at step 4 before the add-on has received event loop cycles to react to the reset in step 2.

I don't think there's a direct way to wait for the add-on to react to this at the moment. We need to either make the add-on persist some state that the test can read and use as a signal to continue, or introduce an arbitrary wait period, or maybe I'll think of something else when I've gotten some sleep. :)

For now: this is an issue with the test and should not block our release.

Flags: needinfo?(nhnt11)
Assignee: nobody → nhnt11
Status: NEW → ASSIGNED
Pushed by nhnt11@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/b8974dc7296f
Wait for state telemetry event after resetting enabled pref to ensure add-on has a chance to react. r=dragana
Duplicate of this bug: 1613866
Status: ASSIGNED → RESOLVED
Closed: 2 months ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 75
You need to log in before you can comment on or make changes to this bug.