Closed Bug 1321706 Opened 8 years ago Closed 7 years ago

Intermittent browser/components/extensions/test/browser/browser_ext_sessions_restore.js | Test timed out -

Categories

(WebExtensions :: Untriaged, defect)

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

Tracking

(firefox51 unaffected, firefox52 unaffected, firefox53 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla53
Tracking Flags:
Tracking Status
firefox51 --- unaffected
firefox52 --- unaffected
firefox53 --- fixed

People

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

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Bug 1321706: Fix race in closed window handling.
59 bytes, text/x-review-board-request
mikedeboer
: review+
Details 
I have looked into this, and I have a theory about what's causing it, but I'm not sure what to do about it. This is happening on all platforms and the failure looks the same everywhere, but I have been unable to reproduce it on either OS X or my Windows VM. 

Based on what I can see in the logs, it looks like the test is timing out when waiting for a "notificationCount" message at [1], which is called from [2]. What's happening in the test at this point is that a window has been opened and some tabs have been added to the window, and then the window is closed. We are expecting a browser.sessions.onChanged event to be fired when this window is closed [3], which will then send the "notificationCount" message back to the test. The log on OS X shows that the window was opened, and the screenshot shows that the window was closed, so I believe that both of those things are happening. What is perhaps causing the failure is that this window, for some reason, when closed, is not being added to the list of closed windows by SessionStore. There is criteria that is used to decide if a window should be added to the list of closed windows [4], but I don't know why most of the time the window in question would be added, and only intermittently it is not, but that is my best guess for what is causing this intermittent.

I'm not sure how to proceed at this point. I could add some logging statements to the test to verify that what I think is happening in the test is actually happening, although I don't know that that knowledge would buy us much. If the problem really is in SessionStore when the decision is being made whether or not to add the window to the list of closed windows, then I think I'd need to add some debug logging to SessionStore, commit that, and then wait to see what info we get when these intermittents happen again. Does that sound like a reasonable approach? What else can anyone suggest?

[1] http://searchfox.org/mozilla-central/source/browser/components/extensions/test/browser/browser_ext_sessions_restore.js#52
[2] http://searchfox.org/mozilla-central/source/browser/components/extensions/test/browser/browser_ext_sessions_restore.js#75
[3] http://searchfox.org/mozilla-central/source/browser/components/extensions/test/browser/browser_ext_sessions_restore.js#15
[4] http://searchfox.org/mozilla-central/source/browser/components/sessionstore/SessionStore.jsm#1508
Flags: needinfo?(kmaglione+bmo)
Flags: needinfo?(aswan)
The failure is pretty infrequent, can you reproduce locally with "mach mochitest --run-until-failure"?
If not and this is only happening in automation, how about adding both sets of logging (to the test and to SessionStore.jsm) and run on try with --rebuild to run it a bunch of times to try to get more information?
Or talk to somebody who has worked on SessionStore.jsm to see if they have any ideas from simple inspection of the test?
Flags: needinfo?(aswan)
I think the problem here is that SessionStore.jsm periodically saves the current session (on a delay) after events that modify session data. Before getCurrentState() returns the session data, it calls _handleClosedWindows(), which iterates over all windows and calls `onClose` for the ones that are already closed. If this happens after the window begins closing, but before "domwindowclosed" is dispatched, `_notifyOfClosedObjectsChange` is never called as a result of the first `onClose` call, and the second `onClose` call winds up resolving before the first `onClose` call has gotten to the point of setting `_notifyOfClosedObjectsChange` to true.
Flags: needinfo?(kmaglione+bmo)
Assignee: nobody → kmaglione+bmo
Thanks for finding, and fixing, that, Kris.
Comment on attachment 8825966 [details]
Bug 1321706: Fix race in closed window handling.

https://reviewboard.mozilla.org/r/104014/#review104894

::: browser/components/sessionstore/SessionStore.jsm:4018
(Diff revision 1)
>        var window = windowsEnum.getNext();
>        if (window.closed) {
> -        this.onClose(window);
> +        promises.push(this.onClose(window));
>        }
>      }
> +    return Promise.all(promises);

Well, I see the race condition here and I also think you're right that it's causing this... BUT can you also look at searchfox.org/mozilla-central/source/browser/components/sessionstore/SessionStore.jsm#1312 where `Promise.resolve()` is used instead of `PromiseUtils.defer()`?
I probably missed this during a review, but I *think* that `Promise.resolve()` returns a resolved Promise object, `Promise.all(...)` will be resolved immediately as well. Am I right?
To verify this, please run this in your console:
```js
Promise.all([Promise.resolve(), Promise.resolve(), Promise.resolve()]).then(function() { console.log("done!"); });
```
Attachment #8825966 - Flags: review?(mdeboer) → review-
Comment on attachment 8825966 [details]
Bug 1321706: Fix race in closed window handling.

https://reviewboard.mozilla.org/r/104014/#review104934

Never mind that, this code just raised a red flag, but is used properly throughout this method.

So, IOW: thanks for fixing this!
Attachment #8825966 - Flags: review- → review+
Pushed by maglione.k@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/65642b8c46cf
Fix race in closed window handling. r=mikedeboer
https://hg.mozilla.org/mozilla-central/rev/65642b8c46cf
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox53: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla53
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: