Closed Bug 618188 Opened 14 years ago Closed 13 years ago

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

Categories

(Firefox :: Session Restore, defect)

Product:
Firefox
Component:
Session Restore
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 6
Tracking Flags:
Tracking Status
status2.0 --- ?

People

(Reporter: cmtalbert, Assigned: ttaubert)

References

Details

(Keywords: intermittent-failure)

Attachments

(3 files, 4 obsolete files)

Full text of the failing tests' run from the log
31.27 KB, text/plain
Details
patch for checkin
2.73 KB, patch
Details | Diff | Splinter Review
Possible fix
1.55 KB, patch
zpao
: review+
Details | Diff | Splinter Review 
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
(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.
(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
Summary: browser-chrome: browser_600545.js intermittently times out → browser-chrome: browser_600545.js (and browser_601955.js) intermittently times out
Version: unspecified → Trunk
Summary: browser-chrome: browser_600545.js (and browser_601955.js) intermittently times out → browser-chrome: browser_600545.js (and _601955.js) intermittently times out
OS: Mac OS X → All
Depends on: 618470
Assignee: nobody → tim.taubert
Status: NEW → ASSIGNED
Attached patch patch v1 (obsolete) — — Splinter Review 

        Attachment #528291 -
        Flags: review?(paul)

    
  
Blocks: 651643

    
    

    
  
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+

    
    

    
  

      
      
      
      

        Attached patch
          
          
        patch for checkin (obsolete)
        — 
          — Splinter Review
      

    


  
(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

    
  
Keywords: checkin-needed

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  
Keywords: checkin-needed
Whiteboard: [orange] → [fixed in cedar]

    
    

    
  
Pushed:
https://bugzilla.mozilla.org/show_bug.cgi?id=618188
Status: ASSIGNED → RESOLVED
Closed: 13 years ago
Flags: in-litmus+
Resolution: --- → FIXED
Whiteboard: [fixed in cedar]
Target Milestone: --- → Firefox 6

    
  
Whiteboard: [orange]

    
    

    
      
  

    
    

    
  
Still seems to be timing out
Status: RESOLVED → REOPENED
Resolution: FIXED → ---

    
    

    
  
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?

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  

      
      
      
      

        Attached patch
          
          
        patch v2 (obsolete)
        — 
          — Splinter Review
      

    


  
(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 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-

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  

      
      
      
      

        Attached patch
          
          
        patch v3 (obsolete)
        — 
          — Splinter Review
      

    


  

        Attachment #529805 -
        Attachment is obsolete: true

        Attachment #531904 -
        Flags: review?(paul)

    
    

    
      
  

    
    

    
      
  

    
    

    
  
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+

    
    

    
      
  

    
    

    
  


  
(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

    
  
Keywords: checkin-needed
Flags: in-litmus+
Keywords: checkin-needed
Hardware: x86 → All
Whiteboard: [orange] → [orange][fixed in cedar]

    
    

    
      
  

    
    

    
  
Pushed:
http://hg.mozilla.org/mozilla-central/rev/fff184536887
Status: REOPENED → RESOLVED
Closed: 13 years ago → 13 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 → ---

    
    

    
      
  

    
    

    
  
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?

    
    

    
  

      
      
      
      

        Attached patch
          
          
        Possible fix
        — 
          — Splinter Review
      

    


  
(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.

    
    

    
  
(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 on attachment 533512 [details] [diff] [review]
Possible fix

Ah, good catch. Thanks!

        Attachment #533512 -
        Flags: review?(paul) → review+

    
  
Status: REOPENED → RESOLVED
Closed: 13 years ago → 13 years ago
Resolution: --- → FIXED

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  
Whiteboard: [orange]

          You need to log in
          before you can comment on or make changes to this bug.
        






  

    
  







  

    

      
Attachment

      

      
      
      
      
    

    

      

        

          

            
General

            

              Creator: 



            

            
Created: 

            
Updated: 

            
Size: