1686894 - Intermittent toolkit/components/antitracking/test/browser/browser_contentBlockingTelemetry.js | Uncaught exception - undefined - timed out after 50 tries.

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

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

---

[task 2021-01-15T06:02:04.714Z] 06:02:04     INFO - TEST-START | toolkit/components/antitracking/test/browser/browser_contentBlockingTelemetry.js
[task 2021-01-15T06:02:13.462Z] 06:02:13     INFO - TEST-INFO | started process screencapture
[task 2021-01-15T06:02:13.554Z] 06:02:13     INFO - TEST-INFO | screencapture: exit 0
[task 2021-01-15T06:02:13.555Z] 06:02:13     INFO - Buffered messages logged at 06:02:04
[task 2021-01-15T06:02:13.555Z] 06:02:13     INFO - Entering test bound setup
[task 2021-01-15T06:02:13.555Z] 06:02:13     INFO - Leaving test bound setup
[task 2021-01-15T06:02:13.556Z] 06:02:13     INFO - Entering test bound testTelemetryForStorageAccessAPI
[task 2021-01-15T06:02:13.556Z] 06:02:13     INFO - Starting testing if storage access API send telemetry probe ...
[task 2021-01-15T06:02:13.556Z] 06:02:13     INFO - Creating a new tab
[task 2021-01-15T06:02:13.556Z] 06:02:13     INFO - Loading the tracking iframe and call the RequestStorageAccess.
[task 2021-01-15T06:02:13.556Z] 06:02:13     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://example.net/browser/toolkit/components/antitracking/test/browser/page.html" line: 0}]
[task 2021-01-15T06:02:13.556Z] 06:02:13     INFO - Sending code to the 3rd party content
[task 2021-01-15T06:02:13.565Z] 06:02:13     INFO - Console message: [JavaScript Warning: "Request to access cookie or storage on “https://tracking.example.org/browser/toolkit/components/antitracking/test/browser/3rdPartyUI.html” was blocked because it came from a tracker and content blocking is enabled."]
[task 2021-01-15T06:02:13.565Z] 06:02:13     INFO - Console message: [JavaScript Warning: "Request to access cookie or storage on “https://tracking.example.org/browser/toolkit/components/antitracking/test/browser/3rdPartyUI.html” was blocked because it came from a tracker and content blocking is enabled."]
[task 2021-01-15T06:02:13.565Z] 06:02:13     INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_contentBlockingTelemetry.js | requestStorageAccess should not throw - true == true - 
[task 2021-01-15T06:02:13.565Z] 06:02:13     INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_contentBlockingTelemetry.js | Should not have worked without user interaction - true == true - 
[task 2021-01-15T06:02:13.566Z] 06:02:13     INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_contentBlockingTelemetry.js | Doesn't yet have storage access - true == true - 
[task 2021-01-15T06:02:13.566Z] 06:02:13     INFO - Let's interact with the tracker
[task 2021-01-15T06:02:13.566Z] 06:02:13     INFO - Console message: [JavaScript Warning: "Request to access cookie or storage on “https://tracking.example.org/browser/toolkit/components/antitracking/test/browser/3rdPartyUI.html” was blocked because it came from a tracker and content blocking is enabled."]
[task 2021-01-15T06:02:13.566Z] 06:02:13     INFO - Buffered messages logged at 06:02:05
[task 2021-01-15T06:02:13.566Z] 06:02:13     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "https://tracking.example.org/browser/toolkit/components/antitracking/test/browser/3rdPartyOpenUI.html?messageme" line: 0}]
[task 2021-01-15T06:02:13.567Z] 06:02:13     INFO - Console message: [JavaScript Warning: "Request to access cookie or storage on “https://tracking.example.org/browser/toolkit/components/antitracking/test/browser/3rdPartyUI.html” was blocked because it came from a tracker and content blocking is enabled."]
[task 2021-01-15T06:02:13.567Z] 06:02:13     INFO - Console message: [JavaScript Warning: "Request to access cookie or storage on “https://tracking.example.org/browser/toolkit/components/antitracking/test/browser/3rdPartyUI.html” was blocked because it came from a tracker and content blocking is enabled."]
[task 2021-01-15T06:02:13.567Z] 06:02:13     INFO - Console message: [JavaScript Warning: "Storage access granted for origin “https://tracking.example.org” on “http://example.net”."]
[task 2021-01-15T06:02:13.567Z] 06:02:13     INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_contentBlockingTelemetry.js | Should have storage access now - true == true - 
[task 2021-01-15T06:02:13.567Z] 06:02:13     INFO - Removing the tab
[task 2021-01-15T06:02:13.567Z] 06:02:13     INFO - Trigger the 'idle-daily' to trigger the telemetry probe.
[task 2021-01-15T06:02:13.567Z] 06:02:13     INFO - Buffered messages finished
[task 2021-01-15T06:02:13.568Z] 06:02:13     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/antitracking/test/browser/browser_contentBlockingTelemetry.js | Uncaught exception - undefined - timed out after 50 tries.
[task 2021-01-15T06:02:13.568Z] 06:02:13     INFO - Leaving test bound testTelemetryForStorageAccessAPI
[task 2021-01-15T06:02:13.568Z] 06:02:13     INFO - Entering test bound testTelemetryForWindowOpenHeuristic
[task 2021-01-15T06:02:13.568Z] 06:02:13     INFO - Starting testing if window open heuristic send telemetry probe ...
[task 2021-01-15T06:02:13.568Z] 06:02:13     INFO - Creating a new tab
[task 2021-01-15T06:02:13.568Z] 06:02:13     INFO - Loading the tracking iframe and trigger the heuristic
[task 2021-01-15T06:02:13.568Z] 06:02:13     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://example.net/browser/toolkit/components/antitracking/test/browser/page.html" line: 0}]
[task 2021-01-15T06:02:13.568Z] 06:02:13     INFO - Checking if storage access is denied
[task 2021-01-15T06:02:13.639Z] 06:02:13     INFO - Sending code to the 3rd party content
[task 2021-01-15T06:02:13.639Z] 06:02:13     INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_contentBlockingTelemetry.js | Doesn't yet have storage access - true == true - 
[task 2021-01-15T06:02:13.639Z] 06:02:13     INFO - Let's do a window.open()
[task 2021-01-15T06:02:13.640Z] 06:02:13     INFO - Console message: [JavaScript Warning: "Request to access cookie or storage on “https://tracking.example.org/browser/toolkit/components/antitracking/test/browser/3rdPartyWO.html” was blocked because it came from a tracker and content blocking is enabled."]
[task 2021-01-15T06:02:13.681Z] 06:02:13     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "https://tracking.example.org/browser/toolkit/components/antitracking/test/browser/3rdPartyOpen.html" line: 0}]
[task 2021-01-15T06:02:13.681Z] 06:02:13     INFO - The popup has been dismissed!
[task 2021-01-15T06:02:13.681Z] 06:02:13     INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_contentBlockingTelemetry.js | Doesn't yet have storage access - true == true - 
[task 2021-01-15T06:02:13.681Z] 06:02:13     INFO - Let's interact with the tracker
[task 2021-01-15T06:02:13.682Z] 06:02:13     INFO - Console message: [JavaScript Warning: "Request to access cookie or storage on “https://tracking.example.org/browser/toolkit/components/antitracking/test/browser/3rdPartyWO.html” was blocked because it came from a tracker and content blocking is enabled."]
[task 2021-01-15T06:02:13.756Z] 06:02:13     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "https://tracking.example.org/browser/toolkit/components/antitracking/test/browser/3rdPartyOpenUI.html?messageme" line: 0}]
[task 2021-01-15T06:02:13.756Z] 06:02:13     INFO - Console message: [JavaScript Warning: "Request to access cookie or storage on “https://tracking.example.org/browser/toolkit/components/antitracking/test/browser/3rdPartyWO.html” was blocked because it came from a tracker and content blocking is enabled."]
[task 2021-01-15T06:02:13.762Z] 06:02:13     INFO - Let's do another window.open()
[task 2021-01-15T06:02:13.762Z] 06:02:13     INFO - Console message: [JavaScript Warning: "Storage access automatically granted for origin “https://tracking.example.org” on “http://example.net”."]
[task 2021-01-15T06:02:13.787Z] 06:02:13     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "https://tracking.example.org/browser/toolkit/components/antitracking/test/browser/3rdPartyOpen.html" line: 0}]
[task 2021-01-15T06:02:13.787Z] 06:02:13     INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_contentBlockingTelemetry.js | Has storage access - true == true - 
[task 2021-01-15T06:02:13.787Z] 06:02:13     INFO - Removing the tab
[task 2021-01-15T06:02:13.788Z] 06:02:13     INFO - Trigger the 'idle-daily' to trigger the telemetry probe.
[task 2021-01-15T06:02:20.890Z] 06:02:20     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-01-15T06:02:20.890Z] 06:02:20     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/antitracking/test/browser/browser_contentBlockingTelemetry.js | Uncaught exception - undefined - timed out after 50 tries.```

Comment 1

[Intermittent Failures Robot]

13 failures in 3810 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 6
• autoland: 5
• try: 2

Platform breakdown:

• macosx1014-64-shippable-qr: 2
• macosx1014-64-qr: 2
• windows10-64: 3
• linux1804-64-shippable: 1
• windows10-64-shippable-qr: 1
• windows7-32-shippable: 3
• windows10-64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686894&startday=2021-01-11&endday=2021-01-17&tree=all

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 3

[Emma Zühlcke [:emz]]

I don't see how this is directly related to Bug 1679512. Perhaps the timing changed a bit?

Tim, since you implemented the test, do you have an idea what could make it intermittent? The failure rate seems relatively low, so I'm not sure if this is worth prioritizing.

Comment 4

[Tim Huang[:timhuang] [PTO 10/23 ~ 10/28]]

From the test code, it doesn't look to me that this is caused by Bug1679512. However, the test browser_contentBlockingTelemetry.js runs after the test browser_contentBlockingAllowListPrincipal.js. So, it could be the case that there are some uncleared states of test 'browser_contentBlockingAllowListPrincipal.js' that cause this intermittent.

Comment 5

[Emma Zühlcke [:emz]]

(In reply to Tim Huang[:timhuang] from comment #4)

From the test code, it doesn't look to me that this is caused by Bug1679512. However, the test browser_contentBlockingTelemetry.js runs after the test browser_contentBlockingAllowListPrincipal.js. So, it could be the case that there are some uncleared states of test 'browser_contentBlockingAllowListPrincipal.js' that cause this intermittent.

Good observation! I can reproduce the failure if I run the two tests in that order.
It seems like we get a higher telemetry value than expected for the storageAccessAPI probe. Which is weird because the test clears telemetry as part of the setup.
browser_contentBlockingAllowListPrincipal.js doesn't interact with that API. However, if I skip test_windowOpen the telemetry test passes.
This seems to be timing related, I can only reproduce it if my CPU isn't busy and I'm running an opt build.

Comment 6

[Intermittent Failures Robot]

19 failures in 665 pushes (0.029 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 12
• mozilla-central: 6
• try: 1

Platform and build breakdown:

• windows10-64-qr: 2
  • opt: 2
• macosx1014-64-qr: 1
  • opt: 1
• windows10-64: 3
  • opt: 3
• windows7-32-shippable: 3
  • opt: 3
• macosx1014-64-shippable-qr: 3
  • opt: 3
• windows7-32: 6
  • opt: 6
• linux1804-64-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686894&startday=2021-01-22&endday=2021-01-22&tree=all

Comment 7

[Intermittent Failures Robot]

67 failures in 3488 pushes (0.019 failures/push) were associated with this bug in the last 7 days.

This is the #15 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 34
• try: 13
• mozilla-central: 20

Platform and build breakdown:

• windows7-32: 14
  • opt: 14
• windows10-64-shippable: 3
  • opt: 3
• windows10-64: 8
  • opt: 8
• macosx1014-64-qr: 10
  • opt: 10
• windows10-64-shippable-qr: 6
  • opt: 6
• macosx1014-64-shippable-qr: 9
  • opt: 9
• windows7-32-shippable: 8
  • opt: 8
• windows10-64-qr: 4
  • opt: 4
• linux1804-64-shippable: 3
  • opt: 3
• macosx1014-64-devedition-qr: 1
  • opt: 1
• windows10-64-devedition: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686894&startday=2021-01-18&endday=2021-01-24&tree=all

Comment 8

[Emma Zühlcke [:emz]]

Attachment: Bug 1686894 - Disable storage access heuristics to prevent telemetry race condition with the next test. r=timhuang!

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/93ee8d68aea4
Disable storage access heuristics to prevent telemetry race condition with the next test. r=timhuang

Comment 10

[Sandor Molnar[:smolnar]]

https://hg.mozilla.org/mozilla-central/rev/93ee8d68aea4

Comment 11

[Julien Cristau [:jcristau]]

https://hg.mozilla.org/releases/mozilla-beta/rev/7eaa565b6d1d

Comment 12

[Intermittent Failures Robot]

35 failures in 3891 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

This is the #31 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 9
• mozilla-central: 10
• mozilla-beta: 13
• try: 3

Platform and build breakdown:

• windows10-64-qr: 2
  • opt: 2
• macosx1014-64-shippable-qr: 9
  • opt: 9
• windows10-64-shippable-qr: 2
  • opt: 2
• windows7-32-shippable: 5
  • opt: 5
• windows10-64-shippable: 2
  • opt: 2
• windows10-64-devedition: 2
  • opt: 2
• macosx1014-64-qr: 5
  • opt: 5
• windows7-32: 2
  • opt: 2
• linux1804-64-shippable: 1
  • opt: 1
• windows10-64: 2
  • opt: 2
• macosx1014-64-devedition-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686894&startday=2021-01-25&endday=2021-01-31&tree=all