(I had already noticed a bug where the screenshot appeared to be taken too late. I just noticed this had been happening for bug 633725. This time, the "more explicit" picture [not copied/attached here, not to bloat] gave me a hint at what the cause could be :->) Bug 414049 added a screenshot feature at automation layer, which probably works great when test harness has hung or the like: http://mxr.mozilla.org/comm-central/source/mozilla/build/automation.py.in#766 727 def waitForFinish(self, proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath): 760 while line != "" and not didTimeout: 766 if self.UNIXISH and not debuggerInfo and not self.haveDumpedScreen and "TEST-UNEXPECTED-FAIL" in line and "Test timed out" in line: 767 self.dumpScreen(utilityPath) But, in the cases I noticed, only one test times out then mochitest harness carries on: http://mxr.mozilla.org/comm-central/source/mozilla/testing/mochitest/tests/SimpleTest/TestRunner.js#68 62 TestRunner._checkForHangs = function() { 65 if (runtime >= TestRunner.timeout * TestRunner._timeoutFactor) { 68 frameWindow.SimpleTest.ok(false, "Test timed out."); 81 frameWindow.SimpleTest.finish(); My first thought would be to use a (not too) short setTimeout(finish) to let the right image be captured (most of the times).

(In reply to Serge Gautherie (:sgautherie) from comment #0) > (I had already noticed a bug where the screenshot appeared to be taken too > late. Adding bug 629996 dependency, which hopefully was that bug.

Sam, would you be interested in fixing this bug?

(In reply to Serge Gautherie (:sgautherie) from comment #2) > Sam, would you be interested in fixing this bug? Sure I can take care of it.

(In reply to Serge Gautherie (:sgautherie) from comment #0) > My first thought would be to use a (not too) short setTimeout(finish) to let > the right image be captured (most of the times). Do you want me to just make the timeout here (http://mxr.mozilla.org/comm-central/source/mozilla/testing/mochitest/tests/SimpleTest/TestRunner.js#116) shorter then or what? Also can you assign the bug to me?

(In reply to Sam Garrett from comment #4) > Do you want me to just make the timeout here > (http://mxr.mozilla.org/comm-central/source/mozilla/testing/mochitest/tests/ > SimpleTest/TestRunner.js#116) shorter then or what? No, the _checkForHangs() "loop" is just fine. What is needed is: *"flush()" the output, if that's possible. *add a little delay so automation.py has time to notice and process "Test timed out". > Also can you assign the bug to me? I would rather do that when a working patch has been attached.

What I have right now is just replacing: frameWindow.SimpleTest.finish(); with: setTimeout(frameWindow.SimpleTest.finish, 1000); Is there a way for me to explicitly flush the output? I looked through SimpleTest.js and didn't see anything. Or even check that automation.py is done?

(In reply to Sam Garrett from comment #6) > setTimeout(frameWindow.SimpleTest.finish, 1000); 1 second seems good (for a start). Add a comment to explain why the delay. > Is there a way for me to explicitly flush the output? I looked through > SimpleTest.js and didn't see anything. There is none, afaict. http://mxr.mozilla.org/comm-central/source/mozilla/testing/mochitest/tests/SimpleTest/MozillaLogger.js https://developer.mozilla.org/en/DOM/window > Or even check that automation.py is done? No, afaik.

Here is the patch using setTimeout. I noticed that we now have the killTest function so I added it there.

Comment on attachment 611623 [details] [diff] [review] Patch using setTimeout to ensure flush. Sorry, taking over: I'm spending more time trying to explain than it's needed to fix this bug :-|

Sam, I'm told my comment 9 may seem rude and I apologize for that: I simply thought more effective at this point to attach a patch and let you check it (by example) than try to do more explanations wrt this very bug :-| I'm pleased you were interested in it and I hope you can fix other bugs as you fixed bug 637103 :-)

Comment on attachment 612290 [details] [diff] [review] (Bv1) Add a 1 second delay before calling killTest(), Fix bug 647323 regression, Remove extra ';' and spaces [Checked in: Comment 17] Per bug 687972 comment 630, it looks like this patch did help :-) (Unless I was just (too) lucky.)

Try run for 3844b13004f6 is complete. Detailed breakdown of the results available here: https://tbpl.mozilla.org/?tree=Try&rev=3844b13004f6 Results (out of 120 total builds): success: 109 warnings: 11 Builds (or logs if builds failed) available at: http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/sgautherie.bz@free.fr-3844b13004f6

(In reply to Mozilla RelEng Bot from comment #12) > https://tbpl.mozilla.org/?tree=Try&rev=3844b13004f6 Succeeded, including one random timeout.

Try run for 85e1ded6cda4 is complete. Detailed breakdown of the results available here: https://tbpl.mozilla.org/?tree=Try&rev=85e1ded6cda4 Results (out of 31 total builds): success: 17 warnings: 14 Builds (or logs if builds failed) available at: http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/sgautherie.bz@free.fr-85e1ded6cda4

Try run for 7ae3d02e3b08 is complete. Detailed breakdown of the results available here: https://tbpl.mozilla.org/?tree=Try&rev=7ae3d02e3b08 Results (out of 31 total builds): exception: 1 success: 16 warnings: 14 Builds (or logs if builds failed) available at: http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/sgautherie.bz@free.fr-7ae3d02e3b08

(In reply to Mozilla RelEng Bot from comment #15) > https://tbpl.mozilla.org/?tree=Try&rev=7ae3d02e3b08 Forced timeout, without fix: all "too late", except "Rev3 Fedora 12 try opt test". (In reply to Mozilla RelEng Bot from comment #14) > https://tbpl.mozilla.org/?tree=Try&rev=85e1ded6cda4 Forced timeout, with fix: all "good" :-)

Comment on attachment 612290 [details] [diff] [review] (Bv1) Add a 1 second delay before calling killTest(), Fix bug 647323 regression, Remove extra ';' and spaces [Checked in: Comment 17] https://hg.mozilla.org/mozilla-central/rev/b7adf1bde2f6

Bv1, for Aurora (and Beta). [Approval Request Comment] Regression caused by (bug #): Bug 414049. User impact if declined: None, but useless screenshot on test timeout. Testing completed (on m-c, etc.): Try and this comment. Risk to taking this patch (and alternatives if risky): None, test-only. String changes made by this patch: None.

Comment on attachment 612748 [details] [diff] [review] (Cv1-ab) Add a 1 second delay before calling finish(), Remove extra ';' and spaces [Checkin: Comment 20] [Triage Comment] Test-only change. Approved for Aurora 13 and Beta 12.

Comment on attachment 612748 [details] [diff] [review] (Cv1-ab) Add a 1 second delay before calling finish(), Remove extra ';' and spaces [Checkin: Comment 20] http://hg.mozilla.org/releases/mozilla-aurora/rev/551fcc0596d1

Missed Gecko 12 :-|

Ftr (that may be unrelated, but just in case), I wonder if this somehow had the (positive) side-effect of letting "too slow" (!= hang) test complete: I have recently noticed a couple "false positive" timeouts on SeaMonkey where the test actually continues after the timeout is logged (and screenshot taken) then ends with no (other) failure in about 5mn(30s). One example: http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey-Aurora/1335354618.1335357762.3281.gz WINNT 5.2 comm-aurora debug test mochitests-4/5 on 2012/04/25 04:50:18 s: cn-sea-qm-win2k3-01 { 109290 INFO TEST-PASS | /tests/layout/style/test/test_value_computation.html | should not get initial value for 'visibility:collapse' on elementf. - collapse should not equal visible 109291 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/style/test/test_value_computation.html | Test timed out. [...] 109292 INFO TEST-PASS | /tests/layout/style/test/test_value_computation.html | should be testing with values that compute to different things for 'white-space' - pre should not equal normal [...] 109540 INFO TEST-END | /tests/layout/style/test/test_value_computation.html | finished in 325202ms 109541 INFO TEST-START | /tests/layout/style/test/test_value_storage.html }