1037597 - Intermittent test_seek.html | application crashed [@ mozilla::AudioSink::Drain()] after "Assertion failure: mPlaying && !mAudioStream->IsPaused(), at content/media/AudioSink.cpp:208"

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[Ryan VanderMeulen [:RyanVM]]

Fallout from bug 996465 maybe?

https://tbpl.mozilla.org/php/getParsedLog.php?id=43630909&tree=Mozilla-Inbound

Rev4 MacOSX Snow Leopard 10.6 mozilla-inbound debug test mochitest-1 on 2014-07-11 11:31:30 PDT for push 9ded0b5313b4
slave: t-snow-r4-0083

12:13:42     INFO -  SEEK-TEST: Started r11025_s16_c1.wav seek test 11
12:13:42     INFO -  SEEK-TEST: Finished r11025_s16_c1.wav seek test 11 token: r11025_s16_c1.wav-10-seek11.js
12:13:42     INFO -  SEEK-TEST: Started r11025_s16_c1.wav seek test 12
12:13:42     INFO -  SEEK-TEST: Finished r11025_s16_c1.wav seek test 10 token: r11025_s16_c1.wav-9-seek10.js
12:13:43     INFO -  System JS : ERROR jar:file:///builds/slave/talos-slave/test/build/application/FirefoxNightlyDebug.app/Contents/MacOS/omni.ja!/components/nsHandlerService.js:891 - NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProperties.get]
12:13:43     INFO -  System JS : ERROR jar:file:///builds/slave/talos-slave/test/build/application/FirefoxNightlyDebug.app/Contents/MacOS/omni.ja!/components/nsHandlerService.js:891 - NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProperties.get]
12:13:43     INFO -  SEEK-TEST: Started r11025_s16_c1.wav seek test 13
12:13:43     INFO -  SEEK-TEST: Finished r11025_s16_c1.wav seek test 12 token: r11025_s16_c1.wav-11-seek12.js
12:13:43     INFO -  System JS : ERROR jar:file:///builds/slave/talos-slave/test/build/application/FirefoxNightlyDebug.app/Contents/MacOS/omni.ja!/components/nsHandlerService.js:891 - NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProperties.get]
12:13:43     INFO -  System JS : ERROR jar:file:///builds/slave/talos-slave/test/build/application/FirefoxNightlyDebug.app/Contents/MacOS/omni.ja!/components/nsHandlerService.js:891 - NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProperties.get]
12:13:44     INFO -  SEEK-TEST: Started audio.wav seek test 1
12:13:44     INFO -  SEEK-TEST: Finished r11025_s16_c1.wav seek test 13 token: r11025_s16_c1.wav-12-seek13.js
12:13:44     INFO -  System JS : ERROR jar:file:///builds/slave/talos-slave/test/build/application/FirefoxNightlyDebug.app/Contents/MacOS/omni.ja!/components/nsHandlerService.js:891 - NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProperties.get]
12:13:44     INFO -  System JS : ERROR jar:file:///builds/slave/talos-slave/test/build/application/FirefoxNightlyDebug.app/Contents/MacOS/omni.ja!/components/nsHandlerService.js:891 - NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProperties.get]
12:13:45     INFO -  SEEK-TEST: Started audio.wav seek test 2
12:13:45     INFO -  Assertion failure: mPlaying && !mAudioStream->IsPaused(), at /builds/slave/m-in-osx64-d-00000000000000000/build/content/media/AudioSink.cpp:208
12:13:45     INFO -  nsRunnableMethodImpl<void (mozilla::AudioSink::*)(), void, true>::Run() [obj-firefox/dist/include/nsThreadUtils.h:391]
12:13:45     INFO -  nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:766]
12:13:45     INFO -  NS_ProcessNextEvent(nsIThread*, bool) [xpcom/glue/nsThreadUtils.cpp:256]
12:13:45     INFO -  mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:326]
12:13:45     INFO -  MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:504]
12:13:45     INFO -  nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.cpp:355]
12:13:46     INFO -  _pt_root [nsprpub/pr/src/pthreads/ptthread.c:215]
12:13:46     INFO -  libSystem.B.dylib + 0x39fd6
12:13:47     INFO -  TEST-INFO | Main app process: killed by SIGHUP
12:13:47  WARNING -  TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_seek.html | application terminated with exit code 1
12:13:47     INFO -  INFO | runtests.py | Application ran for: 0:40:32.289965
12:13:47     INFO -  INFO | zombiecheck | Reading PID log: /var/folders/MV/MV-XewSzHlurwRmheWnLhU+++-k/-Tmp-/tmprMms3Opidlog
12:14:08  WARNING -  PROCESS-CRASH | /tests/content/media/test/test_seek.html | application crashed [@ mozilla::AudioSink::Drain()]
12:14:08     INFO -  Crash dump filename: /var/folders/MV/MV-XewSzHlurwRmheWnLhU+++-k/-Tmp-/tmpuM5WGX.mozrunner/minidumps/C225A0E6-183E-463F-B3D2-3A9E5AA03B06.dmp
12:14:08     INFO -  Operating system: Mac OS X
12:14:08     INFO -                    10.6.8 10K549
12:14:08     INFO -  CPU: amd64
12:14:08     INFO -       family 6 model 23 stepping 10
12:14:08     INFO -       2 CPUs
12:14:08     INFO -  Crash reason:  EXC_BAD_ACCESS / KERN_INVALID_ADDRESS
12:14:08     INFO -  Crash address: 0x0
12:14:08     INFO -  Thread 62 (crashed)
12:14:08     INFO -   0  XUL!mozilla::AudioSink::Drain() [AudioSink.cpp:9ded0b5313b4 : 208 + 0x0]
12:14:08     INFO -      rbx = 0x00007fff700102f8   r12 = 0x000000011a6c8801
12:14:08     INFO -      r13 = 0x0000000000000000   r14 = 0x000000011bef47c0
12:14:08     INFO -      r15 = 0x000000011bef47c0   rip = 0x00000001037074cc
12:14:08     INFO -      rsp = 0x000000010809fc70   rbp = 0x000000010809fc90
12:14:08     INFO -      Found by: given as instruction pointer in context
12:14:08     INFO -   1  XUL!mozilla::AudioSink::AudioLoop() [AudioSink.cpp:9ded0b5313b4 : 180 + 0x7]
12:14:08     INFO -      rbx = 0x000000011a6c8898   r12 = 0x000000011a6c8801
12:14:08     INFO -      r13 = 0x0000000000000000   r14 = 0x0000000100304330
12:14:08     INFO -      r15 = 0x000000011bef47c0   rip = 0x0000000103705fbb
12:14:08     INFO -      rsp = 0x000000010809fca0   rbp = 0x000000010809fcd0
12:14:08     INFO -      Found by: call frame info
12:14:08     INFO -   2  XUL!nsRunnableMethodImpl<void (mozilla::AudioSink::*)(), void, true>::Run() [nsThreadUtils.h:9ded0b5313b4 : 391 + 0x15]
12:14:08     INFO -      rbx = 0x0000000100336aa0   r12 = 0x00000001003a9a00
12:14:08     INFO -      r13 = 0x0000000000015401   r14 = 0x0000000100336b7c
12:14:08     INFO -      r15 = 0x0000000100336b7c   rip = 0x0000000103713246
12:14:08     INFO -      rsp = 0x000000010809fce0   rbp = 0x000000010809fce0
12:14:08     INFO -      Found by: call frame info
12:14:08     INFO -   3  XUL!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:9ded0b5313b4 : 766 + 0x5]
12:14:08     INFO -      rbx = 0x0000000100336aa0   r12 = 0x00000001003a9a00
12:14:08     INFO -      r13 = 0x0000000000015401   r14 = 0x0000000100336b7c
12:14:08     INFO -      r15 = 0x0000000100336b7c   rip = 0x0000000101cd28ac
12:14:08     INFO -      rsp = 0x000000010809fcf0   rbp = 0x000000010809fdc0
12:14:08     INFO -      Found by: call frame info
12:14:08     INFO -   4  XUL!NS_ProcessNextEvent(nsIThread*, bool) [nsThreadUtils.cpp:9ded0b5313b4 : 256 + 0xc]
12:14:08     INFO -      rbx = 0x0000000000000000   r12 = 0x00000001003a9a00
12:14:08     INFO -      r13 = 0x0000000000015401   r14 = 0x000000011e2e39a0
12:14:08     INFO -      r15 = 0x000000010809fd01   rip = 0x0000000101c3c723
12:14:08     INFO -      rsp = 0x000000010809fdd0   rbp = 0x000000010809fde0
12:14:08     INFO -      Found by: call frame info

Comment 1

[JW Wang [:jwwang] [:jw_wang]]

Attachment: 1037597_fix_AudioSink_races.patch

Fix some races in AudioSink.cpp.

Comment 2

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8462298 [details] [diff] [review]
1037597_fix_AudioSink_races.patch

Review of attachment 8462298 [details] [diff] [review]:
-----------------------------------------------------------------

::: content/media/AudioSink.cpp
@@ +139,5 @@
>    }
>  
>    while (1) {
> +    {
> +      ReentrantMonitorAutoEnter mon(GetReentrantMonitor());

WaitForAudioToPlay() and IsPlaybackContinuing() should run in the same monitor to avoid |mPlaying| changes in-between.

@@ -139,5 @@
>    }
>  
>    while (1) {
> -    WaitForAudioToPlay();
> -    if (!IsPlaybackContinuing()) {

It is possible for |mPlaying| to become false before IsPlaybackContinuing() acquiring the monitor. Then AudioStream::Resume() won't be called in IsPlaybackContinuing(). The rest of the code will run with the paused audio stream and assertion will fail.

@@ +177,5 @@
>        mStateMachine->OnAudioEndTimeUpdate(endTime);
>      }
>    }
>    ReentrantMonitorAutoEnter mon(GetReentrantMonitor());
> +  MOZ_ASSERT(mStopAudioThread || AudioQueue().AtEndOfStream());

This condition should hold for it is the same one to exit the while loop.

@@ +178,5 @@
>      }
>    }
>    ReentrantMonitorAutoEnter mon(GetReentrantMonitor());
> +  MOZ_ASSERT(mStopAudioThread || AudioQueue().AtEndOfStream());
> +  if (!mStopAudioThread && mPlaying) {

When |mStopAudioThread| is false, AudioQueue().AtEndOfStream() must be true for the reason above. Also we have to check |mPlaying| again here for it can change again while we are outside of monitor.

Comment 3

[JW Wang [:jwwang] [:jw_wang]]

try on desktop platforms: https://tbpl.mozilla.org/?tree=Try&rev=024c261d9315
try on Android: https://tbpl.mozilla.org/?tree=Try&rev=32dd8f8554ee
try on B2G emulator: https://tbpl.mozilla.org/?tree=Try&rev=fb5949991418

Comment 4

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8462298 [details] [diff] [review]
1037597_fix_AudioSink_races.patch

Review of attachment 8462298 [details] [diff] [review]:
-----------------------------------------------------------------

Matthew is a better reviewer for audio related things I think.

Comment 5

[Matthew Gregan [:kinetik]]

Comment on attachment 8462298 [details] [diff] [review]
1037597_fix_AudioSink_races.patch

Review of attachment 8462298 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks.

Strangely, I fixed this exact bug the same way... but I have no idea where my fix went, obviously never made it to Bugzilla. :-/

Comment 6

[JW Wang [:jwwang] [:jw_wang]]

See comment 3 for the Try results.

Comment 7

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/5f1dc690c111

Comment 8

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/5f1dc690c111

Comment 9

[Ryan VanderMeulen [:RyanVM]]

Please nominate this for Aurora uplift when you get a chance :)

Comment 10

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8462298 [details] [diff] [review]
1037597_fix_AudioSink_races.patch

Approval Request Comment
[Feature/regressing bug #]:948269
[User impact if declined]:declined software quality for decreased test coverage
[Describe test coverage new/current, TBPL]:
tested on Try: https://tbpl.mozilla.org/?tree=Try&rev=b1e57fc15d87
[Risks and why]: low, the change is simiple and has been run well on central for days.
[String/UUID change made/needed]:none

Comment 11

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/80c6d41ee608