Intermittent browser_ext_contextMenus_icons.js | Test timed out

RESOLVED FIXED

Status

defect
RESOLVED FIXED
2 years ago
Last year

People

(Reporter: aryx, Assigned: zombie)

Tracking

({intermittent-failure})

unspecified

Firefox Tracking Flags

(firefox55 disabled, firefox56 disabled)

Details

(Whiteboard: [stockwell fixed:other])

Attachments

(2 attachments)

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

[task 2017-03-29T04:44:39.574259Z] 04:44:39     INFO - GECKO(1282) | --DOMWINDOW == 15 (0x7ff698150000) [pid = 1282] [serial = 215] [outer = (nil)] [url = data:application/vnd.mozilla.xul+xml;charset=utf-8,%3C?xml%20version=%221.0%22?%3E%0A%20%20%3Cwindow%20id=%22documentElement%22/%3E]
[task 2017-03-29T04:44:39.576695Z] 04:44:39     INFO - GECKO(1282) | --DOMWINDOW == 14 (0x7ff69a5b0000) [pid = 1282] [serial = 219] [outer = (nil)] [url = data:application/vnd.mozilla.xul+xml;charset=utf-8,%3C?xml%20version=%221.0%22?%3E%0A%20%20%3Cwindow%20id=%22documentElement%22/%3E]
[task 2017-03-29T04:45:21.881990Z] 04:45:21     INFO - TEST-INFO | started process screentopng
[task 2017-03-29T04:45:23.556455Z] 04:45:23     INFO - TEST-INFO | screentopng: exit 0
[task 2017-03-29T04:45:23.556887Z] 04:45:23     INFO - Buffered messages logged at 04:43:51
[task 2017-03-29T04:45:23.557216Z] 04:45:23     INFO - Entering test bound 
[task 2017-03-29T04:45:23.561591Z] 04:45:23     INFO - Buffered messages logged at 04:43:53
[task 2017-03-29T04:45:23.563939Z] 04:45:23     INFO - Console message: [JavaScript Warning: "Password fields present on an insecure (http://) page. This is a security risk that allows user login credentials to be stolen." {file: "http://mochi.test:8888/browser/browser/components/extensions/test/browser/context.html?test=icons" line: 0 column: 0 source: "0"}]
[task 2017-03-29T04:45:23.565991Z] 04:45:23     INFO - Extension loaded
[task 2017-03-29T04:45:23.568305Z] 04:45:23     INFO - Console message: Warning: attempting to write 4321 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2017-03-29T04:45:23.570346Z] 04:45:23     INFO - Buffered messages logged at 04:43:54
[task 2017-03-29T04:45:23.578266Z] 04:45:23     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_contextMenus_icons.js | contextmenus-icons - 
[task 2017-03-29T04:45:23.580379Z] 04:45:23     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_contextMenus_icons.js | test result correct - 
[task 2017-03-29T04:45:23.582491Z] 04:45:23     INFO - Buffered messages logged at 04:43:55
[task 2017-03-29T04:45:23.584863Z] 04:45:23     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_contextMenus_icons.js | The context menu should display the extension icon next to the root element - 
[task 2017-03-29T04:45:23.589220Z] 04:45:23     INFO - Buffered messages finished
[task 2017-03-29T04:45:23.596551Z] 04:45:23     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_contextMenus_icons.js | Test timed out - 
[task 2017-03-29T04:45:23.598486Z] 04:45:23     INFO - Not taking screenshot here: see the one that was previously logged
[task 2017-03-29T04:45:23.600723Z] 04:45:23     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_contextMenus_icons.js | no tasks awaiting on messages - Got ["child-deleted"], expected []
[task 2017-03-29T04:45:23.605526Z] 04:45:23     INFO - Stack trace:
[task 2017-03-29T04:45:23.609455Z] 04:45:23     INFO -     chrome://mochikit/content/browser-test.js:test_is:911
[task 2017-03-29T04:45:23.611317Z] 04:45:23     INFO -     chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:31
[task 2017-03-29T04:45:23.613096Z] 04:45:23     INFO -     chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:437
[task 2017-03-29T04:45:23.614822Z] 04:45:23     INFO -     timeoutFn@chrome://mochikit/content/browser-test.js:817:9
[task 2017-03-29T04:45:23.616520Z] 04:45:23     INFO -     setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:779:9
[task 2017-03-29T04:45:23.618257Z] 04:45:23     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:655:7
[task 2017-03-29T04:45:23.625623Z] 04:45:23     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:791:59
Summary: Intermittent browser/components/extensions/test/browser/test-oop-extensions/browser_ext_contextMenus_icons.js → Intermittent browser_ext_contextMenus_icons.js | Test timed out
this is failing on win7/8 opt in e10s mode only, not debug at all.

with 21 failures yesterday, this is pretty high on our radar to get a fix.  :andym, is there a chance you can find someone on the webextensions team to get a fix in over the next 2 weeks for this?
Flags: needinfo?(amckay)
Whiteboard: [stockwell needswork]
Assignee: nobody → mwein
Flags: needinfo?(amckay)
See Also: → 1346039
it looks like we see a pair of failures often and the failure in the onclick test is tracked in bug 1346039.  I would prefer to focus on this bug and see this fixed first as it might end up fixing bug 1346039.
:mattw, this is failing very frequently (21 failures yesterday alone! + failures from bug 1346039), are you close to figuring this out, or should we disable the test temporarily?
Flags: needinfo?(mwein)
It looks like the failure started happening right around the time that bug 1318791 landed.
Flags: needinfo?(mwein)
After looking into this more, it looks like both the onclick and icon tests seem to timeout waiting for closeExtensionContextMenu to resolve.

Tomislav, could you take a look into bug 1302742 and bug 1333403 to see if either of those might be causing this issue? Thanks!
Flags: needinfo?(tomica)
(In reply to Matthew Wein [:mattw] from comment #15)
> Tomislav, could you take a look into bug 1302742 and bug 1333403 to see if
> either of those might be causing this issue? Thanks!

It's unlikely bug 1333403 is related, as it didn't touch any of those tests, nor change any of the implementation timings.

Looking at the test for bug 1302742, I guess there could be a async timing issue there, in which case we would likely need a round trip through the extension after the menus are created, something like this:

http://searchfox.org/mozilla-central/source/browser/components/extensions/test/browser/browser_ext_contextMenus.js#321-326
Flags: needinfo?(tomica)
:mattw, it sounds like possibly bug 1302742 could be related, is this something that you or :zombie can get a fix for soon?  The failure rates are pretty high and we are on track for 100+ failures this week.  I don't mind temporarily disabling this on windows+!debug until there is more time to fix this if that is desired.
Flags: needinfo?(mwein)
Attachment #8880755 - Flags: review?(gbrown) → review+
Pushed by jmaher@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/13ce1c218795
Intermittent browser_ext_contextMenus_icons.js. temporarily disable on win/opt. r=gbrown
Keywords: leave-open
Whiteboard: [stockwell needswork] → [stockwell disabled]
Comment on attachment 8880997 [details]
Bug 1351638 - Fix intermittents caused by menus_commands test

https://reviewboard.mozilla.org/r/152356/#review157412

I don't think this is going to help. A round trip shouldn't be necessary here, and the failure screenshot clearly shows that the item has been added to the context menu, but the sub-menu isn't open. So it seems like the problem has to do either with the code that waits for the top-level context menu to open, or the code that attempts to open the sub-menu.

If I had to guess, I'd guess that it's because the context menu is animated open on Windows, and the click event doesn't make it to the sub-menu item. But that's mostly just a guess.
Attachment #8880997 - Flags: review?(kmaglione+bmo)
Attachment #8880997 - Flags: review?(kmaglione+bmo)
I suspect when we fix this test we will fix bug 1346039 as well
Attachment #8880997 - Flags: review?(kmaglione+bmo)
Attachment #8880997 - Flags: review?(kmaglione+bmo)
Duplicate of this bug: 1346039
Duplicate of this bug: 1378048
Assignee: mwein → tomica
Flags: needinfo?(mwein)
So, this was never a problem with menus_icons test (or menus_onclick), but instead with menus_commands intermittently failing to close the top level context menu, as seen in this screenshot:

https://public-artifacts.taskcluster.net/IZHOsQy4Qe6rMuDD5sEWgg/0/public/test_info/mozilla-test-fail-screenshot_7yuvmm.png

I've tried to figure out what's actually causing the menu to remain open, but gave up after a dozen or so tries with various timeouts and requestAnimationsFrames(), and instead just ensured the menu gets closed manually every time.  At least Try seems happy:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=63f67d0e631c&duplicate_jobs=visible
Attachment #8880997 - Flags: review?(kmaglione+bmo)
Comment on attachment 8880997 [details]
Bug 1351638 - Fix intermittents caused by menus_commands test

https://reviewboard.mozilla.org/r/152356/#review159672

::: browser/components/extensions/test/browser/head.js:337
(Diff revision 19)
>    let popupHiddenPromise = BrowserTestUtils.waitForEvent(contentAreaContextMenu, "popuphidden");
>    EventUtils.synthesizeMouseAtCenter(itemToSelect, modifiers);
> -  return popupHiddenPromise;
> +  await popupHiddenPromise;
> +
> +  // Bug 1351638: parent menu fails to close intermittently, make sure it does.
> +  contentAreaContextMenu.hidePopup();

Shouldn't this be before the `await popupHiddenPromise`?
Attachment #8880997 - Flags: review?(kmaglione+bmo) → review+
Comment on attachment 8880997 [details]
Bug 1351638 - Fix intermittents caused by menus_commands test

https://reviewboard.mozilla.org/r/152356/#review159672

> Shouldn't this be before the `await popupHiddenPromise`?

We always get the `popuphidden` from the extension's context menu closing, it's the top level context menu that remains open sometimes, so this works.
Pushed by tomica@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/6b24ed47a268
Fix intermittents caused by menus_commands test r=kmag
Whiteboard: [stockwell disabled] → [stockwell fixed:other]
Duplicate of this bug: 1378233
Resolving as any intermittents remaining are likely unrelated to the original issue.
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Removing leave-open keyword from resolved bugs, per :sylvestre.
Keywords: leave-open
Product: Toolkit → WebExtensions
You need to log in before you can comment on or make changes to this bug.