Closed Bug 1481439 Opened Last year Closed Last year

Intermittent browser/components/extensions/test/browser/browser_ext_omnibox.js | Uncaught exception - Waiting for the autocomplete result for "VeryUniqueKeywordThatDoesNeverMatchAnyTestUrl 7" at [2] to appear - timed out after 50 tries.

Categories

(WebExtensions :: Untriaged, defect, P5)

defect

Tracking

(firefox63 fixed, firefox64 fixed)

RESOLVED FIXED
mozilla64
Tracking Status
firefox63 --- fixed
firefox64 --- fixed

People

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

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

Filed by: nerli [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=192471261&repo=autoland

https://queue.taskcluster.net/v1/task/UZgIO5vpR2-WhchGO653Qw/runs/0/artifacts/public/logs/live_backing.log

[task 2018-08-07T10:29:55.767Z] 10:29:55     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_omnibox.js | Expected "on-input-entered-fired" to have fired with disposition: "currentTab". - 
[task 2018-08-07T10:29:55.767Z] 10:29:55     INFO - Buffered messages logged at 10:29:47
[task 2018-08-07T10:29:55.767Z] 10:29:55     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_omnibox.js | Expected "on-input-changed-fired" to have fired with text: "7". - 
[task 2018-08-07T10:29:55.769Z] 10:29:55     INFO - Buffered messages finished
[task 2018-08-07T10:29:55.770Z] 10:29:55     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_omnibox.js | Uncaught exception - Waiting for the autocomplete result for "VeryUniqueKeywordThatDoesNeverMatchAnyTestUrl 7" at [2] to appear - timed out after 50 tries.
[task 2018-08-07T10:29:55.771Z] 10:29:55     INFO - Leaving test bound 
[task 2018-08-07T10:29:55.772Z] 10:29:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-08-07T10:29:55.773Z] 10:29:55     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_omnibox.js | Extension left running at test shutdown - 
[task 2018-08-07T10:29:55.773Z] 10:29:55     INFO - Stack trace:
[task 2018-08-07T10:29:55.774Z] 10:29:55     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
[task 2018-08-07T10:29:55.775Z] 10:29:55     INFO - chrome://mochikit/content/browser-test.js:nextTest:705
[task 2018-08-07T10:29:55.776Z] 10:29:55     INFO - chrome://mochikit/content/browser-test.js:testScope/test_finish/<:1397
[task 2018-08-07T10:29:55.776Z] 10:29:55     INFO - chrome://mochikit/content/browser-test.js:run:1334
[task 2018-08-07T10:29:55.777Z] 10:29:55     INFO - GECKO(1012) | MEMORY STAT | vsize 1136MB | residentFast 404MB | heapAllocated 121MB
[task 2018-08-07T10:29:55.779Z] 10:29:55     INFO - TEST-OK | browser/components/extensions/test/browser/browser_ext_omnibox.js | took 23329ms
Print useful information about the visible autocompletion results before
failing the test, for debugging.
Can't reproduce locally; will collect relevant information for debugging with the above patch.

I want to understand whether this test failure is just an issue with the test, or with the API implementation.
Assignee: nobody → rob
Status: NEW → ASSIGNED
Keywords: leave-open
Pushed by rob@robwu.nl:
https://hg.mozilla.org/integration/autoland/rev/e642f1e694bb
Print debugging info when browser_ext_omnibox.js fails r=aswan
Comment on attachment 9005265 [details]
Bug 1481439 - Print debugging info when browser_ext_omnibox.js fails

Andrew Swan [:aswan] has approved the revision.
Attachment #9005265 - Flags: review+
See Also: → 1487530
See Also: 1487530
I can't find an obvious logical flaw that would cause the error (investigation below).
Since the failures occur rarely, and on debug builds only, I guess that the time is too short for waitForCondition to complete. Increasing the timeout or retry counts could fix the issue.


The output of the autocompletion at the failure [1] has the following structure:

<xul:richlistbox ..>
  <xul:richlistitem ... ac-text="[keyword] 7" originaltype="action extension heuristic"
                    ... text="[keyword] 7" actiontype="extension" ... />
  <xul:richlistitem ... ac-text="[keyword]" ... originaltype="action extension"
                    ... text=[keyword]" actiontype="extension"
                    ... displayurl="[keyword] a" collapsed="true" />
  <xul:richlistitem ... ac-text="[keyword]" ... originaltype="action extension"
                    ... text=[keyword]" actiontype="extension"
                    ... displayurl="[keyword] b" collapsed="true" />
  <xul:richlistitem ... ac-text="[keyword]" ... originaltype="action extension"
                    ... text=[keyword]" actiontype="extension"
                    ... displayurl="[keyword] c" collapsed="true" />
</xul:richlistbox>

(with [keyword] = "VeryUniqueKeywordThatDoesNeverMatchAnyTestUrl" and 7 being any digit).

When I compare the above result with a passing test, then:
- The first item is identical (with expected ac-text/text)
- Items 2-4 only have a keyword in ac-value/value (not the subsequently typed digit).
- There is an extra collapsed="true" attribute in the failing test that is not present in a passing test run.

The presence of the "collapsed" attribute suggests that _collapseUnusedItems was called with matchCount=1 at:
https://searchfox.org/mozilla-central/rev/a41fd8cb947266ea2e3f463fc6e31c88bfab9d41/toolkit/content/widgets/autocomplete.xml#876
i.e. mInput.controller.matchCount = 1 at
https://searchfox.org/mozilla-central/rev/a41fd8cb947266ea2e3f463fc6e31c88bfab9d41/toolkit/content/widgets/autocomplete.xml#864


The first and only visible item is a heuristic result, i.e. the default extension result from:
https://searchfox.org/mozilla-central/rev/a41fd8cb947266ea2e3f463fc6e31c88bfab9d41/toolkit/components/places/UnifiedComplete.js#1160

The extension items are expected to be added here:
https://searchfox.org/mozilla-central/rev/a41fd8cb947266ea2e3f463fc6e31c88bfab9d41/toolkit/components/places/UnifiedComplete.js#1714-1728


[1] https://searchfox.org/mozilla-central/rev/5a18fb5aeeec99f1ca1c36a697082c221189a3b9/browser/components/extensions/test/browser/browser_ext_omnibox.js#125
The "startInputSession" test helper triggers the autocompletion logic to
kick off the test. In all cases except for "testSuggestions", the search
suggestions are set synchronously. Consequently, the
"waitForAutocompleteResultAt" call at the end of starting the input
session would find the expected suggestion item at the given index.

However, in the case of "testSuggestions", the results are generated
asynchronously. There is no guarantee that the results are set. The test
has only been passing so far because the result items from the previous
test are still cached, and cleared after a 100ms delay by:
https://searchfox.org/mozilla-central/rev/a41fd8cb947266ea2e3f463fc6e31c88bfab9d41/toolkit/components/places/UnifiedComplete.js#1728
On slow test runs, the test fails intermittently when the clean-up logic
runs before the test checked the suggestion item.

This patch fixes the issue by splitting "startInputSession", and only
use "waitForAutocompleteResultAt" after having sent the suggestions.
Comment on attachment 9006980 [details]
Bug 1481439 - Fix intermittent browser_ext_omnibox.js

Andrew Swan [:aswan] has approved the revision.
Attachment #9006980 - Flags: review+
Pushed by rob@robwu.nl:
https://hg.mozilla.org/integration/autoland/rev/9dc78b12d194
Fix intermittent browser_ext_omnibox.js r=aswan
No intermittents occurred after the patch landed.
Keywords: leave-open
Status: ASSIGNED → RESOLVED
Closed: Last year
Resolution: --- → FIXED
Target Milestone: --- → mozilla64
Flags: qe-verify-
You need to log in before you can comment on or make changes to this bug.