Closed Bug 1320230 Opened 5 years ago Closed 4 years ago

Intermittent browser/components/search/test/browser_searchbar_smallpanel_keyboard_navigation.js | Test timed out -

Categories

(Firefox :: Search, defect, P1)

Product:
Firefox
Component:
Search
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 56
Tracking Flags:
Tracking Status
firefox55 --- fixed
firefox56 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed:timing][fxsearch])

Attachments

(1 file)

Bug 1320230 - When monitoring for the search popup hiding on click, use dispatchToMainThread to reset the status rather than setTimeout as it is more reliable.
59 bytes, text/x-review-board-request
florian
: review+
jcristau
: approval-mozilla-beta+
Details
Priority: -- → P3
this started May 24th very infrequently and has really picked up in failure rates 58 the past week

primarily on linux (mix of opt/debug) and a mix of e10s/non-e10s.

here is a linux64-debug log:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=105826677&lineNumber=4077

here is what I see in the above log:
[task 2017-06-09T13:42:06.954807Z] 13:42:06     INFO - TEST-PASS | browser/components/search/test/browser_searchbar_smallpanel_keyboard_navigation.js | the one-off button #6 should be selected - 
[task 2017-06-09T13:42:06.959694Z] 13:42:06     INFO - TEST-PASS | browser/components/search/test/browser_searchbar_smallpanel_keyboard_navigation.js | the one-off button #5 should be selected - 
[task 2017-06-09T13:42:06.961946Z] 13:42:06     INFO - TEST-PASS | browser/components/search/test/browser_searchbar_smallpanel_keyboard_navigation.js | the one-off button #4 should be selected - 
[task 2017-06-09T13:42:06.964146Z] 13:42:06     INFO - Buffered messages logged at 13:40:36
[task 2017-06-09T13:42:06.967530Z] 13:42:06     INFO - TEST-PASS | browser/components/search/test/browser_searchbar_smallpanel_keyboard_navigation.js | the one-off button #3 should be selected - 
[task 2017-06-09T13:42:06.970450Z] 13:42:06     INFO - TEST-PASS | browser/components/search/test/browser_searchbar_smallpanel_keyboard_navigation.js | the one-off button #2 should be selected - 
[task 2017-06-09T13:42:06.972684Z] 13:42:06     INFO - TEST-PASS | browser/components/search/test/browser_searchbar_smallpanel_keyboard_navigation.js | the one-off button #1 should be selected - 
[task 2017-06-09T13:42:06.975821Z] 13:42:06     INFO - TEST-PASS | browser/components/search/test/browser_searchbar_smallpanel_keyboard_navigation.js | no suggestion should be selected - 
[task 2017-06-09T13:42:06.978035Z] 13:42:06     INFO - TEST-PASS | browser/components/search/test/browser_searchbar_smallpanel_keyboard_navigation.js | the textfield value should be unmodified - 
[task 2017-06-09T13:42:06.980649Z] 13:42:06     INFO - TEST-PASS | browser/components/search/test/browser_searchbar_smallpanel_keyboard_navigation.js | the search bar no longer be focused - 
[task 2017-06-09T13:42:06.982901Z] 13:42:06     INFO - Leaving test bound test_shift_tab
[task 2017-06-09T13:42:06.985876Z] 13:42:06     INFO - Entering test bound test_alt_down
[task 2017-06-09T13:42:06.988126Z] 13:42:06     INFO - Opening search panel
[task 2017-06-09T13:42:06.990591Z] 13:42:06     INFO - Buffered messages finished
[task 2017-06-09T13:42:06.992934Z] 13:42:06     INFO - TEST-UNEXPECTED-FAIL | browser/components/search/test/browser_searchbar_smallpanel_keyboard_navigation.js | Test timed out - 
[task 2017-06-09T13:42:06.996026Z] 13:42:06     INFO - Search engine removed: testEngine.xml
[task 2017-06-09T13:42:06.998192Z] 13:42:06     INFO - removing search history values: foo1,foo2,foo3
[task 2017-06-09T13:42:07.001645Z] 13:42:07     INFO - GECKO(1813) | MEMORY STAT | vsize 2418MB | residentFast 272MB | heapAllocated 109MB
[task 2017-06-09T13:42:07.003839Z] 13:42:07     INFO - TEST-OK | browser/components/search/test/browser_searchbar_smallpanel_keyboard_navigation.js | took 90978ms


Given this increase in failures, we should work on addressing this.

:florian, can you get someone from the search team to look into this bug in the next 2 weeks?
Flags: needinfo?(florian)
Whiteboard: [stockwell needswork]
Priority: P3 → P1
Whiteboard: [stockwell needswork] → [stockwell needswork][fxsearch]
Assignee: nobody → standard8
Flags: needinfo?(florian)
Initial analysis:

- Most of the failures seem to be in test_alt_down or test_shift_tab when opening the search panel.
- The failures are always followed by:

browser_tooManyEnginesOffered.js | A promise chain failed to handle a rejection  - at chrome://mochikit/content/browser-test.js:810 - TypeError: this.SimpleTest.isExpectingUncaughtException is not a function

Stack trace:
INFO -     Tester_execTest/<@chrome://mochikit/content/browser-test.js:810:23
INFO -     Tester_execTest@chrome://mochikit/content/browser-test.js:801:9
INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:714:7
INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
INFO -     Tester_execTest@chrome://mochikit/content/browser-test.js:801:9
INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:714:7
INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59

That "is not a function" has been seen before in various bugs. I'm not yet sure if it is just the fact this test has failed that is causing some sort of exception in the follow-on test, or if there's a real issue that isn't being caught until the second test.
Depends on: 1372738
My local testing has determined that the cause of the uncaught exception issue is likely to be the fact that the promise which didn't resolve earlier has subsequently been resolved by browser_tooManyEnginesOffered.js opening the search popup. It then tries to complete the earlier test but fails as everything has been torn down for it.

I've filed bug 1372738 on making the result clearer, however, it won't actually help this intermittent.
:standard8 - what are the next steps on this bug?  Possibly we have  better results so we can maybe see the real failure?
Flags: needinfo?(standard8)
The previous changes in bug 1372738 only clarified the error, they haven't revealed the nature of it.

It looks like the click isn't getting through, so I'm currently trying to clarify if it is or not. Hopefully I'll have a better idea tomorrow, and I'll make an assessment from there of how to move forward with this.
Flags: needinfo?(standard8)
Here's what I think is happening based on the last try server runs:

- The previous test is attempting to close the search popup by pressing tab.
- This triggers the popuphiding event.
- In browser-search-autocomplete-result-popup we have a popuphiding handler that sets this._isHiding to true, and then does a setTimeout(..., 0) to set it back to false again.

- The test that times out, attempts to open the search popup by clicking on the icon.
- There's a mousedown handler in the searchbar binding that sees we're clicking on the searchbar button and because _isHiding is true, it sets this._clickClosedPopup to true.
- The searchbar click handler then sees the _clickClosedPopup being true, thinks that the click is closing rather than opening, and doesn't open the popup.

At which point the test times out because it is still waiting for the popup to open.

The tests are already doing a SimpleTest.executeSoon() call for clicking the on the icon which seems to be trying to work around this.

So my guess at this point is something is making the setTimeout take a little longer than it used to, and it happens on occasion after the click.
The patch replaces setTimeout with a dispatchToMainThread that seems a bit better.

Try run was here: https://treeherder.mozilla.org/#/jobs?repo=try&revision=97c5fdb83655c9731394f96427af34cb79b17689

The test is in the bc11 tests. For a previous run without the patch, I saw failures 3/20 times on the equivalent run.
Comment on attachment 8879947 [details]
Bug 1320230 - When monitoring for the search popup hiding on click, use dispatchToMainThread to reset the status rather than setTimeout as it is more reliable.

https://reviewboard.mozilla.org/r/151324/#review156232
Attachment #8879947 - Flags: review?(florian) → review+
Pushed by mbanner@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ebe6edd383bf
When monitoring for the search popup hiding on click, use dispatchToMainThread to reset the status rather than setTimeout as it is more reliable. r=florian
https://hg.mozilla.org/mozilla-central/rev/ebe6edd383bf
Status: NEW → RESOLVED
Closed: 4 years ago
status-firefox56: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 56
Please request Beta approval on this when you get a chance.
status-firefox55: --- → affected
Flags: needinfo?(standard8)
Whiteboard: [stockwell needswork][fxsearch] → [stockwell fixed:timing][fxsearch]
Comment on attachment 8879947 [details]
Bug 1320230 - When monitoring for the search popup hiding on click, use dispatchToMainThread to reset the status rather than setTimeout as it is more reliable.

Approval Request Comment
[Feature/Bug causing the regression]: Uncertain
[User impact if declined]: None, this is a fix which improves handling of a flag to fix intermittent failure issues. It should have minimal/no impact on user functionality.
[Is this code covered by automated tests?]: Yes
[Has the fix been verified in Nightly?]: The tests still pass.
[Needs manual test from QE? If yes, steps to reproduce]:  No
[List of other uplifts needed for the feature/fix]: None
[Is the change risky?]: No
[Why is the change risky/not risky?]: Small change to the timer used to delay an event.
[String changes made/needed]: None
Flags: needinfo?(standard8)
Attachment #8879947 - Flags: approval-mozilla-beta?
Comment on attachment 8879947 [details]
Bug 1320230 - When monitoring for the search popup hiding on click, use dispatchToMainThread to reset the status rather than setTimeout as it is more reliable.

small change to fix intermittent test failure, beta55+
Attachment #8879947 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
You need to log in before you can comment on or make changes to this bug.