Closed Bug 1608631 Opened 5 years ago Closed 5 years ago

Perma Beta TEST-UNEXPECTED-FAIL | browser_urlbar_event_telemetry.js | value in event urlbar#engagement#enter must match. - "typed" matches "returned" - JS frame :: TelemetryTestUtils.jsm :: assertEvents :: line 212 when Gecko merges to Beta on 2020-02-10

Categories

(Firefox :: Address Bar, defect, P1)

Product:
Firefox
Component:
Address Bar
Type:
defect
Points:
2

Tracking

()

Status:
VERIFIED FIXED
Milestone:
Firefox 74
Iteration:
74.1 - Jan 6 - Jan 19
Tracking Flags:
Tracking Status
firefox-esr68 --- unaffected
firefox72 --- unaffected
firefox73 --- unaffected
firefox74 --- verified

People

(Reporter: malexandru, Assigned: mak)

References

(Regression)

Details

(Keywords: regression)

Attachments

(2 files)

Bug 1608631 - Perma Beta test failure in browser_urlbar_event_telemetry.js. r=adw
47 bytes, text/x-phabricator-request
Details | Review
Bug 1608631 - Perma Beta failure in browser_urlbar_event_telemetry.js. r=adw
47 bytes, text/x-phabricator-request
Details | Review

Central as Beta simulation: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception%2Crunnable&revision=291a9ff0d936e01cac4631a3846283cb97cb40ef&searchStr=%28bc&selectedJob=284523638

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=284523638&repo=try&lineNumber=3358

[task 2020-01-11T11:00:48.457Z] 11:00:48 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | method in event urlbar#engagement#enter must match. - "engagement" matches "engagement" -
[task 2020-01-11T11:00:48.458Z] 11:00:48 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | object in event urlbar#engagement#enter must match. - "enter" matches "enter" -
[task 2020-01-11T11:00:48.459Z] 11:00:48 INFO - Buffered messages finished
[task 2020-01-11T11:00:48.459Z] 11:00:48 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | value in event urlbar#engagement#enter must match. - "typed" matches "returned" - JS frame :: resource://testing-common/TelemetryTestUtils.jsm :: assertEvents :: line 212
[task 2020-01-11T11:00:48.459Z] 11:00:48 INFO - Stack trace:
[task 2020-01-11T11:00:48.459Z] 11:00:48 INFO - resource://testing-common/TelemetryTestUtils.jsm:assertEvents:212
[task 2020-01-11T11:00:48.459Z] 11:00:48 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js:test:1020
[task 2020-01-11T11:00:48.464Z] 11:00:48 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | Actual event urlbar#engagement#enter expected to have extra. - true == true -
[task 2020-01-11T11:00:48.466Z] 11:00:48 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | Expected key elapsed must be in actual extra. Actual keys: [elapsed,numChars,selIndex,selType]. - true == true -
[task 2020-01-11T11:00:48.466Z] 11:00:48 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | extra[elapsed] must match in event urlbar#engagement#enter. - "115" matches "val => parseInt(val) > 0" -
[task 2020-01-11T11:00:48.469Z] 11:00:48 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | Expected key numChars must be in actual extra. Actual keys: [elapsed,numChars,selIndex,selType]. - true == true -
[task 2020-01-11T11:00:48.469Z] 11:00:48 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | extra[numChars] must match in event urlbar#engagement#enter. - "6" matches "6" -
[task 2020-01-11T11:00:48.471Z] 11:00:48 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | Expected key selType must be in actual extra. Actual keys: [elapsed,numChars,selIndex,selType]. - true == true -
[task 2020-01-11T11:00:48.471Z] 11:00:48 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | extra[selType] must match in event urlbar#engagement#enter. - "search" matches "search" -
[task 2020-01-11T11:00:48.471Z] 11:00:48 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | Expected key selIndex must be in actual extra. Actual keys: [elapsed,numChars,selIndex,selType]. - true == true -
[task 2020-01-11T11:00:48.472Z] 11:00:48 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | extra[selIndex] must match in event urlbar#engagement#enter. - "0" matches "0" -
[task 2020-01-11T11:00:48.473Z] 11:00:48 INFO - Running test at index 23
[task 2020-01-11T11:00:48.473Z] 11:00:48 INFO - Sanity check we are not stuck on 'returned'

Marco, could this be caused by the changes in Bug 1601362?

Flags: needinfo?(mak)

Feature not enabled in Beta, I must address the problem in the test.

Assignee: nobody → mak
Blocks: urlbar-update-1
Status: NEW → ASSIGNED
Points: --- → 2
Flags: needinfo?(mak)
Priority: -- → P1
Iteration: --- → 74.1 - Jan 6 - Jan 19

there's also a formatting bug in the telemetry documentation under Event value a few values are not on their own line.

Pushed by mak77@bonardo.net: https://hg.mozilla.org/integration/autoland/rev/d8009608e8e3 Perma Beta test failure in browser_urlbar_event_telemetry.js. r=adw

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

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox74: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 74

Reopening this bug since for today's beta sims we have new perma occurrences with the same failure:
https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed%2Cbusted%2Cexception&revision=56d2c500e446548e868a019ac60bd9ceb719b25b&selectedJob=285352595

Failure log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=285352595&repo=try&lineNumber=4645

:mak, can you please take a look?

Status: RESOLVED → REOPENED
status-firefox74: fixed → affected
tracking-firefox74: + → ---
Flags: needinfo?(mak)
Resolution: FIXED → ---
Target Milestone: Firefox 74 → ---

oh of course, browser.urlbar.update1 only applies to new windows :(

Flags: needinfo?(mak)

Run each test in a new window, to ensure tests isolation and properly support
enabling/disabling the new urlbar design.

Imported the new patch and got this new perma failure:
https://treeherder.mozilla.org/#/jobs?repo=try&selectedJob=285484255&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunnable&revision=71dd9f245d58eae3ec08ba6dbe6662ba040e32dc&searchStr=linux%2Cx64%2Cdebug%2Cmochitests%2Ctest-linux64%2Fdebug-mochitest-browser-chrome-e10s-7%2Cm%28bc7%29

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=285484255&repo=try&lineNumber=22566

[task 2020-01-18T11:53:49.185Z] 11:53:49 INFO - GECKO(3709) | nsStringStats
[task 2020-01-18T11:53:49.186Z] 11:53:49 INFO - GECKO(3709) | => mAllocCount: 178665
[task 2020-01-18T11:53:49.187Z] 11:53:49 INFO - GECKO(3709) | => mReallocCount: 0
[task 2020-01-18T11:53:49.187Z] 11:53:49 INFO - GECKO(3709) | => mFreeCount: 178665
[task 2020-01-18T11:53:49.188Z] 11:53:49 INFO - GECKO(3709) | => mShareCount: 456955
[task 2020-01-18T11:53:49.188Z] 11:53:49 INFO - GECKO(3709) | => mAdoptCount: 18330
[task 2020-01-18T11:53:49.188Z] 11:53:49 INFO - GECKO(3709) | => mAdoptFreeCount: 18792
[task 2020-01-18T11:53:49.189Z] 11:53:49 INFO - GECKO(3709) | => Process ID: 3868, Thread ID: 140078888003392
[task 2020-01-18T11:53:49.283Z] 11:53:49 INFO - GECKO(3709) | 1579348429271 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2020-01-18T11:53:49.284Z] 11:53:49 INFO - GECKO(3709) | 1579348429272 Marionette INFO Stopped listening on port 2828
[task 2020-01-18T11:53:49.284Z] 11:53:49 INFO - GECKO(3709) | 1579348429272 Marionette DEBUG Marionette stopped listening
[task 2020-01-18T11:53:50.832Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709, Main Thread] WARNING: '!mIOThread', file /builds/worker/workspace/build/src/xpcom/io/nsSegmentedBuffer.cpp, line 165
[task 2020-01-18T11:53:50.832Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709, Main Thread] WARNING: '!mIOThread', file /builds/worker/workspace/build/src/xpcom/io/nsSegmentedBuffer.cpp, line 165
[task 2020-01-18T11:53:50.888Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 13 (0x7fc1435fcd40) [pid = 3709] [serial = 405] [outer = (nil)] [url = chrome://browser/content/browser.xhtml]
[task 2020-01-18T11:53:50.889Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (0x7fc146c704c0) [pid = 3709] [serial = 393] [outer = (nil)] [url = chrome://browser/content/browser.xhtml]
[task 2020-01-18T11:53:50.905Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (0x7fc146b56000) [pid = 3709] [serial = 406] [outer = (nil)] [url = about:blank]
[task 2020-01-18T11:53:50.906Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (0x7fc14af8ac00) [pid = 3709] [serial = 394] [outer = (nil)] [url = about:blank]
[task 2020-01-18T11:53:50.907Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 9 (0x7fc17c9ad800) [pid = 3709] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2020-01-18T11:53:50.908Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 8 (0x7fc183d95100) [pid = 3709] [serial = 1] [outer = (nil)] [url = chrome://browser/content/browser.xhtml]
[task 2020-01-18T11:53:50.911Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 7 (0x7fc17255b2e0) [pid = 3709] [serial = 11] [outer = (nil)] [url = chrome://mochikit/content/browser-harness.xhtml]
[task 2020-01-18T11:53:50.912Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (0x7fc188247800) [pid = 3709] [serial = 12] [outer = (nil)] [url = about:blank]
[task 2020-01-18T11:53:50.912Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (0x7fc17b3027a0) [pid = 3709] [serial = 4] [outer = (nil)] [url = chrome://extensions/content/dummy.xhtml]
[task 2020-01-18T11:53:50.914Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (0x7fc17ad23000) [pid = 3709] [serial = 6] [outer = (nil)] [url = chrome://extensions/content/dummy.xhtml]
[task 2020-01-18T11:53:50.919Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (0x7fc17822f100) [pid = 3709] [serial = 8] [outer = (nil)] [url = resource://gre-resources/hiddenWindow.html]
[task 2020-01-18T11:53:50.920Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7fc17b3023e0) [pid = 3709] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2020-01-18T11:53:50.921Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7fc13b60cc00) [pid = 3709] [serial = 467] [outer = (nil)] [url = about:blank]
[task 2020-01-18T11:53:50.936Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7fc175eb6c00) [pid = 3709] [serial = 10] [outer = (nil)] [url = resource://gre-resources/hiddenWindow.html]
[task 2020-01-18T11:53:50.978Z] 11:53:50 INFO - GECKO(3709) | [Parent 3709, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/workspace/build/src/xpcom/base/nsCycleCollector.cpp, line 3362
[task 2020-01-18T11:53:51.055Z] 11:53:51 INFO - GECKO(3709) | nsStringStats
[task 2020-01-18T11:53:51.056Z] 11:53:51 INFO - GECKO(3709) | => mAllocCount: 1886635
[task 2020-01-18T11:53:51.056Z] 11:53:51 INFO - GECKO(3709) | => mReallocCount: 375
[task 2020-01-18T11:53:51.057Z] 11:53:51 INFO - GECKO(3709) | => mFreeCount: 1886635
[task 2020-01-18T11:53:51.057Z] 11:53:51 INFO - GECKO(3709) | => mShareCount: 2387834
[task 2020-01-18T11:53:51.057Z] 11:53:51 INFO - GECKO(3709) | => mAdoptCount: 30482
[task 2020-01-18T11:53:51.057Z] 11:53:51 INFO - GECKO(3709) | => mAdoptFreeCount: 34846
[task 2020-01-18T11:53:51.058Z] 11:53:51 INFO - GECKO(3709) | => Process ID: 3709, Thread ID: 140469563696960
[task 2020-01-18T11:53:51.072Z] 11:53:51 INFO - TEST-INFO | Main app process: exit 0
[task 2020-01-18T11:53:51.073Z] 11:53:51 INFO - TEST-INFO | Confirming we saw 735 DOCSHELL created and 735 destroyed log strings.
[task 2020-01-18T11:53:51.074Z] 11:53:51 INFO - TEST-INFO | Confirming we saw 2086 DOMWINDOW created and 2086 destroyed log strings.
[task 2020-01-18T11:53:51.074Z] 11:53:51 ERROR - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | leaked 2 window(s) until shutdown [url = about:blank]
[task 2020-01-18T11:53:51.075Z] 11:53:51 ERROR - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | leaked 2 window(s) until shutdown [url = chrome://browser/content/browser.xhtml]

Flags: needinfo?(mak)

windows leaks are a problem that may not be trivial to fix. Maybe we should just skip some of the tests if the new design is disabled.

Flags: needinfo?(mak)
Pushed by mak77@bonardo.net: https://hg.mozilla.org/integration/autoland/rev/843ac15878e8 Perma Beta failure in browser_urlbar_event_telemetry.js. r=adw

https://hg.mozilla.org/mozilla-central/rev/843ac15878e8

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
status-firefox74: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 74
Regressions: 1610342
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: