Closed Bug 493647 Opened 11 years ago Closed 10 years ago

mochitest-plain: random "Checking currentTime at end" failure in test_ended1.html, test_ended2.html and others

Categories

(Core :: Audio/Video, defect)

x86
All
defect
Not set

Tracking

()

RESOLVED WORKSFORME

People

(Reporter: mak, Unassigned)

References

Details

(Keywords: intermittent-failure)

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1242678924.1242687489.15253.gz

*** 28057 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/video/test/test_ended2.html | Checking currentTime at end: 3.8989999294281006
28057 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/video/test/test_ended2.html | Checking currentTime at end: 3.8989999294281006
make: *** [mochitest-plain] Error 1
Unknown Error: command finished with exit code: 2
Whiteboard: [orange]
See also bug 494480 (a similar-looking bug in test_wav_trailing.html)
Similar-looking test failure in test_ended1.html:
> 27889 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/video/test/test_ended1.html | Checking currentTime at end: 3.6989998817443848

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1243020371.1243027149.2567.gz
WINNT 5.2 mozilla-1.9.1 unit test on 2009/05/22 12:26:11
Summary: random failure in test_ended2.html → random failure in test_ended1.html, test_ended2.html
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1243164587.1243169840.20435.gz
WINNT 5.2 mozilla-central unit test on 2009/05/24 04:29:47
This happens randomly on SeaMonkey production: example:
{
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1243626553.1243630003.3198.gz
OS X 10.4 comm-central unit test on 2009/05/29 12:49:13

27537 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/video/test/test_ended2.html | Checking currentTime at end: 3.8989999294281006
}

This happens very frequently on SeaMonkey-Ports: example:
{
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey-Ports/1243594435.1243601725.8494.gz
OS X 10.5 comm-1.9.1 unit test on 2009/05/29 03:53:55

27279 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/video/test/test_bug468190.html | Checking currentTime at end: 3.0329999923706055
}

Note this check fails on various tests.

Would this be (related to) bug 495300?
Flags: blocking1.9.1?
Summary: random failure in test_ended1.html, test_ended2.html → mochitest-plain: random "Checking currentTime at end" failure in test_ended1.html, test_ended2.html and others
Serge: why do you think this should block the release of Firefox 3.5?
(In reply to comment #7)

Video is a key feature of 1.9.1 and this bug is suspect,
though I don't know whether it's a tests oddity or something worse.
roc/doublec: possibly the same as bug 495300 or bug 495159 ?
I don't think we've seen this in Firefox since 494336 was fixed, which would have caused some cases of this. I've run mochitests dozens of times and been unable to reproduce this anymore. I recommend not blocking on it.
Flags: blocking1.9.1? → blocking1.9.1-
test_bug482461.html too: (examples)

SeaMonkey-Ports: OS X 10.5 comm-1.9.1 unit test on 2009/05/30

27307 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/video/test/test_bug482461.html | Checking currentTime at end: 0
27301 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/video/test/test_bug482461.html | Checking currentTime at end: 0.13397216796875
27301 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/video/test/test_bug482461.html | Checking currentTime at end: 0.333984375
(In reply to comment #10)

> I don't think we've seen this in Firefox since 494336 was fixed

Wrong:
that bug landed on 1.9.1 at 'May 25 16:08:47 2009 -0700'
and, going backward from now to 2009/05/28 06:41:02, I found (only)

{
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1243560335.1243565921.12585.gz
WINNT 5.2 mozilla-1.9.1 unit test on 2009/05/28 18:25:35

27658 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/video/test/test_bug468190.html | Checking currentTime at end: 3.6989998817443848
}

{
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1243562382.1243568828.17240.gz
WINNT 5.2 mozilla-1.9.1 unit test on 2009/05/28 18:59:42

27904 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/video/test/test_ended1.html | Checking currentTime at end: 3.6989998817443848
}

> I've run mochitests dozens of times and been
> unable to reproduce this anymore.

So, fwiw:
*Firefox (3.5): Windows, rarely.
*SeaMonkey-Ports: MacOSX, often.

Which app/platform did you try to reproduce with?

> I recommend not blocking on it.

Maybe reconsider.
Flags: wanted1.9.1?
OS: Windows XP → All
Sounds to me like it could possibly be a case of rounding or such (depending on what the actually expected currentTime at end is, unfortunately the tests aren't written in a way that they would tell). If so, probably not blocking, but something that should be looked into.
test_bug468190 and test_ended1 expect 3.9 <= currentTime =< 4.0, and test_bug48246 expects 3 < currentTime < 5, so it's not a rounding problem.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1243851986.1243856102.10290.gz
WINNT 5.2 mozilla-central unit test on 2009/06/01 03:26:26

Firefox 3.6 still has it too.
Linux SeaMonkey too (now) :-/

{
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey-Ports/1243836892.1243842344.19956.gz
Linux comm-1.9.1 unit test on 2009/05/31 23:14:52
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey-Ports/1243858678.1243863711.27173.gz
Linux comm-1.9.1 unit test on 2009/06/01 05:17:58

27276 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/video/test/test_bug468190.html | Checking currentTime at end: 3.4660000801086426
}

seen before+after "Ogg" checkins at 'Jun 01 03:40:42 2009 -0700'.

***

And still there on MacOSX SeaMonkey:

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey-Ports/1243855431.1243863550.26997.gz
OS X 10.5 comm-1.9.1 unit test on 2009/06/01 04:23:51
Flags: wanted1.9.1? → wanted1.9.1+
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1244684328.1244690133.10224.gz
OS X 10.4 comm-central unit test on 2009/06/10 18:38:48
test_bug482461.html | Checking currentTime at end: 1.3353686332702637
After bug 494462 Parallels Server 2232 + Xserve 10.5.7 (+ cb-seasmonkey-osx-03/04 10.5.7) upgrades:

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey-Ports/1244685879.1244692862.13844.gz
OS X 10.5 comm-1.9.1 unit test on 2009/06/10 19:04:39
Building on: cb-seamonkey-osx-02
test_bug482461.html | Checking currentTime at end: 0.36735108494758606

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey-Ports/1244692754.1244700088.24141.gz
OS X 10.5 comm-1.9.1 unit test on 2009/06/10 20:59:14
Building on: cb-seamonkey-osx-02
test_bug482461.html | Checking currentTime at end: 0.33433106541633606

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey-Ports/1244703488.1244713408.13750.gz
OS X 10.5 comm-1.9.1 unit test on 2009/06/10 23:58:08
Building on: cb-seamonkey-osx-01
test_bug482461.html | Checking currentTime at end: 0.36735108494758606

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey-Ports/1244704895.1244710227.7854.gz
Linux comm-1.9.1 unit test on 2009/06/11 00:21:35
test_ended1.html | Checking currentTime at end: 2.799333095550537

***

After bug 494462 cb-seasmonkey-osx-01/02 10.5.7 upgrades:

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey-Ports/1244728304.1244735347.31699.gz
OS X 10.5 comm-1.9.1 unit test on 2009/06/11 06:51:44
Building on: cb-seamonkey-osx-02
test_bug468190.html | Checking currentTime at end: 0.666333019733429
test_bug482461.html | Checking currentTime at end: 0.36735108494758606
(In reply to comment #20)
> After bug 494462 cb-seasmonkey-osx-01/02 10.5.7 upgrades:

Don't assume that they were updated when I posted they have been. Actually, they have been updated a few hours before that, but from what I see, that's nothing that really makes a difference.
test_bug482461.html seems to fail every single time on the SeaMonkey 10.5 VMs (others do only intermittently):

27300 INFO Running /tests/content/media/video/test/test_bug482461.html...
27301 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/video/test/test_bug482461.html | Checking currentTime at end: 0.8013110160827637
27302 INFO TEST-PASS | /tests/content/media/video/test/test_bug482461.html | Checking playback has ended

Is there something that makes this test more likely to fail? Can we make it more stable?
I have no idea how that could be so wrong.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1247687050.1247696481.17815.gz
WINNT 5.2 mozilla-1.9.1 unit test on 2009/07/15 12:44:10

... | test_bug468190.html | Checking currentTime at end: 3.8993330001831055
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1249887928.1249894939.23516.gz
WINNT 5.2 mozilla-1.9.1 unit test on 2009/08/10 00:05:28

test_ended2.html | Checking currentTime at end: 3.8663330078125
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey2.0/1250215562.1250223466.2522.gz
Linux comm-1.9.1 unit test on 2009/08/13 19:06:02

test_ended1.html | Checking currentTime at end: 3.232332944869995
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey2.0/1250258190.1250264791.17101.gzLinux
comm-1.9.1 unit test on 2009/08/14 06:56:30

test_bug468190.html | Checking currentTime at end: 2.8993330001831055
Duplicate of this bug: 496697
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey2.0/1250557177.1250564035.5605.gz
Linux comm-1.9.1 unit test on 2009/08/17 17:59:37

test_ended1.html | Checking currentTime at end: 3.5993330478668213
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey2.0/1250571555.1250578249.30516.gz
WINNT 5.2 comm-1.9.1 unit test on 2009/08/17 21:59:15

test_bug468190.html | Checking currentTime at end: 3.8663330078125
Depends on: 510788
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey2.0/1250727089.1250733539.2387.gz
Linux comm-1.9.1 unit test on 2009/08/19 17:11:29

test_ended2.html | Checking currentTime at end: 3.7663331031799316
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey2.0/1251124592.1251134135.1173.gz
WINNT 5.2 comm-1.9.1 unit test on 2009/08/24 07:36:32

test_ended2.html | Checking currentTime at end: 3.432332992553711
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey2.0/1251171721.1251177878.6048.gz
Linux comm-1.9.1 unit test on 2009/08/24 20:42:01

test_bug468190.html | Checking currentTime at end: 2.166332960128784
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey2.0/1251206913.1251214181.26239.gz
Linux comm-1.9.1 unit test on 2009/08/25 06:28:33

test_ended2.html | Checking currentTime at end: 3.799333095550537
Only a reminder on unreliable MacOSX 10.5 SeaMonkey box:
{
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey2.0/1251641727.1251649737.14673.gz
OS X 10.5 comm-1.9.1 unit test on 2009/08/30 07:15:27

test_bug468190.html | Checking currentTime at end: 3.566333055496216
test_ended2.html | Checking currentTime at end: 0.7993329763412476
}
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1251703556.1251708518.5544.gz
WINNT 5.2 mozilla-1.9.1 unit test on 2009/08/31 00:25:56

test_ended2.html | Checking currentTime at end: 3.799333095550537
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1251977505.1251983229.28104.gz
WINNT 5.2 mozilla-1.9.1 unit test on 2009/09/03 04:31:45

test_ended1.html | Checking currentTime at end: 3.8993330001831055
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey2.0/1254277864.1254282893.21351.gz
Linux comm-1.9.1 unit test on 2009/09/29 19:31:04

test_ended2.html | Checking currentTime at end: 2.232332944869995
No case of this in 5 months, probably fixed?
Let's say so...
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → WORKSFORME
Whiteboard: [orange]
You need to log in before you can comment on or make changes to this bug.