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.

Depends on D82233

Depends on D82234

Depends on D82235

Depends on D82236

Depends on D82237

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.

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.

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.

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

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.

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

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

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

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

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

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

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