Closed Bug 824021 Opened 11 years ago Closed 10 years ago

Intermittent browser_625016.js | observe1: 2 windows in data written to disk - Got 1, expected 2 (and one more)

Categories

(Firefox :: Session Restore, defect)

x86
All
defect
Not set
normal

Tracking

()

RESOLVED FIXED
Firefox 31
Tracking Status
firefox29 --- fixed
firefox30 --- fixed
firefox31 --- fixed
firefox-esr24 --- fixed

People

(Reporter: emorley, Assigned: ttaubert)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 2 obsolete files)

Rev3 WINNT 6.1 mozilla-inbound debug test mochitest-browser-chrome on 2012-12-20 09:14:55 PST for push 5f697a87ec46

slave: talos-r3-w7-014

https://tbpl.mozilla.org/php/getParsedLog.php?id=18134561&tree=Mozilla-Inbound

{
WARNING: NS_ENSURE_TRUE(pusher.Push(aBoundElement)) failed: file e:/builds/moz2_slave/m-in-w32-dbg/build/content/xbl/src/nsXBLProtoImplMethod.cpp, line 321
WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x8000FFFF: file e:/builds/moz2_slave/m-in-w32-dbg/build/content/base/src/nsContentUtils.cpp, line 2954
WARNING: NS_ENSURE_TRUE(pusher.Push(aBoundElement)) failed: file e:/builds/moz2_slave/m-in-w32-dbg/build/content/xbl/src/nsXBLProtoImplMethod.cpp, line 321
************************************************************
* Call to xpconnect wrapped JSObject produced this error:  *
[Exception... "'TypeError: this.chatbar.removeAll is not a function' when calling method: [nsIRunnable::run]"  nsresult: "0x8057001c (NS_ERROR_XPC_JS_THREW_JS_OBJECT)"  location: "native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0"  data: no]
************************************************************
TEST-INFO | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | Console message: [JavaScript Error: "[Exception... "'TypeError: this.chatbar.removeAll is not a function' when calling method: [nsIRunnable::run]"  nsresult: "0x8057001c (NS_ERROR_XPC_JS_THREW_JS_OBJECT)"  location: "native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0"  data: no]"]
TEST-INFO | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | observe1: sessionstore-state-write
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | observe1: 2 windows in data being writted to disk - Got 1, expected 2
Stack trace:
    JS frame :: chrome://mochikit/content/browser-test.js :: test_is :: line 474
    JS frame :: chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js :: observe1 :: line 59
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_saveStateObject :: line 3698
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_saveState :: line 3686
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_onTimerCallback :: line 1155
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_observe :: line 596
    native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0

TEST-PASS | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | observe1: no closed windows in data being writted to disk
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | observe1: 1 closed window according to API - Got 0, expected 1
Stack trace:
    JS frame :: chrome://mochikit/content/browser-test.js :: test_is :: line 474
    JS frame :: chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js :: observe1 :: line 65
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_saveStateObject :: line 3698
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_saveState :: line 3686
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_onTimerCallback :: line 1155
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_observe :: line 596
    native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0

TEST-INFO | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | observe1: sessionstore-state-write-complete
++DOCSHELL 3379B810 == 12 [id = 2004]
++DOMWINDOW == 220 (3633DD38) [serial = 5268] [outer = 00000000]
++DOMWINDOW == 221 (36349030) [serial = 5269] [outer = 3633DCE0]
WARNING: NS_ENSURE_TRUE(mMutable) failed: file e:/builds/moz2_slave/m-in-w32-dbg/build/netwerk/base/src/nsSimpleURI.cpp, line 273
++DOMWINDOW == 222 (363489B8) [serial = 5270] [outer = 3633DCE0]
WARNING: NS_ENSURE_TRUE(mMutable) failed: file e:/builds/moz2_slave/m-in-w32-dbg/build/netwerk/base/src/nsSimpleURI.cpp, line 273
TEST-INFO | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | observe2: sessionstore-state-write
TEST-PASS | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | observe2: 1 window in data being writted to disk
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | observe2: 1 closed window in data being writted to disk - Got 0, expected 1
Stack trace:
    JS frame :: chrome://mochikit/content/browser-test.js :: test_is :: line 474
    JS frame :: chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js :: observe2 :: line 85
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_saveStateObject :: line 3698
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_saveState :: line 3686
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_onTimerCallback :: line 1155
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_observe :: line 596
    native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0

TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | observe2: 1 closed window according to API - Got 0, expected 1
Stack trace:
    JS frame :: chrome://mochikit/content/browser-test.js :: test_is :: line 474
    JS frame :: chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js :: observe2 :: line 89
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_saveStateObject :: line 3698
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_saveState :: line 3686
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_onTimerCallback :: line 1155
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: ssi_observe :: line 596
    native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0

TEST-INFO | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | observe2: sessionstore-state-write-complete
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | 1 closed window according to API - Got 0, expected 1
Stack trace:
    JS frame :: chrome://mochikit/content/browser-test.js :: test_is :: line 474
    JS frame :: chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js :: done :: line 111
    JS frame :: chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js :: observe2 :: line 95
    JS frame :: resource:///modules/sessionstore/SessionStore.jsm :: onSuccess :: line 3710
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: effort :: line 53
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: resolveDeferred :: line 125
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: then :: line 34
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: resolve :: line 167
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: resolveDeferred :: line 125
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: then :: line 34
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: resolve :: line 167
    JS frame :: resource://gre/modules/Task.jsm :: TaskImpl_run :: line 220
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: effort :: line 53
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: resolveDeferred :: line 125
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: then :: line 34
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: resolve :: line 167
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: resolveDeferred :: line 125
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: then :: line 34
    JS frame :: resource://gre/modules/commonjs/promise/core.js :: resolve :: line 167
    JS frame :: resource://gre/modules/osfile/_PromiseWorker.jsm :: onmessage :: line 134
    native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0

...
...
}
(OrangeWFM bugs not modified in > 2 months)
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → WORKSFORME
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
This shows the same symptoms as described in bug 919060 comment #133. I'm optimistic that this will be fixed by bug 919060 as well.
Depends on: 919060
I'm quite sure this has the same cause as bug 919060 described in bug 919060 comment #133.
Assignee: nobody → ttaubert
Blocks: 930967
Fixed by bug 919060. *crossing-fingers*
Status: REOPENED → RESOLVED
Closed: 11 years ago11 years ago
Resolution: --- → FIXED
Well, bug 944557 just changed the test, but obviously it was already failing intermittently.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
I unfortunately can't reproduce this locally but I assume it's somehow caused by an already running write that then fires sessionstore-state-write-complete before our actual write takes place. Just using SessionSaver.run() here is a lot simpler actually.

https://tbpl.mozilla.org/?tree=Try&rev=e4907c1ba1dd
Attachment #8400630 - Flags: review?(dteller)
Comment on attachment 8400630 [details] [diff] [review]
0001-Bug-824021-Use-SessionSaver.run-to-force-disk-writes.patch

Review of attachment 8400630 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good.
Attachment #8400630 - Flags: review?(dteller) → review+
Summary: Intermittent browser_625016.js | observe1: 2 windows in data being writted to disk - Got 1, expected 2 (followed by several more, then a timeout) → Intermittent browser_625016.js | observe1: 2 windows in data being written to disk - Got 1, expected 2 (followed by several more, then a timeout)
https://hg.mozilla.org/mozilla-central/rev/7865f11ef8d3
Status: REOPENED → RESOLVED
Closed: 11 years ago10 years ago
Resolution: --- → FIXED
Target Milestone: Firefox 28 → Firefox 31
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Summary: Intermittent browser_625016.js | observe1: 2 windows in data being written to disk - Got 1, expected 2 (followed by several more, then a timeout) → Intermittent browser_625016.js | observe1: 2 windows in data written to disk - Got 1, expected 2 (and one more)
:(
Assignee: ttaubert → nobody
(In reply to Tim Taubert [:ttaubert] from comment #98)
> :(

Don't quit on us :(. This is happening with higher frequency since the mochitest-bc chunking work landed on Friday.
Flags: needinfo?(ttaubert)
Alright, this was almost driving me mad but I think I found the culprit. Due to some message arriving late we seem to call _clearRestoringWindows() shortly before the forceSaveState() call, which leaves us with a single window instead of the expected two.

Compare a succeeding try run:
https://tbpl.mozilla.org/php/getParsedLog.php?id=37864545&tree=Try&full=1

To a failing one:
https://tbpl.mozilla.org/php/getParsedLog.php?id=37864586&tree=Try&full=1#error0

We definitely shouldn't call _clearRestoringWindows() when receiving SessionStore:update messages as those could be caused by DOMSessionStorage modifications and aren't user actions. All other messages are covered by TabOpen or TabSelect events that would then cause us to clear the set of windows to resurrect.
Assignee: nobody → ttaubert
Attachment #8400630 - Attachment is obsolete: true
Attachment #8407184 - Flags: review?(dteller)
Flags: needinfo?(ttaubert)
Try is looking quite nice.
Comment on attachment 8407184 [details] [diff] [review]
0001-Bug-824021-Don-t-clear-set-of-windows-to-resurrect-o.patch

Review of attachment 8407184 [details] [diff] [review]:
-----------------------------------------------------------------

The reasoning and Try look good.
Could you take the opportunity to document _clearRestoringWindows and explain when it should be called?
Attachment #8407184 - Flags: review?(dteller) → review+
Nice one for tracking this down - thank you! :-)
sorry had to backout this change for test failures like https://tbpl.mozilla.org/php/getParsedLog.php?id=37916943&tree=Fx-Team
That Windows-only failure did of course not show up on my Linux-only try runs :/ The test assumes that _clearRestoringWindows() is called when a tab loads, which I think we shouldn't do. A tab finishing loading doesn't indicate a user action, it could be caused by a window.location change, or a meta redirect, or lots of other things. I'll fix the test and ask for review again.
Tiny fix for browser_819510_perwindowpb.js. Failures was reproducible on my Windows VM and is gone with that patch.
Attachment #8407184 - Attachment is obsolete: true
Attachment #8407511 - Flags: review?(dteller)
Comment on attachment 8407511 [details] [diff] [review]
0001-Bug-824021-Don-t-clear-set-of-windows-to-resurrect-o.patch, v2

Review of attachment 8407511 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good.
Attachment #8407511 - Flags: review?(dteller) → review+
https://hg.mozilla.org/mozilla-central/rev/e066aad9ede3
Status: REOPENED → RESOLVED
Closed: 10 years ago10 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.