Closed Bug 458688 Opened 16 years ago Closed 14 years ago

FUEL test browser_Browser.js still times out occasionally

Categories

(Firefox :: General, defect)

Product:
Firefox
Component:
General
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 3.7a5
Tracking Flags:
Tracking Status
status1.9.2 --- .5-fixed

People

(Reporter: ted, Assigned: dao)

References

(
URL
)

Details

(Keywords: intermittent-failure)

Attachments

(3 files, 1 obsolete file)

v2 - uses "load" events for intial pages
6.11 KB, patch
Gavin
: review+
Details | Diff | Splinter Review
patch
4.17 KB, patch
mfinkle
: review+
Details | Diff | Splinter Review
patch
4.74 KB, patch
mossop
: review+
Details | Diff | Splinter Review 
The test in the URL field uses setTimeout extensively. That's bogus, and can cause random failures as shown here:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1223284948.1223288480.11938.gz
Other occurrences, when it fails alone:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1223835200.1223838730.11008.gz
Linux mozilla-central moz2-linux-slave07 dep unit test on 2008/10/12 11:13:20
{
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | Checking 'BrowserTab.uri' after opening - Got about:blank, expected chrome://mochikit/content/browser/browser/fuel/test/ContentA.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | Checking 'BrowserTab.uri' after opening - Got about:blank, expected chrome://mochikit/content/browser/browser/fuel/test/ContentB.html
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | Checking existence of element in content DOM
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | Timed out
}

and

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1223843077.1223846634.32407.gz
Linux mozilla-central moz2-linux-slave08 dep unit test on 2008/10/12 13:24:37
Component: BrowserTest → General
Product: Testing → Firefox
QA Contact: browsertest → general
Version: unspecified → Trunk
This patch switches "setTimeout" to "executeSoon". The tests pass on my local machine. I do wonder if the pages will load fast enough on tinderboxen.

This patch also enables two simple tests in browser_Extensions.js, so we get even basic coverage on that code.
Assignee: nobody → mark.finkle
Attachment #345711 - Flags: review?(gavin.sharp)
I'm not sure I understand the motivation here. executeSoon's advantage over timeouts is really only just that it's more explicit about why the delay is needed (one spin through the event queue). If 1 second timeouts are causing problems, switching to executeSoon is unlikely to help and would probably even hurt.
what you probably want here is to wait for a load event, then use executeSoon
This patch is the same as the previous except I dropped the "executeSoon" used to wait for the pages to load. Instead, I use sequential page "load" events, then use "executeSoon" for other hand-off situations, but not page loads.

[this was based on feedback from gavin and shawn on IRC]
Attachment #345711 - Attachment is obsolete: true
Attachment #346120 - Flags: review?(gavin.sharp)
Attachment #345711 - Flags: review?(gavin.sharp)
Comment on attachment 346120 [details] [diff] [review]
v2 - uses "load" events for intial pages

>     // use a setTimeout so the pageloadwithframes

Change the comment?
Attachment #346120 - Flags: review?(gavin.sharp) → review+
http://hg.mozilla.org/mozilla-central/rev/e1cb4a2a4d7c
Status: NEW → RESOLVED
Closed: 16 years ago
Resolution: --- → FIXED
browser_Browser.js is currently failing intermittently on tinderbox when I don't recall seeing that happen before. Should this be backed out?
(In reply to comment #8)
> browser_Browser.js is currently failing intermittently on tinderbox when I
> don't recall seeing that happen before.

See comment 0 and comment 1 !?
Ok the problem here is that you are racing two page loads. When one page completes it triggers the test to finish. You rely on the other page loading first. Is loading both at the same time necessary?
(In reply to comment #9)
> (In reply to comment #8)
> > browser_Browser.js is currently failing intermittently on tinderbox when I
> > don't recall seeing that happen before.
> 
> See comment 0 and comment 1 !?

I don't see how that answers my question. Presumably if I haven't seen it before it is failing more than previously.
Attached patch patch — — Splinter Review 
This changes the loads to be one after the other. Use a web progress listener to verify the load of page B is completed before checking how many times the load event fired.
Assignee: mark.finkle → dtownsend
Status: RESOLVED → REOPENED
Attachment #346867 - Flags: review?(gavin.sharp)
Resolution: FIXED → ---
(In reply to comment #11)
> I don't see how that answers my question.

It is not supposed to answer your question about a backout.

> Presumably if I haven't seen it before it is failing more than previously.

More often, maybe, I don't know.
I was only commenting that if you have never seen it before, others have.
Comment on attachment 346867 [details] [diff] [review]
patch

Test code only so I think I can r+ this. After Dave explained the issues with me on IRC, I understand why the webprogresslistener is a better choice for monitoring page loads when frames are involved.
Attachment #346867 - Flags: review?(gavin.sharp) → review+
http://hg.mozilla.org/mozilla-central/rev/750eb47b3b91

Thanks Dave!
Status: REOPENED → RESOLVED
Closed: 16 years ago → 16 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 3.1b2
Still timing out occasionally:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1227112647.1227116502.18267.gz

I don't know what's busted.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Summary: FUEL test browser_Browser.js uses setTimeout → FUEL test browser_Browser.js still times out occasionally
(In reply to comment #16)
> Still timing out occasionally:
> http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1227112647.1227116502.18267.gz
> 
> I don't know what's busted.

Suggests the progress listener is never seeing a state change with STATE_IS_WINDOW + STATE_IS_NETWORK + STATE_STOP. Seems strange
(In reply to comment #17)
> Suggests the progress listener is never seeing a state change with
> STATE_IS_WINDOW + STATE_IS_NETWORK + STATE_STOP. Seems strange
Perhaps someone who knows network code can help here.
Or rather it might be seeing it before the corresponding onload, no?  I'm not entirely convinced the ordering of those two is guaranteed, but that's only my best guess as to what's going on here.
Er, nevermind.  It's timing out, not failing the onload test.  Pretty odd.
No, as soon as the progress listener sees STATE_IS_WINDOW + STATE_IS_NETWORK + STATE_STOP it calls onPageBLoadComplete which does a test which would show up in the log. If the load events fire after the progress listener sees that then we'd just see a test failure.
I can't see what might be going on here and won't have time to work on it further for now.
Assignee: dtownsend → nobody
Whiteboard: [orange]
I disabled the test:

http://hg.mozilla.org/mozilla-central/rev/e95463a6c47d
Target Milestone: Firefox 3.1b2 → ---
From my debugging, I can see a bit of non-determinism by watching the state flags that are coming through the web progress listener:

= All Failed Tests Have This Signature =
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 983041
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65537
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 720897
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 720897
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 196612
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65537
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 196612
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65537
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 196612
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onPageBLoadWithFrames was called
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | Timed out

= Passing Tests on Windows Have =
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 983041
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65537
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 720897
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 720897
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 196612
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65537
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 196612
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65537
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 196612
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 131088
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 524304
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 131088
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 524304
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 131088
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onPageBLoadWithFrames was called
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 786448
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ___debugging: onPageBLoadComplete is Called

= Passing Tests on Linux and Mac have =
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 983041
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65537
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 720897
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 720897
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 196612
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65537
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 196612
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65537
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 196612
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 131088
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 524304
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 65552
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 131088
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 524304
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 131088
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onPageBLoadWithFrames was called
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ____debugging: onStateChage the stateFlags are: 786448
TEST-PASS | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | ___debugging: onPageBLoadComplete is Called

The difference is in the 196612 (0x30004), 65552 (0x10010), 65552 (0x10010), 131088 (0x20010) pattern.  This is where the timeout occurs. For passing tests on windows we get three 0x10010 states, and on mac and linux we get two.  On a failing test, it always times out after the first 0x10010 after the 0x30004.

bitwise AND'ing these states to all possible values of the state flag produces the following results:
= 196612 (0x30004) = 
STATE_TRANSFERRING  
STATE_IS_REQUEST  
STATE_IS_DOCUMENT  

= 65552 (0x10010) =
STATE_STOP
STATE_IS_REQUEST 

= 131088 (0x20010) =
STATE_STOP
STATE_IS_DOCUMENT

This honestly doesn't tell me a whole lot, but I'm posting it to see if it spurs any thoughts.  I'm wondering if we're in some kind of race condition with the onPageBLoadWithFrames listener.  I'm going to kick off some runs with that commented out and see what happens.
Still fails with the event listener commented out, but now it does two 0x10010's before timing out in the same place.  So I've affected it slightly, but not enough to make the test pass.  Will try to get the debug HTTP logging turned on and see what that says.
The test was disabled on m-c, but not on 1.9.1, and it's failing on that branch.

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1239451805.1239457218.28818.gz

I'm going to disable this test on 1.9.1 as well.
(In reply to comment #29)
> I'm going to disable this test on 1.9.1 as well.

http://hg.mozilla.org/releases/mozilla-1.9.1/rev/bccb7ddf780c
Attached patch patch — — Splinter Review 
I think the issue with this test is that there can be multiple browser windows open, and then Application.activeWindow isn't necessarily the one that the test lives in. There's no straightforward way to get the fuelWindow for the current window, which is a FUEL design flaw.
Attachment #393455 - Flags: review?(mark.finkle)
This was also an issue with browser_discovery.js on 1.9.1, btw. I fixed that by using the tabbrowser and DOM APIs instead of FUEL, a solution we obviously wouldn't want here: http://hg.mozilla.org/mozilla-central/rev/d53e256b5cb6
Attachment #393455 - Flags: review?(mark.finkle) → review?(dtownsend)
(In reply to comment #31)
> Created an attachment (id=393455) [details]
> patch
> 
> I think the issue with this test is that there can be multiple browser windows
> open, and then Application.activeWindow isn't necessarily the one that the test
> lives in. There's no straightforward way to get the fuelWindow for the current
> window, which is a FUEL design flaw.

If the problem is that there can be multiple browser windows open then doesn't this change make the test fail in that case? Where are the multiple browser windows coming from? Is a previous test not cleaning up properly?
(In reply to comment #33)
> If the problem is that there can be multiple browser windows open then doesn't
> this change make the test fail in that case?

My assumption is that if the window re-gained focused, the other window is closed.

> Where are the multiple browser
> windows coming from? Is a previous test not cleaning up properly?

They must come from previous tests, but usually they try their best to clean up. I think the problem is that window.close isn't completely synchronous, at least on Linux.
Another case where the issue turned out to be another window is bug 498704.
Comment on attachment 393455 [details] [diff] [review]
patch

(In reply to comment #34)
> (In reply to comment #33)
> > If the problem is that there can be multiple browser windows open then doesn't
> > this change make the test fail in that case?
> 
> My assumption is that if the window re-gained focused, the other window is
> closed.

Fair enough.

> > Where are the multiple browser
> > windows coming from? Is a previous test not cleaning up properly?
> 
> They must come from previous tests, but usually they try their best to clean
> up. I think the problem is that window.close isn't completely synchronous, at
> least on Linux.

It's true that window.close isn't synchronous, but there are ways to listen for when a window finally closes. We should probably try to file bugs on tests that don't do this and fix them, or maybe we can do something in the test harness to wait for additional windows to close before running the next tests.
Attachment #393455 - Flags: review?(dtownsend) → review+
http://hg.mozilla.org/mozilla-central/rev/d9742d839d7d

Crossing fingers and resolving...
Assignee: nobody → dao
Status: REOPENED → RESOLVED
Closed: 16 years ago → 15 years ago
Resolution: --- → FIXED
Flags: in-testsuite+
Target Milestone: --- → Firefox 3.7
Target Milestone: Firefox 3.7 → Firefox 3.7a1
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1250624369.1250629992.8552.gz
WINNT 5.2 mozilla-central unit test on 2009/08/18 12:39:29

{
TEST-PASS | ... | Checking event handler for tab move
TEST-UNEXPECTED-FAIL | ... | Timed out
}
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Blocks: 511096
OS X 10.5.2 mozilla-central test everythingelse [testfailed] Started 14:32, finished 15:04
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1252618334.1252620227.9661.gz&fulltext=1
WINNT 5.2 mozilla-central unit test  [testfailed] Started 12:49, finished 15:00
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1252612181.1252619957.6668.gz&fulltext=1
WINNT 5.2 mozilla-central test everythingelse [testfailed] Started 14:42, finished 15:22
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256247755.1256250100.12422.gz&fulltext=1
Summary: FUEL test browser_Browser.js still times out occasionally → mochitest-browser-chrome: FUEL test browser_Browser.js still times out occasionally
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256880024.1256882205.22809.gz
WINNT 5.2 mozilla-central test everythingelse on 2009/10/29 22:20:24
i have been able to reproduce one hang locally in an optimized build.
onStateChange is not hit (so we don't go further onPageBLoadWithFrames: 1, but everything looks fine in the browser window.
and there are no other windows or popups open.
i also have to point out that reproducing these failures in a VM with multiple virtual cpus and low memory values (256MB or less, i'll try with 128) makes these failures more easily reproduceable.
Summary: mochitest-browser-chrome: FUEL test browser_Browser.js still times out occasionally → FUEL test browser_Browser.js still times out occasionally
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257158235.1257163261.26458.gz
Linux mozilla-central test debug everythingelse on 2009/11/02 02:37:15
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257287386.1257291227.611.gz#err0
Linux mozilla-central test opt everythingelse on 2009/11/03 14:29:46
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257695397.1257699334.32472.gz
Linux mozilla-central debug test everythingelse on 2009/11/08 07:49:57
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257789298.1257793801.21853.gz
Linux mozilla-central debug test everythingelse on 2009/11/09 09:54:58
(In reply to comment #52)
> i also have to point out that reproducing these failures in a VM with multiple
> virtual cpus and low memory values (256MB or less, i'll try with 128) makes
> these failures more easily reproduceable.

If this is easily reproducible in a VM, could someone try it in a record-and-replay VM?
One problem is that virtual machine record-and-replay simply does not work with multiple virtual CPUs due to fundamental hardware limitations. Namely, with truly parallel execution on multiple cores, different cores can have races in shared memory, and it's impossible for the virtual machine monitor to detect and reproduce those interactions.

The only way to record and replay genuinely parallel races in shared memory with existing hardware is to instrument instructions that access shared memory, and that's certain to be high overhead. Low-overhead solutions require hardware support (e.g. Bodik et al.'s "Flight Data Recorder") which doesn't exist.
Ah, bummer. :-(
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258425987.1258436698.29117.gz
Linux mozilla-central debug test everythingelse on 2009/11/16 18:46:27  
s: moz2-linux-slave19
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | Timed out
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258796143.1258802246.14380.gz
Linux mozilla-central debug test everythingelse on 2009/11/21 01:35:43
s: moz2-linux-slave26
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259070195.1259075768.1188.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/24 05:43:15
"s: moz2-win32-slave39"
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | Timed out
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259768587.1259775876.16367.gz&fulltext=1

WINNT 5.2 mozilla-central debug test everythingelse

2009/12/02
Started 07:43, finished 09:45
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260187184.1260194786.13490.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/12/07 03:59:44
s: moz2-win32-slave20
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260472914.1260480279.31864.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/12/10 11:21:54
s: win32-slave01
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260488011.1260495939.12442.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/12/10 15:33:31
s: win32-slave10
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260556294.1260563382.10836.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/12/11 10:31:34
s: win32-slave24
TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/fuel/test/browser_Browser.js | Timed out
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260582483.1260588375.28158.gz
Linux mozilla-central debug test everythingelse on 2009/12/11 17:48:03
s: moz2-linux-slave26
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260579911.1260588142.25593.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/12/11 17:05:11
s: win32-slave05
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1260597873.1260604879.12449.gz#err0
WINNT 5.2 mozilla-central debug test everythingelse on 2009/12/11 22:04:33
s: win32-slave43
I still plan to look into this again, but as others should feel free to do so as well, I'm unassigning this from me...
Assignee: dao → nobody
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1261001956.1261010172.20914.gz
Linux mozilla-central debug test everythingelse on 2009/12/16 14:19:16
s: moz2-linux-slave18
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1261169169.1261175015.28939.gz
Linux mozilla-central debug test everythingelse on 2009/12/18 12:46:09
s: moz2-linux-slave23
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1261201678.1261207138.21488.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/12/18 21:47:58
s: win32-slave39
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1261435761.1261441234.13867.gz
Linux mozilla-central opt test everythingelse on 2009/12/21 14:49:21
s: moz2-linux-slave23
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1262166709.1262172164.3001.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/12/30 01:51:49
s: win32-slave27
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1262246595.1262252085.20109.gz
Linux mozilla-central debug test everythingelse on 2009/12/31 00:03:15
s: moz2-linux-slave27
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1263250138.1263254133.12833.gz
Linux mozilla-central opt test everythingelse on 2010/01/11 14:48:58
s: moz2-linux-slave11
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1264194503.1264195721.31922.gz
Linux mozilla-central opt test mochitest-other on 2010/01/22 13:08:23
s: moz2-linux-slave24
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1264431716.1264433065.29492.gz
OS X 10.5.2 mozilla-central opt test mochitest-other on 2010/01/25 07:01:56
s: moz2-darwin9-slave15
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1264434046.1264435116.21166.gz
OS X 10.5.2 mozilla-central opt test mochitest-other on 2010/01/25 07:40:46
s: moz2-darwin9-slave14
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1264711157.1264712704.19893.gz
Linux mozilla-central opt test mochitest-other on 2010/01/28 12:39:17
s: moz2-linux-slave22
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1266001548.1266003385.17804.gz
Linux mozilla-central opt test mochitest-other on 2010/02/12 11:05:48
s: moz2-linux-slave13
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1266519404.1266520475.11175.gz
Linux mozilla-central opt test mochitest-other on 2010/02/18 10:56:44
s: moz2-linux-slave41
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1267056419.1267058618.5961.gz
Linux mozilla-central opt test mochitest-other on 2010/02/24 16:06:59
s: moz2-linux-slave09
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1267633074.1267634491.22760.gz
Linux mozilla-central opt test mochitest-other on 2010/03/03 08:17:54
s: moz2-linux-slave13
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1267825299.1267827524.16837.gz
Linux mozilla-central opt test mochitest-other on 2010/03/05 13:41:39
s: moz2-linux-slave13
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1268187597.1268190056.13410.gz
Linux mozilla-central opt test mochitest-other on 2010/03/09 18:19:57
s: moz2-linux-slave05
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1268449339.1268450825.10595.gz
OS X 10.5.2 mozilla-central opt test mochitest-other on 2010/03/12 19:02:19
s: moz2-darwin9-slave05
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1268554972.1268556332.23206.gz
Linux mozilla-central opt test mochitest-other on 2010/03/14 00:22:52
s: moz2-linux-slave11
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1268616411.1268617523.21680.gz
OS X 10.5.2 mozilla-central opt test mochitest-other on 2010/03/14 18:26:51
s: moz2-darwin9-slave11
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1268950617.1268951422.5505.gz
OS X 10.5.2 mozilla-central opt test mochitest-other on 2010/03/18 15:16:57
s: moz2-darwin9-slave42
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1269650329.1269651094.9923.gz
WINNT 5.2 mozilla-central opt test mochitest-other on 2010/03/26 17:38:49
s: mw32-ix-slave08
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1269821268.1269822044.12803.gz
OS X 10.5.2 mozilla-central opt test mochitest-other on 2010/03/28 17:07:48
s: moz2-darwin9-slave42
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1269958601.1269959375.23878.gz
WINNT 5.2 mozilla-central opt test mochitest-other on 2010/03/30 07:16:41
s: mw32-ix-slave08
Target Milestone: Firefox 3.7a1 → ---
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270167502.1270168278.13953.gz
OS X 10.5.2 mozilla-central opt test mochitest-other on 2010/04/01 17:18:22
s: moz2-darwin9-slave40
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270191419.1270192177.3906.gz
OS X 10.5.2 mozilla-central opt test mochitest-other on 2010/04/01 23:56:59
s: moz2-darwin9-slave42
Let's disable this test, IMO.  It was disabled for a while, until Dao thought he had a fix for it, and we should just go back to that state if we can't figure it out.

dtownsend: is there a bug on auditing the tests with multiple windows to make sure that they wait for the close to finish?  I think that sounds like a promising direction, might help other tests as well.
Note the details and the patterns, though. It started up again on May 2nd, only because the 10.6 debug mochitest-other was unhidden on May 1st, and for whatever reason, it has failed all along more on 10.6 debug than anywhere else. Then suddenly on May 11th, we picked up a few non-Mac fails, then in a separate sudden, after the releng downtime this morning, and then the failure to realize for a while that we weren't getting sendchange on 10.5 after the downtime, every single 10.5 debug mochitest-other has failed. _That_, unlike all the other randomness, makes me think the test has caught something, either in one of the things we pushed while we didn't realize we weren't running Mac tests, or in a change from the downtime.

nthomas was kind enough to trigger builds for the missed changesets, and a few extra tests for the changeset from before the downtime, which I hope will be enough to tell us whether we landed a regression today, or we still haven't noticed all the brokenness from the downtime (or, I guess, whether we just hit a really bad run of luck with those seven runs in a row).
And while the builds for the missing chunk of pushes are still going, the extra tests against 6a71deda9822 (the last changeset from before the downtime, which was the last one to have a 10.5 Mdoth not hit this) both did hit this, pointing an inexplicable finger at something from the downtime as being the reason this test is now apparently permaorange on 10.5 debug.
I was looking at the logs, actually when we browser.addProgressListener, we would expect browser to be waiting for us, really looking at the log it is loading a bunch of pages, or at least many are open:
about:blank, http://example.com/#randomnumber#, about:config, http://example.com/, about:mozilla

All of these pages seem to come from sessionstore/test/browser/browser_522545.js that runs not much before this test... I think disabling this test won't bring anything useful, we should look at tests that run before this one, or, as a workardound, this test should ensure status of the browser on startup and wait for eventual pages that are still loading.
hm, or those tabs/windows are just being destroyed... btw the fact "onStateChange:" is called as soon as we add the progressListener is bad, since something loading is removing the listener before we use it.
sigh, nvm previous comments. The only problem is that onStateChange does never receive complete.

this is what we get in the last log:
STATE_IS_NETWORK + STATE_IS_WINDOW + STATE_IS_DOCUMENT + STATE_IS_REQUEST + STATE_START
STATE_IS_REQUEST + STATE_START
STATE_IS_DOCUMENT + STATE_IS_REQUEST + STATE_TRANSFERRING 
STATE_IS_REQUEST + STATE_STOP
STATE_IS_WINDOW + STATE_IS_DOCUMENT + STATE_IS_REQUEST + STATE_START
STATE_IS_WINDOW + STATE_IS_DOCUMENT + STATE_IS_REQUEST + STATE_START
STATE_IS_REQUEST + STATE_START
STATE_IS_DOCUMENT + STATE_IS_REQUEST + STATE_TRANSFERRING
STATE_IS_REQUEST + STATE_STOP
STATE_IS_REQUEST + STATE_STOP

what we expect
STATE_IS_WINDOW + STATE_IS_NETWORK + STATE_STOP
Assigning to Mark for investigation; please reassign (but not to nobody@) if there's a better owner to be found.
Assignee: nobody → mark.finkle
I landed this: http://hg.mozilla.org/mozilla-central/rev/8e48c8fb8299

NeilAway: dao1: yeah, it would make a difference, given that weak references are broken on trunk
(In reply to comment #154)
> NeilAway: dao1: yeah, it would make a difference, given that weak references
> are broken on trunk

NeilAway: see bug 533290 comment 11 in particular
What you did is compatible with what i was observing, the progresslistener was stopping at random positions, and the windows from previous tests were being collected, thus I guess GC was running and collecting the listener... good catch.
(In reply to comment #143)
> And while the builds for the missing chunk of pushes are still going, the extra
> tests against 6a71deda9822 (the last changeset from before the downtime, which
> was the last one to have a 10.5 Mdoth not hit this) both did hit this, pointing
> an inexplicable finger at something from the downtime as being the reason this
> test is now apparently permaorange on 10.5 debug.

Is it possible that the installation of the resistors onto the Rev3 Leopard machines (bug 563836) affected this? I went over all of the downtime bugs and I can't see anything else that could've.
I think/hope we're done here. Obviously the underlying problem still needs fixing in bug 533290.

Landed on 1.9.2: http://hg.mozilla.org/releases/mozilla-1.9.2/rev/61a692b7799f
Assignee: mark.finkle → dao
Status: REOPENED → RESOLVED
Closed: 15 years ago → 14 years ago
status1.9.2: --- → .5-fixed
Depends on: 533290
Resolution: --- → FIXED
Target Milestone: --- → Firefox 3.7a5
Whiteboard: [orange]
Blocks: 834601
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: