Closed Bug 1610342 Opened 5 years ago Closed 5 years ago

Intermittent browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N)

Categories

(Firefox :: Address Bar, defect, P5)

Product:
Firefox
Component:
Address Bar
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=285649058&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/OyGi57gjRKe4K4MUc9kXjw/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/OyGi57gjRKe4K4MUc9kXjw/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | Should have selected the settings button - true == true -
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - Buffered messages logged at 16:19:43
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - Leaving test bound test
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - Buffered messages finished
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - GECKO(1242) | MEMORY STAT | vsize 4178MB | residentFast 1136MB | heapAllocated 687MB
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - TEST-OK | browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | took 95888ms
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - GECKO(1242) | [Child 1393: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f279ce1d000 == 2 [pid = 1393] [id = {ed37e973-11e0-4387-a975-81d2a7f24600}]
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - GECKO(1242) | [Child 1393: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 6 (0x7f279d0c07a0) [pid = 1393] [serial = 258] [outer = (nil)]
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - GECKO(1242) | [Child 1393, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/workspace/build/src/layout/base/nsPresContext.cpp, line 845
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - GECKO(1242) | [Child 1393: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 7 (0x7f279d07f400) [pid = 1393] [serial = 259] [outer = 0x7f279d0c07a0]
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - GECKO(1242) | [Child 1393: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 8 (0x7f279d2e0800) [pid = 1393] [serial = 260] [outer = 0x7f279d0c07a0]
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - checking window state
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - GECKO(1242) | [Parent 1242, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/workspace/build/src/dom/base/nsFrameLoader.cpp, line 665
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 200 (0x7fbc3c659000) [pid = 1242] [serial = 601] [outer = 0x7fbc97ef26a0]
[task 2020-01-20T16:19:45.096Z] 16:19:45 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 201 (0x7fbc3fe17c00) [pid = 1242] [serial = 602] [outer = 0x7fbc97ef26a0]
[task 2020-01-20T16:19:45.102Z] 16:19:45 INFO - Console message: [JavaScript Error: "[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIControllers.removeController]" nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: chrome://global/content/elements/browser-custom-element.js :: destroy :: line 1374" data: no]"]
[task 2020-01-20T16:19:45.102Z] 16:19:45 INFO - destroy@chrome://global/content/elements/browser-custom-element.js:1374:28
[task 2020-01-20T16:19:45.102Z] 16:19:45 INFO - disconnectedCallback@chrome://global/content/elements/browser-custom-element.js:408:12
[task 2020-01-20T16:19:45.102Z] 16:19:45 INFO - removePreloadedBrowser@resource:///modules/NewTabPagePreloading.jsm:200:41
[task 2020-01-20T16:19:45.102Z] 16:19:45 INFO - nextTest/<@chrome://mochikit/content/browser-test.js:852:34
[task 2020-01-20T16:19:45.102Z] 16:19:45 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:808:67
[task 2020-01-20T16:19:45.102Z] 16:19:45 INFO -
[task 2020-01-20T16:19:45.102Z] 16:19:45 INFO - GECKO(1242) | [Child 1430: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fcac26b5000 == 0 [pid = 1430] [id = {9db2d88e-c1a4-449a-bb64-0a4c4bae312e}] [url = about:blank]
[task 2020-01-20T16:19:45.104Z] 16:19:45 INFO - GECKO(1242) | [Child 1393: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 7 (0x7f279d088400) [pid = 1393] [serial = 256] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:45.120Z] 16:19:45 INFO - GECKO(1242) | [Child 1393: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (0x7f279d2da800) [pid = 1393] [serial = 251] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:45.120Z] 16:19:45 INFO - GECKO(1242) | [Child 1393: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (0x7f279d2e4000) [pid = 1393] [serial = 254] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:45.120Z] 16:19:45 INFO - GECKO(1242) | [Child 1393: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f279ddd8800 == 1 [pid = 1393] [id = {f310f417-5c88-4c21-94d5-d2fc609e4112}] [url = about:blank]
[task 2020-01-20T16:19:45.237Z] 16:19:45 INFO - GECKO(1242) | [Child 1393: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (0x7f279d07f400) [pid = 1393] [serial = 259] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:45.601Z] 16:19:45 INFO - GECKO(1242) | [Child 1393: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (0x7f279d3cd3e0) [pid = 1393] [serial = 255] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:49.564Z] 16:19:49 INFO - GECKO(1242) | [Child 1393: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7f279d2f4800) [pid = 1393] [serial = 257] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:49.600Z] 16:19:49 INFO - GECKO(1242) | [Child 1430: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7fcac1b7b100) [pid = 1430] [serial = 238] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:53.562Z] 16:19:53 INFO - GECKO(1242) | [Child 1430: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7fcac1baf400) [pid = 1430] [serial = 240] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:54.575Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 200 (0x7fbc37c65c00) [pid = 1242] [serial = 560] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:54.576Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 199 (0x7fbc7ab43c00) [pid = 1242] [serial = 455] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:54.577Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc36a47800 == 27 [pid = 1242] [id = {163b51a6-af22-4142-adcc-899ee9f75533}] [url = about:about]
[task 2020-01-20T16:19:54.580Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc36f20000 == 26 [pid = 1242] [id = {e85b0e67-1ce6-4711-a11f-139039a945e2}] [url = about:blank]
[task 2020-01-20T16:19:54.581Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc3758c000 == 25 [pid = 1242] [id = {b716db3d-a3e6-4153-9822-4ff509287f58}] [url = chrome://browser/content/browser.xhtml]
[task 2020-01-20T16:19:54.582Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc36a9b000 == 24 [pid = 1242] [id = {528dd87a-ce7d-4a9f-bef6-dffa5a05573a}] [url = about:preferences#search]
[task 2020-01-20T16:19:54.583Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc51811800 == 23 [pid = 1242] [id = {20ff9e3a-02e7-48e6-961f-4c47d9a30a37}] [url = about:blank]
[task 2020-01-20T16:19:54.585Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc36a46800 == 22 [pid = 1242] [id = {ba847c5b-e736-41f3-a40a-e69e94f3b58d}] [url = about:preferences#search]
[task 2020-01-20T16:19:54.586Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc3c73b000 == 21 [pid = 1242] [id = {dd7f629b-df49-4d47-ac64-6d0fe360234b}] [url = about:blank]
[task 2020-01-20T16:19:54.588Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc37c86000 == 20 [pid = 1242] [id = {0925ca7b-6b0b-45e3-aecf-8b3e2b5a60ec}] [url = chrome://browser/content/browser.xhtml]
[task 2020-01-20T16:19:54.589Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc3d418800 == 19 [pid = 1242] [id = {e66b5e0a-aba3-4e3a-a051-cbd74a11bb1d}] [url = about:blank]
[task 2020-01-20T16:19:54.590Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc37034000 == 18 [pid = 1242] [id = {36543085-513b-4602-9a21-24b085821fe0}] [url = chrome://browser/content/browser.xhtml]
[task 2020-01-20T16:19:54.591Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc37c96000 == 17 [pid = 1242] [id = {5273cdbe-6053-468b-989e-81db1b60d7ad}] [url = about:blank]
[task 2020-01-20T16:19:54.592Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc37038000 == 16 [pid = 1242] [id = {bba4f8bf-fdfe-4a4c-9dc1-0ebfdc22aed1}] [url = chrome://browser/content/browser.xhtml]
[task 2020-01-20T16:19:54.595Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc37eac800 == 15 [pid = 1242] [id = {5ec1573b-67c1-4146-8dc6-0ddafc424361}] [url = about:blank]
[task 2020-01-20T16:19:54.596Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc36a49800 == 14 [pid = 1242] [id = {3d0b2553-36ff-42af-a919-125b311f5c48}] [url = about:preferences#search]
[task 2020-01-20T16:19:54.597Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc36a45800 == 13 [pid = 1242] [id = {866ec527-b8d2-444b-840d-969e8620e9e2}] [url = about:preferences#search]
[task 2020-01-20T16:19:54.598Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc379ce800 == 12 [pid = 1242] [id = {a66141a9-b69a-45f3-a99b-de479ac4b4e8}] [url = about:blank]
[task 2020-01-20T16:19:54.599Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc3781c000 == 11 [pid = 1242] [id = {71742ff7-03f7-43bc-ac71-5d408222b612}] [url = about:blank]
[task 2020-01-20T16:19:54.600Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc671f5000 == 10 [pid = 1242] [id = {3ca01f77-f588-49bc-ad22-58f797712189}] [url = about:about]
[task 2020-01-20T16:19:54.601Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc37c83000 == 9 [pid = 1242] [id = {2e9ead13-d7ae-43e5-9e52-41db04e43fae}] [url = chrome://browser/content/browser.xhtml]
[task 2020-01-20T16:19:54.618Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 198 (0x7fbc71f612e0) [pid = 1242] [serial = 454] [outer = (nil)] [url = chrome://browser/content/browser.xhtml]
[task 2020-01-20T16:19:54.618Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 197 (0x7fbc3782f000) [pid = 1242] [serial = 556] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:54.618Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 196 (0x7fbc3c8e8000) [pid = 1242] [serial = 552] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:54.619Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 195 (0x7fbc45803800) [pid = 1242] [serial = 544] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:54.619Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 194 (0x7fbc3716c000) [pid = 1242] [serial = 548] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:54.619Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 193 (0x7fbc3cbd1c40) [pid = 1242] [serial = 555] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:54.619Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 192 (0x7fbc45ec0b60) [pid = 1242] [serial = 551] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:54.619Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 191 (0x7fbc3dbed4c0) [pid = 1242] [serial = 543] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:54.619Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 190 (0x7fbc44bb1200) [pid = 1242] [serial = 547] [outer = (nil)] [url = about:blank]
[task 2020-01-20T16:19:54.634Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc3804f000 == 8 [pid = 1242] [id = {ba6a244d-3e7b-4125-b7d3-4500bdc456c5}] [url = about:preferences#search]
[task 2020-01-20T16:19:54.641Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc1e604000 == 7 [pid = 1242] [id = {de9ed415-15a5-4a86-a2bf-b377f5aa2ae9}] [url = about:preferences#search]
[task 2020-01-20T16:19:54.649Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc3760d000 == 6 [pid = 1242] [id = {c8184e84-7ec2-496c-83d6-df5ff3d3c4e2}] [url = about:blank]
[task 2020-01-20T16:19:54.649Z] 16:19:54 INFO - GECKO(1242) | [Parent 1242: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fbc1e602800 == 5 [pid = 1242] [id = {f4368d03-b076-47ec-9e46-4e7c1d87d8b4}] [url = about:blank]
[task 2020-01-20T16:20:03.367Z] 16:20:03 INFO - GECKO(1242) | [Child 1329: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f55173e3000 == 0 [pid = 1329] [id = {fac24d10-acd8-4326-9408-1e2998a9f64d}] [url = about:newtab]
[task 2020-01-20T16:20:03.367Z] 16:20:03 INFO - GECKO(1242) | [Child 1329: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7f55187a7e20) [pid = 1329] [serial = 4] [outer = (nil)] [url = about:newtab]
[task 2020-01-20T16:20:03.367Z] 16:20:03 INFO - GECKO(1242) | [Child 1329: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7f55186ce800) [pid = 1329] [serial = 6] [outer = (nil)] [url = about:newtab]

Summary: Intermittent [TV] browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - → Intermittent [tier2] browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N)

Marco,
This looks to be caused by the changes in Bug 1608631, could you please take a look?

Flags: needinfo?(mak)

Yes, it's due to opening new windows, the test is just taking a longer time, but I'm already changing the test in bug 1601052, that should resolve this.

Depends on: 1601052
Flags: needinfo?(mak)
Regressed by: 1608631
Has Regression Range: --- → yes
Keywords: regression

Started appearing on tier 1 jobs: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=286987821&repo=autoland&lineNumber=26952

Summary: Intermittent [tier2] browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N) → Intermittent browser/components/urlbar/tests/browser/browser_urlbar_event_telemetry.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N)

(In reply to Edwin Takahashi (:egao | PTO from 02/01 - 03/01) from comment #6)

This test appears to be failing either permanently or at a very high rate of intermittence on linux1804 platforms:
https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&selectedJob=286996019&tier=1%2C2%2C3&revision=d5c37e500ca106bd0eaa869528f85e1376b8b58b

There's a patch that might fix this here https://bugzilla.mozilla.org/show_bug.cgi?id=1601052#c14

:apavel - thanks for the heads up!

Depends on: 1617603

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
You need to log in before you can comment on or make changes to this bug.