Closed Bug 518970 Opened 15 years ago Closed 14 years ago

frequent timeout in browser_394759_privatebrowsing.js, caused by browser_394759.js and browser_354894.js

Categories

(Firefox :: Session Restore, defect)

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

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 3.7a3
Tracking Flags:
Tracking Status
blocking2.0 --- final+
status1.9.2 --- .4-fixed
status1.9.1 --- .10-fixed

People

(Reporter: dholbert, Assigned: ehsan.akhgari)

References

(
URL
)

Details

(Keywords: intermittent-failure, Whiteboard: [test which aborts the suite])

Attachments

(4 files, 6 obsolete files)

[fail] browser state after testOpenCloseRestoreFromPopup in browser_354894.js
5.89 KB, text/plain
Details
[pass] browser state after testOpenCloseRestoreFromPopup in browser_354894.js
6.00 KB, text/plain
Details
Patch to land
1.18 KB, patch
beltzner
: approval1.9.2.4+
beltzner
: approval1.9.1.10+
Details | Diff | Splinter Review
Remove the debugging info
4.18 KB, patch
dao
: review+
Details | Diff | Splinter Review 
Just seen on Firefox-Unittest tinderbox page:

WINNT 5.2 mozilla-central test opt everythingelse on 2009/09/25 14:46:12
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1253915172.1253918100.15234.gz#err0
{
Running chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js...
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | sessionstore.js was removed

command timed out: 1200 seconds without output
program finished with exit code 1
}

There were only two possibly-guilty changesets -- one was mac-only, and one was a fix in a different test:
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=213da42e5f65&tochange=8b4d2fc47ecf

So, I'm calling this sporadic.
Component: Private Browsing → Session Restore
QA Contact: private.browsing → session.restore
Whiteboard: [orange] [test which aborts the suite]
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1254517284.1254520123.21915.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/02 14:01:24
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1254604259.1254607095.2327.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/03 14:10:59
Assignee: nobody → mak77
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1255083586.1255086209.4141.gz#err0
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/09 03:19:46

since problem is most likely the same as for browser_394759.js i'm going to fix it same way
Attached patch patch v1.0 (obsolete) — — Splinter Review 

        Attachment #405489 -
        Flags: review?(paul)

    
    

    
  

      
      
      
      

        Attached patch
          
          
        diff -w for easier review (obsolete)
        — 
          — Splinter Review
      

    


  

    
    

    
  
Comment on attachment 405489 [details] [diff] [review]
patch v1.0

r=zpao

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

    
    

    
  
http://hg.mozilla.org/mozilla-central/rev/2a6590861731
Status: NEW → RESOLVED
Closed: 15 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 3.7a1

    
    

    
  
at least seems to hit less.
the only difference from browser_394759.js is the useCapture on the internal addEventListeners... but i'm not sure if that could make a difference, will take a deeper look

    
    

    
  
synced usecapture just to be sure, and added a couple info() to see where we fail
http://hg.mozilla.org/mozilla-central/rev/607c935fde96

    
    

    
  
ok, so looks like one of the external "load" event listener is never called or is added too late.

    
    

    
  

      
      
      
      

        Attached patch
          
          
        cleanup event listeners v1.0 (obsolete)
        — 
          — Splinter Review
      

    


  
I can't tell offhand if this could help with the random failures, but there are a certain number of sessionstore browser tests that are not removing no more used event listeners. So i'd like to try cleaning them up.

        Attachment #405927 -
        Flags: review?(dao)

    
    

    
  
(In reply to comment #19)
> I can't tell offhand if this could help with the random failures, but there are
> a certain number of sessionstore browser tests that are not removing no more
> used event listeners. So i'd like to try cleaning them up.

There's a bug for that (which Dão tried a partial fix for): bug 507784.

    
    

    
  
thanks moving there

    
  

        Attachment #405927 -
        Attachment is obsolete: true

        Attachment #405927 -
        Flags: review?(dao)

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1255411911.1255414470.3310.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/12 22:31:51

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1255486031.1255488696.24427.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/13 19:07:11

    
    

    
  
pushed experimental change
http://hg.mozilla.org/mozilla-central/rev/af0ade2a9a1d
will backout if nothing changes.

    
    

    
  
i will backout since not getting better, but thanks to the added info i know what is failing is the first load event.
at that point we could consider to use windowmanager

    
    

    
  
backed out previous experiment
http://hg.mozilla.org/mozilla-central/rev/6240e80d2c21
pushed new experiment (using windowwatcher)
http://hg.mozilla.org/mozilla-central/rev/5ae7b09f730f

if this should work i'll ask postreview directly on the test code.

    
    

    
  
>+  // Prevent VM timers issues, cache now and increment it manually.
>+  const NOW = Date.now();

"increment it manually" isn't going to work, since it's a const.

Is the cause of the failure understood? We should try to get to that point before implementing a different approach.

    
    

    
  
woops right, well it's not a big deal for now i can fix it later in case.

I think we could try to set the load listener before the window is ready to get it (but i don't know windows opening code, for now), using the window watcher will ensure we set it when the window is ready. But if this works we can investigate deeper, backtracing code (other 2 ss tests are failing for the same cause i think). We use this ww+load method in various Places tests and they did never fail. so let's see if that helps for now.
Rather then a new approach this really is just a cleanup with a windowwatcher notification added (so the new approach is basicly adding windowwatcher notification).

    
    

    
  
or otherwise we set it too late. btw i suspect the problem is time in adding load listener, indeed the failure is pretty visible in Optimized builds that are faster.

    
    

    
  
Are you talking about this pattern?

  let newWin = openDialog(location, "_blank", "chrome,all,dialog=no", testURL_A);
  newWin.addEventListener("load", function(aEvent) {

I don't think the load event could be dispatched before the synchronous addEventListener call. We also don't seem to have a problem with that in other tests.

    
    

    
  
yes, i'm talking about that. We fail there, because we print the previous info() but we did not print the info() inside the load handler (that i added in the old experiment). Between that info and the dialog opening handlere there are only var definitions that i doubt can cause a timeout.

So either: the dialog is not opened/load is not fired/load is dired too early or too late/we crash.

i'm starting explorating the too early/too late, other ways are still open though.

    
    

    
  
oh, with windowatcher we can also discover if the problem is that the dialog is not opened for any reason.

    
    

    
  
You could easily verify your theory this way:

  let newWin = openDialog([...]);
  newWin.addEventListener("load", [...]);
  is(newWin.document.readyState, FOO, "...");

FOO should always be "uninitialized", I think, but never "complete".

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1255793142.1255795845.4927.gz#err0

so, the dialog did open (we got openwindow event), but the load event handler was not added/called! crazy.

    
    

    
  
Ah, I see your trying to protect against adding the listener too early rather than too late. That doesn't make more sense to me, though. As soon as we have a window object, it should be ready to get the event listener.

Any other idea why the event listener wouldn't be called? How about polling newWin.document.readyState and newWin.closed to figure out if the window ever finishes loading?

    
    

    
  
You could also use getListenerInfoFor from bug 448602 to verify that the listener has been added.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1255950294.1255953229.504.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/19 04:04:54

    
    

    
  
i'm starting thinking this is a real hang in sessionstore, since it has a load listener that runs before ours.
on next push i'll just add some more dump and move up clearing sessionstore interval pref earlier, maybe we are hanging on file access (this only hangs on Windows after all).
The fact other ss tests are timing out in similar situations concerns me, but the fact that a lot of other tests actually use successfully the above pattern is confusing.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1255990320.1255993078.29753.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/19 15:12:00

With the exception of comment #5 (which isn't this test anyway), every failure has been on an opt build. Not sure if that's relevant, but it's a definite pattern.

Marco, can you reproduce this locally with debug builds? It might be worth building an opt-test build to track it down.

Do we have a list of bugs that are only failing on opt-builds? I'm marking this one [opt-orange] until we come up with some better way of tracking.
Whiteboard: [orange] [test which aborts the suite] → [orange] [test which aborts the suite] [opt-orange]

    
    

    
  
(In reply to comment #44)
> With the exception of comment #5 (which isn't this test anyway), every failure
> has been on an opt build. Not sure if that's relevant, but it's a definite
> pattern.

it is relevant for sure. And all failures on Windows.

> Marco, can you reproduce this locally with debug builds? It might be worth
> building an opt-test build to track it down.

No, it's not reproduceable atm, i was able to reproduce failures before the same changes i did in browser_394759.js
At this point i'll try if i can reproduce in an optimized build, but i've lost lot of time trying to fix this :(

> Do we have a list of bugs that are only failing on opt-builds? I'm marking this
> one [opt-orange] until we come up with some better way of tracking.

bug 521889 and bug 521802, but probably they have also some failure in non optimized builds.

    
    

    
  
oh, this failed on Linux too today.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256053099.1256055776.17565.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/20 08:38:19

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256087154.1256089996.7969.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/20 18:05:54

    
    

    
  
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/20 20:29:42
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256095782.1256098841.6477.gz

    
    

    
  
And to fill in between the two of us,

WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/21 09:49:36
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/21 07:04:55
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/21 06:55:48
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/21 06:16:56
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/21 03:12:43

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256128688.1256131900.15422.gz
Linux mozilla-central test opt everythingelse on 2009/10/21 05:38:08

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256166307.1256169445.20067.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/21 16:05:07
OS: Windows XP → All
Hardware: x86 → All
Summary: Sporadic timeout in browser_394759_privatebrowsing.js → Very very frequent timeout in browser_394759_privatebrowsing.js

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256174498.1256177447.11235.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/21 18:21:38

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256175309.1256178230.19576.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/21 18:35:09

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256180552.1256183364.10772.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/21 20:02:32

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256180964.1256183798.15417.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/21 20:09:24

    
    

    
  
I'm just going to disable this test on m-c in the morning if there are no objections. Unless Marco wants to keep looking at it, I'll carve out some time soon to look into why this is happening.

    
    

    
  
sorry i was unable to do anything for 2 days due to hardware failures, i'm still working to fix them.
even if this is really annoying, disabling it won't help fixing it in any way, unit tests are still reliable, this is only(mostly) failing on windows optimized builds. Since fixing this could clarify the failure reasons for other optimized tests that are timing out, i'd rather stop losing time to report the failure and just ignore it, since actually reporting failures here does not help at all.
If we are going to disable this we will disable a bunch of other tests, without solving a possible real issue.
let me complete an optimized build and try to run tests on it, if i'll be able to reproduce locally then we can disable the test on central, but till then central is the only point where we can reproduce and fix the issue.

    
    

    
  
otherwise, if we want to disable the test, we should disable it with an ifdef DEBUG, since it only fails in optimized builds.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256255974.1256258796.11161.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/22 16:59:34

    
    

    
  
i've run mochitests on an optimized build multiple times in Vista, without seeing any timeout or hang :\

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256287344.1256290149.26140.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/23 01:42:24  

This really hurts, because it aborts the test suite.

Ehsan: can you help Marco out with debugging this failure?

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256277041.1256279877.12519.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/22 22:50:41

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256339643.1256342848.22136.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/23 16:14:03

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256359122.1256361836.32189.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/23 21:38:42

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256436736.1256439467.21017.gz

WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/24 19:12:16

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256565537.1256568534.13853.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/26 06:58:57

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256553128.1256556233.27421.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/26 03:32:08

    
    

    
  
Couldn't waitForFocus be useful here?  I think this type of failure is one that waitForFocus was designed to solve.  Or am I missing something?

BTW, Marco or anyone else, have you been able to reproduce this locally so far?

    
    

    
  
waitForFocus depends on the load event.

    
    

    
  
Is there any way to get a regression range on this?

    
    

    
  
no, because tests on optimized builds have been enabled recently

    
    

    
  
OK.  I don't see anything particularly suspicious here, but maybe I've missed something in the large number of comments here.  Marco, is there anything which would raise your suspicion here?

    
    

    
  
If i would have found something suspicious i'd have already tried to change it.
I think we could early finish() in load event leaving in the info() call and comment out various parts of the sessionstore setup code.
The main difference of this test from the previous ones is that code, if we discover it can cause an hang, then we could restrict the search.

    
    

    
  
(In reply to comment #78)
> If i would have found something suspicious i'd have already tried to change it.
> I think we could early finish() in load event leaving in the info() call and
> comment out various parts of the sessionstore setup code.
> The main difference of this test from the previous ones is that code, if we
> discover it can cause an hang, then we could restrict the search.

By previous ones, you mean the test before your changes, or before your last change?

If someone can reproduce this locally, I think it's best to disable this on m-c and then try to figure out what the problem is.

    
    

    
  
(In reply to comment #79)
> (In reply to comment #78)
> By previous ones, you mean the test before your changes, or before your last
> change?

no i mean other tests using the same "load" pattern, for example browser_394759.js.
My changes actually just ended up being a small cleanup and adding infos, did not change a bit of the issue unfortunatly (once this is sorted out we could get rid of the windowwatcher). I still have a really small cleanup patch around that fixes some minor thing and adds more infos.

> If someone can reproduce this locally, I think it's best to disable this on m-c

nobody can so far, that's why i prefer not disabling it, till someone can reproduce.

    
    

    
  
(In reply to comment #80)
> > If someone can reproduce this locally, I think it's best to disable this on m-c
> 
> nobody can so far, that's why i prefer not disabling it, till someone can
> reproduce.

In that case, I think that's what we should do.  I don't know of any way to solve this issue off-hand.

    
    

    
  
let me push my new patch, i'll do as soon as i can, then we can still disable parts of the setup, to reduce the offending code.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256746127.1256749019.24193.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/28 09:08:47  

Running chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js...
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | sessionstore.js was removed
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Correctly set window count
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Opening new window
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | New window has been opened

command timed out: 1200 seconds without output

    
    

    
  
With your push:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256752615.1256754801.26016.gz
WINNT 5.2 mozilla-central test everythingelse on 2009/10/28 10:56:55  

Running chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js...
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | sessionstore.js was removed
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Correctly set window count
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | sessionstore.js has been recreated - Got false, expected true
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Opening new window
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | New window has been opened
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js |
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Window has 1 listener
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Window has load listener
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Window does not have a capture listener
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js |
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | New window has been loaded
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | New window browser has been loaded
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Window closed
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | The closed window was added to the list
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | The closed window data was stored correctly
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | private browsing enabled
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Recently Closed Windows are removed when entering Private Browsing
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Recently Closed Windows data is cleared when entering Private Browsing
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Opening new window
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | New window has been opened
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js |
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Window has 1 listener
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Window has load listener
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Window does not have a capture listener
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js |
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | New window has been loaded
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | New window browser has been loaded
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Window closed
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | The closed window was added to the list
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | The closed window data was stored correctly
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | private browsing disabled
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | The correct number of recently closed windows were restored when exiting PB mode
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | The data associated with the recently closed window was restored when exiting PB mode
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Console message:

    
    

    
  
pushed http://hg.mozilla.org/mozilla-central/rev/a812503aff1c to wait for sessionstore.js to be written, Windows is taking more time than others.

    
    

    
  
this is before the change in comment 87:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256763306.1256766598.31350.gz
Running chrome://mochikit/content/browser/browser/components/sessionstore
...
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Opening new window
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | New window has been opened
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js |
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Window has 1 listener
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Window has load listener
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Window does not have a capture listener
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js |
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Window closed

this is interesting, looks like we receive a DOMWindowclosed before load can fire.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256788472.1256791389.19659.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/28 20:54:32

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256793659.1256796772.13084.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/28 22:20:59

    
    

    
  
new push: http://hg.mozilla.org/mozilla-central/rev/40b3d440c5a9
since i got that the problem is the window closes before load can fire, i changed the test to detect that situation (And interrupt without timeout) and detect eventual spurious windows-restored notifications.

    
    

    
  
from this log: http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256831010.1256834175.2248.gz
Looks like sessionstore.js is not rewritten correctly on optimized Win, or at least, we don't receive "sessionstore-state-write-complete" notification.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256844076.1256847322.24652.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/29 12:21:16

    
    

    
  
changed the startup order based on other tests around that are not failing.
The actual order makes more sense, also trying to avoid getting a bogus write of the sessionstore file.
http://hg.mozilla.org/mozilla-central/rev/2df99504c1ec

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256952859.1256955877.20308.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/30 18:34:19

[
Running chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js...
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | sessionstore.js was removed

command timed out: 1200 seconds without output
]
Summary: Very very frequent timeout in browser_394759_privatebrowsing.js → mochitest-browser-chrome: very very frequent timeout in browser_394759_privatebrowsing.js

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256960901.1256963683.6762.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/30 20:48:21

    
    

    
  
So, it's pretty clear that AsyncCopy fails, probably because the file is held locked by the OS. We can probably listen on sessionstore-state-write and don't bother looking at the fact the state file has been effectively written or not. That should allow us to move on, but won't yet explain why a window is closed suddenly.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256978552.1256981292.2883.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/10/31 01:42:32

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257133794.1257136774.29552.gz#err2
WINNT 5.2 mozilla-central test opt everythingelse on 2009/11/01 19:49:54

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257135708.1257138608.17242.gz#err2
WINNT 5.2 mozilla-central test opt everythingelse on 2009/11/01 20:21:48

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257136913.1257140150.1323.gz#err2
Linux mozilla-central test opt everythingelse on 2009/11/01 20:41:53

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257142190.1257144969.20874.gz#err2
WINNT 5.2 mozilla-central test opt everythingelse on 2009/11/01 22:09:50

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257144086.1257146862.8907.gz#err2
WINNT 5.2 mozilla-central test opt everythingelse on 2009/11/01 22:41:26

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257199534.1257202870.4117.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/11/02 14:05:34

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257206919.1257209865.18131.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/11/02 16:08:39

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257207672.1257210591.26294.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/11/02 16:21:12

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257236031.1257238778.8846.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/11/03 00:13:51

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257252023.1257255197.6124.gz#err1
WINNT 5.2 mozilla-central test opt everythingelse on 2009/11/03 04:40:23

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257295484.1257298708.19845.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/11/03 16:44:44

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257293950.1257297597.7620.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/11/03 16:19:10

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257291555.1257295506.16663.gz
WINNT 5.2 mozilla-central test opt everythingelse on 2009/11/03 15:39:15

    
    

    
  
removed some check that was causing us to fail when checking sessionstore.js, or timing out while waiting for it to be written.
http://hg.mozilla.org/mozilla-central/rev/df3198a37757

At this point i don't have new ideas, something is closing the window onLoad, with an handler that exists before our own. I suppose could be sessionstore or a previous uncleaned test, but i can't find a test part that could force that behavior.

    
    

    
  
(In reply to comment #117)
> removed some check that was causing us to fail when checking sessionstore.js,
> or timing out while waiting for it to be written.
> http://hg.mozilla.org/mozilla-central/rev/df3198a37757

Is it clear that the timeout while waiting for sessionstore-state-write-complete is a testing quirk rather than a real failure that needs to be investigated?

I also don't understand this change:

-  ok(sessionStoreJS.exists() == false, "sessionstore.js was removed");
+  info("sessionstore.js was correctly removed: " + (!sessionStoreJS.exists()));

    
    

    
  
the file sometimes is held lock by the OS, so it's not correctly removed. actually we don't need it to be in place for this test, so i just info rather than failing.

    
    

    
  
this especially happens on Windows, i've seen other bugs caused by the fact Windows release of file locks is slooow.

    
    

    
  
Testing these things might not be the responsibility of this particular file, but my point is that if there are actual failures, they need to be investigated rather than not testing them anymore.

    
    

    
  
(In reply to comment #121)
> Testing these things might not be the responsibility of this particular file,

Though, maybe it is, as I could imagine that whether sessionstore.js gets written and removed correctly could be relevant for private browsing.

    
    

    
  
i want to know if the fact the file is locked is somehow related to the fact the window is closed. so i need to skip that check and let the test timeout on window load.

That said, i think the fact on Windows FS files can be "in use" after some time you stop using them is pretty known, and i'm not sure what we should investigate about it. The only alternative possibility i could think of is that a previous test is writing a quite large sessionstore, and when we run it has not yet finished.
Also consider the fact that this failure can only be reproduced on tinderboxes, i've found no way to reproduce locally (even in a VM), real machines have also pretty faster IO and less threading issues than VMs. Clearly if you have any idea to suggest, i'm open to accept them and try getting more debug infos.

    
    

    
  
(In reply to comment #122)
> (In reply to comment #121)
> > Testing these things might not be the responsibility of this particular file,
> 
> Though, maybe it is, as I could imagine that whether sessionstore.js gets
> written and removed correctly could be relevant for private browsing.

i guess sessionstore does not even track changes while PB is active.

    
    

    
  
(In reply to comment #123)
> That said, i think the fact on Windows FS files can be "in use" after some time
> you stop using them is pretty known, and i'm not sure what we should
> investigate about it.

It needs to be made out whether there's a deficiency in session restore code or in the tools it uses that could hit users. At least to me, the answer to that isn't clear.

    
    

    
  
(In reply to comment #124)
> (In reply to comment #122)
> > (In reply to comment #121)
> > > Testing these things might not be the responsibility of this particular file,
> > 
> > Though, maybe it is, as I could imagine that whether sessionstore.js gets
> > written and removed correctly could be relevant for private browsing.
> 
> i guess sessionstore does not even track changes while PB is active.

It shouldn't, and that is one of the main things that this test is supposed to ensure.

    
    

    
  
So, here it is some new data:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257409117.1257412155.29435.gz#err0

The test now does not timeout anymore, since i detect window close.
The interesting thing is that now that this does not timeout, the test immediately after this, browser_408470.js, times out. it adds a tab and waits for load handler.

    
    

    
  
(In reply to comment #125)
> (In reply to comment #123)
> It needs to be made out whether there's a deficiency in session restore code or
> in the tools it uses that could hit users. At least to me, the answer to that
> isn't clear.

SS does just asyncOpen and write its file, if the filesystem thinks the file is in use, it will silently fail. Since during PB the session data is not saved, i think the worst thing can happen is that on browser restart it will restore the session that was open BEFORE entering PB, that should not be a privacy concern.
That said, i think that hitting a locked file is hard for real SS code since it uses a delay between writes, while in these tests we phisically remove the file and force a rewrite of it immediately, and that can cause fs headaches.

    
    

    
  
It looks like _writeFile actually knows about the failure. So maybe it should try again after some time? Or maybe it should send a sessionstore-state-write-failed notification?

Otherwise, why don't we use a delay in the test? Would it have to be so long that the test would time out?

    
    

    
  
(In reply to comment #129)
> It looks like _writeFile actually knows about the failure. So maybe it should
> try again after some time? Or maybe it should send a
> sessionstore-state-write-failed notification?

true, we could detect errors in the asyncCopy callback, but i think sending a failed notification is over-engineering the thing, maybe a "retry sooner" solution is better. Still we are already retrying on the interval timer. So we could do that only if we feel that the file could be often locked and interval is too big. I think interval is good enough and having a not-so-small interval reduces the possibility of locking a lot. This is a guess but should be correct enough to consider this a minor problem.

> Otherwise, why don't we use a delay in the test? Would it have to be so long
> that the test would time out?

i suspect so, in a previous change i added a 100ms delay and it was not enough, but actually we could try to set it to 500ms, and restore the write-complete check.

Leaving this apart for a moment, any idea of what could happen with load handler, it's like as soon as this fails, all next tests will timeout. There is a possibility that the culprit is not this test, but the previous one the causes all next tests to timeout: browser_394759.js

    
    

    
  
pushed a cleanup of browser_394759.js
previous tests are probably involved, especially that one and browser_354894.js
http://hg.mozilla.org/mozilla-central/rev/fc4702c75a04

    
    

    
  
(In reply to comment #132)
> pushed a cleanup of browser_394759.js
> previous tests are probably involved, especially that one and browser_354894.js
> http://hg.mozilla.org/mozilla-central/rev/fc4702c75a04

Reverted with http://hg.mozilla.org/mozilla-central/rev/f05767494de2 (didn't backout & merge because it wasn't worth the hassle here) since it seems to have caused bug 527074.

    
    

    
  
Paul, thank you for the backout, time was not good for me :(
this is damn interesting, since the timeout in this bug disappeared(!) and that failure appeared. Unfortunatly there aren't many data available, but looks like touching browser_394759.js caused a failure shift. browser_526613 is the last test in sessionstore browser folder, if we can fix that failure we should be fine.

    
    

    
  
also notice there is also a green run, so the cleanup was correct, but something did open a second browser window in some runs... could even be this was fixed, and bug 527074 is a failure that previously was covered by the timeouts (actually same cause, but tests going on)

    
    

    
  
i compared messages in a successfull run against a failing run.
the only difference is this

TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Console message: [JavaScript Error: "[Exception... "'JavaScript component does not have a method named: "notify"' when calling method: [nsITimerCallback::notify]"  nsresult: "0x80570030 (NS_ERROR_XPC_JSOBJECT_HAS_NO_FUNCTION_NAMED)"  location: "<unknown>"  data: no]"]

in the failing run this message fires during browser_394759_privatebrowsing.js
in the successfull run it fires during 394759.js

    
    

    
  


  
we could probably extract some interesting info from here.

    
    

    
  
Just occurred to me that since I stopped pasting logs in here, someone might think it's gone away - it hasn't.

    
    

    
  
bug 527074 could make this better providing a reliable notification of the end of SetBrowserState, i also think we have a blocker (iirc) about "zombie" tabs, so could be here we are seeing something similar (never loaded tabs). Btw we should wait for the former and then check the latter.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258032267.1258035057.15566.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/12 05:24:27

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258041559.1258045514.3806.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/12 07:59:19

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258041595.1258045792.7091.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/12 07:59:55

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258067676.1258070832.4188.gz#err0
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/12 15:14:36  
"s: moz2-win32-slave27"

    
  
Depends on: 528440

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258129573.1258133228.3580.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/13 08:26:13  
"s: moz2-win32-slave39"

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258118289.1258121322.24539.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/13 05:18:09
"s: moz2-win32-slave15"

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258135584.1258139195.7932.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/13 10:06:24
"s: moz2-win32-slave38"

BTW, these timeouts are now coming after this failure:
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Window was closed before load could fire!

(at least, the log here & in the last 4 comments all had that failure)

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258137847.1258141167.31919.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/13 10:44:07
"s: moz2-win32-slave16"

    
    

    
  
(In reply to comment #148)
> http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258135584.1258139195.7932.gz
> WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/13 10:06:24
> "s: moz2-win32-slave38"
> 
> BTW, these timeouts are now coming after this failure:
> TEST-UNEXPECTED-FAIL |
> chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js
> | Window was closed before load could fire!

yes it's due to my last changes, i'm waiting for a couple other ss tests and a possible test harness change that could interact with this.

    
    

    
  
Could bug 528440 have made a difference for this? Haven't seen a failure since that landed.

    
    

    
  
There have only been three Windows opt builds, though. Still, three is encouraging, since at least 50% of these kind of builds failed yesterday.

    
    

    
  
(In reply to comment #151)
> Could bug 528440 have made a difference for this? Haven't seen a failure since
> that landed.

it could, but also zpao landed Bug 522545, that it's unclear if related.
For sure having ss not taking in count wrong windows is a big win for tests.

    
    

    
  
I think we can close this if nothing shows up later today. There was a fourth Win opt build with a different failure (bug 521802) and another build is on the way. I'll also go through the other open orange bugs in Firefox/Session Restore and resolve them after some time, depending on how often the failures used to occur.

    
    

    
  
i agree, closing.
Status: REOPENED → RESOLVED
Closed: 15 years ago → 15 years ago
Resolution: --- → FIXED

    
    

    
  
we can reopen bugs if new failures should show up, no reasons to wait for something, this failure was requent enough to show up in at least 1 run over 3.

    
  
Resolution: FIXED → WORKSFORME

    
    

    
  
sigh
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258201434.1258204315.24029.gz
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---

    
    

    
  
I wonder if the previous runs were just lucky or if this is less frequent now. We'll see in the next few days...

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258210391.1258213328.776.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/14 06:53:11
"s: moz2-win32-slave15"

    
    

    
  
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/15 10:10:32  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258308632.1258311732.15065.gz

    
    

    
  
doesn't seem to be frequent anymore
Summary: mochitest-browser-chrome: very very frequent timeout in browser_394759_privatebrowsing.js → intermittent timeout in browser_394759_privatebrowsing.js

    
    

    
  
Marco, can you back out the window watcher stuff? It looks like that will incorrectly report a failure when an unrelated window gets destroyed.

    
    

    
  
I think that's the revision we want to go back to as far as the window watcher is concerned, i.e. without any window watcher dependency: http://hg.mozilla.org/mozilla-central/file/6240e80d2c21/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js

    
    

    
  
Alright, this was easy enough to do since the test didn't really depend on the window watcher stuff.
http://hg.mozilla.org/mozilla-central/rev/74e3158a9fc5

    
    

    
  
yep, it was there just for logging open/close. thank you.

    
    

    
  
after <http://hg.mozilla.org/mozilla-central/rev/eb6ad91709a7>:

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | Only one browser window should be open eventually - Got 2, expected 1

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1

buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258566069.1258569909.1877.gz

    
    

    
  
http://hg.mozilla.org/mozilla-central/rev/13601aff9814
Summary: intermittent timeout in browser_394759_privatebrowsing.js → frequent timeout in browser_394759_privatebrowsing.js, caused by browser_394759.js

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258597123.1258601028.1518.gz
Linux mozilla-central opt test everythingelse on 2009/11/18 18:18:43
s: moz2-linux-slave23

    
    

    
  
(In reply to comment #168)
> http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258597123.1258601028.1518.gz
> Linux mozilla-central opt test everythingelse on 2009/11/18 18:18:43
> s: moz2-linux-slave23

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1

    
    

    
  
Linux mozilla-central opt test everythingelse on 2009/11/18 22:58:48
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258613928.1258618963.3822.gz


TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output, killing pid 5433

If this bug is for these different errors could someone in the know update the summary so it is easier to find?

    
    

    
  
(In reply to comment #170)
> If this bug is for these different errors could someone in the know update the
> summary so it is easier to find?

these errors are actual logging added to solve these failures

    
    

    
  

      
      
      
      

        Attached file
          
        oldState in test_purge (obsolete)
        — 
      

    


  

    
    

    
  
about:mozilla and about:buildconfig are from browser_354894.js

    
    

    
  
Yeah, this looks like a bug in _getCurrentState. The whole dependency on domwindowclosed is annyoing. That code should probably use the unload event instead.

    
  
Depends on: 528776

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258685600.1258689846.12154.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/19 18:53:20
"s: moz2-win32-slave35"
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 3 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258686058.1258690530.19552.gz
Linux mozilla-central opt test everythingelse on 2009/11/19 19:00:58
s: moz2-linux-slave27
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 3 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output, killing pid 4201

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258751197.1258754598.13164.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/20 13:06:37
"s: moz2-win32-slave37"

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258761228.1258764675.29532.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/20 15:53:48
"s: moz2-win32-slave37"
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 3 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258769280.1258772283.15851.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/20 18:08:00
"s: moz2-win32-slave40"

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258809969.1258815025.31032.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/21 05:26:09
"s: moz2-win32-slave15"

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258815022.1258818153.3125.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/21 06:50:22
"s: moz2-win32-slave41"

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258946167.1258949185.15960.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/22 19:16:07

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258978147.1258981210.18588.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/23 04:09:07
"s: moz2-win32-slave36"

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259000679.1259004015.24694.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/23 10:24:39
"s: moz2-win32-slave40"

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259014149.1259017409.15051.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/23 14:09:09
"s: moz2-win32-slave34"

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259072424.1259075576.31621.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/24 06:20:24
"s: moz2-win32-slave34"
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 3 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259078897.1259082325.12264.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/24 08:08:17
"s: moz2-win32-slave31"
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 3 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259106071.1259111572.23485.gz
Linux mozilla-central opt test everythingelse on 2009/11/24 15:41:11
s: moz2-linux-slave25

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259198027.1259200859.7004.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/25 17:13:47
"s: moz2-win32-slave16"

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6-Unittest/1259292241.1259295063.2528.gz
WINNT 5.2 mozilla-1.9.2 test everythingelse on 2009/11/26 19:24:01

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259623528.1259626889.31529.gz&fulltext=1
WINNT 5.2 mozilla-central opt test everythingelse on 2009/11/30 15:25:28

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259717570.1259720956.12155.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/01 17:32:50
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259726575.1259729468.7826.gz
 WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/01 20:02:55

    
    

    
  
WINNT 5.2 mozilla-central opt test everythingelse [testfailed] Started 14:31, finished 15:23
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259879505.1259882541.8065.gz&fulltext=1

    
    

    
  
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/03 18:52:43
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259895163.1259898150.5293.gz

At least the fourth time today... did something make this worse?

    
    

    
  
(In reply to comment #207)
> At least the fourth time today... did something make this worse?

doubt it, this is due to bug 528776, and can happen quite frequently

    
    

    
  
also bug 531519
Depends on: 531519

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259957848.1259960748.15295.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/04 12:17:28
s: moz2-win32-slave25
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 3 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260528059.1260532279.5084.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/11 02:40:59
s: win32-slave30
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 3 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260562247.1260565234.30974.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/11 12:10:47
s: win32-slave25
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 3 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260585914.1260589103.3872.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/11 18:45:14
s: win32-slave39

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260594806.1260597950.2985.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/11 21:13:26
s: win32-slave38

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260579172.1260582396.26565.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/11 16:52:52
s: win32-slave39
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 3 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260563659.1260567912.28270.gz
Linux mozilla-central opt test everythingelse on 2009/12/11 12:34:19
s: moz2-linux-slave19
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 3 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output, killing pid 11193

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260605170.1260608233.16072.gz#err0
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/12 00:06:10  
s: win32-slave26

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 3 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260618322.1260621498.4332.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/12 03:45:22
s: win32-slave26

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260609457.1260613256.6941.gz
Linux mozilla-central opt test everythingelse on 2009/12/12 01:17:37
s: moz2-linux-slave23

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260646672.1260649858.1413.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/12 11:37:52
s: win32-slave32
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 2 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260648038.1260654261.17489.gz
Linux mozilla-central opt test everythingelse on 2009/12/12 12:00:38
s: moz2-linux-slave18
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 2 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1
buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output, killing pid 17315

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260659487.1260664719.3516.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/12 15:11:27
s: win32-slave37

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260684869.1260687724.24165.gz#err0
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/12 22:14:29  
s: win32-slave16

    
    

    
  
Bug 531519 made one window go away, bug 528776 didn't make the other one go away. So there's still something weird going on. Bug 534489 might be related.

    
  
Summary: frequent timeout in browser_394759_privatebrowsing.js, caused by browser_394759.js → frequent timeout in browser_394759_privatebrowsing.js, caused by browser_394759.js and browser_354894.js

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260736441.1260741847.1881.gz
Linux mozilla-central opt test everythingelse on 2009/12/13 12:34:01
s: moz2-linux-slave25

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 2 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260738008.1260742354.8000.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/13 13:00:08
s: win32-slave28

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260760380.1260765070.28367.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/13 19:13:00
s: win32-slave27

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260770208.1260773864.27923.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/13 21:56:48
s: win32-slave27

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260769637.1260773197.20272.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/13 21:47:17
s: win32-slave32

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260773702.1260777882.7303.gz
Linux mozilla-central opt test everythingelse on 2009/12/13 22:55:02
s: moz2-linux-slave27

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260779067.1260781986.19291.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/14 00:24:27
s: win32-slave15

    
    

    
  
Linux mozilla-central opt test
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260791741.1260796420.23057.gz

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_354894.js | browser windows after testOpenCloseRestoreFromPopup (getBrowserState) - Got 2, expected 1

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_354894.js | browser windows after testNotificationCount (getBrowserState) - Got 2, expected 1

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 2 windows instead of 1

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1

buildbot.slave.commands.TimeoutError: command timed out: 1200 seconds without output, killing pid 5336

    
    

    
  


  

        Attachment #405489 -
        Attachment is obsolete: true

        Attachment #405490 -
        Attachment is obsolete: true

        Attachment #410918 -
        Attachment is obsolete: true

        Attachment #413333 -
        Attachment is obsolete: true

    
    

    
  


  
Apparently the first '_closedWindows' entry here equals the last 'windows' entry in the previous attachment.

    
  

        Attachment #417462 -
        Attachment description: browser state after testOpenCloseRestoreFromPopup in browser_354894.js → [fail] browser state after testOpenCloseRestoreFromPopup in browser_354894.js

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260839410.1260842377.24615.gz
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/14 17:10:10
s: win32-slave27

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_354894.js | browser windows after testOpenCloseRestoreFromPopup (getBrowserState) - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_354894.js | browser windows after testNotificationCount (getBrowserState) - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | oldState in test_purge has 2 windows instead of 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_purge - Got 2, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially - Got 2, expected 1

    
    

    
  
(Oh, and a crapload of others - hard though it is to believe, I finally got tired of pasting log links in here, so just figure that its failing five or ten times a day.)

    
    

    
  
Do we need more data here? I think I've got this in a recorded VMWare session.

    
    

    
  
(In reply to comment #241)
> Do we need more data here? I think I've got this in a recorded VMWare session.

The point we need to look at is known now (testOpenCloseRestoreFromPopup in browser_354894.js), and it's relatively easy to get additional data, since it's a chrome test and failing rather regularly, so I think we should be able to figure this out soon. However if this doesn't work out as planned, we might want to resort to the recorded session indeed.

    
    

    
  
WINNT 5.2 mozilla-central opt test everythingelse on 2009/12/16 06:51:08
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1260975068.1260979450.22354.gz

    
    

    
  
This doesn't happen anymore, but I don't think it has actually been fixed...

For the record, when this failed, newWin was still restoring (i.e. newWin.__SS_restoreID was nonempty) at the end of testOpenCloseRestoreFromPopup.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1264198769.1264201991.5676.gz
WINNT 5.2 mozilla-central debug test mochitest-other on 2010/01/22 14:19:29
s: win32-slave20

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1264199633.1264202394.10478.gz
WINNT 5.2 mozilla-central debug test mochitest-other on 2010/01/22 14:33:53
s: win32-slave22

Odd that after that long layoff, we're suddenly seeing this (well, something very like this, anyway) again.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1264688941.1264690788.7408.gz
WINNT 5.2 mozilla-1.9.2 opt test mochitest-other on 2010/01/28 06:29:01
s: win32-slave16

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1266529143.1266534986.2625.gz
WINNT 5.2 mozilla-central debug test mochitest-other on 2010/02/18 13:39:03
s: win32-slave42

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1267072622.1267074461.19032.gz
WINNT 5.2 mozilla-1.9.2 opt test mochitest-other on 2010/02/24 20:37:02

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1267104072.1267105699.7455.gz
WINNT 5.2 mozilla-1.9.2 opt test mochitest-other on 2010/02/25 05:21:12

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1267231772.1267234478.14670.gz
WINNT 5.2 mozilla-1.9.2 opt test mochitest-other on 2010/02/26 16:49:32
s: win32-slave16

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1267278006.1267280004.14581.gz
WINNT 5.2 mozilla-1.9.2 opt test mochitest-other on 2010/02/27 05:40:06
s: mw32-ix-slave10

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1267278989.1267280858.17392.gz
WINNT 5.2 mozilla-1.9.2 opt test mochitest-other on 2010/02/27 05:56:29
s: mw32-ix-slave07

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1267284112.1267285767.32442.gz
WINNT 5.2 mozilla-1.9.2 opt test mochitest-other on 2010/02/27 07:21:52
s: win32-slave39

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1267449435.1267451377.6402.gz
WINNT 5.2 mozilla-1.9.2 opt test mochitest-other on 2010/03/01 05:17:15
s: win32-slave39

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1267472123.1267476628.30337.gz
Linux mozilla-central debug test mochitest-other on 2010/03/01 11:35:23

So, the thing that is happening here is that it seems that two tests are running interleaved.  I'm not really sure why, but Marco thinks that it should be relevant to this bug.

++DOMWINDOW == 135 (0xb518ad8) [serial = 1436] [outer = 0xb3085f0]
WARNING: NS_ENSURE_SUCCESS(rv, 0) failed with result 0x8000FFFF: file /builds/moz2_slave/mozilla-central-linux-debug/build/content/base/src/nsContentUtils.cpp, line 2809
NEXT ERROR TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | Timed out
TEST-INFO | checking window state
Running chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js...
Chrome file doesn't exist: /builds/slave/mozilla-central-linux-debug-unittest-mochitest-other/build/mochitest/browser/browser/components/sessionstore/test/browser/head.js
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Only one browser window should be open initially
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | sessionstore.js was correctly removed: true
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | sessionstore.js is being written
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | There were 0 popup windows to repoen
NEXT ERROR TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | There were 3 normal windows to repoen - Got 0, expected 3
++DOMWINDOW == 136 (0xa9cdcc0) [serial = 1437] [outer = 0xa7117f8]
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Private Browsing is disabled
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Correctly set window count
TEST-INFO | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759_privatebrowsing.js | Opening new window
pldhash: for the table at address 0xaf1a348, the given entrySize of 48 probably favors chaining over double hashing.
++DOCSHELL 0xaf1a2e0 == 23
++DOMWINDOW == 137 (0xb2205f0) [serial = 1438] [outer = (nil)]
++DOMWINDOW == 138 (0xaea5b60) [serial = 1439] [outer = 0xb2205c0]
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | number of browser windows after test_behavior
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | 1 tab was removed
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | The correct tab was removed
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | The correct tab was remembered
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | Selected tab has changed
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | The window title was correctly updated
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | 2 tabs were removed
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | The correct tabs were removed
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | The correct tabs were remembered
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | Selected tab has changed
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | The window title was correctly updated
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | The correct number of tabs were removed, and the correct ones
TEST-PASS | chrome://mochikit/content/browser/browser/components/sessionstore/test/browser/browser_394759.js | All tabs to be forgotten were indeed removed

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1267483473.1267486086.1321.gz
WINNT 5.2 mozilla-1.9.2 opt test mochitest-other on 2010/03/01 14:44:33
s: win32-slave40
blocking2.0: --- → ?

          status1.9.2:
          --- → ?

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1267564669.1267566070.14563.gz
Linux mozilla-central opt test mochitest-other on 2010/03/02 13:17:49

    
    

    
  
i'm going to double the timeout for this test, it takes some time to run. and let's see how it will behave.

    
    

    
  
Are you sure that these tests aren't suffering from the same problem as browser_459906.js was? I see a lot of executeSoon, how do we know that sessionstore's work has completed before those callbacks run?

    
    

    
  
(In reply to comment #260)
> Are you sure that these tests aren't suffering from the same problem as
> browser_459906.js was? I see a lot of executeSoon, how do we know that
> sessionstore's work has completed before those callbacks run?

not 100%. Still, looks like the timeout is happening at different times, and just some log above we noticed the timeout was not actually a timeout since another test was running in the middle of this one.
Since enlarging timeout has no drawbacks (apart the fact it does not fix the original perf problem) i think it is the best solution for now.
If what you suggest would be true, then we will see the timeout going back pretty soon at about the same position as above logs.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1267692112.1267694759.22831.gz
WINNT 5.2 mozilla-1.9.2 opt test mochitest-other on 2010/03/04 00:41:52  
s: win32-slave37

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1267707535.1267709330.15610.gz
WINNT 5.2 mozilla-1.9.2 opt test mochitest-other on 2010/03/04 04:58:55  
s: mw32-ix-slave04

    
  
Blocks: 549672

    
    

    
  

      
      
      
      

        Attached patch
          
          
        Patch (v1) (obsolete)
        — 
          — Splinter Review
      

    


  
The problem turned out to be a typo in nsSessionStore.js!  A timing issue caused this to be intermittent, because the broken code path is not executed except if the machine is extremely fast.  Ben had such a machine today (see bug 549672) and I spent a lot of time debugging this.

I filed bug 551856 to catch JS type errors in the browser-chrome suite in the future, so that we can make sure that this won't happen again.

I'll also submit another patch to remove the debugging information that was added to this test.  Thanks to everyone who spent time trying to fix this bug!
Assignee: mak77 → ehsan.akhgari
Status: REOPENED → ASSIGNED

        Attachment #432025 -
        Flags: review?(jmuizelaar)

    
    

    
  
Comment on attachment 432025 [details] [diff] [review]
Patch (v1)

Looks good to me.

        Attachment #432025 -
        Flags: review?(jmuizelaar) → review+

    
    

    
  

      
      
      
      

        Attached patch
          
          
        Patch to land
        — 
          — Splinter Review
      

    


  

        Attachment #432025 -
        Attachment is obsolete: true

    
    

    
  
(In reply to comment #265)
> I'll also submit another patch to remove the debugging information that was
> added to this test.

i don't think there is really the need to remove debugging code from the test, unless it is ugly. It could help in future and it is still testing code.

Good catch, btw.

    
    

    
  


  
This patch removes the debugging info which was added to the tests as part of this bug.  I decided to keep some of the extra checks, because they won't hurt!

        Attachment #432029 -
        Flags: review?(dietrich)

    
    

    
  
(In reply to comment #268)
> (In reply to comment #265)
> > I'll also submit another patch to remove the debugging information that was
> > added to this test.
> 
> i don't think there is really the need to remove debugging code from the test,
> unless it is ugly. It could help in future and it is still testing code.

I've just remove info() calls, which are ugly, and pollute the output of the test.  I don't feel strongly about them, though, so feel free to r- if you think we shouldn't take that change.

    
    

    
  
looking at them, i'm fine with your changes.

    
    

    
  
http://hg.mozilla.org/mozilla-central/rev/23f377267915
Status: ASSIGNED → RESOLVED
Closed: 15 years ago → 14 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: Firefox 3.7a1 → Firefox 3.7a3

    
  

        Attachment #432025 -
        Flags: approval1.9.2.3?

        Attachment #432025 -
        Flags: approval1.9.1.10?

    
    

    
  
Comment on attachment 432029 [details] [diff] [review]
Remove the debugging info

stealing the review since I added all this stuff

        Attachment #432029 -
        Flags: review?(dietrich) → review+

        Attachment #432028 -
        Flags: approval1.9.2.3?

        Attachment #432028 -
        Flags: approval1.9.1.10?

    
    

    
  
Comment on attachment 432028 [details] [diff] [review]
Patch to land

This patch will fix rare cases of bug where we will fail to restore a previously closed window.

This is an issue that causes to fail tests 100% of the time on the new, super fast Linux build machines we have.

I'd like to take this patch on 1.9.1 and 1.9.2 primarily to avoid turning the tree orange when these new machines start running tests.

Ehsan tells me there should be no downside to landing it on these branches.

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1268402921.1268405273.13046.gz
WINNT 5.2 mozilla-1.9.2 opt test mochitest-other on 2010/03/12 06:08:41

    
  

        Attachment #432025 -
        Flags: approval1.9.2.3?

        Attachment #432025 -
        Flags: approval1.9.1.10?

    
    

    
  
Debugging info removed from trunk:

http://hg.mozilla.org/mozilla-central/rev/ba56722f2e69
Whiteboard: [orange] [test which aborts the suite] [opt-orange] → [orange] [test which aborts the suite] [opt-orange][typo fix]

    
    

    
  
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1269260014.1269261678.12253.gz#err0
WINNT 5.2 mozilla-1.9.2 opt test mochitest-other on 2010/03/22 05:13:34

    
    

    
  
Comment on attachment 432028 [details] [diff] [review]
Patch to land

a=beltzner for both branches

        Attachment #432028 -
        Flags: approval1.9.2.3?

        Attachment #432028 -
        Flags: approval1.9.2.3+

        Attachment #432028 -
        Flags: approval1.9.1.10?

        Attachment #432028 -
        Flags: approval1.9.1.10+

    
  
Blocks: 561718
blocking2.0: ? → final+

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  
Whiteboard: [orange] [test which aborts the suite] [opt-orange][typo fix] → [test which aborts the suite] [opt-orange][typo fix]

    
  
Whiteboard: [test which aborts the suite] [opt-orange][typo fix] → [test which aborts the suite]

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






  

    
  







  

    

      
Attachment

      

      
      
      
      
    

    

      

        

          

            
General

            

              Creator: 



            

            
Created: 

            
Updated: 

            
Size: