1648468 - Split UrlbarProviderAutofill out from UnifiedComplete

Status: RESOLVED FIXED

(Firefox :: Address Bar, task, P3)

Comment 1

[Harry Twyford]

The scope of this patch grew quite large. I was originally splitting the points between this and bug 1649162, but a lot of the work from that patch moved here. See bug 1649162 comment 3.

Comment 2

[Harry Twyford]

Attachment: Bug 1648468 - Part 1 - Create UrlbarProviderAutofill.jsm.

Depends on D82233

Comment 3

[Harry Twyford]

Attachment: Bug 1648468 - Part 2 - Dedupe results matching autofill in the muxer.

Depends on D82234

Comment 4

[Harry Twyford]

Attachment: Bug 1648468 - Part 3 - Allow UrlbarProviderTokenAliasEngines to provide its own heuristic result.

Depends on D82235

Comment 5

[Harry Twyford]

Attachment: Bug 1648468 - Part 4 - Port autofill unit tests to browser/components/urlbar.

Depends on D82236

Comment 6

[Harry Twyford]

Attachment: Bug 1648468 - Part 5 - Move some deduping code from UnifiedComplete to the UrlbarMuxer.

Depends on D82237

Comment 7

[Drew Willcoxon :adw]

Attachment: debug.diff

This patch has some logging in a11y and urlbar that helped me track down the browser_test_focus_urlbar.js hang due to the part-1 patch. I'm posting it in case it's useful. It also has a two-line fix (described below at the end).

The problem is that the aria-activedescendant attribute on the input ends up with an ID that does not exist. The a11y path ends up here: https://searchfox.org/mozilla-central/rev/622dbd3409610ad3f71b56c9a6a92da905dab0aa/accessible/generic/DocAccessible.cpp#1078 At that point in the test, the input is focused, and so DocAccessible::ARIAActiveDescendantChanged sees that the ID doesn't exist and it focuses the input again, but the test expects the first result to be focused.

aria-activedescendant ends up wrong because we change the ID of the heuristic row but then don't update the corresponding ID in aria-activedescendant due to the fact that there's a selected element. And this happens currently, even without the autofill patches.

This is what happens when part 1 is applied:

1. Test presses the down arrow key (starting here)
2. onQueryResults is called with a heuristic from Autofill and a non-heuristic from HeuristicFallback. (Strangely the Autofill result doesn't trigger a call to _notifyResultsFromProvider. That seems wrong. Because of how it adds its result in isActive? I didn't investigate. So what ends up triggering this call to onQueryResults is the heuristic timer timing out. HeuristicFallback and UnifiedComplete do trigger calls to _notifyResultsFromProvider, as expected.)
3. onQueryResults is called again with two more non-heuristic results from UnifiedComplete.
4. onQueryResults calls _updateResults
5. _updateResults changes the row ID of the heuristic (via _updateRow)
6. _selectedElement remains the heuristic row (which is right), so onQueryResults does not update the selected result. But now the ID in aria-activedescendant does not exist, and because the selected result isn't updated, aria-activedescendant remains wrong.
7. a11y focus event fires, and since the ID in aria-activedescendant doesn't exist, the focus remains in the input
8. The test hangs waiting for the heuristic to be focused

Without part 1, the difference is that the focus event fires before aria-activedescendant becomes wrong. I don't know why. (I didn't track down how DocAccessible::ARIAActiveDescendantChanged is called.) But I'm not sure it's important because we expect some timing differences with the autofill patch applied, and we still end up with the wrong aria-activedescendant. It just doesn't mess up the test. Steps without part 1:

1. Test presses the down arrow key
2. onQueryResults is called with a heuristic from UnifiedComplete and a non-heuristic from HeuristicFallback
3. a11y focus event fires, changing the focus from the input to the heuristic, and the test has a PASS for this ("Received focus event")
4. onQueryResults is called again with a non-heuristic from UnifiedComplete
5. onQueryResults calls _updateResults
6. _updateResults changes the row ID of the heuristic (via _updateRow)
7. _selectedElement remains the heuristic row (which is right), so onQueryResults does not update the selected result. But now the ID in aria-activedescendant does not exist, and because the selected result isn't updated, aria-activedescendant remains wrong.
8. Somehow this doesn't mess anything up! The test continues and passes

So afaict this has always been wrong. We've always changed the heuristic row ID while it's selected and then not updated aria-activedescendant.

The fix I have for this in the patch is to set the heuristic row ID back to the old ID after _updateRow is called on it. (This line is commented out in the patch so I could reproduce the hang while verifying the fix.) Without thinking about it more, I'm not sure whether that's a proper fix or not. We'd need to look into whether it's OK to use the same ID over multiple queries.

I also added calls to Cu.reportError in onQueryResults if there's a selected result but its ID doesn't match aria-activedescendant. We should have something like that.

Comment 8

[Drew Willcoxon :adw]

Attachment: debug.diff log with part 1 applied

Here's a log with debug.diff and patch 1 applied. It's hard to read but I thought I'd post it in case it's useful. The end is where the test hangs. I switched to my terminal and hit Ctrl-C to kill the test. That's the FocusManager::NotifyOfDOMBlur call near the end.

Comment 9

[Drew Willcoxon :adw]

Attachment: debug.diff log without part 1 applied

This is without part 1 applied. I modified the test so it artificially hangs at the same spot to make the logs easier to compare.

Comment 10

[Drew Willcoxon :adw]

(In reply to Drew Willcoxon :adw from comment #7)

The fix I have for this in the patch is to set the heuristic row ID back to the old ID after _updateRow is called on it.

This should probably happen for the currently selected row, not the heuristic in particular.

Another way to fix this would be to force aria-activedescendant to be the selected ID in onQueryResults, instead of having only checks like I suggested earlier. Not sure which is better.

Comment 11

[Harry Twyford]

Thank you for this very thorough investigation!

(In reply to Drew Willcoxon :adw from comment #7)

2. onQueryResults is called with a heuristic from Autofill and a non-heuristic from HeuristicFallback. (Strangely the Autofill result doesn't trigger a call to _notifyResultsFromProvider. That seems wrong. Because of how it adds its result in isActive? I didn't investigate. So what ends up triggering this call to onQueryResults is the heuristic timer timing out. HeuristicFallback and UnifiedComplete do trigger calls to

This is strange. I added a log statement to the beginning of _notifyResultsFromProvider and Autofill seems to hit it whenever it returns a result. Maybe the timing is different between our machines? I don't think it fetching its result in isActive would be the cause; it returns the result in startQuery, albeit very quickly.

(In reply to Drew Willcoxon :adw from comment #10)

This should probably happen for the currently selected row, not the heuristic in particular.

Another way to fix this would be to force aria-activedescendant to be the selected ID in onQueryResults, instead of having only checks like I suggested earlier.

I'm in favour of this approach. I don't think we want to mess with the uniqueness of the IDs. I'll post a patch so we can continue discussion in more detail there.

Comment 12

[Harry Twyford]

Attachment: Bug 1648468 - Part 6 - Resolve a11y focus issue causing a failure in browser_test_focus_urlbar.js. r?adw!

The line that adds suggestedIndex in the test should also fix bug 1652138.

Comment 13

[Harry Twyford]

With part 6 applied: https://treeherder.mozilla.org/#/jobs?repo=try&revision=f66e08dbd5072eb21b7c39a083bd6e32717d73e1

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/69a210ce0e9a
Part 1 - Create UrlbarProviderAutofill.jsm. r=adw
https://hg.mozilla.org/integration/autoland/rev/10447a3e04ff
Part 2 - Dedupe results matching autofill in the muxer. r=adw
https://hg.mozilla.org/integration/autoland/rev/bb37a0821844
Part 3 - Allow UrlbarProviderTokenAliasEngines to provide its own heuristic result. r=adw
https://hg.mozilla.org/integration/autoland/rev/97c7475abf85
Part 4 - Port autofill unit tests to browser/components/urlbar. r=adw
https://hg.mozilla.org/integration/autoland/rev/fc7a6b8f84a2
Part 5 - Move some deduping code from UnifiedComplete to the UrlbarMuxer. r=adw,mak
https://hg.mozilla.org/integration/autoland/rev/60b6915e8037
Part 6 - Resolve a11y focus issue causing a failure in browser_test_focus_urlbar.js. r=adw

Comment 15

[Razvan Maries]

Backed out for perma failures.

Push with failure: https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedTaskRun=DYZCz3hnRaOFo6es6tk7Hw.0&resultStatus=testfailed%2Cbusted%2Cexception&revision=60b6915e80372d04839514e1cef668c9e311e21a&failure_classification_id=2

Logs:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=309461727&repo=autoland&lineNumber=1175
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=309464666&repo=autoland&lineNumber=2645

Backout: https://hg.mozilla.org/integration/autoland/rev/9d9c973b0043c704c79cc789c58441ded6ce8583

Comment 16

[Harry Twyford]

I fixed the cause of the backout. New try is green: https://treeherder.mozilla.org/#/jobs?repo=try&revision=c77318c3167a7be88c912e79f46688c2c68ccbcc

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ebac9fb9da0d
Part 1 - Create UrlbarProviderAutofill.jsm. r=adw
https://hg.mozilla.org/integration/autoland/rev/1edf02398318
Part 2 - Dedupe results matching autofill in the muxer. r=adw
https://hg.mozilla.org/integration/autoland/rev/60a36d4424df
Part 3 - Allow UrlbarProviderTokenAliasEngines to provide its own heuristic result. r=adw
https://hg.mozilla.org/integration/autoland/rev/3bded27be98e
Part 4 - Port autofill unit tests to browser/components/urlbar. r=adw
https://hg.mozilla.org/integration/autoland/rev/91a4b5b593bf
Part 5 - Move some deduping code from UnifiedComplete to the UrlbarMuxer. r=adw,mak
https://hg.mozilla.org/integration/autoland/rev/918db5010acb
Part 6 - Resolve a11y focus issue causing a failure in browser_test_focus_urlbar.js. r=adw

Comment 18

[Natalia Csoregi [:nataliaCs]]

Backed out for failures on test_keywords.js

backout: https://hg.mozilla.org/integration/autoland/rev/bd511bc456e4d8f26892e2229c670e53a016efec

push: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=linux%2C18.04%2Cx64%2Ctsan%2Copt%2Cxpcshell%2Ctests%2Ctest-linux1804-64-tsan%2Fopt-xpcshell-e10s-5%2Cx%28x5%29&revision=918db5010acbe863b1ff4da0ede5bcc62dd2c9ea&selectedTaskRun=JpQicKNRRcWlkUff8eHQyw.0

failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=309481968&repo=autoland&lineNumber=2528

[task 2020-07-12T05:55:46.250Z] 05:55:46 INFO - TEST-START | browser/components/urlbar/tests/unit/test_keywords.js
[task 2020-07-12T05:55:58.872Z] 05:55:58 WARNING - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/unit/test_keywords.js | xpcshell return code: 0
[task 2020-07-12T05:55:58.872Z] 05:55:58 INFO - TEST-INFO took 12618ms
[task 2020-07-12T05:55:58.873Z] 05:55:58 INFO - >>>>>>>
[task 2020-07-12T05:55:58.873Z] 05:55:58 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-07-12T05:55:58.873Z] 05:55:58 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-07-12T05:55:58.873Z] 05:55:58 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-07-12T05:55:58.873Z] 05:55:58 INFO - running event loop
[task 2020-07-12T05:55:58.873Z] 05:55:58 INFO - browser/components/urlbar/tests/unit/test_keywords.js | Starting initXPCShellDependencies
[task 2020-07-12T05:55:58.873Z] 05:55:58 INFO - (xpcshell/head.js) | test initXPCShellDependencies pending (2)
[task 2020-07-12T05:55:58.874Z] 05:55:58 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2020-07-12T05:55:58.874Z] 05:55:58 INFO - (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2020-07-12T05:55:58.874Z] 05:55:58 INFO - (xpcshell/head.js) | test initXPCShellDependencies finished (2)
[task 2020-07-12T05:55:58.874Z] 05:55:58 INFO - browser/components/urlbar/tests/unit/test_keywords.js | Starting setup
[task 2020-07-12T05:55:58.874Z] 05:55:58 INFO - (xpcshell/head.js) | test setup pending (2)
[task 2020-07-12T05:55:58.874Z] 05:55:58 INFO - (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2020-07-12T05:55:58.874Z] 05:55:58 INFO - "Adding engine: engine-suggestions.xml"
[task 2020-07-12T05:55:58.874Z] 05:55:58 INFO - "Adding engine from URL: http://localhost:9000/data/engine-suggestions.xml"
[task 2020-07-12T05:55:58.875Z] 05:55:58 INFO - PID 13484 | console.error: SearchCache: "_readCacheFile: Error reading cache file:" (new Error("", "(unknown module)"))
[task 2020-07-12T05:55:58.875Z] 05:55:58 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "DEPRECATION WARNING: Calling FileUtils.getDir(..., ..., true) causes main thread I/O and should be avoided especially during startup/shutdown
[task 2020-07-12T05:55:58.875Z] 05:55:58 INFO - You may find more details about this deprecation at: https://bugzilla.mozilla.org/show_bug.cgi?id=921157
[task 2020-07-12T05:55:58.875Z] 05:55:58 INFO - resource://gre/modules/FileUtils.jsm 81 FileUtils_getDir
[task 2020-07-12T05:55:58.875Z] 05:55:58 INFO - resource://gre/modules/ExtensionPermissions.jsm 137 _init
[task 2020-07-12T05:55:58.875Z] 05:55:58 INFO - resource://gre/modules/ExtensionPermissions.jsm 146 lazyInit
[task 2020-07-12T05:55:58.875Z] 05:55:58 INFO - resource://gre/modules/ExtensionPermissions.jsm 218 get
[task 2020-07-12T05:55:58.875Z] 05:55:58 INFO - resource://gre/modules/ExtensionPermissions.jsm 266 _get
[task 2020-07-12T05:55:58.876Z] 05:55:58 INFO - resource://gre/modules/ExtensionPermissions.jsm 271 _getCached/<
[task 2020-07-12T05:55:58.876Z] 05:55:58 INFO - resource://gre/modules/ExtensionParent.jsm 1829 get
[task 2020-07-12T05:55:58.876Z] 05:55:58 INFO - /builds/worker/workspace/build/tests/xpcshell/head.js 248 _do_main
[task 2020-07-12T05:55:58.877Z] 05:55:58 INFO - /builds/worker/workspace/build/tests/xpcshell/head.js 577 _execute_test
[task 2020-07-12T05:55:58.877Z] 05:55:58 INFO - -e 1 null

Comment 19

[Harry Twyford]

Attachment: Bug 1648468 - Part 7 - Temporarily disable test_keywords.js on Linux to resolve bug 1474616. r?mak

Comment 20

[Harry Twyford]

I'm going to temporarily disable the broken test on Linux. The failures are intermittent, and the behaviour being tested appears to work reliably in real-life scenarios. I'll fix the test ASAP, just this is a very large stack of patches and will quickly bitrot if left unlanded for some time. Try looks good: https://treeherder.mozilla.org/#/jobs?repo=try&revision=e1aa917b0390606b67196f8e34823bd06e2254ad

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/77d3548f6c1b
Part 1 - Create UrlbarProviderAutofill.jsm. r=adw
https://hg.mozilla.org/integration/autoland/rev/7dae25cc139a
Part 2 - Dedupe results matching autofill in the muxer. r=adw
https://hg.mozilla.org/integration/autoland/rev/9d9c4e355185
Part 3 - Allow UrlbarProviderTokenAliasEngines to provide its own heuristic result. r=adw
https://hg.mozilla.org/integration/autoland/rev/94795935db52
Part 4 - Port autofill unit tests to browser/components/urlbar. r=adw
https://hg.mozilla.org/integration/autoland/rev/7ea832ed5d98
Part 5 - Move some deduping code from UnifiedComplete to the UrlbarMuxer. r=adw,mak
https://hg.mozilla.org/integration/autoland/rev/6cb8b095be15
Part 6 - Resolve a11y focus issue causing a failure in browser_test_focus_urlbar.js. r=adw
https://hg.mozilla.org/integration/autoland/rev/51a157c5fe34
Part 7 - Temporarily disable test_keywords.js on Linux to resolve bug 1474616. r=mak

Comment 22

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/77d3548f6c1b
https://hg.mozilla.org/mozilla-central/rev/7dae25cc139a
https://hg.mozilla.org/mozilla-central/rev/9d9c4e355185
https://hg.mozilla.org/mozilla-central/rev/94795935db52
https://hg.mozilla.org/mozilla-central/rev/7ea832ed5d98
https://hg.mozilla.org/mozilla-central/rev/6cb8b095be15
https://hg.mozilla.org/mozilla-central/rev/51a157c5fe34