The default bug view has changed. See this FAQ.

(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.