Closed Bug 1552410 Opened 5 months ago Closed 4 months ago

Intermittent browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Should have been found in autocomplete - false == true - JS frame :: chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser...

Categories

(Firefox :: Address Bar, defect, P1)

defect
Points:
5

Tracking

()

RESOLVED FIXED
Firefox 69
Iteration:
69.4 - Jun 24 - Jul 7
Tracking Status
firefox-esr60 --- unaffected
firefox67 --- unaffected
firefox68 --- fixed
firefox69 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell unknown])

Attachments

(1 file)

Filed by: aiakab [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=246899952&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/dd7R_o2kRn6VYoL3UneNPQ/runs/0/artifacts/public/logs/live_backing.log


21:50:08 INFO - Search for data:text/html,<body><iframe src=""></iframe></body> in open tabs.
21:50:08 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | data:text/html,<body><iframe src=""></iframe></body> was found in autocomplete, was expected - true == true -
21:50:08 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Should have a tab switch result - 1 == 1 -
21:50:08 INFO - Search for https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 in open tabs.
21:50:08 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 was found in autocomplete, was expected - true == true -
21:50:08 INFO - Leaving test bound step_5
21:50:08 INFO - Entering test bound step_6
21:50:08 INFO - Running step 6 - check swapBrowsersAndCloseOther preserves registered switch-to-tab result
21:50:08 INFO - Buffered messages logged at 21:50:08
21:50:08 INFO - Searching open pages.
21:50:08 INFO - Console message: [JavaScript Error: "Given tab is not restoring." {file: "resource:///modules/sessionstore/SessionStore.jsm" line: 5164}]
21:50:08 INFO - _resetLocalTabRestoringState@resource:///modules/sessionstore/SessionStore.jsm:5164:10
21:50:08 INFO - receiveMessage@resource:///modules/sessionstore/SessionStore.jsm:1007:30
21:50:08 INFO - MessageListener.receiveMessageonLoad/<@resource:///modules/sessionstore/SessionStore.jsm:1123:10
21:50:08 INFO - onLoad@resource:///modules/sessionstore/SessionStore.jsm:1121:14
21:50:08 INFO - onBeforeBrowserWindowShown@resource:///modules/sessionstore/SessionStore.jsm:1302:10
21:50:08 INFO - ssi_observe@resource:///modules/sessionstore/SessionStore.jsm:774:14
21:50:08 INFO - onLoad@chrome://browser/content/browser.js:1537:18
21:50:08 INFO - EventHandlerNonNull
@chrome://browser/content/browser.xul:102:39
21:50:08 INFO -
21:50:08 INFO - Buffered messages finished
21:50:08 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Should have been found in autocomplete - false == true - JS frame :: chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js :: checkAutocompleteResults :: line 197
21:50:08 INFO - Stack trace:
21:50:08 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:checkAutocompleteResults:197
21:50:08 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:ensure_opentabs_match_db:165
21:50:08 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:step_6:97
21:50:08 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1116
21:50:08 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1144
21:50:08 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1005
21:50:08 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
21:50:08 INFO - Not taking screenshot here: see the one that was previously logged
21:50:08 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Should have been found in autocomplete - false == true - JS frame :: chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js :: checkAutocompleteResults :: line 197
21:50:08 INFO - Stack trace:
21:50:08 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:checkAutocompleteResults:197
21:50:08 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:ensure_opentabs_match_db:165
21:50:08 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:step_6:97
21:50:08 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1116
21:50:08 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1144
21:50:08 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1005
21:50:08 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
21:50:08 INFO - Not taking screenshot here: see the one that was previously logged
21:50:08 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Should have been found in autocomplete - false == true - JS frame :: chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js :: checkAutocompleteResults :: line 197
21:50:08 INFO - Stack trace:
21:50:08 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:checkAutocompleteResults:197
21:50:08 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:ensure_opentabs_match_db:165
21:50:08 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:step_6:97
21:50:08 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1116
21:50:08 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1144
21:50:08 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1005
21:50:08 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
21:50:08 INFO - Searching open pages.
21:50:08 INFO - Skip heuristic match
21:50:08 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Should have a tab switch result - 1 == 1 -

frequency of the failure increased. No failures on Linux...

Priority: P5 → P2

There are 23 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-06-18&endday=2019-06-25&tree=trunk&bug=1552410

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=253306388&repo=mozilla-inbound&lineNumber=5212

11:35:11 INFO - TEST-START | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js
11:35:14 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Should have been found in autocomplete - false == true - JS frame :: chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js :: checkAutocompleteResults :: line 197
11:35:14 INFO - Stack trace:
11:35:14 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:checkAutocompleteResults:197
11:35:14 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:ensure_opentabs_match_db:165
11:35:14 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:step_6:97
11:35:14 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1115
11:35:14 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1143
11:35:14 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1004
11:35:14 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
11:35:14 INFO - Not taking screenshot here: see the one that was previously logged
11:35:14 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Should have been found in autocomplete - false == true - JS frame :: chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js :: checkAutocompleteResults :: line 197
11:35:14 INFO - Stack trace:
11:35:14 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:checkAutocompleteResults:197
11:35:14 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:ensure_opentabs_match_db:165
11:35:14 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:step_6:97
11:35:14 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1115
11:35:14 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1143
11:35:14 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1004
11:35:14 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
11:35:14 INFO - Not taking screenshot here: see the one that was previously logged
11:35:14 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Should have been found in autocomplete - false == true - JS frame :: chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js :: checkAutocompleteResults :: line 197
11:35:14 INFO - Stack trace:
11:35:14 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:checkAutocompleteResults:197
11:35:14 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:ensure_opentabs_match_db:165
11:35:14 INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:step_6:97
11:35:14 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1115
11:35:14 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1143
11:35:14 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1004
11:35:14 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
11:35:14 INFO - Searching open pages.
11:35:14 INFO - Skip heuristic match
11:35:14 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Should have a tab switch result - 1 == 1 -
11:35:14 INFO - Search for data:text/html,<body><iframe src=""></iframe></body> in open tabs.
11:35:14 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | data:text/html,<body><iframe src=""></iframe></body> was found in autocomplete, was expected - true == true -
11:35:14 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Should have a tab switch result - 1 == 1 -
11:35:14 INFO - Search for https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 in open tabs.
11:35:14 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 was found in autocomplete, was expected - true == true -
11:35:14 INFO - Leaving test bound step_6
11:35:14 INFO - Entering test bound step_7
11:35:14 INFO - Running step 7 - close all tabs
11:35:14 INFO - Removing tab: about:blank
11:35:14 INFO - Removing tab: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16
11:35:14 INFO - Removing tab: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16
11:35:14 INFO - Removing tab: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16
11:35:14 INFO - Removing tab: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16
11:35:14 INFO - Removing tab: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16
11:35:14 INFO - Removing tab: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16
11:35:14 INFO - Removing tab: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16
11:35:14 INFO - Removing tab: data:text/html,<body><iframe src=""></iframe></body>
11:35:14 INFO - Searching open pages.
11:35:14 INFO - Skip heuristic match
11:35:14 INFO - Leaving test bound step_7
11:35:14 INFO - Entering test bound cleanup
11:35:14 INFO - Cleaning up

Drew, could you assign this to someone?

Flags: needinfo?(adw)
Whiteboard: [stockwell needswork:owner]
Assignee: nobody → adw
Status: NEW → ASSIGNED
Flags: needinfo?(adw)
Priority: P2 → P1
Iteration: --- → 69.4 - Jun 24 - Jul 7
Points: --- → 5

I can reproduce this intermittently locally with --verify. The test is failing in step 6 after it calls gBrowser.swapBrowsersAndCloseOther() and checks the switch-to-tab results in the view. It looks like UrlbarProviderUnifiedComplete.cancelQuery() ends up always getting called at that point, in both passing runs and failing runs. The difference between passing and failing is that in failing runs, cancelQuery() gets called before the UnifiedComplete listener in UrlbarProviderUnifiedComplete receives all the results -- often or always after receiving only the first result. In passing runs, cancelQuery() gets called after the listener receives all four results. I don't know why yet.

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

IThe difference between passing and failing is that in failing runs, cancelQuery() gets called before the UnifiedComplete listener in UrlbarProviderUnifiedComplete receives all the results -- often or always after receiving only the first result. In passing runs, cancelQuery() gets called after the listener receives all four results.

May it depend on when the TabSelect event arrives?

On failing runs, cancelQuery is being called early because _on_resize is being called, and _on_resize closes the popup. :-O The test doesn't resize the window...

cancelQuery@resource:///modules/UrlbarProviderUnifiedComplete.jsm:167:13
cancel@resource:///modules/UrlbarProvidersManager.jsm:366:16
cancelQuery@resource:///modules/UrlbarProvidersManager.jsm:245:11
cancelQuery@resource:///modules/UrlbarController.jsm:141:18
close@resource:///modules/UrlbarView.jsm:182:21
_on_resize@resource:///modules/UrlbarView.jsm:879:10
handleEvent@resource:///modules/UrlbarView.jsm:285:23
EventListener.handleEvent*_on_popupshowing@resource:///modules/UrlbarView.jsm:861:17
handleEvent@resource:///modules/UrlbarView.jsm:285:23
_openPanel@resource:///modules/UrlbarView.jsm:376:16
onQueryResults@resource:///modules/UrlbarView.jsm:239:10
_notify@resource:///modules/UrlbarController.jsm:536:25
receiveResults@resource:///modules/UrlbarController.jsm:168:10
notifyResults@resource:///modules/UrlbarProvidersManager.jsm:415:23
add@resource:///modules/UrlbarProvidersManager.jsm:421:7
onSearchResult@resource:///modules/UrlbarProviderUnifiedComplete.jsm:136:13
notify@resource://gre/modules/UnifiedComplete.jsm:2547:22
notifyResult@resource://gre/modules/UnifiedComplete.jsm:2562:7
_addMatch@resource://gre/modules/UnifiedComplete.jsm:1973:10
_addSearchEngineMatch@resource://gre/modules/UnifiedComplete.jsm:1708:10
_matchCurrentSearchEngine@resource://gre/modules/UnifiedComplete.jsm:1628:10
async*_matchFirstHeuristicResult@resource://gre/modules/UnifiedComplete.jsm:1355:32
execute@resource://gre/modules/UnifiedComplete.jsm:903:35
asyncstartSearch/<@resource://gre/modules/UnifiedComplete.jsm:2692:50
promise callback
startSearch@resource://gre/modules/UnifiedComplete.jsm:2692:30
startQuery/<@resource:///modules/UrlbarProviderUnifiedComplete.jsm:146:23
startQuery@resource:///modules/UrlbarProviderUnifiedComplete.jsm:129:11
start@resource:///modules/UrlbarProvidersManager.jsm:338:30
startQuery@resource:///modules/UrlbarProvidersManager.jsm:232:17
startQuery@resource:///modules/UrlbarController.jsm:113:24
startQuery@resource:///modules/UrlbarInput.jsm:669:52
startSearch@resource://testing-common/UrlbarTestUtils.jsm:367:19
promiseAutocompleteResultPopup@resource://testing-common/UrlbarTestUtils.jsm:82:14
asyncpromiseAutocompleteResultPopup@chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/head-common.js:61:26
checkAutocompleteResults@chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:174:9
ensure_opentabs_match_db@chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:169:10
step_2@chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:50:9
Async
Tester_execTest/<@chrome://mochikit/content/browser-test.js:1115:34

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

step_2@chrome://mochitests/content/browser/browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js:50:9
Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1115:34

This stack is from step 6. The reason it has step_2 near the bottom is that the popup is never closed from step 2 to step 6. The test also opens the popup in step 1, but it's then automatically closed at the start of step 2 when step 2 removes and switches tabs.

I can't get the failure to happen when I close the popup at the end of each step. Actually just awaiting a turn of the event loop seems to be enough (await new Promise(r => setTimeout(r, 0)). But I don't understand why that seems to work.

Oh great, there's also bug 1548111

See Also: → 1548111
Pushed by dwillcoxon@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e1d7069da898
Fix intermittent failure in browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js. r=mak
Regressions: 1562058
Status: ASSIGNED → RESOLVED
Closed: 4 months ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 69
Regressions: 1548111
Depends on: 1562416

(In reply to Intermittent Failures Robot from comment #21)

1 failures in 4710 pushes (0.0 failures/push) were associated with this bug
in the last 7 days.

Repository breakdown:

  • mozilla-release: 1

Probably (hopefully) this is actually bug 1548111, which is on 69 but not 68/release.

You need to log in before you can comment on or make changes to this bug.