The default bug view has changed. See this FAQ.

browser-chrome: browser_600545.js (and _601955.js) intermittently times out

RESOLVED FIXED in Firefox 6

Status

()

Firefox
Session Restore
RESOLVED FIXED
6 years ago
4 years ago

People

(Reporter: cmtalbert, Assigned: ttaubert)

Tracking

({intermittent-failure})

Trunk
Firefox 6
intermittent-failure
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(status2.0 ?)

Details

Attachments

(3 attachments, 4 obsolete attachments)

(Reporter)

Description

6 years ago
The browser chrome test browser_600545.js intermittently times out and then causes a few other errors afterward saying "found a tab after previous test timed out"

Zpao was saying that it might be a listener being removed too late when a tab is closing. The test was found to be flaky in running solo mode as well on bug 600545.

also there are some odd warnings scattered about the logs: "NetworkPrioritizer.jsm, line 117: reference to undefined property aBrowser.webNavigation" too, which may not be related.  Filing a separate bug on that too.

                aBrowser.webNavigation" 
Log: http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1291939684.1291942553.22646.gz&fulltext=1#err0

Rev3 MacOSX Leopard 10.5.8 mozilla-central debug test mochitest-other on 2010/12/09 16:08:04

s: talos-r3-leopard-008
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser/browser_600545.js | Test timed out
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser/browser_600545.js | Found a tab after previous test timed out: http://example.com/#2
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser/browser_600545.js | Found a tab after previous test timed out: http://example.com/#1
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser/browser_600545.js | Found a browser window after previous test timed out
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser/browser_600545.js | Number of tabs in retreived session data, matches number of tabs set. - Got 1, expected 7
(Reporter)

Comment 1

6 years ago
(In reply to comment #0)
> also there are some odd warnings scattered about the logs:
> "NetworkPrioritizer.jsm, line 117: reference to undefined property
> aBrowser.webNavigation" too, which may not be related.  Filing a separate bug
> on that too.
That's covered in bug 618193.
(Reporter)

Comment 2

6 years ago
Created attachment 496704 [details]
Full text of the failing tests' run from the log
(In reply to comment #0)
> Zpao was saying that it might be a listener being removed too late when a tab
> is closing.

I think I intended this for the NetworkPrioritizer warnings in bug 618193
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Summary: browser-chrome: browser_600545.js intermittently times out → browser-chrome: browser_600545.js (and browser_601955.js) intermittently times out
Version: unspecified → Trunk
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Summary: browser-chrome: browser_600545.js (and browser_601955.js) intermittently times out → browser-chrome: browser_600545.js (and _601955.js) intermittently times out
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
status2.0: --- → ?
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
OS: Mac OS X → All
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Updated

6 years ago
Depends on: 618470
(Assignee)

Updated

6 years ago
Assignee: nobody → tim.taubert
Status: NEW → ASSIGNED
(Assignee)

Comment 179

6 years ago
Created attachment 528291 [details] [diff] [review]
patch v1
Attachment #528291 - Flags: review?(paul)
(Assignee)

Updated

6 years ago
Blocks: 651643
(Assignee)

Comment 180

6 years ago
Comment on attachment 528291 [details] [diff] [review]
patch v1

Passed try:

http://tbpl.mozilla.org/?tree=Try&pusher=tim.taubert@gmx.de&rev=92d26f4d79b1
Comment on attachment 528291 [details] [diff] [review]
patch v1

Review of attachment 528291 [details] [diff] [review]:

let is the new var! Otherwise that should be fine.
Attachment #528291 - Flags: review?(paul) → review+
(Assignee)

Comment 182

6 years ago
Created attachment 528410 [details] [diff] [review]
patch for checkin

(In reply to comment #181)
> let is the new var! Otherwise that should be fine.

Of course, damn copy'n'paste :)
Attachment #528291 - Attachment is obsolete: true
(Assignee)

Updated

6 years ago
Keywords: checkin-needed
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Keywords: checkin-needed
Whiteboard: [orange] → [fixed in cedar]
Pushed:
https://bugzilla.mozilla.org/show_bug.cgi?id=618188
Status: ASSIGNED → RESOLVED
Last Resolved: 6 years ago
Flags: in-litmus+
Resolution: --- → FIXED
Whiteboard: [fixed in cedar]
Target Milestone: --- → Firefox 6

Updated

6 years ago
Whiteboard: [orange]
Comment hidden (Treeherder Robot)

Comment 188

6 years ago
Still seems to be timing out
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
(Assignee)

Comment 189

6 years ago
It timed out while waiting for the session state to be saved:

>  waitForBrowserState(state, function() {
>    waitForSaveState(function () {

Paul: As waitForBrowserState() uses executeSoon() to execute the callback, is it possible that the state has been saved already by "sessionstore.interval" or something equivalent?
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1304352830.1304356602.27596.gz
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 194

6 years ago
Created attachment 529805 [details] [diff] [review]
patch v2

(In reply to comment #189)
> It timed out while waiting for the session state to be saved:
> 
> >  waitForBrowserState(state, function() {
> >    waitForSaveState(function () {
> 
> Paul: As waitForBrowserState() uses executeSoon() to execute the callback, is
> it possible that the state has been saved already by "sessionstore.interval" or
> something equivalent?

sessionstore.interval decreased to 2000ms.
Attachment #528410 - Attachment is obsolete: true
Attachment #529805 - Flags: review?(paul)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment on attachment 529805 [details] [diff] [review]
patch v2

>+  Services.prefs.setIntPref("browser.sessionstore.interval", 2000);

I don't think this is going to help. If the problem is that we're saving before waitForSaveState, then making the timer shorter would actually just exacerbate the problem (I think).

Really we want something like I just proposed in bug 656147.

But until that happens, we can work around this more scientifically than just grasping at straws:
* In waitForSaveState, look up sessionstore.interval, then add 1000 (just to be sure, give time for JSON crap, writing to disk since that happens after the interval timer)
* create a one shot timer which would just call aSaveStateCallback (and remove the observer), then start it
* in the observer callback, cancel the timer
* keep sessionstore.interval to something small like you have.

This *should* make sure that we never just get stuck waiting for a notification that's not coming (and it doesn't matter that it's not coming because it's already happened)

Tim: Do you still want to own this bug and take the above on?
Attachment #529805 - Flags: review?(paul) → review-
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 209

6 years ago
Created attachment 531904 [details] [diff] [review]
patch v3
Attachment #529805 - Attachment is obsolete: true
Attachment #531904 - Flags: review?(paul)
(Assignee)

Comment 210

6 years ago
Comment on attachment 531904 [details] [diff] [review]
patch v3

Passed try:

http://tbpl.mozilla.org/?tree=Try&pusher=tim.taubert@gmx.de&rev=b2f2899ca3a0
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment on attachment 531904 [details] [diff] [review]
patch v3

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

::: browser/components/sessionstore/test/browser/head.js
@@ +126,3 @@
>    function observer(aSubject, aTopic, aData) {
>      Services.obs.removeObserver(observer, topic, false);
> +    clearTimeout(timeout);

Let's make this
> timeout = clearTimeout(timeout);

@@ +133,4 @@
>    registerCleanupFunction(function() {
>      if (observing) {
>        Services.obs.removeObserver(observer, topic, false);
>      }

And that way here we can say
> if (timeout) clearTimeout...
just to make sure that we don't accidentally call that when we shouldn't
Attachment #531904 - Flags: review?(paul) → review+
Comment hidden (Treeherder Robot)
(Assignee)

Comment 215

6 years ago
Created attachment 532770 [details] [diff] [review]
patch for checkin

(In reply to comment #213)
> Let's make this
> > timeout = clearTimeout(timeout);
> 
> And that way here we can say
> > if (timeout) clearTimeout...
> just to make sure that we don't accidentally call that when we shouldn't

Fixed.
Attachment #531904 - Attachment is obsolete: true
(Assignee)

Updated

6 years ago
Keywords: checkin-needed
Flags: in-litmus+
Keywords: checkin-needed
Hardware: x86 → All
Whiteboard: [orange] → [orange][fixed in cedar]
Comment hidden (Treeherder Robot)
Pushed:
http://hg.mozilla.org/mozilla-central/rev/fff184536887
Status: REOPENED → RESOLVED
Last Resolved: 6 years ago6 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Whiteboard: [orange][fixed in cedar] → [orange]
Just saw this random orange. Starring now.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Comment hidden (Treeherder Robot)
Actually, this is different than the timeout. It looks to be related to the new patch. Should I open a new bug?
Quick guess, it looks like the observer can get removed twice in this test. Which might perhaps trigger the assertion in the log?
Created attachment 533512 [details] [diff] [review]
Possible fix

(In reply to comment #221)
> Quick guess, it looks like the observer can get removed twice in this test.
> Which might perhaps trigger the assertion in the log?

I think so, but I have no idea how could it be happened yet.
Attachment #533512 - Flags: review?(paul)
Hmm, perhaps somehow the test finishes before the timeout? In any case that patch looks like it should prevent such a problem.
(Assignee)

Comment 224

6 years ago
(In reply to comment #222)
> I think so, but I have no idea how could it be happened yet.

The setTimeout callback doesn't set "observing = false". So in case we trigger the actual timeout which was intermittent before we now fail because we try to remove the observer a second time when cleaning up. Damn :/

Your patch looks good and should solve that!
Comment hidden (Treeherder Robot)
Comment on attachment 533512 [details] [diff] [review]
Possible fix

Ah, good catch. Thanks!
Attachment #533512 - Flags: review?(paul) → review+
Keywords: checkin-needed
Pushed followup: http://hg.mozilla.org/mozilla-central/rev/4f5014edbd42
Keywords: checkin-needed

Updated

6 years ago
Status: REOPENED → RESOLVED
Last Resolved: 6 years ago6 years ago
Resolution: --- → FIXED
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Keywords: intermittent-failure
Whiteboard: [orange]
You need to log in before you can comment on or make changes to this bug.