Closed Bug 1797094 Opened 2 years ago Closed 1 year ago

Intermittent toolkit/components/cookiebanners/test/browser/browser_bannerClicking.js | single tracking bug

Categories

(Core :: Privacy: Anti-Tracking, defect, P2)

Product:
Core
Component:
Privacy: Anti-Tracking
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
110 Branch
Tracking Flags:
Tracking Status
firefox-esr102 --- unaffected
firefox107 --- unaffected
firefox108 --- unaffected
firefox109 --- fixed
firefox110 --- fixed

People

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

References

(Blocks 1 open bug, Regression)

Details

(Keywords: intermittent-failure, intermittent-testcase, regression, Whiteboard: [stockwell disable-recommended])

Attachments

(2 files, 1 obsolete file)

Bug 1797094 - Clean up banner clicking telemetry state on failure. r=timhuang!
48 bytes, text/x-phabricator-request
Details | Review
Bug 1797094 - Disable click result telemetry on linux. r=timhuang!
48 bytes, text/x-phabricator-request
Details | Review

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

[task 2022-10-24T12:32:48.716Z] 12:32:48     INFO - TEST-START | toolkit/components/cookiebanners/test/browser/browser_bannerClicking.js
[task 2022-10-24T12:32:48.748Z] 12:32:48     INFO - GECKO(18325) | console.log: ** CookieBannerListService.jsm: "shutdown"
[task 2022-10-24T12:32:49.080Z] 12:32:49     INFO - GECKO(18325) | console.debug: CookieBannerChild: "onDOMContentLoaded" ({didLoad:false})
[task 2022-10-24T12:32:49.084Z] 12:32:49     INFO - GECKO(18325) | console.debug: CookieBannerChild: "Send message to get rule for example.com"
[task 2022-10-24T12:32:49.162Z] 12:32:49     INFO - GECKO(18325) | console.debug: CookieBannerChild: "Got rules:" []
[task 2022-10-24T12:38:48.733Z] 12:38:48     INFO - TEST-INFO | started process screentopng
[task 2022-10-24T12:38:49.091Z] 12:38:49     INFO - TEST-INFO | screentopng: exit 0
[task 2022-10-24T12:38:49.091Z] 12:38:49     INFO - Buffered messages logged at 12:32:48
[task 2022-10-24T12:38:49.092Z] 12:38:49     INFO - Entering setup bound clickTestSetup
[task 2022-10-24T12:38:49.093Z] 12:38:49     INFO - Leaving setup bound clickTestSetup
[task 2022-10-24T12:38:49.093Z] 12:38:49     INFO - Entering test bound test_cookie_banner_service_disabled
[task 2022-10-24T12:38:49.094Z] 12:38:49     INFO - Opening https://example.com/browser/toolkit/components/cookiebanners/test/browser/file_banner.html
[task 2022-10-24T12:38:49.095Z] 12:38:49     INFO - Buffered messages logged at 12:32:49
[task 2022-10-24T12:38:49.099Z] 12:38:49     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "https://example.com/browser/toolkit/components/cookiebanners/test/browser/file_banner.html" line: 0}]
[task 2022-10-24T12:38:49.100Z] 12:38:49     INFO - Buffered messages logged at 12:34:18
[task 2022-10-24T12:38:49.101Z] 12:38:49     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 2
[task 2022-10-24T12:38:49.102Z] 12:38:49     INFO - Buffered messages logged at 12:35:48
[task 2022-10-24T12:38:49.102Z] 12:38:49     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 1
[task 2022-10-24T12:38:49.103Z] 12:38:49     INFO - Buffered messages logged at 12:37:10
[task 2022-10-24T12:38:49.104Z] 12:38:49     INFO - Console message: [JavaScript Error: "Invalid ETag value "undefined"" {file: "resource://services-settings/SyncHistory.jsm" line: 52}]
[task 2022-10-24T12:38:49.105Z] 12:38:49     INFO - store@resource://services-settings/SyncHistory.jsm:52:13
[task 2022-10-24T12:38:49.105Z] 12:38:49     INFO - 
[task 2022-10-24T12:38:49.106Z] 12:38:49     INFO - Buffered messages finished
[task 2022-10-24T12:38:49.109Z] 12:38:49     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/cookiebanners/test/browser/browser_bannerClicking.js | Test timed out - 
[task 2022-10-24T12:38:49.109Z] 12:38:49     INFO - GECKO(18325) | console.log: ** CookieBannerListService.jsm: "importAllRules"
[task 2022-10-24T12:38:49.109Z] 12:38:49     INFO - GECKO(18325) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2022-10-24T12:38:49.110Z] 12:38:49     INFO - GECKO(18325) | MEMORY STAT heapAllocated not supported in this build configuration.
[task 2022-10-24T12:38:49.110Z] 12:38:49     INFO - GECKO(18325) | MEMORY STAT | vsize 20975265MB | residentFast 1352MB
[task 2022-10-24T12:38:49.111Z] 12:38:49     INFO - TEST-OK | toolkit/components/cookiebanners/test/browser/browser_bannerClicking.js | took 360045ms

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

Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=397350325&repo=autoland

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

Set release status flags based on info from the regressing bug 1797078

:pbz, since you are the author of the regressor, bug 1797078, could you take a look?

For more information, please visit auto_nag documentation.

status-firefox107: --- → unaffected
status-firefox108: --- → unaffected
status-firefox109: --- → affected
status-firefox-esr102: --- → unaffected
Flags: needinfo?(pbz)
Keywords: regression
Assignee: nobody → pbz
Status: REOPENED → ASSIGNED
Flags: needinfo?(pbz)

There have been 66 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • linux1804-64-asan-qr
  • linux1804-64-qr
  • linux1804-64-shippable-qr
  • linux1804-64-tsan-qr
[task 2022-12-04T10:35:49.612Z] 10:35:49     INFO - TEST-PASS | toolkit/components/cookiebanners/test/browser/browser_bannerClicking.js | Counter for label 'success' has correct state. - 
[task 2022-12-04T10:35:49.612Z] 10:35:49     INFO - Buffered messages finished
[task 2022-12-04T10:35:49.613Z] 10:35:49     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/cookiebanners/test/browser/browser_bannerClicking.js | Counter for label 'success_dom_content_loaded' has correct state. - Got 1, expected undefined
[task 2022-12-04T10:35:49.613Z] 10:35:49     INFO - Stack trace:
[task 2022-12-04T10:35:49.613Z] 10:35:49     INFO - chrome://mochikit/content/browser-test.js:test_is:1477
[task 2022-12-04T10:35:49.613Z] 10:35:49     INFO - chrome://mochitests/content/browser/toolkit/components/cookiebanners/test/browser/head.js:testMetricState:298
[task 2022-12-04T10:35:49.613Z] 10:35:49     INFO - chrome://mochitests/content/browser/toolkit/components/cookiebanners/test/browser/head.js:testClickResultTelemetry:323
[task 2022-12-04T10:35:49.614Z] 10:35:49     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-12-04T10:35:49.614Z] 10:35:49     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/cookiebanners/test/browser/browser_bannerClicking.js | Counter for label 'success_mutation_pre_load' has correct state. - Got undefined, expected 1
[task 2022-12-04T10:35:49.614Z] 10:35:49     INFO - Stack trace:
[task 2022-12-04T10:35:49.614Z] 10:35:49     INFO - chrome://mochikit/content/browser-test.js:test_is:1477
[task 2022-12-04T10:35:49.615Z] 10:35:49     INFO - chrome://mochitests/content/browser/toolkit/components/cookiebanners/test/browser/head.js:testMetricState:298
[task 2022-12-04T10:35:49.615Z] 10:35:49     INFO - chrome://mochitests/content/browser/toolkit/components/cookiebanners/test/browser/head.js:testClickResultTelemetry:323
[task 2022-12-04T10:35:49.615Z] 10:35:49     INFO - TEST-PASS | toolkit/components/cookiebanners/test/browser/browser_bannerClicking.js | Counter for label 'success_mutation_post_load' has correct state. -
Flags: needinfo?(tihuang)
Whiteboard: [stockwell needswork:owner]

Pump up the priority given that this is the #8 intermittent.

Priority: P5 → P2

Looks like there is a race condition with test_clicking_with_delayed_banner which causes us to handle the banner on DOMContentLoaded rather than later. This leads to an unexpected telemetry state. The telemetry test function does not clear telemetry when it throws so subsequent telemetry assertions also fail.
This is a bit difficult to troubleshoot because the issue is really hard to produce locally. It only reproduces on Linux debug for me so far.

Increasing the delay for the banner to show up (later) does make the test a bit less intermittent but it doesn't seem to address the root cause.

This is to avoid failing subsequent tests in case of a test failure.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

Set release status flags based on info from the regressing bug 1797078

status-firefox110: --- → affected
Blocks: 1805653
Attachment #9307136 - Attachment description: WIP: Bug 1797094 - Clean up banner clicking telemetry state on failure. r=timhuang! → Bug 1797094 - Clean up banner clicking telemetry state on failure. r=timhuang!
Attachment #9308247 - Attachment description: WIP: Bug 1797094 - Disable click result telemetry on linux. r=timhuang! → Bug 1797094 - Disable click result telemetry on linux. r=timhuang!
Attachment #9307137 - Attachment is obsolete: true
Pushed by pzuhlcke@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/4bebe691b203
Clean up banner clicking telemetry state on failure. r=timhuang
https://hg.mozilla.org/integration/autoland/rev/646f6ecba7da
Disable click result telemetry on linux. r=timhuang

https://hg.mozilla.org/mozilla-central/rev/4bebe691b203
https://hg.mozilla.org/mozilla-central/rev/646f6ecba7da

Status: ASSIGNED → RESOLVED
Closed: 1 year ago → 1 year ago
status-firefox110: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → 110 Branch

The patch landed in nightly and beta is affected.
:pbz, is this bug important enough to require an uplift?

  • If yes, please nominate the patch for beta approval.
  • If no, please set status-firefox109 to wontfix.

For more information, please visit auto_nag documentation.

Flags: needinfo?(pbz)
Flags: needinfo?(pbz)
See Also: → 1801717
See Also: → 1808838
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: