Open Bug 510001 Opened 15 years ago Updated 2 years ago

mochitest-plain: intermittent "test_bug507902.html | Test timed out"

Categories

(Core :: Layout, defect, P5)

Product:
Core
Component:
Layout
Platform:
x86
Windows XP
Type:
defect

Tracking

()

Status:
REOPENED
Milestone:
mozilla1.9.2b1

People

(Reporter: jrmuizel, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, Whiteboard: [test is disabled])

Attachments

(3 files)

debugging patch v1
4.73 KB, patch
Waldo
: review+
Details | Diff | Splinter Review
patch to test whether setting onload after src is an issue
2.05 KB, patch
Details | Diff | Splinter Review
patch fixing the hardcoded port and adding an onerror debugging dump
1.77 KB, patch
Details | Diff | Splinter Review
Blocks: 438871
Whiteboard: [orange]
Assignee: nobody → bobbyholley
pushed fix to mc in bug 9bcf62d5073b. Optimistically resolving as fixed. Please re-open if you see this again.
Status: NEW → RESOLVED
Closed: 15 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla1.9.2b1
Bug 511211 says this also happens on 1.9.1.  (Not sure why it's a different bug report, though.)
Bug 511211 seems to be invalid - resolving it as such.
looks like the failure did actually reoccur, but on mc.
http://tinderbox.mozilla.org/showlog.cgi?tree=Firefox&errorparser=unittest&logfile=1250617322.1250622373.21834.gz&buildtime=1250617322&buildname=WINNT%205.2%20mozilla-central%20unit%20test&fulltext=

reopening.

I'm pretty stumped. Jeff - any ideas?
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Summary: ERROR TEST-UNEXPECTED-FAIL | /tests/layout/generic/test/test_bug507902.html | Test timed out. → mochitest-plain: intermittent "test_bug507902.html | Test timed out"
I don't have any obvious ideas; the logs don't give near enough information to tell where things go astray.  I'd add dumps to all the methods in there to determine which was called last; from there it should be possible to figure out more accurately what's happened.
Added a debugging dump patch to throw up onto the tinderbox. Flagging jeff for review.
Attachment #395613 - Flags: review?
Attachment #395613 - Flags: review? → review?(jwalden+bmo)
Comment on attachment 395613 [details] [diff] [review]
debugging patch v1

I wouldn't have bothered getting review on this, adding dump statements is a trivial enough change.  :-)
Attachment #395613 - Flags: review?(jwalden+bmo) → review+
I thought everything except bustage fixes needed review?

pushed dump patch as f00c51fa1eb4.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1250872964.1250882083.18818.gz
WINNT 5.2 mozilla-central unit test on 2009/08/21 09:42:44  

46044 INFO TEST-PASS | /tests/layout/generic/test/test_bug470212.html | rangeCount should be 0
46046 INFO Running /tests/layout/generic/test/test_bug507902.html...
This test is failing intermittently, see bug 510001 - If you see orange here, please paste the following debugging output on the bug!
test_bug507902.html DEBUG - Current Stage: 0

command timed out: 300 seconds without output
If it's "small enough" and merely a followup, I believe we've always been fine about not needing a review.  Better to beg forgiveness than ask permission, in my book...

That debug output, assuming it works as expected when the test passes, suggests the orange is not a result of httpd.js bugs or misuses.  Agree?
So what seems to be happening here is the following:

1) foo.src = url
2) function call
3) (within the function call) foo.onload = bar
4) bar never gets called, test times out

I don't know much about how events in the DOM work - is it ok to set an onload handler after setting the src? (I've seen this in several other mochitests). Does the fact that onload is set in a function call change things?
Seems like a race condition? Maybe the test should be setting the onload handler before setting .src.
Perhaps.  I tend to write things in that order.

But I don't think it should matter.  nsImageLoadingContent::FireEvent fires image onload events asynchronously.
dbaron - can you clarify what you mean by 'asynchronously'? If the onload handler is set after the load, does it still get called? Does control ever leave js between the time the src is set and the time the handler is set? I've read online that 
img.src = foo
img.onload = bar

is known to be safe in firefox but not in ie. Is this still true?

I'd like to avoid switching the order "because it seems right." Doing so might make the problem disappear, but perhaps not actually address the root cause. I'd rather get to the bottom of it, whatever it is. Either what's happening now is safe, or it's not right?
just added a patch that sets a placeholder onload handler before src that will spew a warning if it ever gets called. This should help us get to the bottom of this.

Pushed to mc as 6a7bc6f644c5. r=lumpy
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1251236437.1251238907.20069.gz
WINNT 5.2 mozilla-central test mochitests on 2009/08/25 14:40:37  

46126 INFO Running /tests/layout/generic/test/test_bug507902.html...
This test is failing intermittently, see bug 510001 - If you see orange here, please paste the following debugging output on the bug!
test_bug507902.html DEBUG - Current Stage: 0
46127 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/generic/test/test_bug507902.html | Test timed out.

Does that help?
ted - thanks, that does help a lot. Given that I landed dummy onload handlers that were set before src, we can now rule out the "src before onload race condition" theory.

Any other ideas? Should we try setting something for onerror and see what happens?
Feel free to land whatever debugging code you deem necessary in tests without review. If it helps you fix a test (or some underlying bug), it's well worth it.
at first I thought the error might have something to do with the fact that the server port was hardcoded in the test as 8888. Ted says this shouldn't be a problem, but I left the fix in anyway. The real reason I'm pushing this patch is to see if we get onerror for the image (since according to smaug img onerror doesn't bubble).

pushed to mc as 72d25f49cbcb. r=lumpy ;-)
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1251823830.1251829787.16545.gz

46354 INFO Running /tests/layout/generic/test/test_bug507902.html...
This test is failing intermittently, see bug 510001 - If you see orange here, please paste the following debugging output on the bug!
test_bug507902.html DEBUG - Current Stage: 0

command timed out: 300 seconds without output
program finished with exit code 1
elapsedTime=1634.453000
TinderboxPrint: mochitest-plain<br/><em class="testfail">T-FAIL</em>
so we're not hitting onload, and we're not hitting onerror. I'm baffled - anyone else have bright ideas?
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1251968128.1251970577.14443.gz
WINNT 5.2 mozilla-central test mochitests on 2009/09/03 01:55:28
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1252107968.1252110203.27010.gz
WINNT 5.2 mozilla-central test mochitests on 2009/09/04 16:46:08
{
46185 INFO Running /tests/layout/generic/test/test_bug507902.html...
This test is failing intermittently, see bug 510001 - If you see orange here, please paste the following debugging output on the bug!
test_bug507902.html DEBUG - Current Stage: 0
46186 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/generic/test/test_bug507902.html | Test timed out.
}
WINNT 5.2 mozilla-central test mochitests
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1252292993.1252295232.27007.gz
46181 INFO Running /tests/layout/generic/test/test_bug507902.html...
This test is failing intermittently, see bug 510001 - If you see orange here, please paste the following debugging output on the bug!
test_bug507902.html DEBUG - Current Stage: 0
46182 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/generic/test/test_bug507902.html | Test timed out.
46184 INFO Running /tests/layout/generic/test/test_movement_by_characters.html...
WINNT 5.2 mozilla-central test mochitests
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1252301699.1252304009.23588.gz
46191 INFO TEST-PASS | /tests/layout/generic/test/test_bug503813.html | Expected hover style
46193 INFO Running /tests/layout/generic/test/test_bug507902.html...
This test is failing intermittently, see bug 510001 - If you see orange here, please paste the following debugging output on the bug!
test_bug507902.html DEBUG - Current Stage: 0
46194 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/generic/test/test_bug507902.html | Test timed out.
46196 INFO Running /tests/layout/generic/test/test_movement_by_characters.html...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6-Unittest/1252664384.1252666798.5331.gz
WINNT 5.2 mozilla-1.9.2 test mochitests on 2009/09/11 03:19:44
Wait, WTF? The latest log paul posted doesn't even display the message about the test failing intermittently. So the issue is probably something that happens even earlier (maybe during SimpleTest.waitForExplicitFinish()?).

Waldo - thoughts?
That's on 1.9.2. Did you land your debug output there, or just trunk?
(In reply to comment #35)
> That's on 1.9.2. Did you land your debug output there, or just trunk?

Ahhh, that would explain it. Disregard my last comment.
Nothing more useful here:
46367 INFO Running /tests/layout/generic/test/test_bug507902.html...
This test is failing intermittently, see bug 510001 - If you see orange here, please paste the following debugging output on the bug!
test_bug507902.html DEBUG - Current Stage: 0

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

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1253617095.1253624854.15437.gz
Basically the same thing here, except the harness timed the test out instead of the whole thing failing:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1253617815.1253619813.15862.gz
Ted - I know what needs to happen to make progress here (bug 515495), but it could be a while. Should we just disable the test?
That's probably the best solution, unfortunately. You're also welcome to stick some logging printfs anywhere you please in the codebase if it would help dig further. I suspect that sticking them in imagelib would result in a massive amount of spew, so maybe not practical.
Ted - I need to head out in a sec and I don't have a clean tree. Can you push a disable patch when you get the chance?
I just hit this...

46204 INFO Running /tests/layout/generic/test/test_bug507902.html...
This test is failing intermittently, see bug 510001 - If you see orange here, please paste the following debugging output on the bug!
test_bug507902.html DEBUG - Current Stage: 0

http://tinderbox.mozilla.org/showlog.cgi?log=TraceMonkey/1253753164.1253758692.14001.gz
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1253829452.1253831342.17238.gz
WINNT 5.2 mozilla-central test opt mochitests on 2009/09/24 14:57:32

Same as comment 42.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1254398959.1254400950.31489.gz
Linux mozilla-central test opt mochitests on 2009/10/01 05:09:19

47249 INFO Running /tests/layout/generic/test/test_bug507902.html...
This test is failing intermittently, see bug 510001 - If you see orange here, please paste the following debugging output on the bug!
test_bug507902.html DEBUG - Current Stage: 0
test_bug507902.html DEBUG - Current Stage: 1
test_bug507902.html DEBUG - Current Stage: 2
test_bug507902.html DEBUG - Current Stage: 3
test_bug507902.html DEBUG - Current Stage: 4
test_bug507902.html DEBUG - Current Stage: 5
test_bug507902.html DEBUG - Current Stage: 6
test_bug507902.html DEBUG - Current Stage: 7
test_bug507902.html DEBUG - starting server load
file_IconTestServer.js DEBUG - Got initial request
file_IconTestServer.js DEBUG - Playing the waiting game
test_bug507902.html DEBUG - Current Stage: 8
test_bug507902.html DEBUG - drawing loading icon
test_bug507902.html DEBUG - Current Stage: 9
test_bug507902.html DEBUG - signaling server to continue
file_IconTestServer.js DEBUG - Got continue command
test_bug507902.html DEBUG - Current Stage: 10
47250 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/generic/test/test_bug507902.html | Test timed out.
Linux mozilla-central test opt mochitests
Started 08:49, finished 09:22
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1254412162.1254414117.24299.gz&fulltext=1
WINNT 5.2 mozilla-central test mochitests Started 11:06, finished 11:49
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1254420376.1254422916.29391.gz&fulltext=1
59504 INFO Running /tests/layout/generic/test/test_bug507902.html...
This test is failing intermittently, see bug 510001 - If you see orange here, please paste the following debugging output on the bug!
test_bug507902.html DEBUG - Current Stage: 0
59505 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/generic/test/test_bug507902.html | Test timed out.

bholley, any update on looking into this? It seems to be happening fairly frequently.
It'll be a bit before we have the logging capabilities to tackle this (bug 515495).

Pushed a disable to mc as 08ac2d3caca8.
landed on 192 as 21d9599fc6bf.
Whiteboard: [orange] → [orange][test is disabled]
Blocks: 586078
I'll have my hands full with XPConnect and js-ctypes for the foreseeable future - resetting assignee to default.
Assignee: bobbyholley+bmo → nobody
Whiteboard: [orange][test is disabled] → [test is disabled]
Priority: -- → P5
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: