Closed Bug 1352711 Opened 8 years ago Closed 7 years ago

Intermittent toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_notifications.html | message queue is empty - got "[\"closed\"]", expected "[]"

Categories

(WebExtensions :: General, defect, P2)

Product:
WebExtensions
Component:
General
Type:
defect

Tracking

(firefox-esr52 unaffected, firefox55 wontfix, firefox56 fixed, firefox57 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla57
Tracking Flags:
Tracking Status
firefox-esr52 --- unaffected
firefox55 --- wontfix
firefox56 --- fixed
firefox57 --- fixed

People

(Reporter: aryx, Assigned: bsilverberg)

References

Details

(Keywords: dev-doc-complete, intermittent-failure, Whiteboard: [stockwell fixed:logic][notifications]triaged)

Attachments

(1 file)

Bug 1352711 - Add a notifications.onShown event and use it to fix an intermittent in test_ext_notifications.html,
59 bytes, text/x-review-board-request
mixedpuppy
: review+
lizzard
: approval-mozilla-beta+
Details
https://treeherder.mozilla.org/logviewer.html#?job_id=88074199&repo=mozilla-inbound 15:30:09 INFO - 1164 INFO SpawnTask.js | Entering test test_buttons_unsupported 15:30:09 INFO - 1165 INFO Extension loaded 15:30:09 INFO - Buffered messages logged at 15:30:09 15:30:09 INFO - 1166 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_notifications.html | notifications.create with buttons option threw an expected exception 15:30:09 INFO - 1167 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_notifications.html | buttons-unsupported 15:30:09 INFO - 1168 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_notifications.html | test result correct 15:30:09 INFO - 1169 INFO SpawnTask.js | Leaving test test_buttons_unsupported 15:30:09 INFO - Buffered messages finished 15:30:09 ERROR - 1170 INFO TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_notifications.html | message queue is empty - got "[\"closed\"]", expected "[]" 15:30:09 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:310:5 15:30:09 INFO - ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:27:7 15:30:09 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1220:19 15:30:09 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1229:13 15:30:09 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1229:13 15:30:09 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1229:13 15:30:09 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1229:13 15:30:09 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1229:13 15:30:09 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1229:13 15:30:09 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1229:13 15:30:09 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1229:13 15:30:09 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1229:13 15:30:09 INFO - SimpleTest.finish@SimpleTest/SimpleTest.js:1233:5 15:30:09 INFO - add_task/</<@SimpleTest/SpawnTask.js:288:11 15:30:09 INFO - onFulfilled@SimpleTest/SpawnTask.js:69:15 15:30:09 INFO - promise callback*next@SimpleTest/SpawnTask.js:104:45 15:30:09 INFO - onFulfilled@SimpleTest/SpawnTask.js:73:7 15:30:09 INFO - promise callback*next@SimpleTest/SpawnTask.js:104:45 15:30:09 INFO - onFulfilled@SimpleTest/SpawnTask.js:73:7 15:30:09 INFO - promise callback*next@SimpleTest/SpawnTask.js:104:45 15:30:09 INFO - onFulfilled@SimpleTest/SpawnTask.js:73:7 15:30:09 INFO - promise callback*next@SimpleTest/SpawnTask.js:104:45 15:30:09 INFO - onFulfilled@SimpleTest/SpawnTask.js:73:7 15:30:09 INFO - promise callback*next@SimpleTest/SpawnTask.js:104:45 15:30:09 INFO - onFulfilled@SimpleTest/SpawnTask.js:73:7 15:30:09 INFO - promise callback*next@SimpleTest/SpawnTask.js:104:45 15:30:09 INFO - onFulfilled@SimpleTest/SpawnTask.js:73:7 15:30:09 INFO - co/<@SimpleTest/SpawnTask.js:58:5 15:30:09 INFO - co@SimpleTest/SpawnTask.js:54:10 15:30:09 INFO - add_task/<@SimpleTest/SpawnTask.js:270:9 15:30:09 INFO - setTimeout handler*SimpleTest_setTimeoutShim@SimpleTest/SimpleTest.js:672:12 15:30:09 INFO - add_task@SimpleTest/SpawnTask.js:269:7 15:30:09 INFO - @toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_notifications.html:21:1
this is primarily win7-debug failures. Here is a recent log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=114790278&lineNumber=21597 and related data from the log: 0:26:50 INFO - 1804 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_notifications.html | background test passed 10:26:50 INFO - 1805 INFO SpawnTask.js | Leaving test test_notification 10:26:50 INFO - 1806 INFO SpawnTask.js | Entering test test_notification_events 10:26:50 INFO - 1807 INFO Extension loaded 10:26:50 INFO - 1808 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_notifications.html | got correct id from onClosed listener 10:26:50 INFO - 1809 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_notifications.html | got correct id from notifications.create 10:26:50 INFO - 1810 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_notifications.html | background test passed 10:26:50 INFO - 1811 INFO SpawnTask.js | Leaving test test_notification_events 10:26:50 INFO - 1812 INFO SpawnTask.js | Entering test test_notification_clear 10:26:50 INFO - 1813 INFO Extension loaded 10:26:50 INFO - Buffered messages logged at 10:21:38 10:26:50 INFO - 1814 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_notifications.html | background test passed 10:26:50 INFO - Buffered messages finished 10:26:50 ERROR - 1815 INFO TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_notifications.html | Test timed out. 10:26:50 INFO - reportError@SimpleTest/TestRunner.js:121:7 10:26:50 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7 10:26:50 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 10:26:50 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 10:26:50 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 10:26:50 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 10:26:50 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 10:26:50 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 10:26:50 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 10:26:50 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 10:26:50 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 10:26:50 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 10:26:50 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 10:26:50 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 10:26:50 INFO - TestRunner.runTests@SimpleTest/TestRunner.js:380:5 10:26:50 INFO - RunSet.runtests@SimpleTest/setup.js:194:3 10:26:50 INFO - RunSet.runall@SimpleTest/setup.js:173:5 10:26:50 INFO - hookupTests@SimpleTest/setup.js:266:5 10:26:50 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5 10:26:50 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11 10:26:50 INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3 10:26:50 INFO - hookup@SimpleTest/setup.js:246:5 10:26:50 INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=c%3A%5Cusers%5Cgenericworker%5Cappdata%5Clocal%5Ctemp&cleanupCrashes=true:11:1 10:26:51 INFO - Not taking scre enshot here: see the one that was previously logged 10:26:51 ERROR - 1816 INFO TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_notifications.html | Extension left running at test shutdown 10:26:51 INFO - ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:109:7 10:26:51 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1224:19 As this test is timing out, I don't think we need to extend it, typically on win7 debug we run in <30 seconds which leaves plenty of time to finish prior to a upper limit. I assume the test is failing to see an event. :andym, I see you are the triage owner for the toolkit:webextensions component, can you help find someone from the webextensions team to look into this in the next 2 weeks?
Flags: needinfo?(amckay)
Whiteboard: [stockwell needswork]
I'll take a look.
Assignee: nobody → bob.silverberg
Component: WebExtensions: Untriaged → WebExtensions: General
Flags: needinfo?(amckay)
Priority: -- → P2
Whiteboard: [stockwell needswork] → [stockwell needswork][notifications]triaged
From the test output we can see that the test is never seeing the "closed" message that is expected to be sent from the `browser.notifications.onClosed` event, but that the test _is_ seeing the "cleared" message that is sent from the background script after awaiting `browser.notifications.clear()`. We cannot tell from the test log whether the `clear()` method returned "true" or "false" which is unfortunate. My guess is that the call to `clear` is failing for some timing-related reason (possibly because we call clear() before the notification has been shown). The test can be changed to check the return value of `clear` in the background script, rather than passing it back to the test in a message, which will provide evidence of whether this is the case. That still won't fix the issue if I'm correct though. Perhaps we need to wait for the notification to be shown before trying to clear it? There isn't a way to do that with the current code, but we could add some code to the observer in ext-notifications.js [1] which could emit an event when the alert is shown. In order for the test to use that, we'd either need to expose it as an API event, or trigger our own test-only event that we can wait for. I think the former is better for a number of reasons: - It seems like a reasonable thing to add to the API, although I'm not sure if it will be 100% reliable on all platforms, and there's a documented issue with it when running in full-screen [2], but I think we can just include that caveat in our own documentation as well. - It will allow the test to run inside the background script, rather than having to message back and forth between the background script and the test. - Adding a test-only notification to production code seems like a bad thing to do. What do you think, Kris? [1] http://searchfox.org/mozilla-central/rev/bbc1c59e460a27b20929b56489e2e55438de81fa/toolkit/components/extensions/ext-notifications.js#52 [2] http://searchfox.org/mozilla-central/rev/bbc1c59e460a27b20929b56489e2e55438de81fa/toolkit/components/alerts/nsIAlertsService.idl#187-190
Flags: needinfo?(kmaglione+bmo)
FTR, I discussed this with Kris over IRC and he was fine with adding an onShown event.
Flags: needinfo?(kmaglione+bmo)
Keywords: dev-doc-needed
I think new APIs should at least be done in a new bug, making that a blocker to the intermittent.
Comment on attachment 8892784 [details] Bug 1352711 - Add a notifications.onShown event and use it to fix an intermittent in test_ext_notifications.html, https://reviewboard.mozilla.org/r/163770/#review169270
Attachment #8892784 - Flags: review?(mixedpuppy) → review+
Pushed by bsilverberg@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/b1f9a49249a0 Add a notifications.onShown event and use it to fix an intermittent in test_ext_notifications.html, r=mixedpuppy
https://hg.mozilla.org/mozilla-central/rev/b1f9a49249a0
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox57: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
Please request Beta approval on this.
status-firefox55: --- → wontfix
status-firefox56: --- → affected
status-firefox-esr52: --- → unaffected
Flags: needinfo?(bob.silverberg)
Comment on attachment 8892784 [details] Bug 1352711 - Add a notifications.onShown event and use it to fix an intermittent in test_ext_notifications.html, Approval Request Comment [Feature/Bug causing the regression]: 1190324 [User impact if declined]: No user impact, but this is a pretty frequent intermittent so it would be good to remove it from beta as well as nightly. [Is this code covered by automated tests?]: Yes [Has the fix been verified in Nightly?]: No [Needs manual test from QE? If yes, steps to reproduce]: No [List of other uplifts needed for the feature/fix]: None [Is the change risky?]: No [Why is the change risky/not risky?]: It's a change to a single test and a minor change to the notifications API. [String changes made/needed]: None
Flags: needinfo?(bob.silverberg)
Attachment #8892784 - Flags: approval-mozilla-beta?
Whiteboard: [stockwell needswork][notifications]triaged → [stockwell fixed:logic][notifications]triaged
Comment on attachment 8892784 [details] Bug 1352711 - Add a notifications.onShown event and use it to fix an intermittent in test_ext_notifications.html, Test fix, let's get rid of an intermittent orange.
Attachment #8892784 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
I've added a page for onShown, let me know if that covers it: https://developer.mozilla.org/en-US/Add-ons/WebExtensions/API/notifications/onShown.
Flags: needinfo?(bob.silverberg)
Looks good. Thanks Will!
Flags: needinfo?(bob.silverberg)
Is manual testing required on this bug? If yes, please provide some STR and the proper extension(if required) or set the “qe-verify -“ flag. Thanks!
Flags: needinfo?(bob.silverberg)
Flags: needinfo?(bob.silverberg) → qe-verify-
Product: Toolkit → WebExtensions
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: