1349253 - Assertion: MOZ_ASSERT(!mMaster->IsWaitingAudioData());

Status: RESOLVED FIXED

(Core :: Audio/Video: Playback, defect, P1)

Description

[Jean-Yves Avenard [:jya]]

I was playing with this page:
https://people-mozilla.org/~jyavenard/tests/mse_mp4/paper.html

after installing the about:media plugin and so was going back and forth the tab and pressing refresh.

It triggered the assertion on MOZ_ASSERT(!mMaster->IsWaitingAudioData());


  void OnSeekRejected(const SeekRejectValue& aReject)
  {
    mSeekRequest.Complete();

    if (aReject.mError == NS_ERROR_DOM_MEDIA_WAITING_FOR_DATA) {
      SLOG("OnSeekRejected reason=WAITING_FOR_DATA type=%d", aReject.mType);
      MOZ_ASSERT(!mMaster->IsRequestingAudioData());
      MOZ_ASSERT(!mMaster->IsRequestingVideoData());
      MOZ_ASSERT(!mMaster->IsWaitingAudioData());


https://dxr.mozilla.org/mozilla-central/source/dom/media/MediaDecoderStateMachine.cpp#1249

Comment 1

[Jean-Yves Avenard [:jya]]

Happened again..

stack trace this time:

Assertion failure: !mMaster->IsWaitingAudioData(), at c:/Users/jyavenard/Work/Mozilla/mozilla-central/dom/media/MediaDecoderStateMachine.cpp:1249
#01: <lambda_cd9ff50803bc5d18f4676b706a3f3f60>::operator() (c:\users\jyavenard\work\mozilla\mozilla-central\dom\media\mediadecoderstatemachine.cpp:1174)
#02: mozilla::MozPromise<mozilla::media::TimeUnit,mozilla::SeekRejectValue,1>::InvokeCallbackMethod<<lambda_cd9ff50803bc5d18f4676b706a3f3f60>,void (__cdecl <lambda_cd9ff50803bc5d18f4676b706a3f3f60>::*)(mozilla::SeekRejectValue const & __ptr64)const __ptr64,moz (c:\users\jyavenard\work\mozilla\mozilla-central\obj-x86_64-pc-mingw32\dist\include\mozilla\mozpromise.h:478)
#03: mozilla::MozPromise<mozilla::media::TimeUnit,mozilla::SeekRejectValue,1>::FunctionThenValue<<lambda_1107e2d1f70e3b0d2fcffba12253b475>,<lambda_cd9ff50803bc5d18f4676b706a3f3f60> >::DoResolveOrRejectInternal (c:\users\jyavenard\work\mozilla\mozilla-central\obj-x86_64-pc-mingw32\dist\include\mozilla\mozpromise.h:630)
#04: mozilla::MozPromise<mozilla::media::TimeUnit,mozilla::SeekRejectValue,1>::ThenValueBase::DoResolveOrReject (c:\users\jyavenard\work\mozilla\mozilla-central\obj-x86_64-pc-mingw32\dist\include\mozilla\mozpromise.h:433)
#05: mozilla::MozPromise<mozilla::media::TimeUnit,mozilla::SeekRejectValue,1>::ThenValueBase::ResolveOrRejectRunnable::Run (c:\users\jyavenard\work\mozilla\mozilla-central\obj-x86_64-pc-mingw32\dist\include\mozilla\mozpromise.h:340)
#06: mozilla::AutoTaskDispatcher::TaskGroupRunnable::Run (c:\users\jyavenard\work\mozilla\mozilla-central\obj-x86_64-pc-mingw32\dist\include\mozilla\taskdispatcher.h:196)
#07: mozilla::TaskQueue::Runner::Run (c:\users\jyavenard\work\mozilla\mozilla-central\xpcom\threads\taskqueue.cpp:233)
#08: nsThreadPool::Run (c:\users\jyavenard\work\mozilla\mozilla-central\xpcom\threads\nsthreadpool.cpp:227)
#09: nsThread::ProcessNextEvent (c:\users\jyavenard\work\mozilla\mozilla-central\xpcom\threads\nsthread.cpp:1270)
#10: NS_ProcessNextEvent (c:\users\jyavenard\work\mozilla\mozilla-central\xpcom\threads\nsthreadutils.cpp:389)
#11: mozilla::ipc::MessagePumpForNonMainThreads::Run (c:\users\jyavenard\work\mozilla\mozilla-central\ipc\glue\messagepump.cpp:338)
#12: MessageLoop::RunInternal (c:\users\jyavenard\work\mozilla\mozilla-central\ipc\chromium\src\base\message_loop.cc:239)
#13: MessageLoop::RunHandler (c:\users\jyavenard\work\mozilla\mozilla-central\ipc\chromium\src\base\message_loop.cc:232)
#14: MessageLoop::Run (c:\users\jyavenard\work\mozilla\mozilla-central\ipc\chromium\src\base\message_loop.cc:212)
#15: nsThread::ThreadFunc (c:\users\jyavenard\work\mozilla\mozilla-central\xpcom\threads\nsthread.cpp:502)
#16: _PR_NativeRunThread (c:\users\jyavenard\work\mozilla\mozilla-central\nsprpub\pr\src\threads\combined\pruthr.c:406)
#17: pr_root (c:\users\jyavenard\work\mozilla\mozilla-central\nsprpub\pr\src\md\windows\w95thred.c:96)
#18: o__realloc_base[C:\Windows\System32\ucrtbase.dll +0x1cab0]
#19: BaseThreadInitThunk[C:\Windows\System32\KERNEL32.DLL +0x8364]
#20: RtlUserThreadStart[C:\Windows\SYSTEM32\ntdll.dll +0x670d1]

Comment 2

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

Can you do |MOZ_LOG=MediaDecoder:4 ./mach run xxx| and upload the logs?

Comment 3

[Jean-Yves Avenard [:jya]]

It's not one easy to reproduce, if I enable such verbose logs, pretty certain I won't be able to reproduce it..

Seems related to not disconnecting the waiting promise (the test doesn't call endOFStrea,, so when you reach the end of the content it goes into waiting mode), and either refreshing the page, or going into suspend mode (when you switch tabs and come back)

Comment 4

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

No, MediaDecoder:4 is not as verbose as MediaSample:4. You can give it a shot.

Comment 5

[Jean-Yves Avenard [:jya]]

You could too :)

Comment 6

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

Alas, I can't repro the crash. :(

Comment 7

[Tzuhao Kuo [:kaku]]

Attachment: log-3.log

I can reproduce it!!! See the attachment for full log.

This happens if we have a video element with MeidaSource, and we stop feeding data to the element so that its MDSM keeps waiting for audio/video data and transits to BUFFERING state.

In BUFFERING state, trigger suspend-video-decoder, then resume it. The resuming turns the MDSM into SEEKING state to do a "video-only seek". 

A video-only seek does not reset MDSM's audio decoding states (it resets the video decoding states only), so the MDSM keeps waiting for audio data. 
http://searchfox.org/mozilla-central/rev/d441cb24482c2e5448accaf07379445059937080/dom/media/MediaDecoderStateMachine.cpp#1208-1210

Then, a audio-request-rejection with error=NS_ERROR_DOM_MEDIA_WAITING_FOR_DATA hits the assertion.
http://searchfox.org/mozilla-central/rev/d441cb24482c2e5448accaf07379445059937080/dom/media/MediaDecoderStateMachine.cpp#1284-1293

Comment 8

[Tzuhao Kuo [:kaku]]

Attachment: Bug 1349253 - modify the assertion;

Review commit: https://reviewboard.mozilla.org/r/146648/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/146648/

Comment 9

[Tzuhao Kuo [:kaku]]

Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=3aff48d7ed57c97ad726fc4666a048d585bca030

Comment 10

[Tzuhao Kuo [:kaku]]

Comment on attachment 8875239 [details]
Bug 1349253 - modify the assertion;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/146648/diff/1-2/

Comment 11

[Tzuhao Kuo [:kaku]]

Comment on attachment 8875239 [details]
Bug 1349253 - modify the assertion;

https://reviewboard.mozilla.org/r/146648/#review151094

::: dom/media/MediaDecoderStateMachine.cpp:1316
(Diff revision 2)
>        HandleEndOfAudio();
>        HandleEndOfVideo();

Maybe we should also apply these two handlers according to the `aReject.mType`. Should we?

Comment 12

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

Comment on attachment 8875239 [details]
Bug 1349253 - modify the assertion;

https://reviewboard.mozilla.org/r/146648/#review151138

nice diagram!

Comment 13

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

Comment on attachment 8875239 [details]
Bug 1349253 - modify the assertion;

https://reviewboard.mozilla.org/r/146648/#review151094

> Maybe we should also apply these two handlers according to the `aReject.mType`. Should we?

IIRC, NS_ERROR_DOM_MEDIA_END_OF_STREAM is received only when both audio and video reach the end. Otherwise, MFR will try its best to seek to the specified target. Please check this issue with jya.

Comment 14

[Tzuhao Kuo [:kaku]]

Thanks for the review, let's check in this patch and follow up the issue in comment 13 simultaneously.

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/bf544b2ca2bc
modify the assertion; r=jwwang

Comment 16

[Jean-Yves Avenard [:jya]]

Comment on attachment 8875239 [details]
Bug 1349253 - modify the assertion;

https://reviewboard.mozilla.org/r/146648/#review151184

::: commit-message-2c628:11
(Diff revision 2)
> +MFR discards the whole seek operation without applying audio-seek.
> +
> +video    | audio     |
> +waiting  | waiting   | What MDSM receives
> +-----------------------------------------------------------------------------
> +   X     |    X      | resove mSeekRequest

resolve

Comment 17

[Jean-Yves Avenard [:jya]]

Comment on attachment 8875239 [details]
Bug 1349253 - modify the assertion;

https://reviewboard.mozilla.org/r/146648/#review151186

::: commit-message-2c628:19
(Diff revision 2)
> +-----------------------------------------------------------------------------
> +   X     |    O      | reject mSeekRequest with type=AUDIO, error=WAITING
> +-----------------------------------------------------------------------------
> +   O     |    O      | reject mSeekRequest with type=VIDEO, error=WAITING
> +-----------------------------------------------------------------------------
> +

this nice diagram will get lost quickly in the log. Wouldn't it be nicer to have this in the code too?

Comment 18

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/bf544b2ca2bc