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

Reporter

Description

•

6 years ago

treeherder

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 -

Comment hidden (Intermittent Failures Robot)

Marco Bonardo [:mak]

Comment 5

•

5 years ago

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

Priority: P5 → P2

Comment hidden (Intermittent Failures Robot)

Razvan Maries

Comment 8

•

5 years ago

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]

Drew Willcoxon :adw

Assignee

Updated

•

5 years ago

Assignee: nobody → adw

Status: NEW → ASSIGNED

Flags: needinfo?(adw)

Priority: P2 → P1

Drew Willcoxon :adw

Assignee

Updated

•

5 years ago

Iteration: --- → 69.4 - Jun 24 - Jul 7

Points: --- → 5

Drew Willcoxon :adw

Assignee

Comment 9

•

5 years ago

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.

Comment hidden (Intermittent Failures Robot)

Marco Bonardo [:mak]

Comment 11

•

5 years ago

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

Drew Willcoxon :adw

Assignee

Comment 12

•

5 years ago

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 callbackstartSearch@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
AsyncTester_execTest/<@chrome://mochikit/content/browser-test.js:1115:34

Drew Willcoxon :adw

Assignee

Comment 13

•

5 years ago

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

Drew Willcoxon :adw

Assignee

Comment 14

•

5 years ago

Try run that closes the popup each time it's opened: https://treeherder.mozilla.org/#/jobs?repo=try&revision=95f6afa49be33f1a407208a476df5631d6cfbc81

Drew Willcoxon :adw

Assignee

Comment 15

•

5 years ago

Oh great, there's also bug 1548111

Comment 16

•

5 years ago

Attached file Bug 1552410 - Fix intermittent failure in browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js. — Details

No failures on try after many retriggers: https://treeherder.mozilla.org/#/jobs?repo=try&revision=95f6afa49be33f1a407208a476df5631d6cfbc81&selectedJob=253610974 (Although an intermittent timeout, which is another bug, bug 1548111, did happen.)

Pulsebot

Comment 17

•

5 years ago

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

Andreea Pavel [:apavel]

Updated

•

5 years ago

Regressions: 1562058

Razvan Maries

Comment 18

•

5 years ago

bugherder

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

Status: ASSIGNED → RESOLVED

Closed: 5 years ago

status-firefox69: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → Firefox 69

Ryan VanderMeulen [:RyanVM]

Updated

•

5 years ago

status-firefox67: --- → unaffected

status-firefox68: --- → affected

status-firefox-esr60: --- → unaffected

Ryan VanderMeulen [:RyanVM]

Comment 19

•

5 years ago

bugherder uplift

https://hg.mozilla.org/releases/mozilla-beta/rev/060e5273db16

status-firefox68: affected → fixed

Edwin Takahashi (:egao | infrequent contributor)

Updated

•

5 years ago

Blocks: 1558321

Andreea Pavel [:apavel]

Updated

•

5 years ago

Regressions: 1548111

Comment hidden (Intermittent Failures Robot)

Drew Willcoxon :adw

Assignee

Updated

•

5 years ago

Depends on: 1562416

Comment hidden (Intermittent Failures Robot)

Drew Willcoxon :adw

Assignee

Comment 22

•

5 years ago

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

Marco Bonardo [:mak]

Updated

•

4 years ago

Keywords: regression