Closed Bug 1285500 Opened 9 years ago Closed 7 years ago

Intermittent browser_ext_browserAction_popup.js | Test timed out -

Categories

(WebExtensions :: General, defect, P2)

Product:
WebExtensions
Component:
General
Type:
defect

Tracking

(firefox59 disabled)

Status:
RESOLVED FIXED
Tracking Flags:
Tracking Status
firefox59 --- disabled

People

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

References

Details

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

Attachments

(3 files)

Screenshot of state of Firefox when the test times out
131.31 KB, image/png
Details
Bug 1285500 - Rewrite browser_ext_browserAction_popup test and avoid intermittency on the 'overflow menu' test. r?mixedpuppy!
47 bytes, text/x-phabricator-request
Details | Review
Bug 1285500 - Re-enable browser_ext_browserAction_popup.js on windows opt. r?mixedpuppy!
47 bytes, text/x-phabricator-request
Details | Review
Component: General → WebExtensions
Product: Firefox → Toolkit
Priority: -- → P4
Whiteboard: triaged
Status: NEW → RESOLVED
Closed: 8 years ago
Keywords: bulk-close-intermittents
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
:andym , this is occurring again, 41 occurrences in the last 7 days. Could you, please, take a look?
Flags: needinfo?(amckay)
Whiteboard: triaged → triaged [stockwell needswork:owner]
I will look into this one.
Assignee: nobody → bob.silverberg
Component: WebExtensions: Untriaged → WebExtensions: General
Flags: needinfo?(amckay)
Priority: P4 → P2
The failure rate has gone up, there have been 134 failures in the last week. :bsilverberg Did you have the chance to look into this?
Flags: needinfo?(bob.silverberg)
Pushed by jmaher@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/412cf5a16642 Disable browser_ext_browserAction_popup.js on windows/debug for frequent failures. r=me, a=testonly
this has been disabled, please remember to enable it while working on a patch
Whiteboard: triaged [stockwell disable-recommended] → triaged [stockwell disabled]
https://hg.mozilla.org/mozilla-central/rev/412cf5a16642
Status: REOPENED → RESOLVED
Closed: 8 years ago → 8 years ago
status-firefox59: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla59
Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---
Kris, Luca and I spent a lot of time debugging and trying to figure out what's causing this intermittent, but didn't come to any concrete conclusions. We are concerned that it might not be a test issue and may be a bug in the browserAction code, or underlying popup code which is triggered by the fact that this test opens and closes the browserAction multiple times in quick succession. We were able to reproduce the failure both on Windows and on Linux running with --verify. When this fails on infra, it always seems to fail in the same place, which is after this sequence of messages: INFO - Starting next test INFO - Click browser action again, expect popup "b". INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup.js | expected popup opened - Expected: from-popup-b, Actual: from-popup-b - INFO - Closing for panel INFO - State of panel widget-overflow is: closed INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_browserAction_popup.js | Panel containing the action should be closed - INFO - Starting next test INFO - Clear popup URL. Click browser action. Expect click event. Which are followed by the timeout messages: 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 - When we reproduced the failure, it sometimes was in that place, but also occurred after other tests. When the test fails, it always seems to be with a browserAction popup open, and the popup looks empty. I am attaching a screenshot. As the person who wrote the test and the person who likely best understands both the browserAction code and the underlying popup code, could you please take a look and see if you can figure out what the problem might be?
Flags: needinfo?(bob.silverberg) → needinfo?(kmaglione+bmo)
Assignee: bob.silverberg → nobody
Product: Toolkit → WebExtensions
status-firefox58: disabled → ---
Flags: needinfo?(kmaglione+bmo)

Did you mean bug 1528098? But that was only removing dead code, so unless the test was extremely flaky, to the point of depending exactly on the kind of code the compiler generated, I don't think that my patch could change anything.

If it is bug 1528613, I'd be even more baffled :)

Flags: needinfo?(emilio)

Uhm, I meant 1528098, sorry. I'll edit the above.

Emilio, should we disable this? or can you fix it?

There are 64 total failures in the last 7 days, majority on linux, opt and pgo.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=229991066&repo=mozilla-inbound&lineNumber=4298

[task 2019-02-22T22:54:09.849Z] 22:54:09 INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_browserAction_pageAction_icon_permissions.js
[task 2019-02-22T22:54:10.680Z] 22:54:10 INFO - GECKO(6440) | 1550876050677 addons.webextension.<unknown> ERROR Loading extension 'null': Reading manifest: Error processing browser_action.default_icon: Value "chrome://browser/content/browser.xul" must either: be an object value, or match the format "strictRelativeUrl"
[task 2019-02-22T22:54:10.681Z] 22:54:10 INFO - GECKO(6440) | Extension startup failed: Extension contains packaging errors
[task 2019-02-22T22:54:10.683Z] 22:54:10 INFO - GECKO(6440) | undefined
[task 2019-02-22T22:54:10.699Z] 22:54:10 INFO - GECKO(6440) | monitorConsole | [0] matched {"message":"[JavaScript Error: "1550876050677\taddons.webextension.<unknown>\tERROR\tLoading extension 'null': Reading manifest: Error processing browser_action.default_icon: Value "chrome://browser/content/browser.xul" must either: be an object value, or match the format "strictRelativeUrl"" {file: "resource://gre/modules/Log.jsm" line: 679}]\nappend@resource://gre/modules/Log.jsm:679:12\nlog@resource://gre/modules/Log.jsm:360:16\nerror@resource://gre/modules/Log.jsm:368:10\n_logMessage@resource://gre/modules/Extension.jsm:376:26\nlogError@resource://gre/modules/Extension.jsm:372:10\npackagingError@resource://gre/modules/Extension.jsm:359:10\nmanifestError@resource://gre/modules/Extension.jsm:345:10\nparseManifest@resource://gre/modules/Extension.jsm:649:12\nasyncloadManifest@resource://gre/modules/Extension.jsm:890:12\nasync_receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:613:23\nChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:81:30\nChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:43:8\nstartup@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2055:12\ntestSecureManifestURLsDenied@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_browserAction_pageAction_icon_permissions.js:203:38\nAsyncTester_execTest/<@chrome://mochikit/content/browser-test.js:1106:34\nasyncTester_execTest@chrome://mochikit/content/browser-test.js:1134:12\nnextTest/<@chrome://mochikit/content/browser-test.js:995:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:803:59\n","errorMessage":"1550876050677\taddons.webextension.<unknown>\tERROR\tLoading extension 'null': Reading manifest: Error processing browser_action.default_icon: Value "chrome://browser/content/browser.xul" must either: be an object value, or match the format "strictRelativeUrl"","sourceName":"resource://gre/modules/Log.jsm","sourceLine":"","lineNumber":679,"columnNumber":0,"category":"XPConnect JavaScript","windowID":0,"isScriptError":true,"isConsoleEvent":false,"isWarning":false,"isException":false,"isStrict":false,"innerWindowID":0}
[task 2019-02-22T22:54:10.709Z] 22:54:10 INFO - GECKO(6440) | 1550876050699 addons.webextension.<unknown> ERROR Loading extension 'null': Reading manifest: Error processing page_action.default_icon: Value "chrome://browser/content/browser.xul" must either: be an object value, or match the format "strictRelativeUrl"
[task 2019-02-22T22:54:10.711Z] 22:54:10 INFO - GECKO(6440) | Extension startup failed: Extension contains packaging errors
[task 2019-02-22T22:54:10.712Z] 22:54:10 INFO - GECKO(6440) | undefined
[task 2019-02-22T22:54:10.729Z] 22:54:10 INFO - GECKO(6440) | monitorConsole | [0] matched {"message":"[JavaScript Error: "1550876050699\taddons.webextension.<unknown>\tERROR\tLoading extension 'null': Reading manifest: Error processing page_action.default_icon: Value "chrome://browser/content/browser.xul" must either: be an object value, or match the format "strictRelativeUrl"" {file: "resource://gre/modules/Log.jsm" line: 679}]\nappend@resource://gre/modules/Log.jsm:679:12\nlog@resource://gre/modules/Log.jsm:360:16\nerror@resource://gre/modules/Log.jsm:368:10\n_logMessage@resource://gre/modules/Extension.jsm:376:26\nlogError@resource://gre/modules/Extension.jsm:372:10\npackagingError@resource://gre/modules/Extension.jsm:359:10\nmanifestError@resource://gre/modules/Extension.jsm:345:10\nparseManifest@resource://gre/modules/Extension.jsm:649:12\nasyncloadManifest@resource://gre/modules/Extension.jsm:890:12\nasync_receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:613:23\nChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:81:30\nChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:43:8\nstartup@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2055:12\ntestSecureManifestURLsDenied@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_browserAction_pageAction_icon_permissions.js:203:38\nAsyncTester_execTest/<@chrome://mochikit/content/browser-test.js:1106:34\nasyncTester_execTest@chrome://mochikit/content/browser-test.js:1134:12\nnextTest/<@chrome://mochikit/content/browser-test.js:995:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:803:59\n","errorMessage":"1550876050699\taddons.webextension.<unknown>\tERROR\tLoading extension 'null': Reading manifest: Error processing page_action.default_icon: Value "chrome://browser/content/browser.xul" must either: be an object value, or match the format "strictRelativeUrl"","sourceName":"resource://gre/modules/Log.jsm","sourceLine":"","lineNumber":679,"columnNumber":0,"category":"XPConnect JavaScript","windowID":0,"isScriptError":true,"isConsoleEvent":false,"isWarning":false,"isException":false,"isStrict":false,"innerWindowID":0}
[task 2019-02-22T22:54:10.732Z] 22:54:10 INFO - GECKO(6440) | 1550876050710 addons.webextension.<unknown> ERROR Loading extension 'null': Reading manifest: Error processing browser_action.default_icon: Value "javascript:true" must either: be an object value, or match the format "strictRelativeUrl"
[task 2019-02-22T22:54:10.733Z] 22:54:10 INFO - GECKO(6440) | Extension startup failed: Extension contains packaging errors
[task 2019-02-22T22:54:10.734Z] 22:54:10 INFO - GECKO(6440) | undefined
[task 2019-02-22T22:54:10.743Z] 22:54:10 INFO - GECKO(6440) | monitorConsole | [0] matched {"message":"[JavaScript Error: "1550876050710\taddons.webextension.<unknown>\tERROR\tLoading extension 'null': Reading manifest: Error processing browser_action.default_icon: Value "javascript:true" must either: be an object value, or match the format "strictRelativeUrl"" {file: "resource://gre/modules/Log.jsm" line: 679}]\nappend@resource://gre/modules/Log.jsm:679:12\nlog@resource://gre/modules/Log.jsm:360:16\nerror@resource://gre/modules/Log.jsm:368:10\n_logMessage@resource://gre/modules/Extension.jsm:376:26\nlogError@resource://gre/modules/Extension.jsm:372:10\npackagingError@resource://gre/modules/Extension.jsm:359:10\nmanifestError@resource://gre/modules/Extension.jsm:345:10\nparseManifest@resource://gre/modules/Extension.jsm:649:12\nasyncloadManifest@resource://gre/modules/Extension.jsm:890:12\nasync_receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:613:23\nChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:81:30\nChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:43:8\nstartup@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2055:12\ntestSecureManifestURLsDenied@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_browserAction_pageAction_icon_permissions.js:203:38\nAsyncTester_execTest/<@chrome://mochikit/content/browser-test.js:1106:34\nasyncTester_execTest@chrome://mochikit/content/browser-test.js:1134:12\nnextTest/<@chrome://mochikit/content/browser-test.js:995:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:803:59\n","errorMessage":"1550876050710\taddons.webextension.<unknown>\tERROR\tLoading extension 'null': Reading manifest: Error processing browser_action.default_icon: Value "javascript:true" must either: be an object value, or match the format "strictRelativeUrl"","sourceName":"resource://gre/modules/Log.jsm","sourceLine":"","lineNumber":679,"columnNumber":0,"category":"XPConnect JavaScript","windowID":0,"isScriptError":true,"isConsoleEvent":false,"isWarning":false,"isException":false,"isStrict":false,"innerWindowID":0}
[task 2019-02-22T22:54:10.744Z] 22:54:10 INFO - GECKO(6440) | 1550876050731 addons.webextension.<unknown> ERROR Loading extension 'null': Reading manifest: Error processing page_action.default_icon: Value "javascript:true" must either: be an object value, or match the format "strictRelativeUrl"
[task 2019-02-22T22:54:10.745Z] 22:54:10 INFO - GECKO(6440) | Extension startup failed: Extension contains packaging errors
[task 2019-02-22T22:54:10.746Z] 22:54:10 INFO - GECKO(6440) | undefined
[task 2019-02-22T22:54:10.755Z] 22:54:10 INFO - GECKO(6440) | monitorConsole | [0] matched {"message":"[JavaScript Error: "1550876050731\taddons.webextension.<unknown>\tERROR\tLoading extension 'null': Reading manifest: Error processing page_action.default_icon: Value "javascript:true" must either: be an object value, or match the format "strictRelativeUrl"" {file: "resource://gre/modules/Log.jsm" line: 679}]\nappend@resource://gre/modules/Log.jsm:679:12\nlog@resource://gre/modules/Log.jsm:360:16\nerror@resource://gre/modules/Log.jsm:368:10\n_logMessage@resource://gre/modules/Extension.jsm:376:26\nlogError@resource://gre/modules/Extension.jsm:372:10\npackagingError@resource://gre/modules/Extension.jsm:359:10\nmanifestError@resource://gre/modules/Extension.jsm:345:10\nparseManifest@resource://gre/modules/Extension.jsm:649:12\nasyncloadManifest@resource://gre/modules/Extension.jsm:890:12\nasync_receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:613:23\nChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:81:30\nChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:43:8\nstartup@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2055:12\ntestSecureManifestURLsDenied@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_browserAction_pageAction_icon_permissions.js:203:38\nAsyncTester_execTest/<@chrome://mochikit/content/browser-test.js:1106:34\nasyncTester_execTest@chrome://mochikit/content/browser-test.js:1134:12\nnextTest/<@chrome://mochikit/content/browser-test.js:995:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:803:59\n","errorMessage":"1550876050731\taddons.webextension.<unknown>\tERROR\tLoading extension 'null': Reading manifest: Error processing page_action.default_icon: Value "javascript:true" must either: be an object value, or match the format "strictRelativeUrl"","sourceName":"resource://gre/modules/Log.jsm","sourceLine":"","lineNumber":679,"columnNumber":0,"category":"XPConnect JavaScript","windowID":0,"isScriptError":true,"isConsoleEvent":false,"isWarning":false,"isException":false,"isStrict":false,"innerWindowID":0}
[task 2019-02-22T22:54:10.764Z] 22:54:10 INFO - GECKO(6440) | MEMORY STAT | vsize 691MB | residentFast 350MB | heapAllocated 145MB
[task 2019-02-22T22:54:10.765Z] 22:54:10 INFO - TEST-OK | browser/components/extensions/test/browser/browser_ext_browserAction_pageAction_icon_permissions.js | took 912ms
[task 2019-02-22T22:54:10.786Z] 22:54:10 INFO - checking window state
[task 2019-02-22T22:54:10.823Z] 22:54:10 INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_browserAction_popup.js

[task 2019-02-22T22:54:56.455Z] 22:54:56 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_browserAction_popup.js | expected popup opened - Expected: from-popup-a, Actual: from-popup-a -
[task 2019-02-22T22:54:56.456Z] 22:54:56 INFO - Starting next test
[task 2019-02-22T22:54:56.456Z] 22:54:56 INFO - Call triggerAction again. Expect remaining popup closed.
[task 2019-02-22T22:54:56.456Z] 22:54:56 INFO - Popup is open. Waiting for close
[task 2019-02-22T22:54:56.457Z] 22:54:56 INFO - Buffered messages finished
[task 2019-02-22T22:54:56.458Z] 22:54:56 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_browserAction_popup.js | Test timed out -
[task 2019-02-22T22:54:56.459Z] 22:54:56 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-02-22T22:54:56.460Z] 22:54:56 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_browserAction_popup.js | Extension left running at test shutdown -
[task 2019-02-22T22:54:56.460Z] 22:54:56 INFO - Stack trace:
[task 2019-02-22T22:54:56.461Z] 22:54:56 INFO - chrome://mochikit/content/browser-test.js:test_ok:1304
[task 2019-02-22T22:54:56.461Z] 22:54:56 INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
[task 2019-02-22T22:54:56.462Z] 22:54:56 INFO - chrome://mochikit/content/browser-test.js:nextTest:705
[task 2019-02-22T22:54:56.462Z] 22:54:56 INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1202
[task 2019-02-22T22:54:56.463Z] 22:54:56 INFO - setTimeout handlerchrome://mochikit/content/browser-test.js:Tester_execTest:1164
[task 2019-02-22T22:54:56.463Z] 22:54:56 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:995
[task 2019-02-22T22:54:56.464Z] 22:54:56 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
[task 2019-02-22T22:54:56.465Z] 22:54:56 INFO - GECKO(6440) | JavaScript error: chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_browserAction_popup.js, line 16: TypeError: ext is undefined
[task 2019-02-22T22:54:56.466Z] 22:54:56 INFO - Console message: [JavaScript Error: "Promise rejected after context unloaded: Message manager disconnected
[task 2019-02-22T22:54:56.466Z] 22:54:56 INFO - " {file: "moz-extension://d0ba6e8b-aa95-4fa5-867f-ae7df9c19789/popup-a.js" line: 5}]
[task 2019-02-22T22:54:56.467Z] 22:54:56 INFO - window.onload@moz-extension://d0ba6e8b-aa95-4fa5-867f-ae7df9c19789/popup-a.js:5:27
[task 2019-02-22T22:54:56.467Z] 22:54:56 INFO -
[task 2019-02-22T22:54:56.468Z] 22:54:56 INFO - Console message: [JavaScript Error: "Promise rejected after context unloaded: Message manager disconnected
[task 2019-02-22T22:54:56.469Z] 22:54:56 INFO - " {file: "moz-extension://d0ba6e8b-aa95-4fa5-867f-ae7df9c19789/popup-a.js" line: 5}]
[task 2019-02-22T22:54:56.469Z] 22:54:56 INFO - window.onload@moz-extension://d0ba6e8b-aa95-4fa5-867f-ae7df9c19789/popup-a.js:5:27
[task 2019-02-22T22:54:56.470Z] 22:54:56 INFO -
[task 2019-02-22T22:54:56.470Z] 22:54:56 INFO - Console message: [JavaScript Error: "TypeError: ext is undefined" {file: "chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_browserAction_popup.js" line: 16}]
[task 2019-02-22T22:54:56.472Z] 22:54:56 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-02-22T22:54:56.473Z] 22:54:56 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_browserAction_popup.js | A promise chain failed to handle a rejection: ext is undefined - stack: assertViewCount@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_browserAction_popup.js:16:3
[task 2019-02-22T22:54:56.473Z] 22:54:56 INFO - testInArea/<@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_browserAction_popup.js:222:7
[task 2019-02-22T22:54:56.473Z] 22:54:56 INFO - asynctestMessage@chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:79:9
[task 2019-02-22T22:54:56.474Z] 22:54:56 INFO - listener@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2088:33
[task 2019-02-22T22:54:56.474Z] 22:54:56 INFO - loadExtension/<@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2021:13
[task 2019-02-22T22:54:56.474Z] 22:54:56 INFO - ChromePowers.prototype._sendReply@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:33:28
[task 2019-02-22T22:54:56.475Z] 22:54:56 INFO - messageListener@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:587:16
[task 2019-02-22T22:54:56.475Z] 22:54:56 INFO - emit@resource://gre/modules/ExtensionCommon.jsm:310:24
[task 2019-02-22T22:54:56.476Z] 22:54:56 INFO - receiveMessage@resource://gre/modules/Extension.jsm:1524:20
[task 2019-02-22T22:54:56.476Z] 22:54:56 INFO - MessageListener.receiveMessageExtension@resource://gre/modules/Extension.jsm:1380:19
[task 2019-02-22T22:54:56.476Z] 22:54:56 INFO - generate@resource://testing-common/ExtensionTestCommon.jsm:384:12
[task 2019-02-22T22:54:56.477Z] 22:54:56 INFO - _receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:579:45
[task 2019-02-22T22:54:56.477Z] 22:54:56 INFO - ChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:81:30
[task 2019-02-22T22:54:56.477Z] 22:54:56 INFO - ChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:43:8
[task 2019-02-22T22:54:56.478Z] 22:54:56 INFO - loadExtension@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2070:10
[task 2019-02-22T22:54:56.478Z] 22:54:56 INFO - ExtensionTestUtils.loadExtension@chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:105:33
[task 2019-02-22T22:54:56.478Z] 22:54:56 INFO - testInArea@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_browserAction_popup.js:22:38
[task 2019-02-22T22:54:56.479Z] 22:54:56 INFO - asynctestBrowserActionInPanel@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_browserAction_popup.js:270:9
[task 2019-02-22T22:54:56.479Z] 22:54:56 INFO - AsyncTester_execTest/<@chrome://mochikit/content/browser-test.js:1106:34
[task 2019-02-22T22:54:56.479Z] 22:54:56 INFO - asyncTester_execTest@chrome://mochikit/content/browser-test.js:1134:12
[task 2019-02-22T22:54:56.480Z] 22:54:56 INFO - nextTest/<@chrome://mochikit/content/browser-test.js:995:14
[task 2019-02-22T22:54:56.480Z] 22:54:56 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:803:59
[task 2019-02-22T22:54:56.480Z] 22:54:56 INFO - Rejection date: Fri Feb 22 2019 22:54:55 GMT+0000 (Coordinated Universal Time) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 257
[task 2019-02-22T22:54:56.481Z] 22:54:56 INFO - Stack trace:
[task 2019-02-22T22:54:56.481Z] 22:54:56 INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:257
[task 2019-02-22T22:54:56.481Z] 22:54:56 INFO - chrome://mochikit/content/browser-test.js:nextTest:745
[task 2019-02-22T22:54:56.482Z] 22:54:56 INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1202
[task 2019-02-22T22:54:56.482Z] 22:54:56 INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1164
[task 2019-02-22T22:54:56.482Z] 22:54:56 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:995
[task 2019-02-22T22:54:56.482Z] 22:54:56 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
[task 2019-02-22T22:54:56.483Z] 22:54:56 INFO - GECKO(6440) | MEMORY STAT | vsize 700MB | residentFast 324MB | heapAllocated 95MB
[task 2019-02-22T22:54:56.484Z] 22:54:56 INFO - TEST-OK | browser/components/extensions/test/browser/browser_ext_browserAction_popup.js | took 45088ms

Flags: needinfo?(emilio)

As I said I'm pretty sure my patch is not related to this failure. Seems like the extension is not there in assertViewCount, but I'm not quite sure how can that happen, not familiar with any of the extensions code.

Maybe aswan knows?

Flags: needinfo?(emilio) → needinfo?(aswan)

(In reply to Emilio Cobos Álvarez (:emilio) from comment #45)

As I said I'm pretty sure my patch is not related to this failure. Seems like the extension is not there in assertViewCount, but I'm not quite sure how can that happen, not familiar with any of the extensions code.

It looks that the actual failure for the test is a timeout while waiting the popup to be closed, the "TypeError: ext is undefined" error message triggered from assertViewCount looks like a side effect of the timeout failures (basically the popup is being closed when the test is exiting because of the timeout, and the extension has been already unloaded at that point).

At a first glance it seems to be that the test timeout is always happening while testing the browserAction popup from the overflow menu, personally I don't see how bug 1528098 could have any role on triggering this intermittent, my guess it that bug 1528098 is unrelated.

Maybe aswan knows?

I'm moving the needinfo from aswan to me, as I'm already been looking into a number of intermittents related to the browserAction popups lately, I'm going to take a look at this one too.

Flags: needinfo?(aswan) → needinfo?(lgreco)

This test failure has started to spike on Feb 15, and looking to the most recent changes applied to files that could trigger this failure, my guess was that my changes from Bug 1446027 are the only ones that could have started to trigger this kind of failure, and the push date for 4e0d6226ba5f is exactly Feb 15.

As mentioned in comment 47 the failure is always happening while the browserAction is placed in the overflow menu, I've been able to trigger the failure locally (on linux64 opt, using --verify) and then double-check that the failure can't be reproduced anymore when all the changes introduced from Bug 1446027 on ExtensionPopups.jsm are reverted.

It seems that the small additional lag time introduced by the await on the promise returned by promiseDocumentFlushed is what is making the rapid sequence of test cases able to get stuck when the browserAction panel is a subview of the overflow panel, by avoiding to wait for promiseDocumentFlushed only when the browserAction is placed in the overflow panel seems to be also enough to fix the test failure.

Alternatively, another option could be to rewrite the test and make it able to prevent that race from being triggered (e.g. by making sure that we always await the popup to be completely load and ready before proceeding with the rest of the test).

Flags: needinfo?(lgreco)

This patch rewrites the browser_ext_browserAction_popup.js test file to make it easier to follow the
sequence of its test cases (in the previous version of this test file, the logic that was executing
the sequence of test cases was fragmented in a bunch of listeners, in both the test extension and
the privileged test code) and to make the test able to wait for the popups to be fully loaded or
fully destroyed before moving to the next test case.

Assignee: nobody → lgreco
Status: REOPENED → ASSIGNED

Pushed by apavel@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a56af9e8313b
Rewrite browser_ext_browserAction_popup test and avoid intermittency on the 'overflow menu' test. r=mixedpuppy

Keywords: checkin-needed
Pushed by luca.greco@alcacoop.it: https://hg.mozilla.org/integration/autoland/rev/db533ea3d561 Re-enable browser_ext_browserAction_popup.js on windows opt. r=mixedpuppy
Status: ASSIGNED → RESOLVED
Closed: 8 years ago → 7 years ago
Keywords: leave-open
Resolution: --- → FIXED
Whiteboard: triaged [stockwell disabled] → triaged [stockwell fixed]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: