Closed Bug 1571932 Opened 6 years ago Closed 5 years ago

Intermittent browser/base/content/test/general/browser_datachoices_notification.js | No version should be set on init. - 37 == 0 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js :: tes

Categories

(Firefox :: Settings UI, defect, P1)

Product:
Firefox
Component:
Settings UI
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
86 Branch
Tracking Flags:
Tracking Status
firefox-esr78 --- wontfix
firefox84 --- wontfix
firefox85 --- wontfix
firefox86 --- fixed

People

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

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [test isolation][stockwell disabled])

Attachments

(4 files)

Bug 1571932 - Add some extra checks, earlier, to help diagnose an intermittent r?janerik!
47 bytes, text/x-phabricator-request
Details | Review
Bug 1571932 - Enable Trace Telemetry logging in datachoices test r?janerik!
47 bytes, text/x-phabricator-request
Details | Review
Bug 1571932 - Skip intermittently-failing test that we probably don't need r?TravisLong!
48 bytes, text/x-phabricator-request
Details | Review
Bug 1571932 - Skip intermittently-failing subtest that we probably don't need r?TravisLong!
48 bytes, text/x-phabricator-request
Details | Review

Filed by: rmaries [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=260244868&repo=mozilla-inbound
Full log: https://queue.taskcluster.net/v1/task/IKGaMVggQf6n5KQvAxUEFw/runs/0/artifacts/public/logs/live_backing.log

[task 2019-08-07T00:33:50.851Z] 00:33:50 INFO - TEST-START | browser/base/content/test/general/browser_ctrlTab.js
[task 2019-08-07T00:33:53.416Z] 00:33:53 INFO - GECKO(1862) | MEMORY STAT | vsize 3410MB | residentFast 608MB | heapAllocated 291MB
[task 2019-08-07T00:33:53.417Z] 00:33:53 INFO - TEST-OK | browser/base/content/test/general/browser_ctrlTab.js | took 2591ms
[task 2019-08-07T00:33:53.433Z] 00:33:53 INFO - checking window state
[task 2019-08-07T00:33:53.434Z] 00:33:53 INFO - GECKO(1862) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object
[task 2019-08-07T00:33:53.435Z] 00:33:53 INFO - TEST-START | browser/base/content/test/general/browser_datachoices_notification.js
[task 2019-08-07T00:33:54.370Z] 00:33:54 INFO - TEST-INFO | started process screentopng
[task 2019-08-07T00:33:54.763Z] 00:33:54 INFO - TEST-INFO | screentopng: exit 0
[task 2019-08-07T00:33:54.763Z] 00:33:54 INFO - Buffered messages logged at 00:33:53
[task 2019-08-07T00:33:54.764Z] 00:33:54 INFO - Entering test bound setup
[task 2019-08-07T00:33:54.764Z] 00:33:54 INFO - Leaving test bound setup
[task 2019-08-07T00:33:54.765Z] 00:33:54 INFO - Entering test bound test_single_window
[task 2019-08-07T00:33:54.766Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | No version should be set on init. - 0 == 0 -
[task 2019-08-07T00:33:54.766Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | No date should be set on init. - "0" == 0 -
[task 2019-08-07T00:33:54.767Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | User not notified about datareporting policy. - true == true -
[task 2019-08-07T00:33:54.767Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | User should not be allowed to upload. - true == true -
[task 2019-08-07T00:33:54.767Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | Must have a timer callback. - true == true -
[task 2019-08-07T00:33:54.768Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | Timeout should match - 10000 == 10000 -
[task 2019-08-07T00:33:54.769Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | Notification Displayed. - 1 == 1 -
[task 2019-08-07T00:33:54.769Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | User should be allowed to upload now. - true == true -
[task 2019-08-07T00:33:54.770Z] 00:33:54 INFO - Console message: [JavaScript Error: "uncaught exception: Object" {file: "resource://testing-common/PromiseTestUtils.jsm" line: 112}]
[task 2019-08-07T00:33:54.770Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | There is 1 button in the data reporting notification. - 1 == 1 -
[task 2019-08-07T00:33:54.770Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | No notifications remain. - 0 == 0 -
[task 2019-08-07T00:33:54.771Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | true == true -
[task 2019-08-07T00:33:54.771Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | User notified about datareporting policy. - true == true -
[task 2019-08-07T00:33:54.772Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | Version pref set. - 37 == 37 -
[task 2019-08-07T00:33:54.773Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | Date pref set. - 1565138033445 > -1 -
[task 2019-08-07T00:33:54.773Z] 00:33:54 INFO - Leaving test bound test_single_window
[task 2019-08-07T00:33:54.773Z] 00:33:54 INFO - Entering test bound test_multiple_windows
[task 2019-08-07T00:33:54.773Z] 00:33:54 INFO - Buffered messages logged at 00:33:54
[task 2019-08-07T00:33:54.774Z] 00:33:54 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | 2nd window has a global notification box. - {"_insertElementFn":"element => {\n element.classList.add("global-notificationbox");\n element.setAttribute("notificationside", "bottom");\n document.getElementById("browser-bottombox").appendChild(element);\n }","_animating":false,"currentNotification":null} == true -
[task 2019-08-07T00:33:54.774Z] 00:33:54 INFO - Buffered messages finished
[task 2019-08-07T00:33:54.774Z] 00:33:54 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_datachoices_notification.js | No version should be set on init. - 37 == 0 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js :: test_multiple_windows :: line 230
[task 2019-08-07T00:33:54.775Z] 00:33:54 INFO - Stack trace:
[task 2019-08-07T00:33:54.776Z] 00:33:54 INFO - chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js:test_multiple_windows:230
[task 2019-08-07T00:33:54.776Z] 00:33:54 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1346
[task 2019-08-07T00:33:54.777Z] 00:33:54 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1381
[task 2019-08-07T00:33:54.777Z] 00:33:54 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1209
[task 2019-08-07T00:33:54.777Z] 00:33:54 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
[task 2019-08-07T00:33:54.777Z] 00:33:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-08-07T00:33:54.778Z] 00:33:54 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_datachoices_notification.js | No date should be set on init. - "1565138033973" == 0 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js :: test_multiple_windows :: line 235
[task 2019-08-07T00:33:54.778Z] 00:33:54 INFO - Stack trace:
[task 2019-08-07T00:33:54.779Z] 00:33:54 INFO - chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js:test_multiple_windows:235
[task 2019-08-07T00:33:54.779Z] 00:33:54 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1346
[task 2019-08-07T00:33:54.780Z] 00:33:54 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1381
[task 2019-08-07T00:33:54.780Z] 00:33:54 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1209
[task 2019-08-07T00:33:54.781Z] 00:33:54 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
[task 2019-08-07T00:33:54.781Z] 00:33:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-08-07T00:33:54.782Z] 00:33:54 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_datachoices_notification.js | User not notified about datareporting policy. - false == true - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js :: test_multiple_windows :: line 240
[task 2019-08-07T00:33:54.782Z] 00:33:54 INFO - Stack trace:
[task 2019-08-07T00:33:54.782Z] 00:33:54 INFO - chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js:test_multiple_windows:240
[task 2019-08-07T00:33:54.782Z] 00:33:54 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1346
[task 2019-08-07T00:33:54.782Z] 00:33:54 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1381
[task 2019-08-07T00:33:54.782Z] 00:33:54 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1209
[task 2019-08-07T00:33:54.783Z] 00:33:54 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
[task 2019-08-07T00:33:54.783Z] 00:33:54 INFO - Not taking screenshot here: see the one that was previously logged

Whiteboard: [test isolation]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE

This is still happening.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=311202585&repo=mozilla-esr68&lineNumber=2248

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
Resolution: --- → INCOMPLETE

This started to get frequent last Friday. Please investigate.

Severity: normal → --
Flags: needinfo?(jaws)
Priority: P5 → --

Chris, is this something you can look into?

Flags: needinfo?(jaws) → needinfo?(chutten)

Eep. Well, that's an odd failure. It initially looks like it's not resetting state properly between runs, but the timestamp changed making me think this is actually picking up a change in how things work.

I can try poking my nose around at this, but this isn't code I'm the most familiar with. Fingers crossed, I guess.

Assignee: nobody → chutten
Severity: -- → S4
Status: REOPENED → ASSIGNED
Flags: needinfo?(chutten)
Priority: -- → P1

I suspect maybe that something's happening while closing all notifications, but
I can't reproduce the intermittent locally so I'll have to land this test
change to see what information we can glean.

Marking leave-open so we can keep tracking intermittents here while the added checks hopefully provide some insight.

Keywords: leave-open
Pushed by chutten@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/3948bc1b5d98 Add some extra checks, earlier, to help diagnose an intermittent r=janerik

Hi Chris, are you still working on this?

There are 32 total failures in the last 7 days on

  • opt: linux1804-64, windows10-64, windows10-64-qr, windows10-64-shippable

recent failure log: https://treeherder.mozilla.org/logviewer?job_id=324007482&repo=autoland&lineNumber=2746

[task 2020-12-09T04:56:13.085Z] 04:56:13 INFO - TEST-START | browser/base/content/test/general/browser_datachoices_notification.js
[task 2020-12-09T04:56:14.187Z] 04:56:14 INFO - TEST-INFO | started process screenshot
[task 2020-12-09T04:56:14.286Z] 04:56:14 INFO - TEST-INFO | screenshot: exit 0
[task 2020-12-09T04:56:14.286Z] 04:56:14 INFO - Buffered messages logged at 04:56:13
[task 2020-12-09T04:56:14.286Z] 04:56:14 INFO - Entering test bound setup
[task 2020-12-09T04:56:14.287Z] 04:56:14 INFO - Leaving test bound setup
[task 2020-12-09T04:56:14.287Z] 04:56:14 INFO - Entering test bound test_single_window
[task 2020-12-09T04:56:14.287Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | No version should be set on init. - 0 == 0 -
[task 2020-12-09T04:56:14.287Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | No date should be set on init. - "0" == 0 -
[task 2020-12-09T04:56:14.287Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | User not notified about datareporting policy. - true == true -
[task 2020-12-09T04:56:14.287Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | User should not be allowed to upload. - true == true -
[task 2020-12-09T04:56:14.287Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | Must have a timer callback. - true == true -
[task 2020-12-09T04:56:14.287Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | Timeout should match - 10000 == 10000 -
[task 2020-12-09T04:56:14.288Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | Notification Displayed. - 1 == 1 -
[task 2020-12-09T04:56:14.288Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | User should be allowed to upload now. - true == true -
[task 2020-12-09T04:56:14.288Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | There is 1 button in the data reporting notification. - 1 == 1 -
[task 2020-12-09T04:56:14.288Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | No notifications remain. - 0 == 0 -
[task 2020-12-09T04:56:14.288Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | true == true -
[task 2020-12-09T04:56:14.288Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | User notified about datareporting policy. - true == true -
[task 2020-12-09T04:56:14.288Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | Version pref set. - 37 == 37 -
[task 2020-12-09T04:56:14.288Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | Date pref set. - 1607489773090 > -1 -
[task 2020-12-09T04:56:14.289Z] 04:56:14 INFO - Leaving test bound test_single_window
[task 2020-12-09T04:56:14.289Z] 04:56:14 INFO - Entering test bound test_multiple_windows
[task 2020-12-09T04:56:14.289Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | No version should be set on init. - 0 == 0 -
[task 2020-12-09T04:56:14.289Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | No date should be set on init. - "0" == 0 -
[task 2020-12-09T04:56:14.289Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | User not notified about datareporting policy. - true == true -
[task 2020-12-09T04:56:14.289Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | No version should be set on init. - 0 == 0 -
[task 2020-12-09T04:56:14.289Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | No date should be set on init. - "0" == 0 -
[task 2020-12-09T04:56:14.289Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | User not notified about datareporting policy. - true == true -
[task 2020-12-09T04:56:14.289Z] 04:56:14 INFO - Buffered messages logged at 04:56:14
[task 2020-12-09T04:56:14.290Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | 2nd window has a global notification box. - {"_insertElementFn":"element => {\n element.classList.add("global-notificationbox");\n element.setAttribute("notificationside", "bottom");\n document.getElementById("browser-bottombox").appendChild(element);\n }","_animating":false,"currentNotification":null} == true -
[task 2020-12-09T04:56:14.290Z] 04:56:14 INFO - Buffered messages finished
[task 2020-12-09T04:56:14.290Z] 04:56:14 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_datachoices_notification.js | No version should be set on init. - 37 == 0 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js :: assertCoherentInitialState :: line 148
[task 2020-12-09T04:56:14.290Z] 04:56:14 INFO - Stack trace:
[task 2020-12-09T04:56:14.290Z] 04:56:14 INFO - chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js:assertCoherentInitialState:148
[task 2020-12-09T04:56:14.290Z] 04:56:14 INFO - chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js:test_multiple_windows:241
[task 2020-12-09T04:56:14.290Z] 04:56:14 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-09T04:56:14.290Z] 04:56:14 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_datachoices_notification.js | No date should be set on init. - "1607489773654" == 0 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js :: assertCoherentInitialState :: line 153
[task 2020-12-09T04:56:14.290Z] 04:56:14 INFO - Stack trace:
[task 2020-12-09T04:56:14.290Z] 04:56:14 INFO - chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js:assertCoherentInitialState:153
[task 2020-12-09T04:56:14.290Z] 04:56:14 INFO - chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js:test_multiple_windows:241
[task 2020-12-09T04:56:14.291Z] 04:56:14 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-09T04:56:14.291Z] 04:56:14 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_datachoices_notification.js | User not notified about datareporting policy. - false == true - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js :: assertCoherentInitialState :: line 158
[task 2020-12-09T04:56:14.291Z] 04:56:14 INFO - Stack trace:
[task 2020-12-09T04:56:14.291Z] 04:56:14 INFO - chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js:assertCoherentInitialState:158
[task 2020-12-09T04:56:14.291Z] 04:56:14 INFO - chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js:test_multiple_windows:241
[task 2020-12-09T04:56:14.291Z] 04:56:14 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-09T04:56:14.291Z] 04:56:14 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_datachoices_notification.js | User should not be allowed to upload. - false == true - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js :: test_multiple_windows :: line 248
[task 2020-12-09T04:56:14.292Z] 04:56:14 INFO - Stack trace:
[task 2020-12-09T04:56:14.292Z] 04:56:14 INFO - chrome://mochitests/content/browser/browser/base/content/test/general/browser_datachoices_notification.js:test_multiple_windows:248
[task 2020-12-09T04:56:14.292Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | Must have a timer callback. - true == true -
[task 2020-12-09T04:56:14.292Z] 04:56:14 INFO - TEST-PASS | browser/base/content/test/general/browser_datachoices_notification.js | Timeout should match - 10000 == 10000 -
[task 2020-12-09T04:56:58.109Z] 04:56:58 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-09T04:56:58.109Z] 04:56:58 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_datachoices_notification.js | Test timed out -
[task 2020-12-09T04:56:58.474Z] 04:56:58 INFO - GECKO(9600) | MEMORY STAT | vsize 2104609MB | vsizeMaxContiguous 65778094MB | residentFast 456MB | heapAllocated 115MB
[task 2020-12-09T04:56:58.474Z] 04:56:58 INFO - TEST-OK | browser/base/content/test/general/browser_datachoices_notification.js | took 45381ms
[task 2020-12-09T04:56:58.493Z] 04:56:58 INFO - checking window state
[task 2020-12-09T04:56:58.493Z] 04:56:58 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-09T04:56:58.493Z] 04:56:58 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_datachoices_notification.js | Found a browser window after previous test timed out -
[task 2020-12-09T04:56:58.493Z] 04:56:58 INFO - GECKO(9600) | must wait for focus

Flags: needinfo?(chutten)
Whiteboard: [test isolation] → [test isolation][stockwell needswork:owner]

Yes, sorry for the silence. Distracted by other things.

So the failure's on line 241 which nixes my theory for what's going wrong. Unfortunately this test isn't properly situated in the tree so it doesn't have Telemetry logging turned on. Had I not been so confident that my theory was correct I would've fixed that the first time.

Try as I might I can't seem to get this to fail locally. I've got it running in a while loop with logging on and am hoping for the best.

If I can't get it to reproduce in 10min or so I will check in the logging.

Flags: needinfo?(chutten)

ni?myself so I check this after the next intermittent with the logging happens.

Flags: needinfo?(chutten)
Pushed by chutten@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/72c3348d44b7 Enable Trace Telemetry logging in datachoices test r=TravisLong

Lucky me, the push with the change failed on TV immediately!

So unfortunately the Telemetry logs are identical between my successful run locally and the failing run on mac TV. It goes a little something like:

 0:11.67 INFO Console message: 1608146035443	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: datareporting.policy.dataSubmissionPolicyAcceptedVersion
 0:11.67 INFO Console message: 1608146035443	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: datareporting.policy.dataSubmissionPolicyNotifiedTime
 0:11.67 INFO Console message: 1608146035443	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
 0:11.67 INFO Console message: 1608146035443	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
 0:12.81 INFO Console message: 1608146036367	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.nextSync
 0:12.81 INFO Console message: 1608146036367	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.globalScore
 0:12.81 INFO Console message: 1608146036369	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.clients.lastSync
 0:12.92 INFO Console message: 1608146036753	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.tabs.lastSync
 0:12.93 INFO Console message: 1608146036763	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: services.sync.declinedEngines
 0:13.00 INFO Console message: 1608146036808	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
 0:13.00 INFO Console message: 1608146036809	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
 0:13.00 INFO Console message: 1608146036809	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
 0:13.00 INFO Console message: 1608146036809	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::_showInfobar - User not notified, notifying now.
 0:13.00 INFO Console message: 1608146036809	Toolkit.Telemetry	INFO	DataNotificationInfoBar::Creating data reporting policy notification.
 0:13.00 INFO Console message: 1608146036813	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::_userNotified
 0:13.00 INFO Console message: 1608146036813	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::_recordNotificationData
 0:13.00 INFO Console message: 1608146036813	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::set dataSubmissionPolicyNotifiedDate - aDate: Wed Dec 16 2020 14:13:56 GMT-0500 (Eastern Standard Time)
 0:13.00 INFO Console message: 1608146036813	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: datareporting.policy.dataSubmissionPolicyNotifiedTime
 0:13.00 INFO Console message: 1608146036813	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: datareporting.policy.dataSubmissionPolicyAcceptedVersion
 0:13.00 INFO Console message: 1608146036813	Toolkit.Telemetry	TRACE	TelemetrySend::notifyCanUpload - notifying before sending is enabled. Ignoring.
 0:13.00 INFO Console message: 1608146036814	Toolkit.Telemetry	INFO	DataNotificationInfoBar::Creating data reporting policy notification.
 0:13.00 INFO Console message: 1608146036817	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::_userNotified
 0:13.00 INFO Console message: 1608146036817	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::_recordNotificationData
 0:13.00 INFO Console message: 1608146036817	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::set dataSubmissionPolicyNotifiedDate - aDate: Wed Dec 16 2020 14:13:56 GMT-0500 (Eastern Standard Time)
 0:13.00 INFO Console message: 1608146036817	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: datareporting.policy.dataSubmissionPolicyNotifiedTime
 0:13.00 INFO Console message: 1608146036817	Toolkit.Telemetry	TRACE	TelemetrySend::notifyCanUpload - notifying before sending is enabled. Ignoring.
 0:13.31 INFO Console message: 1608146037145	Toolkit.Telemetry	DEBUG	DataNotificationInfoBar::Closing notification.

The only change appears to be that the failing run on macos is missing the final line

 0:13.31 INFO Console message: 1608146037145	Toolkit.Telemetry	DEBUG	DataNotificationInfoBar::Closing notification.

But I assume that's because the test never gets to the part of the test that closes the notification and so that should be expected.

Unfortunately the test logs and the console messages appear to be buffered differently so I can't reconstruct a precise order of events. (Just because everything is happening in the same order doesn't mean everything is happening at the right time).

At this point I'd like to re-evaluate the value of this test. We try not to show the infobar any more (going on three years now), relying instead on opening a tab with the Privacy Notice as the fulfillment of the reporting policy. This test is covering a mechanism we don't intend to ever use, for the subfractional number of times it involves multiple windows.

I think we can skip this test relying on the other test coverage (notably toolkit/components/telemetry/tests/unit/test_TelemetryReportingPolicy.js) to cover the code always (okay, almost always) runs. needinfo Jan-Erik for a sober second thought.

If Jan-Erik agrees with me about the value of this test, I will:

  1. Remove the logging and extra checks from this test that I added earlier in this bug
  2. File a new bug (P4) to investigate whether we can remove the mechanism entirely or decide to fix the test
  3. Leave the test in place but skipped, with a comment pointing to #2
Flags: needinfo?(chutten) → needinfo?(jrediger)

I agree with :chutten's comments above. If this exercises not-really used code and produces nothing but flaky tests there's next to no value for it and tracking this down seems to be rather hard right now. The 3-step plan forward sounds fine.

Flags: needinfo?(jrediger)
Blocks: 1683333
Pushed by chutten@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/f4380ffa8aad Skip intermittently-failing test that we probably don't need r=TravisLong
Regressions: 1683385

Bother. How did I miss that this was a browser-chrome test and thus can't have subtests skip_if'd.

Commenting it out as a block instead. Patch for review shortly.

Flags: needinfo?(chutten)
Pushed by chutten@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/5f58c4b5d0f6 Skip intermittently-failing subtest that we probably don't need r=TravisLong
Whiteboard: [test isolation][stockwell needswork:owner] → [test isolation][stockwell disabled]

Unsurprisingly it looks like that takes care of that.

Status: ASSIGNED → RESOLVED
Closed: 5 years ago → 5 years ago
Resolution: --- → FIXED
status-firefox84: --- → wontfix
status-firefox85: --- → wontfix
status-firefox86: --- → fixed
status-firefox-esr78: --- → wontfix
Target Milestone: --- → 86 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: