1612903 - Perma TV browser/components/urlbar/tests/browser/browser_urlbar_interventions.js | Test timed out -

Status: RESOLVED FIXED

(Firefox :: Address Bar, defect, P3)

Description

[Treeherder Bug Filer]

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

---

[task 2020-02-03T13:35:02.015Z] 13:35:02 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_interventions.js | Refresh dialog opened - true == true -
[task 2020-02-03T13:35:02.016Z] 13:35:02 INFO - Leaving test bound refresh
[task 2020-02-03T13:35:02.016Z] 13:35:02 INFO - Entering test bound clear
[task 2020-02-03T13:35:02.017Z] 13:35:02 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_interventions.js | true == true -
[task 2020-02-03T13:35:02.017Z] 13:35:02 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_interventions.js | 7 == 7 -
[task 2020-02-03T13:35:02.018Z] 13:35:02 INFO - Buffered messages finished
[task 2020-02-03T13:35:02.018Z] 13:35:02 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_urlbar_interventions.js | Test timed out -
[task 2020-02-03T13:35:02.023Z] 13:35:02 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_urlbar_interventions.js | Shouldn't be able to reset from mochitest's temporary profile once removed from the profile manager. - true == true -
[task 2020-02-03T13:35:02.023Z] 13:35:02 INFO - GECKO(1237) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2020-02-03T13:35:02.023Z] 13:35:02 INFO - GECKO(1237) | MEMORY STAT | vsize 3053MB | residentFast 336MB | heapAllocated 112MB
[task 2020-02-03T13:35:02.023Z] 13:35:02 INFO - TEST-OK | browser/components/urlbar/tests/browser/browser_urlbar_interventions.js | took 90359ms
[task 2020-02-03T13:35:02.032Z] 13:35:02 INFO - GECKO(1237) | [Child 1424: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f834c5e9800 == 1 [pid = 1424] [id = {cc173cc4-9169-4307-b1ac-61dc6e1073e6}]
[task 2020-02-03T13:35:02.034Z] 13:35:02 INFO - GECKO(1237) | [Child 1424: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7f834e4295c0) [pid = 1424] [serial = 1] [outer = (nil)]
[task 2020-02-03T13:35:02.035Z] 13:35:02 INFO - GECKO(1237) | [Child 1424, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/workspace/build/src/layout/base/nsPresContext.cpp, line 845
[task 2020-02-03T13:35:02.036Z] 13:35:02 INFO - GECKO(1237) | [Child 1424: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7f834d071c00) [pid = 1424] [serial = 2] [outer = 0x7f834e4295c0]
[task 2020-02-03T13:35:02.036Z] 13:35:02 INFO - checking window state
[task 2020-02-03T13:35:02.038Z] 13:35:02 INFO - GECKO(1237) | [Parent 1237, Main Thread] WARNING: NS_ENSURE_TRUE(GetWrapper()) failed: file /builds/worker/workspace/build/src/dom/ipc/JSWindowActor.cpp, line 61
[task 2020-02-03T13:35:02.039Z] 13:35:02 INFO - GECKO(1237) | [Parent 1237, 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-02-03T13:35:02.040Z] 13:35:02 INFO - GECKO(1237) | [Parent 1237: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 11 (0x7fb9d35e8000) [pid = 1237] [serial = 15] [outer = 0x7fb9dacdf5c0]
[task 2020-02-03T13:35:02.040Z] 13:35:02 INFO - GECKO(1237) | [Parent 1237: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 12 (0x7fb9d3789800) [pid = 1237] [serial = 16] [outer = 0x7fb9dacdf5c0]
[task 2020-02-03T13:35:02.077Z] 13:35:02 INFO - GECKO(1237) | [Child 1392: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f7a81b15000 == 0 [pid = 1392] [id = {6f28f3cf-b938-4a0b-b405-e9ec9318a964}] [url = about:blank]
[task 2020-02-03T13:35:03.420Z] 13:35:03 INFO - GECKO(1237) | [Parent 1237: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (0x7fb9dba3e000) [pid = 1237] [serial = 7] [outer = (nil)] [url = about:blank]
[task 2020-02-03T13:35:03.727Z] 13:35:03 INFO - GECKO(1237) | [Child 1392: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7f7a82568000) [pid = 1392] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2020-02-03T13:35:03.728Z] 13:35:03 INFO - GECKO(1237) | [Child 1392: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7f7a839295c0) [pid = 1392] [serial = 1] [outer = (nil)] [url = about:blank]
[task 2020-02-03T13:35:04.106Z] 13:35:04 INFO - GECKO(1237) | [Child 1324: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7ff12e0db000 == 0 [pid = 1324] [id = {e956cbe3-8d53-46bc-b915-3df1ed312333}] [url = about:newtab]
[task 2020-02-03T13:35:04.106Z] 13:35:04 INFO - GECKO(1237) | [Child 1324: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7ff12f389e20) [pid = 1324] [serial = 4] [outer = (nil)] [url = about:newtab]
[task 2020-02-03T13:35:04.106Z] 13:35:04 INFO - GECKO(1237) | [Child 1324: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7ff12f369000) [pid = 1324] [serial = 6] [outer = (nil)] [url = about:newtab]
[task 2020-02-03T13:35:04.845Z] 13:35:04 INFO - GECKO(1237) | Completed ShutdownLeaks collections in process 1424
[task 2020-02-03T13:35:04.906Z] 13:35:04 INFO - GECKO(1237) | Completed ShutdownLeaks collections in process 1392
[task 2020-02-03T13:35:05.379Z] 13:35:05 INFO - GECKO(1237) | Completed ShutdownLeaks collections in process 1324
[task 2020-02-03T13:35:05.560Z] 13:35:05 INFO - GECKO(1237) | Completed ShutdownLeaks collections in process 1300
[task 2020-02-03T13:35:06.307Z] 13:35:06 INFO - GECKO(1237) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpkYYKsR.mozrunner/runtests_leaks_tab_pid1472.log
[task 2020-02-03T13:35:06.383Z] 13:35:06 INFO - GECKO(1237) | [Child 1472, Main Thread] WARNING: No CID found when attempting to map contract ID: file /builds/worker/workspace/build/src/xpcom/components/nsComponentManager.cpp, line 721
[task 2020-02-03T13:35:06.459Z] 13:35:06 INFO - GECKO(1237) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2020-02-03T13:35:06.539Z] 13:35:06 INFO - GECKO(1237) | [Child 1472, Main Thread] WARNING: could not set real-time limit at process startup: file /builds/worker/workspace/build/src/dom/ipc/ContentChild.cpp, line 1822
[task 2020-02-03T13:35:08.700Z] 13:35:08 INFO - GECKO(1237) | [Parent 1237: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (0x7fb9d35e8000) [pid = 1237] [serial = 15] [outer = (nil)] [url = about:blank]
[task 2020-02-03T13:35:09.262Z] 13:35:09 INFO - GECKO(1237) | Completed ShutdownLeaks collections in process 1237

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 6
• mozilla-central: 5

Platform breakdown:

• linux1804-64: 6
• linux1804-64-shippable: 3
• linux1804-64-ccov: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1612903&startday=2020-02-03&endday=2020-02-09&tree=all

Comment 2

[Harry Twyford]

This failure is what's causing the Linux perma-fail on Part 1 of the patch for bug 1613549. It appears to be an async issue with checkIntervention. I think the promises here aren't finishing correctly and it interferes with the next test that runs in browser_urlbar_interventions.js. Adding a short timeout fixes the issue, although I'll see if I can find the root cause.

Comment 3

[Harry Twyford]

I'm unassigning from this since I'll be out next week. Anyone else, please feel free to pick this up.

On the second time checkIntervention is run, it enters awaitTip. It fetches the results, successfully finds a tip result, then calls waitForAutocompleteResultAt. The test then hangs on promiseSearchComplete. In my testing, this failure is intermittent and Linux-only. I got the test to hang more reliably when applying Part 1 of the patch from bug 1613549.

Comment 4

[Marco Bonardo [:mak]]

investigating...

Comment 5

[Marco Bonardo [:mak]]

The problem is that promiseSearchComplete expects the panel to be open, but for some reason at this point it's closed. Probably we are not waiting for something that ends up closing the panel at an unexpected time. I'll try to find what causes the panel to close.

Comment 6

[Marco Bonardo [:mak]]

And the view close is caused by a blur event, somehow activated when the modal alert dialog goes away. It looks like the modal dialog causes unexpected problems and it's not enough to just wait for it to be closed.

Comment 7

[Marco Bonardo [:mak]]

Attachment: Bug 1612903 - TV failure in browser_urlbar_interventions.js. r=adw

Opening modal dialogs seems to cause focus misbehavior on Linux, run tests in new tabs to better isolate them.

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/15945e2886c2
TV failure in browser_urlbar_interventions.js. r=adw

Comment 9

[Alexandru Michis [:malexandru]]

https://hg.mozilla.org/mozilla-central/rev/15945e2886c2

Comment 10

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/releases/mozilla-beta/rev/ccba1ca23e939039941018e23b3860364742a456