Closed Bug 562004 Opened 14 years ago Closed 14 years ago

Wave tests time out intermittently, aborting the test suite: test_wav_ended1.html, test_wav_ended2.html, test_wav_onloadedmetadata.html, test_wav_timeupdate1.html

Categories

(Core :: Audio/Video, defect)

x86
Linux
defect
Not set
normal

Tracking

()

RESOLVED FIXED

People

(Reporter: hsivonen, Unassigned)

References

()

Details

(Keywords: intermittent-failure)

From http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1272367753.1272369882.4643.gz#err0 :
47809 INFO Running /tests/content/media/test/test_wav_ended1.html...
NEXT ERROR 47810 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_wav_ended1.html | Test timed out.
47812 INFO Running /tests/content/media/test/test_wav_ended2.html...
NEXT ERROR 47813 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_wav_ended2.html | Test timed out.
47815 INFO Running /tests/content/media/test/test_wav_onloadedmetadata.html...
47816 INFO TEST-PASS | /tests/content/media/test/test_wav_onloadedmetadata.html | No more than 1 onloadedmetadata events
47817 INFO TEST-PASS | /tests/content/media/test/test_wav_onloadedmetadata.html | Duration should be around 1.0
47818 INFO TEST-PASS | /tests/content/media/test/test_wav_onloadedmetadata.html | No more than 1 onloadeddata events
NEXT ERROR 47819 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_wav_onloadedmetadata.html | Test timed out.
47821 INFO Running /tests/content/media/test/test_wav_timeupdate1.html...
47822 INFO TEST-PASS | /tests/content/media/test/test_wav_timeupdate1.html | Duration should be around 1.0: 1
47823 INFO TEST-PASS | /tests/content/media/test/test_wav_timeupdate1.html | Check currentTime of 0.20000000298023224 is greater than last time of 0
47824 INFO TEST-PASS | /tests/content/media/test/test_wav_timeupdate1.html | Check currentTime of 0.3001360595226288 is greater than last time of 0.20000000298023224
47825 INFO TEST-PASS | /tests/content/media/test/test_wav_timeupdate1.html | Check currentTime of 0.40099772810935974 is greater than last time of 0.3001360595226288
47826 INFO TEST-PASS | /tests/content/media/test/test_wav_timeupdate1.html | Check currentTime of 0.5012245178222656 is greater than last time of 0.40099772810935974
47827 INFO TEST-PASS | /tests/content/media/test/test_wav_timeupdate1.html | Check currentTime of 0.601360559463501 is greater than last time of 0.5012245178222656
47828 INFO TEST-PASS | /tests/content/media/test/test_wav_timeupdate1.html | Check currentTime of 0.7015873193740845 is greater than last time of 0.601360559463501
47829 INFO TEST-PASS | /tests/content/media/test/test_wav_timeupdate1.html | Check currentTime of 0.801814079284668 is greater than last time of 0.7015873193740845
47830 INFO TEST-PASS | /tests/content/media/test/test_wav_timeupdate1.html | Check currentTime of 0.9020408391952515 is greater than last time of 0.801814079284668
47831 INFO TEST-PASS | /tests/content/media/test/test_wav_timeupdate1.html | Check currentTime of 1 is greater than last time of 0.9020408391952515
NEXT ERROR 47832 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_wav_timeupdate1.html | Test timed out.
47833 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up.
47834 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 70 remaining tests.

The push was about HTML5 parser bits that aren't turned on yet.
Possibly the landing of bug 560708 causing this?
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1272477953.1272480015.26203.gz
Rev3 Fedora 12 mozilla-central opt test mochitests-1/5 on 2010/04/28 11:05:53
s: talos-r3-fed-031
(In reply to comment #4)
> http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1272477953.1272480015.26203.gz
> Rev3 Fedora 12 mozilla-central opt test mochitests-1/5 on 2010/04/28 11:05:53
> s: talos-r3-fed-031

This contains a callstack:

Thread 14
 0  linux-gate.so + 0x424
 1  libasound.so.2.0.0 + 0x4b835
 2  libasound.so.2.0.0 + 0x4ba0a
 3  libasound.so.2.0.0 + 0x4bb4a
 4  libasound.so.2.0.0 + 0x901ea
 5  libasound.so.2.0.0 + 0x4611b
 6  libxul.so!sa_stream_write [sydney_audio_alsa.c:5e93ba534a98 : 197 + 0x9]
 7  libxul.so!nsAudioStream::Drain [nsAudioStream.cpp:5e93ba534a98 : 224 + 0xf]
 8  libxul.so!nsWaveStateMachine::Run [nsWaveDecoder.cpp:5e93ba534a98 : 746 + 0x8]

nsAudioStream::Drain() is doing a blocking write to playback the remaining buffered audio. This blocking write is not returning, it's a bug in ALSA (the same one which is causing bug 557432).

We could change nsAudioStream::Drain() to do non-blocking writes for the WAV backend. Or rewrite libsydneyaudio to be callback based. Or update ALSA on the tinderbox machines?
This is only failing on the new Fedora tinderboxen.  On the old Linux machines, we probably weren't exercising the sound code at all because snd_pcm_open would return an error (as the tinderboxen had no sound hardware) and we'd use the no-audio path.  On these machines, snd_pcm_open probably succeeds because PulseAudio is installed and running (which, if these machines also have no sound hardware, is probably just throwing away the sound samples).  So this could be a bug in sydneyaudio, ALSA, the ALSA Pulse plugin, or PulseAudio.  I'll try to reproduce this locally in the next few days and dig deeper.
releng should have spare Fedora slaves that you can borrow before too long, if you can't reproduce elsewhere.
Summary: Wave tests time out in a way that looks random: test_wav_ended1.html, test_wav_ended2.html, test_wav_onloadedmetadata.html, test_wav_timeupdate1.html → Wave tests time out intermittently, aborting the test suite: test_wav_ended1.html, test_wav_ended2.html, test_wav_onloadedmetadata.html, test_wav_timeupdate1.html
Depends on: 571798
I'm pretty sure this failure (test_wav_ended2, at least) is caused by the same bug that causes bug 569163.
Depends on: 569163
Marking fixed by bug 569163.
Status: NEW → RESOLVED
Closed: 14 years ago
Resolution: --- → FIXED
Whiteboard: [orange]
You need to log in before you can comment on or make changes to this bug.