1442187 - browser_ext_browserAction_popup.js and browser_ext_browserAction_popup_resize.js fails after bug 1193394

Status: RESOLVED FIXED

(WebExtensions :: General, defect)

Description

[Tooru Fujisawa [:arai]]

In bug 1193394, I've disabled Enable browser_ext_browserAction_popup.js and browser_ext_browserAction_popup_resize.js
we should investigate the actual reason why they started failing.

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=a54ef2d8f89626be6809676ff3534f077910052c&selectedJob=165137002
> INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup.js | Panel containing the action should be closed - 
> INFO - Stack trace:
> INFO - chrome://mochitests/content/browser/browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup.js:testInArea/<:230
> ...
> INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup.js | Test timed out - 
> INFO - Not taking screenshot here: see the one that was previously logged
> INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup.js | Extension left running at test shutdown - 
> INFO - Stack trace:
> INFO -     chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
> INFO -     chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:663
> INFO -     timeoutFn@chrome://mochikit/content/browser-test.js:1159:9
> INFO -     setTimeout handler*SimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:676:12
> INFO -     timeoutFn@chrome://mochikit/content/browser-test.js:1152:15
> INFO -     setTimeout handler*SimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:676:12
> INFO -     timeoutFn@chrome://mochikit/content/browser-test.js:1152:15
> INFO -     setTimeout handler*SimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:676:12
> INFO -     timeoutFn@chrome://mochikit/content/browser-test.js:1152:15
> INFO -     setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1121:9
> INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:955:9
> INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
> ...
> INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_resize.js | Test timed out - 
> INFO - Not taking screenshot here: see the one that was previously logged
> INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_resize.js | Extension left running at test shutdown - 
> INFO - Stack trace:
> INFO -     chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
> INFO -     chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:663
> INFO -     timeoutFn@chrome://mochikit/content/browser-test.js:1159:9
> INFO -     setTimeout handler*SimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:676:12
> INFO -     timeoutFn@chrome://mochikit/content/browser-test.js:1152:15
> INFO -     setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1121:9
> INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:955:9
> INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
> INFO - GECKO(1049) | MEMORY STAT | vsize 20974108MB | residentFast 1108MB
> INFO - TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_resize.js | took 180234ms
> INFO - checking window state
> INFO - Not taking screenshot here: see the one that was previously logged
> INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup_resize.js | Found a browser window after previous test timed out -

Comment 1

[Hiroyuki Ikezoe (:hiro)]

On debug build an assertion happened.

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

[task 2018-03-01T09:14:14.796Z] 09:14:14     INFO - GECKO(1038) | [Parent 1038, Main Thread] ###!!! ASSERTION: Creating widget for MenuPopupFrame with children: '!mGeneratedChildren && !PrincipalChildList().FirstChild()', file /builds/worker/workspace/build/src/layout/xul/nsMenuPopupFrame.cpp, line 267
[task 2018-03-01T09:14:14.796Z] 09:14:14     INFO - GECKO(1038) | #01: nsMenuPopupFrame::AttributeChanged [layout/xul/nsMenuPopupFrame.cpp:2310]
[task 2018-03-01T09:14:14.796Z] 09:14:14     INFO - 
[task 2018-03-01T09:14:14.797Z] 09:14:14     INFO - GECKO(1038) | #02: mozilla::ServoRestyleManager::AttributeChanged [layout/base/ServoRestyleManager.cpp:1512]
[task 2018-03-01T09:14:14.797Z] 09:14:14     INFO - 
[task 2018-03-01T09:14:14.797Z] 09:14:14     INFO - GECKO(1038) | #03: mozilla::PresShell::AttributeChanged [layout/base/RestyleManagerInlines.h:74]
[task 2018-03-01T09:14:14.798Z] 09:14:14     INFO - 
[task 2018-03-01T09:14:14.799Z] 09:14:14     INFO - GECKO(1038) | #04: nsNodeUtils::AttributeChanged [dom/base/nsNodeUtils.cpp:170]
[task 2018-03-01T09:14:14.799Z] 09:14:14     INFO - 
[task 2018-03-01T09:14:14.800Z] 09:14:14     INFO - GECKO(1038) | #05: mozilla::dom::Element::UnsetAttr [dom/base/Element.cpp:3050]
[task 2018-03-01T09:14:14.801Z] 09:14:14     INFO - 
[task 2018-03-01T09:14:14.801Z] 09:14:14     INFO - GECKO(1038) | #06: mozilla::dom::Element::RemoveAttribute [dom/bindings/ErrorResult.h:377]
[task 2018-03-01T09:14:14.802Z] 09:14:14     INFO - 
[task 2018-03-01T09:14:14.803Z] 09:14:14     INFO - GECKO(1038) | #07: mozilla::dom::ElementBinding::removeAttribute [s3:gecko-generated-sources:bc569c42ebea88ed8d0769ce05fb6fd2c8871792a7b35ebfc4c793afdeb631b934b25a7dee9dce6cd917dcce7c57fb8cc903224575f193a7ff8740ffed43dd3d/dom/bindings/ElementBinding.cpp::1312]
[task 2018-03-01T09:14:14.804Z] 09:14:14     INFO - 
[task 2018-03-01T09:14:14.804Z] 09:14:14     INFO - GECKO(1038) | #08: mozilla::dom::GenericBindingMethod [dom/bindings/BindingUtils.cpp:3033]
[task 2018-03-01T09:14:14.805Z] 09:14:14     INFO - 
[task 2018-03-01T09:14:14.807Z] 09:14:14     INFO - GECKO(1038) | #09: js::CallJSNative [js/src/vm/JSContext-inl.h:291]

CCing some browser guys and emilio. :)

Comment 2

[Hiroyuki Ikezoe (:hiro)]

Oh nvm.  The assertion happened in a subsequent test.

Comment 3

[Hiroyuki Ikezoe (:hiro)]

This is caused by bug 1428839.

Comment 4

[Hiroyuki Ikezoe (:hiro)]

Bisected. https://hg.mozilla.org/integration/mozilla-inbound/rev/96dd6c0d53b9

Comment 5

[:Gijs (he/him)]

Paolo, any idea what's going on here?

Comment 6

[Hiroyuki Ikezoe (:hiro)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/9683f24ff8ec5ba768c4a0a124d8439c228b2c8b
More failed tests due to this or bug 1442218.

Comment 7

[:Paolo Amadini]

My best guess at the moment is that something is waiting for a microtask instead of an event loop tick.

It may help to look for instances where we can use "BrowserTestUtils.waitForEvent" instead of direct event listeners, or wait for the ViewShown event instead of "popupshown".

Comment 8

[Hiroyuki Ikezoe (:hiro)]

I started looking at the failure on browser_ext_browserAction_popup_resize.js.  With the new microtask handling, it seems that PanelMultiView._activateView() is called after _showSubView() call.  So prevPanelView.active check [1] fails.

[1] https://hg.mozilla.org/integration/mozilla-inbound/rev/96dd6c0d53b9#l1.99

I will keep tracking down.

Comment 9

[Hiroyuki Ikezoe (:hiro)]

As for browser_ext_browserAction_popup_resize.js, we need to add "await showBrowserAction(extension, win);" in openPanel() just before calling clickBrowserAction().  Yeah, clickBrowserAction() also calls "await showBrowserAction(extension, win);", so I guess we do click the button before some important preparations finished.

Comment 10

[Tooru Fujisawa [:arai]]

oops, I didn't meant to clear ni? flag at the same time.
anyway, hiro is looking into this.

Comment 11

[Hiroyuki Ikezoe (:hiro)]

FWIW, I did push a try run with a workaround;
https://treeherder.mozilla.org/#/jobs?repo=try&revision=9752618a6a6238fb74af5cd99f4585a163aec68d

There are several popupshown listeners, they conflict each other, in this failure case especially OverflowableToolbar and PanelMultiView.

Comment 12

[Kris Maglione [:kmag]]

Attachment: Bug 1442187: Wait until next tick after popupshown before resolving show().

With the migration of Promise microtasks to the main microtask queue, promise
resolution handlers are now called immediately after any JS event listener
returns. The result of this is that in the case of the show() method, the
resolution handlers now run before the view's own popupshown handlers run and
the view is set active, which breaks handlers which expect it to act more
sensibly.

By deferring the resolution until the next tick, the resolution handlers are
called when the view is visible and in a consistent state.

Review commit: https://reviewboard.mozilla.org/r/224562/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/224562/

Comment 13

[Hiroyuki Ikezoe (:hiro)]

Thank you :kmag!!  (I'd really want to stamp r+ for the patch.:) )

Comment 14

[:Gijs (he/him)]

Comment on attachment 8955380 [details]
Bug 1442187: Wait until next tick after popupshown before resolving show().

https://reviewboard.mozilla.org/r/224562/#review230616

rs=me for fixing this issue and allowing the tests to be re-enabled.

Can you re-enable the tests in the same commit?

Separately, should we investigate using capturing listeners for the popupshown event in PanelMultiView to ensure its event handlers run before the others?

Comment 15

[Kris Maglione [:kmag]]

(In reply to :Gijs from comment #14)
> Can you re-enable the tests in the same commit?

The tests were re-enabled when the microtasks bug was backed out. I tested locally with those changes applied, though.

> Separately, should we investigate using capturing listeners for the
> popupshown event in PanelMultiView to ensure its event handlers run before
> the others?

Perhaps, but that only really helps as long as we don't have any other capturing listeners that cause similar problems. And it might get us into weird situations if some other listener cancels the popupshowing event.

But it would probably be better than the current situation.

Comment 16

[Kris Maglione [:kmag]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/2a775fb2d85e9794364569b1bff761459b270c61
Bug 1442187: Wait until next tick after popupshown before resolving show(). r=Gijs

Comment 17

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/mozilla-central/rev/2a775fb2d85e

Comment 18

[marius.santa]

Is manual testing required on this bug? If Yes, please provide some STR and the proper webextension(if required), if No set the “qe-verify-“ flag.