(Try to) Ensure screenshots on test timeouts are not taken too late

RESOLVED FIXED in Firefox 13

Status

Testing
Mochitest
P2
normal
RESOLVED FIXED
6 years ago
5 years ago

People

(Reporter: sgautherie, Assigned: sgautherie)

Tracking

(Blocks: 1 bug, {autotest-issue})

Trunk
mozilla14
autotest-issue
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox11 wontfix, firefox12 wontfix, firefox13 fixed, firefox-esr10 wontfix)

Details

Attachments

(2 attachments, 1 obsolete attachment)

(Assignee)

Description

6 years ago
(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).
(Assignee)

Comment 1

6 years ago
(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.
Blocks: 629996
Keywords: autotest-issue
(Assignee)

Comment 2

5 years ago
Sam, would you be interested in fixing this bug?
OS: Linux → All
Hardware: x86 → All

Comment 3

5 years ago
(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.

Comment 4

5 years ago
(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?
(Assignee)

Comment 5

5 years ago
(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.

Comment 6

5 years ago
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?
(Assignee)

Comment 7

5 years ago
(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.

Comment 8

5 years ago
Created attachment 611623 [details] [diff] [review]
Patch using setTimeout to ensure flush.

Here is the patch using setTimeout. I noticed that we now have the killTest function so I added it there.
Attachment #611623 - Flags: feedback?(sgautherie.bz)
(Assignee)

Updated

5 years ago
Assignee: nobody → sgautherie.bz
Blocks: 647323
Status: NEW → ASSIGNED
Component: General → Mochitest
QA Contact: general → mochitest
Target Milestone: --- → mozilla14
(Assignee)

Comment 9

5 years ago
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 :-|
Attachment #611623 - Attachment is obsolete: true
Attachment #611623 - Flags: feedback?(sgautherie.bz) → review-
(Assignee)

Comment 10

5 years ago
Created 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]

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 :-)
Attachment #612290 - Flags: review?(ted.mielczarek)
(Assignee)

Updated

5 years ago
Blocks: 687972
(Assignee)

Comment 11

5 years ago
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.)

Comment 12

5 years ago
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
(Assignee)

Updated

5 years ago
Blocks: 706534
(Assignee)

Updated

5 years ago
Blocks: 736363
(Assignee)

Comment 13

5 years ago
(In reply to Mozilla RelEng Bot from comment #12)
>     https://tbpl.mozilla.org/?tree=Try&rev=3844b13004f6

Succeeded, including one random timeout.

Comment 14

5 years ago
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

Comment 15

5 years ago
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
(Assignee)

Comment 16

5 years ago
(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" :-)
status-firefox-esr10: --- → wontfix
status-firefox11: --- → wontfix
status-firefox12: --- → affected
status-firefox13: --- → affected
Priority: -- → P2
Attachment #612290 - Flags: review?(ted.mielczarek) → review+
(Assignee)

Comment 17

5 years ago
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
Attachment #612290 - Attachment description: (Bv1) Add a 1 second delay before calling killTest(), Fix bug 647323 regression, Remove extra ';' and spaces → (Bv1) Add a 1 second delay before calling killTest(), Fix bug 647323 regression, Remove extra ';' and spaces [Checked in: Comment 17]
(Assignee)

Updated

5 years ago
Status: ASSIGNED → RESOLVED
Last Resolved: 5 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
(Assignee)

Updated

5 years ago
Blocks: 593491
(Assignee)

Comment 18

5 years ago
Created attachment 612748 [details] [diff] [review]
(Cv1-ab) Add a 1 second delay before calling finish(), Remove extra ';' and spaces [Checkin: Comment 20]

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.
Attachment #612748 - Flags: approval-mozilla-beta?
Attachment #612748 - Flags: approval-mozilla-aurora?
(Assignee)

Updated

5 years ago
Blocks: 679848
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.
Attachment #612748 - Flags: approval-mozilla-beta?
Attachment #612748 - Flags: approval-mozilla-beta+
Attachment #612748 - Flags: approval-mozilla-aurora?
Attachment #612748 - Flags: approval-mozilla-aurora+
(Assignee)

Updated

5 years ago
Keywords: checkin-needed
Whiteboard: [c-n: patch Cv1-ab to m-a and m-b]
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
Attachment #612748 - Attachment description: (Cv1-ab) Add a 1 second delay before calling finish(), Remove extra ';' and spaces → (Cv1-ab) Add a 1 second delay before calling finish(), Remove extra ';' and spaces [Checkin: Comment 20]
(Assignee)

Updated

5 years ago
status-firefox13: affected → fixed
Whiteboard: [c-n: patch Cv1-ab to m-a and m-b] → [c-n: patch Cv1-ab to m-b]
(Assignee)

Comment 21

5 years ago
Missed Gecko 12 :-|
status-firefox12: affected → wontfix
Keywords: checkin-needed
Whiteboard: [c-n: patch Cv1-ab to m-b]
(Assignee)

Comment 22

5 years ago
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
}
You need to log in before you can comment on or make changes to this bug.