#[markdown(off)]
Filed by: cbrindusan [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=231939103&repo=autoland

https://queue.taskcluster.net/v1/task/DfpZqC92Sry6PQf06zA4jg/runs/0/artifacts/public/logs/live_backing.log

17:32:08 INFO - TEST-START | browser/components/urlbar/tests/browser/browser_caret_navigation.js
17:32:08 INFO - GECKO(5480) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1551804626\appdata\local\temp\tmpzopzor.mozrunner\runtests_leaks_tab_pid8072.log
17:32:08 INFO - GECKO(5480) | ++DOCSHELL 0000017F93C4C800 == 1 [pid = 8072] [id = {8b76e724-88d9-4494-b8b6-5b447567779a}]
17:32:08 INFO - GECKO(5480) | ++DOMWINDOW == 1 (0000017F994F4020) [pid = 8072] [serial = 1] [outer = 0000000000000000]
17:32:08 INFO - GECKO(5480) | [Parent 8688, Main Thread] WARNING: '!parent', file z:/build/build/src/netwerk/ipc/NeckoParent.cpp, line 956
17:32:08 INFO - GECKO(5480) | ++DOMWINDOW == 2 (0000017F99481800) [pid = 8072] [serial = 2] [outer = 0000017F994F4020]
17:32:08 INFO - GECKO(5480) | ++DOMWINDOW == 3 (0000017F9B26DC00) [pid = 8072] [serial = 3] [outer = 0000017F994F4020]
17:32:08 INFO - GECKO(5480) | [Parent 8688, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/startupcache/StartupCacheUtils.cpp, line 157
17:32:08 INFO - TEST-INFO | started process screenshot
17:32:08 INFO - TEST-INFO | screenshot: exit 0
17:32:08 INFO - Buffered messages logged at 17:32:08
17:32:08 INFO - Entering test bound
17:32:08 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_caret_navigation.js | KEY_ArrowDown: Should have started a query - true == true -
17:32:08 INFO - Console message: [JavaScript Warning: "Key event not available on some keyboard layouts: key=“i” modifiers=“accel,alt,shift” id=“key_browserToolbox”" {file: "chrome://mochikit/content/tests/SimpleTest/EventUtils.js" line: 869}]
17:32:08 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_caret_navigation.js | KEY_ArrowDown: Heuristic result should be selected - 0 == 0 -
17:32:08 INFO - Buffered messages finished
17:32:08 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_caret_navigation.js | KEY_ArrowDown: Input selection should be empty - 3 == 10 - JS frame :: chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_caret_navigation.js :: checkPopupOpens :: line 53

Retriggered: https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&searchStr=windows%2C10%2Cx64%2Cccov%2Cdebug%2Cmochitests%2Cwith%2Ce10s%2Ctest-windows10-64-ccov%2Fdebug-mochitest-browser-chrome-e10s-3%2Cm-e10s%28bc3%29&tochange=bd68f490ca078d2b7a5a10f47b2f9d5f1abbdbc4&fromchange=325cacd860797a527eddfb6652984169a3882523

At first, this failure was for Test-verify, then moved to [tier1]:
https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=231939103&revision=2ee118b40f31cc0b201e26a32135581b33329697

The culprit seems to be https://bugzilla.mozilla.org/show_bug.cgi?id=1525910

(In reply to Cristina Coroiu [:ccoroiu] from comment #1)

The culprit seems to be https://bugzilla.mozilla.org/show_bug.cgi?id=1525910

That's just the bug where the test was added.

There are 71 failures associated to this bug in the last 7 days. These are occurring on windows10-64 and windows7-32 debug builds.

Recent log: https://treeherder.mozilla.org/logviewer.html#?job_id=233135958&repo=autoland

Over the last 7 days this bug has 61 failures, these happen on windows10-64, windows7-32, windows10-64-ccov

Here is the latest failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=235662520&repo=autoland&lineNumber=20661

Hello,

Marco, Dao can you please take a look at this?
This is still failing on windows10-64, windows7-32, windows10-64-ccov platforms, debug build type.
In the last 30 days has failed 271 times and it is on disable recommended list.

Thank you

Apparently I can reproduce the bug locally in a --verify, I'll have a look in the next days to see if I can help.

I don't understand the test on Windows, checkPopupOpens should check the selection doesn't change, we start from [3,10] and on Windows pressing down/up to open the popup is not supposed to change the selection. The test instead checks the selection goes away. This should be a permanent failure, but sometimes the caret jumps to the end as the test expects.

That intermittent behavior is probably due to the fact the event bufferer delays handling of the down key, and by doing that it also delays the call to preventDefault(). preventDefault() won't work properly in controller's handleKeyNavigation. We could make the bufferer preventDefault() any delayed event, though that could mean to reimplement default behaviors. From a quick test on Windows it doesn't seem to break things, but it would be better to make that change sooner than later if we want it.

Because the bufferer problem is complex, for now I'll fix the test expected outcome and disable it on Windows. It will still require a patch for the preventDefault problem, but for now I don't have a clear idea on how to do it. That said we can remove some failure noise from the tree since we know what causes the failure.

https://hg.mozilla.org/mozilla-central/rev/278767179a87

Backed out changeset 278767179a87 for turning Bug 1352679 into permafail.

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&fromchange=625e9335159cefd680bfd517ac7c3310b80a9bf8&searchStr=os%2Cx%2C10.10%2Cshippable%2Copt%2Cmochitests%2Cwith%2Ce10s%2Ctest-macosx64-shippable%2Fopt-mochitest-browser-chrome-e10s-2%2Cm-e10s%28bc2%29&tochange=2c261b95d855b3f61595342fdce6cd64fd1f1cc1

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=238112838&repo=autoland&lineNumber=5372

Backout link: https://hg.mozilla.org/integration/autoland/rev/ca7e5845a89512d93f2106b33d94ab9006230e76

12:17:42 INFO - TEST-OK | browser/components/urlbar/tests/browser/browser_autocomplete_tag_star_visibility.js | took 1078ms
12:17:42 INFO - checking window state
12:17:42 INFO - TEST-START | browser/components/urlbar/tests/browser/browser_canonizeURL.js
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: http://www.example.com/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:http://www.example.com/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: http://www.example.com/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: http://example.com/test/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:http://example.com/test/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: http://example.com/test/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: http://www.ex-ample.com/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:http://www.ex-ample.com/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: http://www.ex-ample.com/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: http://www.example.com/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:http://www.example.com/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: http://www.example.com/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: http://www.example.com/foo
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:http://www.example.com/foo
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: http://www.example.com/foo
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: http://www.example.com/foo%20bar
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:http://www.example.com/foo%20bar
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: http://www.example.com/foo%20bar
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: http://example.net/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:http://example.net/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: http://example.net/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: http://example/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:http://example/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: http://example/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: http://example:8080/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:http://example:8080/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: http://example:8080/
12:17:42 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: http://ex-ample.foo/
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:http://ex-ample.foo/
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: http://ex-ample.foo/
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: http://example.foo/bar
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:http://example.foo/bar
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: http://example.foo/bar
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: http://1.1.1.1/
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:http://1.1.1.1/
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: http://1.1.1.1/
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: ftp://example/
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:ftp://example/
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: ftp://example/
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: http://ftp.example.bar/
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:http://ftp.example.bar/
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: http://ftp.example.bar/
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Waiting for URL: https://www.google.com/search?client=firefox-b-1-d&q=ex+ample
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: onStateChange f0001:https://www.google.com/search?client=firefox-b-1-d&q=ex+ample
12:17:43 INFO - GECKO(1082) | waitForDocLoadAndStopIt: Document start: https://www.google.com/search?client=firefox-b-1-d&q=ex+ample
12:18:27 INFO - TEST-INFO | started process screencapture
12:18:27 INFO - TEST-INFO | screencapture: exit 0
12:18:27 INFO - Buffered messages logged at 12:17:42
12:18:27 INFO - Entering test bound checkCtrlWorks
12:18:27 INFO - Testing input string: "example" - expected: "http://www.example.com/"
12:18:27 INFO - Testing input string: "http://example.com/test/" - expected: "http://example.com/test/"
12:18:27 INFO - Testing input string: "ex-ample" - expected: "http://www.ex-ample.com/"
12:18:27 INFO - Testing input string: " example " - expected: "http://www.example.com/"
12:18:27 INFO - Testing input string: " example/foo " - expected: "http://www.example.com/foo"
12:18:27 INFO - Testing input string: " example/foo bar " - expected: "http://www.example.com/foo%20bar"
12:18:27 INFO - Testing input string: "example.net" - expected: "http://example.net/"
12:18:27 INFO - Testing input string: "http://example" - expected: "http://example/"
12:18:27 INFO - Testing input string: "example:8080" - expected: "http://example:8080/"
12:18:27 INFO - Testing input string: "ex-ample.foo" - expected: "http://ex-ample.foo/"
12:18:27 INFO - Buffered messages logged at 12:17:43
12:18:27 INFO - Testing input string: "example.foo/bar " - expected: "http://example.foo/bar"
12:18:27 INFO - Testing input string: "1.1.1.1" - expected: "http://1.1.1.1/"
12:18:27 INFO - Testing input string: "ftp://example" - expected: "ftp://example/"
12:18:27 INFO - Testing input string: "ftp.example.bar" - expected: "http://ftp.example.bar/"
12:18:27 INFO - Testing input string: "ex ample" - expected: "https://www.google.com/search?client=firefox-b-1-d&q=ex+ample"
12:18:27 INFO - Leaving test bound checkCtrlWorks
12:18:27 INFO - Entering test bound checkPrefTurnsOffCanonize
12:18:27 INFO - Console message: [JavaScript Error: "Security Error: Content at about:newtab may not load or link to chrome://mozapps/skin/places/defaultFavicon.svg."]
12:18:27 INFO - Console message: [JavaScript Error: "Security Error: Content at about:newtab may not load or link to chrome://mozapps/skin/places/defaultFavicon.svg."]
12:18:27 INFO - Buffered messages finished
12:18:27 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_canonizeURL.js | Test timed out -
12:18:27 INFO - GECKO(1082) | MEMORY STAT | vsize 4547MB | residentFast 371MB | heapAllocated 123MB
12:18:27 INFO - TEST-OK | browser/components/urlbar/tests/browser/browser_canonizeURL.js | took 45051ms

interesting, my Try run didn't show that ;(
https://treeherder.mozilla.org/#/jobs?repo=try&revision=a5b64fc31e4fe1b2c549110f00ece35b8754aa1d

ah, MacOS, of course.

The reason browser_canonizeURL fails is because it's wrong. On the Mac canonization happens on ctrl+Enter, if it's disabled ctrl+enter is supposed to just load in the current tab. The test instead is testing CMD+enter on Mac, that we preventDefault here https://searchfox.org/mozilla-central/rev/6db0a6a56653355fcbb25c4fa79c6e7ffc6f88e9/browser/components/urlbar/UrlbarController.jsm#274 and thus the test just hangs waiting for a tab that is not supposed to exist.
Currently this works just because we delay the preventDefault call... Fwiw that beep prevention code doesn't seem to be necessary on today's MacOS, but I'll file a bug apart for that, the important thing here is that the test must be fixed to use ctrl+Enter.

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

Looks like these failures occasionally hit Beta too. Is this worth backport consideration?

(In reply to Ryan VanderMeulen [:RyanVM] from comment #28)

Looks like these failures occasionally hit Beta too. Is this worth backport consideration?

There should be no big risk considered the Quantum Bar is disabled, though not all the QB code is in Beta, so we should first verify if applying this patch would cause different test failures. Not sure it's worth the time if the failures are not very frequent.

Fail reappeared on beta.
Log link: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=245610520&repo=mozilla-beta&lineNumber=54553

Log snippet:

20:15:07 INFO - GECKO(10232) | --DOCSHELL 000001C0B470E800 == 3 [pid = 3988] [id = {cd1994b8-8a6d-4b33-8b8b-252af3d0320d}] [url = about:blank]
20:15:08 INFO - GECKO(10232) | [Parent 4536, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/startupcache/StartupCacheUtils.cpp, line 157
20:15:08 INFO - TEST-INFO | started process screenshot
20:15:08 INFO - TEST-INFO | screenshot: exit 0
20:15:08 INFO - Buffered messages logged at 20:15:07
20:15:08 INFO - Entering test bound
20:15:08 INFO - Buffered messages logged at 20:15:08
20:15:08 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_caret_navigation.js | KEY_ArrowDown: Should have started a query - true == true -
20:15:08 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_caret_navigation.js | KEY_ArrowDown: Heuristic result should be selected - 0 == 0 -
20:15:08 INFO - Buffered messages finished
20:15:08 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_caret_navigation.js | KEY_ArrowDown: Input selection should be empty - 3 == 10 - JS frame :: chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_caret_navigation.js :: checkPopupOpens :: line 53
20:15:08 INFO - Stack trace:
20:15:08 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_caret_navigation.js:checkPopupOpens:53
20:15:08 INFO - Not taking screenshot here: see the one that was previously logged
20:15:08 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_caret_navigation.js | KEY_ArrowDown: Caret is at the expected position - 3 == 26 - JS frame :: chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_caret_navigation.js :: checkPopupOpens :: line 54
20:15:08 INFO - Stack trace:
20:15:08 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_caret_navigation.js:checkPopupOpens:54
20:15:08 INFO - GECKO(10232) | [Parent 4536, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/startupcache/StartupCacheUtils.cpp, line 157
20:15:08 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_caret_navigation.js | KEY_ArrowUp: Should have started a query - true == true -
20:15:08 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_caret_navigation.js | KEY_ArrowUp: Heuristic result should be selected - 0 == 0 -
20:15:08 INFO - Not taking screenshot here: see the one that was previously logged
20:15:08 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_caret_navigation.js | KEY_ArrowUp: Input selection should be empty - 3 == 10 - JS frame :: chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_caret_navigation.js :: checkPopupOpens :: line 53
20:15:08 INFO - Stack trace:
20:15:08 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_caret_navigation.js:checkPopupOpens:53
20:15:08 INFO - Not taking screenshot here: see the one that was previously logged
20:15:08 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_caret_navigation.js | KEY_ArrowUp: Caret is at the expected position - 3 == 26 - JS frame :: chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_caret_navigation.js :: checkPopupOpens :: line 54
20:15:08 INFO - Stack trace:
20:15:08 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_caret_navigation.js:checkPopupOpens:54
20:15:08 INFO - GECKO(10232) | [Parent 4536, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/startupcache/StartupCacheUtils.cpp, line 157
20:15:08 INFO - Leaving test bound
20:15:08 INFO - GECKO(10232) | MEMORY STAT | vsize 2103386MB | vsizeMaxContiguous 66491056MB | residentFast 482MB | heapAllocated 179MB
20:15:08 INFO - TEST-OK | browser/components/urlbar/tests/browser/browser_caret_navigation.js | took 638ms

It actually never disappeared in beta, see comment 28. It was clearly marked as a wontfix on 67, and afaik we didn't merge to 68 yet.