Closed Bug 1336806 Opened 4 years ago Closed 3 years ago

Intermittent browser/base/content/test/general/browser_bookmark_popup.js | Panel should still be 'open' for non-autoclose - Got closed, expected open

Categories

(Firefox :: Bookmarks & History, defect, P1)

defect

Tracking

()

RESOLVED FIXED
Firefox 56
Tracking Status
firefox56 --- fixed

People

(Reporter: aryx, Assigned: standard8)

References

Details

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

Attachments

(1 file)

https://treeherder.mozilla.org/logviewer.html#?job_id=74590465&repo=mozilla-inbound

05:17:09     INFO - Entering test bound mouse_hovering_panel_should_prevent_autoclose
05:17:09     INFO - TEST-PASS | browser/base/content/test/general/browser_bookmark_popup.js | Page should only be starred prior to popupshown if editing bookmark - 
05:17:09     INFO - TEST-PASS | browser/base/content/test/general/browser_bookmark_popup.js | Panel should be 'closed' to start test - 
05:17:09     INFO - TEST-PASS | browser/base/content/test/general/browser_bookmark_popup.js | Panel should be 'open' after shownPromise is resolved - 
05:17:09     INFO - Buffered messages logged at 05:17:09
05:17:09     INFO - TEST-PASS | browser/base/content/test/general/browser_bookmark_popup.js | Only one bookmark should exist - 
05:17:09     INFO - TEST-PASS | browser/base/content/test/general/browser_bookmark_popup.js | Page is starred - 
05:17:09     INFO - TEST-PASS | browser/base/content/test/general/browser_bookmark_popup.js | title should match isEditingBookmark state - 
05:17:09     INFO - Buffered messages finished
05:17:09     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_bookmark_popup.js | Panel should still be 'open' for non-autoclose - Got closed, expected open
05:17:09     INFO - Stack trace:
05:17:09     INFO -     chrome://mochikit/content/browser-test.js:test_is:911
05:17:09     INFO -     chrome://mochitests/content/browser/browser/base/content/test/general/browser_bookmark_popup.js:test_bookmarks_popup/<:56
05:17:09     INFO -     test_bookmarks_popup@chrome://mochitests/content/browser/browser/base/content/test/general/browser_bookmark_popup.js:20:9
05:17:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:319:42
05:17:09     INFO -     TaskImpl@resource://gre/modules/Task.jsm:277:3
05:17:09     INFO -     asyncFunction@resource://gre/modules/Task.jsm:252:14
05:17:09     INFO -     Task_spawn@resource://gre/modules/Task.jsm:166:12
05:17:09     INFO -     TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
05:17:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
05:17:09     INFO -     TaskImpl@resource://gre/modules/Task.jsm:277:3
05:17:09     INFO -     asyncFunction@resource://gre/modules/Task.jsm:252:14
05:17:09     INFO -     Task_spawn@resource://gre/modules/Task.jsm:166:12
05:17:09     INFO -     TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
05:17:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
05:17:09     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
05:17:09     INFO -     walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
05:17:09     INFO -     Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
05:17:09     INFO -     schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
05:17:09     INFO -     completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
05:17:09     INFO -     promise callback*completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:698:7
05:17:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:324:15
05:17:09     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
05:17:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
05:17:09     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
05:17:09     INFO -     walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
05:17:09     INFO -     Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
05:17:09     INFO -     schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
05:17:09     INFO -     completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
05:17:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:324:15
05:17:09     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
05:17:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
05:17:09     INFO -     TaskImpl@resource://gre/modules/Task.jsm:277:3
05:17:09     INFO -     asyncFunction@resource://gre/modules/Task.jsm:252:14
05:17:09     INFO -     fetchBookmarksByURL/<@resource://gre/modules/Bookmarks.jsm:1163:22
05:17:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:319:42
05:17:09     INFO -     TaskImpl@resource://gre/modules/Task.jsm:277:3
05:17:09     INFO -     asyncFunction@resource://gre/modules/Task.jsm:252:14
05:17:09     INFO -     executeBeforeShutdown@resource://gre/modules/Sqlite.jsm:374:25
05:17:09     INFO -     executeBeforeShutdown@resource://gre/modules/Sqlite.jsm:1248:12
05:17:09     INFO -     withConnectionWrapper/<@resource://gre/modules/PlacesUtils.jsm:1455:14
05:17:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:319:42
05:17:09     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
05:17:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
05:17:09     INFO -     TaskImpl@resource://gre/modules/Task.jsm:277:3
05:17:09     INFO -     asyncFunction@resource://gre/modules/Task.jsm:252:14
05:17:09     INFO -     Task_spawn@resource://gre/modules/Task.jsm:166:12
05:17:09     INFO -     withConnectionWrapper@resource://gre/modules/PlacesUtils.jsm:1453:12
05:17:09     INFO -     fetchBookmarksByURL@resource://gre/modules/Bookmarks.jsm:1160:10
05:17:09     INFO -     fetch/<@resource://gre/modules/Bookmarks.jsm:596:25
05:17:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:319:42
05:17:09     INFO -     TaskImpl@resource://gre/modules/Task.jsm:277:3
05:17:09     INFO -     asyncFunction@resource://gre/modules/Task.jsm:252:14
05:17:09     INFO -     Task_spawn@resource://gre/modules/Task.jsm:166:12
05:17:09     INFO -     fetch@resource://gre/modules/Bookmarks.jsm:589:12
05:17:09     INFO -     test_bookmarks_popup/<@chrome://mochitests/content/browser/browser/base/content/test/general/browser_bookmark_popup.js:67:28
05:17:09     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:319:42
05:17:09     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
05:17:09     INFO -     walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
05:17:09     INFO -     Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
05:17:09     INFO -     schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
05:17:09     INFO -     completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
05:17:09     INFO - Not taking screenshot here: see the one that was previously logged
05:17:09     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_bookmark_popup.js | uncaught exception - NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsINavBookmarksService.getBookmarkURI] at SU_removeBookmarkButtonCommand@chrome://browser/content/browser-places.js:326:27
Flags: needinfo?(jaws)
Sounds like the getBookmarkURI call hits a non-existing id
(In reply to Marco Bonardo [::mak] from comment #1)
> Sounds like the getBookmarkURI call hits a non-existing id

The first failure here is that the panel is closed when it was expected to be opened. Now it looks like the test continues, and popupHideFn() calls document.getElementById("editBookmarkPanelRemoveButton").click(); even though the panel is hidden (presumably hidden because it was already removed?)

So I think the fact there is a non-existing id is a symptom of the first problem, the panel being closed when it should have been opened.

If this test only failed once I don't think it's worth it to dig deeper in to this race condition.
Flags: needinfo?(jaws)
Assignee: nobody → standard8
Status: NEW → ASSIGNED
Priority: -- → P1
Whiteboard: [fxsearch]
From what I can tell, it seems like putting the mouse in the middle of the panel, rather than over the remove button, is possibly more reliable.

I'm not sure why though. The only other thing I can think of is that mouse hover is somehow unreliable in the test suites. I think this is potentially worth a try and we'll see how it goes...

This is an older try run without the patch:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=0c837a938564f86772abc9b3a8ba54403902d12b

This is a try run with the patch:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=c4d26a221ad886ae237ef87e22161541dfdbd449
Comment on attachment 8887090 [details]
Bug 1336806 - Disable animation of the bookmark popup panel during tests to aid timing and avoid intermittent issues.

https://reviewboard.mozilla.org/r/157828/#review162978

My only fear is that there may be a real bug when the user hovers certain elements inside the panel and we should not close it, but we do instead. But it's also an edge case and we could act on it when we actually get some REAL reports of it, possibly with decent STR.
If you can find anything additional about why it's failing that will be appreciated, otherwise I don't think it's worth bumping our head against this wall for days.
Attachment #8887090 - Flags: review?(mak77) → review+
Pushed by mbanner@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/33a29b909d86
In browser_bookmark_popup.js' hover tests, place the mouse in the middle of the panel to try and avoid intermittents. r=mak
Ok, I'm going to go for the slightly more complicated route of making sure the timer doesn't fire until we've moved the mouse, and only moving it in the edit function.
Flags: needinfo?(standard8)
After some investigation, I realised that moving the mouse after the panel is opened causes a "mousemove" event, which cancels the timer that we are interested in testing.

I'm now working on another theory that the panel is taking slightly longer to open (due to the async changes), and is hitting the point where it isn't quite fully open (and not seen as hovering) when we hit the 350ms timer (normally this is 3.5s but in tests it is shortened).

Hence, I'm going to try removing the animation and see how that goes.
Disabling the animation of the panel seems to have fixed things. Ignore non-windows on the try runs they were me checking something else.

Before patch:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=f51e08c22f4b1cb964d318f81de275cfbb70f8d0

after patch:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=3d2f1d583900e9dfedce0da62e1a82faeffa175c

Note especially the Windows 7 VM tc-M tests - 4/6 failed on the before patch run, 0 / 46 on the after patch run.
Attachment #8887090 - Flags: review+ → review?(mak77)
Comment on attachment 8887090 [details]
Bug 1336806 - Disable animation of the bookmark popup panel during tests to aid timing and avoid intermittent issues.

https://reviewboard.mozilla.org/r/157828/#review164082
Attachment #8887090 - Flags: review?(mak77) → review+
Pushed by mbanner@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b3fae55d844b
Disable animation of the bookmark popup panel during tests to aid timing and avoid intermittent issues. r=mak
https://hg.mozilla.org/mozilla-central/rev/b3fae55d844b
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 56
You need to log in before you can comment on or make changes to this bug.