Intermittent browser_ext_browserAction_popup.js | Test timed out -

RESOLVED FIXED

Status

defect
P2
normal
RESOLVED FIXED
3 years ago
3 months ago

People

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

Tracking

({intermittent-failure})

unspecified

Firefox Tracking Flags

(firefox59 disabled)

Details

(Whiteboard: triaged [stockwell fixed])

Attachments

(3 attachments)

Updated

3 years ago
Component: General → WebExtensions
Product: Firefox → Toolkit

Updated

3 years ago
Priority: -- → P4
Whiteboard: triaged
Comment hidden (Intermittent Failures Robot)
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
: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
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
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)
Comment hidden (Intermittent Failures Robot)

Comment 13

2 years ago
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]

Comment 15

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/412cf5a16642
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
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)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Duplicate of this bug: 1419872
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Assignee: bob.silverberg → nobody
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)

Updated

Last year
Product: Toolkit → WebExtensions
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.

Comment hidden (Intermittent Failures Robot)

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 - async
testMessage@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 - async
testBrowserActionInPanel@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 - async
Tester_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)
Comment hidden (Intermittent Failures Robot)
Assignee

Comment 47

4 months ago

(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)
Assignee

Comment 48

4 months ago

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)
Assignee

Comment 49

4 months ago

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

Updated

4 months ago
Assignee: nobody → lgreco
Status: REOPENED → ASSIGNED

Comment 50

4 months ago

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

Comment 53

4 months ago
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
Comment hidden (Intermittent Failures Robot)
Assignee

Updated

4 months ago
Status: ASSIGNED → RESOLVED
Closed: 2 years ago4 months ago
Keywords: leave-open
Resolution: --- → FIXED
Whiteboard: triaged [stockwell disabled] → triaged [stockwell fixed]
Comment hidden (Intermittent Failures Robot)
You need to log in before you can comment on or make changes to this bug.