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

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.

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.

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

Backed out for frequent failures like https://treeherder.mozilla.org/logviewer.html#?job_id=114935822&repo=autoland https://hg.mozilla.org/integration/autoland/rev/355e74213db4db405eab0c272b67510955f7d424

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.

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.

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

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