Closed Bug 1264818 Opened 10 years ago Closed 10 years ago

Intermittent test_ext_notifications.html | Test timed out. | Extension left running at test shutdown

Categories

(WebExtensions :: Untriaged, defect)

Product:
WebExtensions
Component:
Untriaged
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox48 fixed, firefox49 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla49
Iteration:
48.3 - Apr 25
Tracking Flags:
Tracking Status
firefox48 --- fixed
firefox49 --- fixed

People

(Reporter: KWierso, Assigned: bsilverberg)

References

Details

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

Attachments

(1 obsolete file)

I find it very difficult to imagine how any of those three changesets could cause the problem. But, maybe I'm just not imaginative enough? Bug 1263443 only affects editor/libeditor/nsHTMLAbsPosition.cpp, and does nothing but fix a regression from a year ago that caused an incorrect attribute to be gotten/set in some editor context (presumably involving absolute positioning). Bug 1213670 does nothing but remove tests. It makes no changes outside the test-only directory dom/imptests/, except removing a reference from layout/reftests/ to said directory (after accounting for the followup patch to fix an extra line removed by mistake). Bug 1055776 just moves the three properties .namespaceURI, .prefix, and .localName from the Node interface to Element. The practical impact AFAIK is that accessing them on non-Element Nodes will now return undefined instead of null. They are not really used anyway in HTML, only XML. I grepped all the JS files included by the failing test, and found only reference to .localName (SimpleTest.js:822), which is being called on a XULElement, which extends Element, so should be unaffected. Anything is possible, of course!
Flags: needinfo?(ayg)
I wonder why this test suddenly started intermittently failing on April 13? It looks like it's always on Windows 7 debug. I could attempt to reproduce locally, but I don't have access to a Windows 7 box. Does anyone on the team? Is there a VM image available preconfigured to build Firefox on Windows 7?
Assignee: nobody → bob.silverberg
Iteration: --- → 48.3 - Apr 25
Depends on: 1265451
Luca pointed out the following exceptions that he saw in the log for one of the failures: 17:59:09 INFO - JavaScript error: chrome://extensions/content/ext-notifications.js, line 59: TypeError: notificationsMap.get(...) is undefined 17:59:09 INFO - JavaScript error: chrome://global/content/alerts/alert.js, line 269: NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS: [JavaScript Error: "notificationsMap.get(...) is undefined" {file: "chrome://extensions/content/ext-notifications.js" line: 59}]'[JavaScript Error: "notificationsMap.get(...) is undefined" {file: "chrome://extensions/content/ext-notifications.js" line: 59}]' when calling method: [nsIObserver::observe] and suggested that perhaps the problem is that the observer is firing after the extension has been unloaded. I'll see if I can repro this and also update the code to deal with that scenario.
Whiteboard: [notifications]triaged
I haven't been able to repro yet, but based on Luca's findings and a review of the code this change should be made, and could very well eliminate the intermittent failure. Luca volunteered to test it out on his Windows box at home tomorrow.
Comment on attachment 8742463 [details] MozReview Request: Bug 1264818 - Intermittent test_ext_notifications.html | Test timed out. | Extension left running at test shutdown, r?aswan https://reviewboard.mozilla.org/r/47211/#review43915 Doing this cleanup seems reasonable, though you are calling `closeAlert()` on all notifications created by an extension when that extension shuts down. I can't seem to find up to dated documentation on nsIAlertsService to see if it is expected that `observe()` gets called after close. Also, I'm having a hard time connecting this with the failures from the bug. The problem you address here is about what happens after an extension is unloaded but unloading the extension is the very last thing that happens in every test in test_ext_notifications.html!
Attachment #8742463 - Flags: review?(aswan)
https://reviewboard.mozilla.org/r/47211/#review43915 It does seem a bit odd that this is happening, and intermittenly at that, but the message that Luca uncovered specifically pointed to `file: "chrome://extensions/content/ext-notifications.js" line: 59}]' when calling method: [nsIObserver::observe]`, which is the code that gets run by the observer when an alert is closed. It also makes sense that, if the extension were unloaded at that time, `notificationsMap.get(this.extension)` would return `undefined`, so I think it *is* likely that this could be the source of the failures. The alerts are generated by the OS, not by Firefox, so it's actually not that strange that the alert might close after the extension has been unloaded. Although that happens at the end of the test, the tests do run quite quickly, so the OS might not have a chance to close the alert before the test finishes.
https://reviewboard.mozilla.org/r/47211/#review43915 Also, here are the docs that I used when working on this: https://developer.mozilla.org/en-US/docs/Mozilla/Tech/XPCOM/Reference/Interface/nsIAlertsService, the docs do make mention of the observer being called when an alert is closed.
Comment on attachment 8742463 [details] MozReview Request: Bug 1264818 - Intermittent test_ext_notifications.html | Test timed out. | Extension left running at test shutdown, r?aswan https://reviewboard.mozilla.org/r/47211/#review43959
Attachment #8742463 - Flags: review+
https://reviewboard.mozilla.org/r/47211/#review43915 Oh I definitely agree that this code is responsible for those lines in the log. But I don't see a direct connection between those lines and the test failure. But I'll comment on that separately in the bug. Regarding the other comment, the documentation you linked to doesn't document the `closeAlert()` method on `nsIAlertsSerivce`. But empirically it seems like it must be possible for the observer to be called even after calling `closeAlert()` since that's the only reasonable way to explain those errors. So, lets land this to get rid of those errors, but I don't think they're related to the intermittent failures that this bug is about.
From comparing the log of a failed run (https://treeherder.mozilla.org/logviewer.html#?job_id=25847134&repo=mozilla-inbound#L18774) with the test code (https://dxr.mozilla.org/mozilla-central/source/toolkit/components/extensions/test/mochitest/test_ext_notifications.html#85) its clear that we are in test_notifications_clear() and that all the logic in the background script has run (since we see "background test passed" on line 18773). So we're at line 112, waiting for the "closed" message, which apparently never comes. The background script should have sent the "cleared" message (since it does so right before logging the "background test passed" message) and indeed we see on line 18831 of the test log that there is an incoming message sitting unprocessed in the queue. I sampled a few other failures from treeherder and they all follow the exact same pattern. Which suggests that this is telling us about a real bug in which we're occasionally dropping the onClosed events that come from browser.notifications.clear(), but only on windows.
And, following up to my own comment, `clear()` immediately removes the notification from the notificationMap (https://dxr.mozilla.org/mozilla-central/source/toolkit/components/extensions/ext-notifications.js#44) so unless `nsIAlertsService.closeAlert()` is guaranteed to call the notification observer synchronously from `closeAlert()`, we can drop the closed notifications. Alas, the MDN docs for nsIAlertsService appear to be out of date, they don't mention `closeAlert()` at all.
Depends on: 1265716
Attachment #8742463 - Attachment is obsolete: true
Thanks Andrew. I opened bug 1265716 in order to land the fix, which will allow this to keep open to track the intermittent.
I am still not able to reproduce it on my Win7 box, but I found another bug that worth a mention (and should be fixed): the observer at line: https://dxr.mozilla.org/mozilla-central/source/toolkit/components/extensions/ext-notifications.js#54 can receive an "alertshow" topic (e.g. https://dxr.mozilla.org/mozilla-central/search?q=alertshow&redirect=false&case=true) and it wrongly assumes that it needs to remove the notification, and after that, if we try to close the alert using notifications.clear, it will fail (and return false) because the notificationId cannot be found anymore in the notification map.
(In reply to Luca Greco [:rpl] from comment #16) > the observer at line: > https://dxr.mozilla.org/mozilla-central/source/toolkit/components/extensions/ > ext-notifications.js#54 > can receive an "alertshow" topic (e.g. > https://dxr.mozilla.org/mozilla-central/ > search?q=alertshow&redirect=false&case=true) > and it wrongly assumes that it needs to remove the notification, and after > that, if we try to close the alert using notifications.clear, it will fail > (and return false) because the notificationId cannot be found anymore in the > notification map. Opened Bug 1265797 to track the above issue.
Assignee: bob.silverberg → nobody
I think the test just needs to be split up. We're doing too much in that test file.
Looks like this was fixed by https://hg.mozilla.org/mozilla-central/rev/5bdcb5693f01
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Assignee: nobody → bob.silverberg
status-firefox48: affected → fixed
status-firefox49: --- → fixed
Depends on: 1265797
Target Milestone: --- → mozilla49
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: