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

RESOLVED FIXED in Firefox 56

Status

defect
P2
normal
RESOLVED FIXED
2 years ago
Last year

People

(Reporter: aryx, Assigned: bsilverberg)

Tracking

({dev-doc-complete, intermittent-failure})

unspecified
mozilla57
Dependency tree / graph
Bug Flags:
in-testsuite +
qe-verify -

Firefox Tracking Flags

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

Details

(Whiteboard: [stockwell fixed:logic][notifications]triaged)

Attachments

(1 attachment)

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

Comment 14

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

Comment 20

2 years ago
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)
Assignee

Comment 21

2 years ago
FTR, I discussed this with Kris over IRC and he was fine with adding an onShown event.
Flags: needinfo?(kmaglione+bmo)
Assignee

Updated

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

2 years ago
mozreview-review
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+

Comment 25

2 years ago
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: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
Please request Beta approval on this.
Flags: needinfo?(bob.silverberg)
Assignee

Comment 28

2 years ago
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+
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)
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)
Assignee

Comment 38

2 years ago
Looks good. Thanks Will!
Flags: needinfo?(bob.silverberg)

Comment 39

2 years ago
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)
Assignee

Updated

2 years ago
Flags: needinfo?(bob.silverberg) → qe-verify-

Updated

Last year
Product: Toolkit → WebExtensions
You need to log in before you can comment on or make changes to this bug.