1788813 - Intermittent browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | After filtering we must have the expected number of events. - 5 == 3 - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertEvents :: line 181

Status: RESOLVED FIXED

(Firefox :: General, defect, P1)

Description

[Treeherder Bug Filer]

Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=389222988&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Z0Eba3zmT92HXsAf2fylMQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Z0Eba3zmT92HXsAf2fylMQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2022-09-01T23:03:52.662Z] 23:03:52     INFO - TEST-PASS | browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | parent must be in snapshot. Has [parent]. - true == true - 
[task 2022-09-01T23:03:52.663Z] 23:03:52     INFO - Buffered messages finished
[task 2022-09-01T23:03:52.664Z] 23:03:52     INFO - TEST-UNEXPECTED-FAIL | browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | After filtering we must have the expected number of events. - 5 == 3 - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertEvents :: line 181
[task 2022-09-01T23:03:52.664Z] 23:03:52     INFO - Stack trace:
[task 2022-09-01T23:03:52.665Z] 23:03:52     INFO - resource://testing-common/TelemetryTestUtils.jsm:assertEvents:181
[task 2022-09-01T23:03:52.665Z] 23:03:52     INFO - chrome://mochitests/content/browser/browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js:test_time_updates_correctly/<:371
[task 2022-09-01T23:03:52.666Z] 23:03:52     INFO - TEST-PASS | browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | category in event firefoxview#tab_pickup_open#tabs must match. - "firefoxview" matches "firefoxview" - 
[task 2022-09-01T23:03:52.667Z] 23:03:52     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-09-01T23:03:52.668Z] 23:03:52     INFO - TEST-UNEXPECTED-FAIL | browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | method in event firefoxview#tab_pickup_open#tabs must match. - "tab_pickup_open" matches "entered" - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertEvents :: line 216
[task 2022-09-01T23:03:52.668Z] 23:03:52     INFO - Stack trace:
[task 2022-09-01T23:03:52.669Z] 23:03:52     INFO - resource://testing-common/TelemetryTestUtils.jsm:assertEvents:216
[task 2022-09-01T23:03:52.670Z] 23:03:52     INFO - chrome://mochitests/content/browser/browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js:test_time_updates_correctly/<:371
[task 2022-09-01T23:03:52.670Z] 23:03:52     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-09-01T23:03:52.671Z] 23:03:52     INFO - TEST-UNEXPECTED-FAIL | browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | object in event firefoxview#tab_pickup_open#tabs must match. - "tabs" matches "firefoxview" - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertEvents :: line 216
[task 2022-09-01T23:03:52.671Z] 23:03:52     INFO - Stack trace:
[task 2022-09-01T23:03:52.672Z] 23:03:52     INFO - resource://testing-common/TelemetryTestUtils.jsm:assertEvents:216
[task 2022-09-01T23:03:52.672Z] 23:03:52     INFO - chrome://mochitests/content/browser/browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js:test_time_updates_correctly/<:371
[task 2022-09-01T23:03:52.673Z] 23:03:52     INFO - TEST-PASS | browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | category in event firefoxview#closed_tabs_open#tabs must match. - "firefoxview" matches "firefoxview" - 
[task 2022-09-01T23:03:52.674Z] 23:03:52     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-09-01T23:03:52.674Z] 23:03:52     INFO - TEST-UNEXPECTED-FAIL | browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | method in event firefoxview#closed_tabs_open#tabs must match. - "closed_tabs_open" matches "synced_tabs" - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertEvents :: line 216
[task 2022-09-01T23:03:52.675Z] 23:03:52     INFO - Stack trace:
[task 2022-09-01T23:03:52.676Z] 23:03:52     INFO - resource://testing-common/TelemetryTestUtils.jsm:assertEvents:216
[task 2022-09-01T23:03:52.676Z] 23:03:52     INFO - chrome://mochitests/content/browser/browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js:test_time_updates_correctly/<:371
[task 2022-09-01T23:03:52.677Z] 23:03:52     INFO - TEST-PASS | browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | object in event firefoxview#closed_tabs_open#tabs must match. - "tabs" matches "tabs" - 
[task 2022-09-01T23:03:52.677Z] 23:03:52     INFO - TEST-PASS | browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | Actual event firefoxview#closed_tabs_open#tabs expected to have extra. - true == true - 
[task 2022-09-01T23:03:52.678Z] 23:03:52     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-09-01T23:03:52.679Z] 23:03:52     INFO - TEST-UNEXPECTED-FAIL | browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | Uncaught exception in test - at resource://testing-common/TelemetryTestUtils.jsm:238 - TypeError: right-hand side of 'in' should be an object, got undefined
[task 2022-09-01T23:03:52.679Z] 23:03:52     INFO - Stack trace:
[task 2022-09-01T23:03:52.680Z] 23:03:52     INFO - assertEvents@resource://testing-common/TelemetryTestUtils.jsm:238:1
[task 2022-09-01T23:03:52.680Z] 23:03:52     INFO - test_time_updates_correctly/<@chrome://mochitests/content/browser/browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js:371:26
[task 2022-09-01T23:03:52.681Z] 23:03:52     INFO - Leaving test bound test_time_updates_correctly
[task 2022-09-01T23:03:52.681Z] 23:03:52     INFO - Console message: 1662073432037	FirefoxView.TabsSetup	DEBUG	maybeUpdateUI, conditions not met to exit state: : synced-tabs-not-ready
[task 2022-09-01T23:03:52.684Z] 23:03:52     INFO - Console message: 1662073432037	FirefoxView.TabsSetup	DEBUG	maybeUpdateUI, _uiUpdateNeeded:: true
[task 2022-09-01T23:03:52.686Z] 23:03:52     INFO - GECKO(15275) | JavaScript error: resource:///modules/AsyncTabSwitcher.jsm, line 378: TypeError: can't access property "schemeIs", requestedBrowser.currentURI is null
[task 2022-09-01T23:03:52.687Z] 23:03:52     INFO - Console message: [JavaScript Error: "TypeError: can't access property "schemeIs", requestedBrowser.currentURI is null" {file: "resource:///modules/AsyncTabSwitcher.jsm" line: 378}]
[task 2022-09-01T23:03:52.688Z] 23:03:52     INFO - updateDisplay@resource:///modules/AsyncTabSwitcher.jsm:378:26
[task 2022-09-01T23:03:52.689Z] 23:03:52     INFO - postActions@resource:///modules/AsyncTabSwitcher.jsm:673:10
[task 2022-09-01T23:03:52.689Z] 23:03:52     INFO - handleEvent@resource:///modules/AsyncTabSwitcher.jsm:1127:12
[task 2022-09-01T23:03:52.681Z] 23:03:52     INFO - Console message: 1662073432037	FirefoxView.TabsSetup	DEBUG	maybeUpdateUI, conditions not met to exit state: : synced-tabs-not-ready
[task 2022-09-01T23:03:52.684Z] 23:03:52     INFO - Console message: 1662073432037	FirefoxView.TabsSetup	DEBUG	maybeUpdateUI, _uiUpdateNeeded:: true
[task 2022-09-01T23:03:52.686Z] 23:03:52     INFO - GECKO(15275) | JavaScript error: resource:///modules/AsyncTabSwitcher.jsm, line 378: TypeError: can't access property "schemeIs", requestedBrowser.currentURI is null
[task 2022-09-01T23:03:52.687Z] 23:03:52     INFO - Console message: [JavaScript Error: "TypeError: can't access property "schemeIs", requestedBrowser.currentURI is null" {file: "resource:///modules/AsyncTabSwitcher.jsm" line: 378}]
[task 2022-09-01T23:03:52.688Z] 23:03:52     INFO - updateDisplay@resource:///modules/AsyncTabSwitcher.jsm:378:26
[task 2022-09-01T23:03:52.689Z] 23:03:52     INFO - postActions@resource:///modules/AsyncTabSwitcher.jsm:673:10
[task 2022-09-01T23:03:52.689Z] 23:03:52     INFO - handleEvent@resource:///modules/AsyncTabSwitcher.jsm:1127:12
[task 2022-09-01T23:03:52.690Z] 23:03:52     INFO - 
[task 2022-09-01T23:03:52.691Z] 23:03:52     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/" line: 0}]
[task 2022-09-01T23:03:53.163Z] 23:03:53     INFO - GECKO(15275) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2022-09-01T23:03:53.165Z] 23:03:53     INFO - GECKO(15275) | MEMORY STAT | vsize 11443MB | residentFast 503MB | heapAllocated 238MB
[task 2022-09-01T23:03:53.168Z] 23:03:53     INFO - TEST-OK | browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | took 3201ms
[task 2022-09-01T23:03:53.169Z] 23:03:53     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-09-01T23:03:53.170Z] 23:03:53     INFO - TEST-UNEXPECTED-FAIL | browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | Found an unexpected tab at the end of test run: https://example.com/ - 
[task 2022-09-01T23:03:53.183Z] 23:03:53     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-09-01T23:03:53.185Z] 23:03:53     INFO - TEST-UNEXPECTED-FAIL | browser/components/firefoxview/tests/browser/browser_tab_pickup_list.js | Found an unexpected tab at the end of test run: about:firefoxview - 
[task 2022-09-01T23:03:53.216Z] 23:03:53     INFO - checking window state
[task 2022-09-01T23:03:53.232Z] 23:03:53     INFO - GECKO(15275) | Completed ShutdownLeaks collections in process 15275

Comment 1

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

:sfoster, since you are the author of the regressor, bug 1784902, could you take a look?

For more information, please visit auto_nag documentation.

Comment 2

[Sam Foster [:sfoster] (he/him)]

(In reply to Release mgmt bot [:suhaib / :marco/ :calixte] from comment #1)

:sfoster, since you are the author of the regressor, bug 1784902, could you take a look?

i can take a look at this, but due to my timezone and the US holiday on monday I'm going to leave it unassigned in case anyone else wants/needs to fix it before I can get to it.

Comment 3

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

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

Comment 4

[:Gijs (he/him)]

So I ran into an issue when trying to land the patch in bug 1787565 that has the same root cause. I was going to file a new bug and then realized this bug already existed. Here's what I was going to write - hopefully this is useful once everyone's back from the public holidays etc.

My patch in bug 1787565 got backed out because there were additional, unexpected telemetry events when the (pre-existing) browser_recently_closed_tabs.js test runs.

The stacks I get for these when I added logging look like this:

 1:51.00 INFO Console message: [JavaScript Error: "Recording telemetry for opening the container tab-pickup-container" {file: "chrome://browser/content/helpers.mjs" line: 67}]
onToggleContainer@chrome://browser/content/helpers.mjs:67:6
handleEvent@chrome://browser/content/tab-pickup-container.mjs:53:24

Unfortunately this doesn't make it clear what caused the event to fire. In this case the event gets recorded between the test clearing the list of telemetry events, and adding the new events, so the telemetry test utils complain that the expected events and actual events do not match.

Nothing in this test touches the tab-pickup-container at all, and these issues happen even when running just this test, and I also see occasional spurious log messages from the recently closed tabs container. For instance, here is the start of a test run:

 1:26.92 GECKO(5958) 1662248009314	Marionette	DEBUG	Closed connection 1
 1:27.28 INFO *** Start BrowserChrome Test Results ***
 1:27.31 INFO checking window state
 1:27.36 TEST_START: browser/components/firefoxview/tests/browser/browser_recently_closed_tabs.js
 1:27.41 INFO Entering test bound test_empty_list
 1:28.00 INFO Console message: 1662248010367	FirefoxView.TabsSetup	DEBUG	maybeUpdateUI, conditions not met to exit state: : not-signed-in
 1:28.00 INFO Console message: 1662248010367	FirefoxView.TabsSetup	DEBUG	maybeUpdateUI, _uiUpdateNeeded:: true
 1:28.02 INFO Console message: [JavaScript Error: "Recording telemetry for opening the container tab-pickup-container" {file: "chrome://browser/content/helpers.mjs" line: 67}]
onToggleContainer@chrome://browser/content/helpers.mjs:67:6
handleEvent@chrome://browser/content/tab-pickup-container.mjs:53:24
 1:28.20 PASS collapsible container should have correct styling when the list is empty - 
 1:28.20 PASS Expected #recently-closed-tabs-placeholder to be visible - 

The test hasn't done anything that actively opens/closes the container. I think in some cases (though it doesn't seem to happen every time!), we fire a toggle event that then collects telemetry.

I can reproduce manually by just opening about:telemetry in the events section, filter for firefoxview, then select the fxview tab and just repeatedly refresh it a bunch of times.

I eventually tracked this down by just adding a capturing toggle event listener to the root element synchronously (from contentTheme.js, just as a temporary hack, as it's the only script we load synchronously - unlike all the module scripts we use!).

It seems this event always fires, when the element gets connected to the DOM. However, we only catch it some of the time - it seems to depend on whether the module that adds the custom handling for the custom elements has loaded and run by the time we add the node to the DOM. This usually doesn't happen, but sometimes does, which is leading to the spurious events.

I think I can work around this in the (unrelated) test in bug 1787565 for now by just clearing the telemetry events after the page loads. But of course these failures are actually revealing a real bug, that we should fix (ie there shouldn't be telemetry events for "opening" these containers on page load).

Comment 5

[:Gijs (he/him)]

I think it's kind of surprising this is how DOM works but apparently it's specced and other browsers do the same. Testcase: https://jsbin.com/badufixime/edit?html,js,output .

Comment 6

[:Gijs (he/him)]

Upping this in priority/severity because the underlying issue is an implementation one rather than a test issue, and anyway the failure rate is super high.

Comment 7

[:Gijs (he/him)]

Attachment: Bug 1788813 - do not report spurious telemetry events for the toggling of the recently closed or tab pickup lists as a result of pageload, r?sfoster,sclements

Comment 8

[Intermittent Failures Robot]

29 failures in 3537 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 22
• mozilla-central: 7

Platform and build breakdown:

• linux1804-64-qr: 5
  • debug: 2
  • opt: 3
• windows10-64-2004-qr: 4
  • opt: 4
• windows10-32-2004-qr: 2
  • opt: 2
• macosx1015-64-qr: 1
  • opt: 1
• linux1804-64-asan-qr: 5
  • opt: 5
• linux1804-64-tsan-qr: 2
  • opt: 2
• windows10-64-2004-ccov-qr: 1
  • opt: 1
• macosx1100-64-shippable-qr: 5
  • opt: 5
• linux1804-64-shippable-qr: 3
  • opt: 3
• windows10-64-2004-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1788813&startday=2022-08-29&endday=2022-09-04&tree=all

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/cc37f301f988
do not report spurious telemetry events for the toggling of the recently closed or tab pickup lists as a result of pageload, r=sclements

Comment 10

[Iulian Moraru]

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

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 9
• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 2
  • opt: 2
• windows10-64-2004-qr: 2
  • opt: 2
• linux1804-64-qr: 5
  • debug: 5
• linux1804-64-tsan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1788813&startday=2022-09-05&endday=2022-09-11&tree=all