Closed Bug 1613994 Opened 6 years ago Closed 6 years ago

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

Categories

(Firefox :: Security, defect, P5)

Product:
Firefox
Component:
Security
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 75
Tracking Flags:
Tracking Status
firefox73 --- fixed
firefox74 --- fixed
firefox75 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

Bug 1613994 - Wait for state telemetry event after resetting enabled pref to ensure add-on has a chance to react. r=dragana!
47 bytes, text/x-phabricator-request
Details | Review

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

status-firefox73: --- → affected
status-firefox74: --- → affected
Flags: needinfo?(nhnt11)
Regressed by: 1613659
Has Regression Range: --- → yes
Keywords: regression

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

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

Status: ASSIGNED → RESOLVED
Closed: 6 years ago
status-firefox75: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 75
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: