Closed Bug 1532738 Opened 7 months ago Closed 4 months ago

Intermittent 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

Categories

(Firefox :: Address Bar, defect, P2)

defect
Points:
3

Tracking

()

RESOLVED FIXED
Firefox 68
Iteration:
68.2 - Apr 1 - 14
Tracking Status
firefox-esr60 --- unaffected
firefox66 --- unaffected
firefox67 --- wontfix
firefox68 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: mak)

References

(Blocks 2 open bugs)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered][stockwell disable-recommended])

Attachments

(1 file)

#[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

Summary: Intermittent [TV] 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 → Intermittent 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
Blocks: 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.

Priority: P5 → P2
Assignee: nobody → dao+bmo
Status: NEW → ASSIGNED

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

Whiteboard: [retriggered] → [retriggered] [stockwell needswork]

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

Flags: needinfo?(dao+bmo)
Whiteboard: [retriggered] [stockwell disable-recommended] → [retriggered] [stockwell needswork]
Points: --- → 3
Whiteboard: [retriggered] [stockwell disable-recommended] → [retriggered] [stockwell needswork]

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

Flags: needinfo?(mak77)
Whiteboard: [retriggered] [stockwell disable-recommended] → [retriggered][stockwell needswork:owner]

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.

Assignee: dao+bmo → mak77
Flags: needinfo?(dao+bmo)

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.

Flags: needinfo?(mak77)
Keywords: leave-open
Blocks: 1541806
Pushed by mak77@bonardo.net:
https://hg.mozilla.org/integration/autoland/rev/278767179a87
Fix the expected outcome of browser_caret_navigation.js. r=dao
Keywords: leave-open
Status: ASSIGNED → RESOLVED
Closed: 6 months ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 68

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

Status: RESOLVED → REOPENED
Flags: needinfo?(mak77)
Resolution: FIXED → ---
Target Milestone: Firefox 68 → ---
Flags: needinfo?(mak77)

ah, MacOS, of course.

Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell needswork:owner]

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.

Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell needswork]
Pushed by mak77@bonardo.net:
https://hg.mozilla.org/integration/autoland/rev/b1741ada6397
Fix the expected outcome of browser_caret_navigation.js. r=dao
Status: REOPENED → RESOLVED
Closed: 6 months ago5 months ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 68

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

Flags: needinfo?(mak77)

(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.

Flags: needinfo?(mak77)

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

Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Target Milestone: Firefox 68 → ---

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.

Status: REOPENED → RESOLVED
Closed: 5 months ago4 months ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 68
Iteration: --- → 68.2 - Apr 1 - 14
You need to log in before you can comment on or make changes to this bug.