1915045 - Assertion failure: !mMaster->OutOfDecodedVideo() || mMaster->IsRequestingVideoData() || mMaster->IsWaitingVideoData(), at /home/user/code/mozilla-unified/dom/media/MediaDecoderStateMachine.cpp:3323

Status: RESOLVED FIXED

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

Description

[Tyson Smith [:tsmith]]

Found with m-c 20240823-1883fd8e3792 (--enable-debug --enable-fuzzing)

This was found by visiting a live website with a debug build.

STR:

• Launch browser and visit site

This issue was triggered by visiting http://dcsdschools.org/.

A Pernosco session is available here: https://pernos.co/debug/IyiNfxmlNCTj2uIbOrlCCQ/index.html

Assertion failure: !mMaster->OutOfDecodedVideo() || mMaster->IsRequestingVideoData() || mMaster->IsWaitingVideoData(), at /home/user/code/mozilla-unified/dom/media/MediaDecoderStateMachine.cpp:3323

#0 0x3185da8d289 in mozilla::MediaDecoderStateMachine::BufferingState::Step() /home/user/code/mozilla-unified/dom/media/MediaDecoderStateMachine.cpp:3321:5
#1 0x3185da98a7d in mozilla::MediaDecoderStateMachine::RunStateMachine() /home/user/code/mozilla-unified/dom/media/MediaDecoderStateMachine.cpp:4256:14
#2 0x3185dae6410 in mozilla::MediaDecoderStateMachine::ScheduleStateMachineIn(mozilla::media::TimeUnit const&)::$_0::operator()() const /home/user/code/mozilla-unified/dom/media/MediaDecoderStateMachine.cpp:4388:15
#3 0x3185dae6410 in std::enable_if<!TakesAnyArguments<void (mozilla::MediaDecoderStateMachine::ScheduleStateMachineIn(mozilla::media::TimeUnit const&)::$_0::*)() const>, mozilla::detail::MethodTrait<void (mozilla::MediaDecoderStateMachine::ScheduleStateMachineIn(mozilla::media::TimeUnit const&)::$_0::*)() const>::ReturnType>::type mozilla::MozPromise<bool, bool, true>::InvokeMethod<mozilla::MediaDecoderStateMachine::ScheduleStateMachineIn(mozilla::media::TimeUnit const&)::$_0, void (mozilla::MediaDecoderStateMachine::ScheduleStateMachineIn(mozilla::media::TimeUnit const&)::$_0::*)() const, bool>(mozilla::MediaDecoderStateMachine::ScheduleStateMachineIn(mozilla::media::TimeUnit const&)::$_0*, void (mozilla::MediaDecoderStateMachine::ScheduleStateMachineIn(mozilla::media::TimeUnit const&)::$_0::*)() const, bool&&) /home/user/code/mozilla-unified/objdir-ff-debug/dist/include/mozilla/MozPromise.h:659:12
#4 0x3185dae6410 in std::enable_if<!false, void>::type mozilla::MozPromise<bool, bool, true>::InvokeCallbackMethod<false, mozilla::MediaDecoderStateMachine::ScheduleStateMachineIn(mozilla::media::TimeUnit const&)::$_0, void (mozilla::MediaDecoderStateMachine::ScheduleStateMachineIn(mozilla::media::TimeUnit const&)::$_0::*)() const, bool, RefPtr<mozilla::MozPromise<bool, bool, true>::Private>>(mozilla::MediaDecoderStateMachine::ScheduleStateMachineIn(mozilla::media::TimeUnit const&)::$_0*, void (mozilla::MediaDecoderStateMachine::ScheduleStateMachineIn(mozilla::media::TimeUnit const&)::$_0::*)() const, bool&&, RefPtr<mozilla::MozPromise<bool, bool, true>::Private>&&) /home/user/code/mozilla-unified/objdir-ff-debug/dist/include/mozilla/MozPromise.h:683:5
#5 0x3185dae6410 in mozilla::MozPromise<bool, bool, true>::ThenValue<mozilla::MediaDecoderStateMachine::ScheduleStateMachineIn(mozilla::media::TimeUnit const&)::$_0, mozilla::MediaDecoderStateMachine::ScheduleStateMachineIn(mozilla::media::TimeUnit const&)::$_1>::DoResolveOrRejectInternal(mozilla::MozPromise<bool, bool, true>::ResolveOrRejectValue&) /home/user/code/mozilla-unified/objdir-ff-debug/dist/include/mozilla/MozPromise.h:857:9
#6 0x3185b9675c3 in mozilla::MozPromise<bool, bool, true>::ThenValueBase::ResolveOrRejectRunnable::Run() /home/user/code/mozilla-unified/objdir-ff-debug/dist/include/mozilla/MozPromise.h:488:21
#7 0x3185964567d in mozilla::TaskQueue::Runner::Run() /home/user/code/mozilla-unified/xpcom/threads/TaskQueue.cpp:257:20
#8 0x31859676e05 in nsThreadPool::Run() /home/user/code/mozilla-unified/xpcom/threads/nsThreadPool.cpp:456:14
#9 0x3185966d0e9 in nsThread::ProcessNextEvent(bool, bool*) /home/user/code/mozilla-unified/xpcom/threads/nsThread.cpp:1149:16
#10 0x31859673b7b in NS_ProcessNextEvent(nsIThread*, bool) /home/user/code/mozilla-unified/xpcom/threads/nsThreadUtils.cpp:480:10
#11 0x3185a32d48a in mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) /home/user/code/mozilla-unified/ipc/glue/MessagePump.cpp:299:20
#12 0x3185a24ce48 in MessageLoop::RunInternal() /home/user/code/mozilla-unified/ipc/chromium/src/base/message_loop.cc:370:10
#13 0x3185a24cd39 in MessageLoop::RunHandler() /home/user/code/mozilla-unified/ipc/chromium/src/base/message_loop.cc:363:3
#14 0x3185a24cd39 in MessageLoop::Run() /home/user/code/mozilla-unified/ipc/chromium/src/base/message_loop.cc:345:3
#15 0x31859668483 in nsThread::ThreadFunc(void*) /home/user/code/mozilla-unified/xpcom/threads/nsThread.cpp:366:10
#16 0x7ffffffc8553 in _pt_root /home/user/code/mozilla-unified/nsprpub/pr/src/pthreads/ptthread.c:201:5
#17 0x68d47d90dac2 in start_thread nptl/pthread_create.c:442:8
#18 0x68d47d99ea03 in __clone misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:100

Comment 1

[Tyson Smith [:tsmith]]

A site that reports this issue also triggers this:

Assertion failure: aTrackData.mBufferedRanges.IsEmpty(), at /builds/worker/checkouts/gecko/dom/media/mediasource/TrackBuffersManager.cpp:2692

#0 0x7fffec19340f in mozilla::TrackBuffersManager::RemoveFrames(mozilla::media::TimeIntervals const&, mozilla::TrackBuffersManager::TrackData&, unsigned int, mozilla::TrackBuffersManager::RemovalMode) /builds/worker/checkouts/gecko/dom/media/mediasource/TrackBuffersManager.cpp:2692:5
#1 0x7fffec18c8bf in mozilla::TrackBuffersManager::CodedFrameRemoval(mozilla::media::Interval<mozilla::media::TimeUnit> const&) /builds/worker/checkouts/gecko/dom/media/mediasource/TrackBuffersManager.cpp:784:5
#2 0x7fffec18b2dd in mozilla::TrackBuffersManager::ProcessTasks() /builds/worker/checkouts/gecko/dom/media/mediasource/TrackBuffersManager.cpp:241:17
#3 0x7fffec18ad5c in mozilla::TrackBuffersManager::QueueTask(mozilla::SourceBufferTask*) /builds/worker/checkouts/gecko/dom/media/mediasource/TrackBuffersManager.cpp:163:3
#4 0x7fffec18f13a in mozilla::TrackBuffersManager::CodedFrameRemovalWithPromise(mozilla::media::Interval<mozilla::media::TimeUnit> const&) /builds/worker/checkouts/gecko/dom/media/mediasource/TrackBuffersManager.cpp:721:3
#5 0x7fffec0163c5 in operator()<StoreCopyPassByRRef<NS_ConvertUTF8toUTF16> &> /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:1085:18
#6 0x7fffec0163c5 in __invoke_impl<RefPtr<mozilla::MozPromise<bool, nsresult, true> >, (lambda at /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:1084:9), StoreCopyPassByRRef<NS_ConvertUTF8toUTF16> &> /builds/worker/fetches/sysroot-x86_64-linux-gnu/usr/lib/gcc/x86_64-linux-gnu/8/../../../../include/c++/8/bits/invoke.h:60:14
#7 0x7fffec0163c5 in __invoke<(lambda at /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:1084:9), StoreCopyPassByRRef<NS_ConvertUTF8toUTF16> &> /builds/worker/fetches/sysroot-x86_64-linux-gnu/usr/lib/gcc/x86_64-linux-gnu/8/../../../../include/c++/8/bits/invoke.h:95:14
#8 0x7fffec0163c5 in __apply_impl<(lambda at /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:1084:9), std::tuple<StoreCopyPassByRRef<NS_ConvertUTF8toUTF16> > &, 0UL> /builds/worker/fetches/sysroot-x86_64-linux-gnu/usr/lib/gcc/x86_64-linux-gnu/8/../../../../include/c++/8/tuple:1678:14
#9 0x7fffec0163c5 in apply<(lambda at /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:1084:9), std::tuple<StoreCopyPassByRRef<NS_ConvertUTF8toUTF16> > &> /builds/worker/fetches/sysroot-x86_64-linux-gnu/usr/lib/gcc/x86_64-linux-gnu/8/../../../../include/c++/8/tuple:1687:14
#10 0x7fffec0163c5 in apply<mozilla::gmp::GMPParent, RefPtr<mozilla::MozPromise<bool, nsresult, true> > (mozilla::gmp::GMPParent::*)(const nsTSubstring<char16_t> &)> /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:1083:12
#11 0x7fffec0163c5 in Invoke /builds/worker/workspace/obj-build/dist/include/mozilla/MozPromise.h:1689:47
#12 0x7fffec0163c5 in mozilla::detail::ProxyRunnable<mozilla::MozPromise<bool, nsresult, true>, RefPtr<mozilla::MozPromise<bool, nsresult, true>> (mozilla::TrackBuffersManager::*)(mozilla::media::Interval<mozilla::media::TimeUnit> const&), mozilla::TrackBuffersManager, StoreCopyPassByRRef<mozilla::media::Interval<mozilla::media::TimeUnit>>>::Run() /builds/worker/workspace/obj-build/dist/include/mozilla/MozPromise.h:1709:42
#13 0x7fffe7dad635 in mozilla::TaskQueue::Runner::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskQueue.cpp:257:20
#14 0x7fffe7dd9295 in nsThreadPool::Run() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadPool.cpp:456:14
#15 0x7fffe7dcf836 in nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1153:16
#16 0x7fffe7dd631f in NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:480:10
#17 0x7fffe896c71c in mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:299:20
#18 0x7fffe88be331 in RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:362:3
#19 0x7fffe88be331 in MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:344:3
#20 0x7fffe7dcad63 in nsThread::ThreadFunc(void*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:366:10
#21 0x7ffff79e96df in _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:191:3
#22 0x7ffff7a85ac2 in start_thread nptl/pthread_create.c:442:8
#23 0x7ffff7b1784f  misc/../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Comment 2

[Karl Tomlinson (:karlt)]

The assertion was added when non-polling buffering was implemented.
"Only switch to buffering mode when the reader is waiting for data" and "Stop using buffering heuristics when they're not requested" surrounding changes go together with each other and were related.

At the time EnsureVideoDecodeTaskQueued() would set mVideoRequestStatus via DispatchDecodeTasksIfNeeded().

When DispatchDecodeTasksIfNeeded() was removed, it was not obvious that the assertion would have still held.

Comment 3

[Karl Tomlinson (:karlt)]

In the pernosco recording:

1. While in LoopingDecodingState, a RequestVideoData() completed. HandleVideoDecoded() did not queue another video decode because mMaster->HaveEnoughDecodedVideo() was true.
2. mMaster->HaveEnoughDecodedVideo() was still true when the mPlayState watcher ran.
3. DecodingState::Step() started playback, which caused the VideoSink to pop frames from the video queue.
4. The same DecodingState::Step() then switched to BufferingState because it is OutOfDecodedAudio(). This disconnected the mOnVideoPopped listener before the asynchronous notification is received.
5. BufferingState::Step() is a no-op and will not advance to DecodingState because OutOfDecodedVideo(), due to the popped frames in 3, and nothing to request decode of more video.

Comment 4

[Karl Tomlinson (:karlt)]

The logic became incomplete as of https://hg.mozilla.org/mozilla-central/rev/4c879d5173d1f32f83fa2e3d943cd7409f360590 but this may have become more of a problem since https://hg.mozilla.org/mozilla-central/rev/acb4ae1c1e57de7130cbfb499d6c30dcf134dfbb allowed the playback position to get ahead of audio frames, leading to decoded frames being drained immediately when playback resumes.

Comment 5

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1388665

Comment 6

[Karl Tomlinson (:karlt)]

Attachment: Bug 1915045 Ensure decode tasks are scheduled on BufferingState::Enter() r?#media-playback-reviewers

BufferingState::Step() needs these in order to transition to DecodingState,
if Reader()->UseBufferingHeuristics().

The same tasks are scheduled even when !UseBufferingHeuristics() for
consistency with HandleAudioDecoded/HandleVideoDecoded() and with the behavior
prior to
https://hg.mozilla.org/mozilla-central/rev/4c879d5173d1f32f83fa2e3d943cd7409f360590

Comment 7

[Karl Tomlinson (:karlt)]

Attachment: Bug 1915045 Test playback after waiting for audio r?#media-playback-reviewers

Comment 8

[Karl Tomlinson (:karlt)]

Attachment: Bug 1915045 introduce and use MediaDecoderStateMachineBase::IsTrackingAudioData() and IsTrackingVideoData() helpers r?#media-playback-reviewers

These are named after MozPromise::ThenCommand::Track(), which sets the request
holders.

Comment 9

[Alastor Wu [:alwu]]

(In reply to Karl Tomlinson (:karlt) from comment #3)

In the pernosco recording:

1. While in LoopingDecodingState, a RequestVideoData() completed. HandleVideoDecoded() did not queue another video decode because mMaster->HaveEnoughDecodedVideo() was true.
2. mMaster->HaveEnoughDecodedVideo() was still true when the mPlayState watcher ran.
3. DecodingState::Step() started playback, which caused the VideoSink to pop frames from the video queue.
4. The same DecodingState::Step() then switched to BufferingState because it is OutOfDecodedAudio(). This disconnected the mOnVideoPopped listener before the asynchronous notification is received.
5. BufferingState::Step() is a no-op and will not advance to DecodingState because OutOfDecodedVideo(), due to the popped frames in 3, and nothing to request decode of more video.

Karlt, will this issue cause playback stuck on the BufferingState? I wonder if it's also a part of reason causing Youtube infinite buffering. Thanks.

Comment 10

[Karl Tomlinson (:karlt)]

(In reply to Alastor Wu [:alwu] from comment #9)

Karlt, will this issue cause playback stuck on the BufferingState?

Yes, that's correct.

I wonder if it's also a part of reason causing Youtube infinite buffering. Thanks.

Quite plausibly.

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0156dcd4aad2
Ensure decode tasks are scheduled on BufferingState::Enter() r=media-playback-reviewers,alwu

Comment 12

[Atila Butkovits]

https://hg.mozilla.org/mozilla-central/rev/0156dcd4aad2

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ce02ddde7ac5
introduce and use MediaDecoderStateMachineBase::IsTrackingAudioData() and IsTrackingVideoData() helpers r=media-playback-reviewers,alwu

Comment 14

[agoloman]

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

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b986fa50452f
Test playback after waiting for audio r=media-playback-reviewers,alwu

Comment 16

[Karl Tomlinson (:karlt)]

(In reply to Tyson Smith [:tsmith] from comment #1)

A site that reports this issue also triggers this:

Assertion failure: aTrackData.mBufferedRanges.IsEmpty(), at /builds/worker/checkouts/gecko/dom/media/mediasource/TrackBuffersManager.cpp:2692

I don't expect that to be addressed by the patch here. That is tracked in bug 1849216 and dependencies.

Comment 17

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/50032 for changes under testing/web-platform/tests

Comment 18

[Serban Stanca [:SerbanS]]

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

Comment 19

[Atila Butkovits]

Backed out as a suspected cause of bug 1941164.

Backout link: https://hg.mozilla.org/integration/autoland/rev/45f68751c2a6677f127f1d1125aea72adce108af

Comment 20

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Upstream PR was closed without merging

Comment 21

[Karl Tomlinson (:karlt)]

Only the test for this bug was backed out, because it depends on a fix for bug 1940883.

Comment 22

[amarc]

Backout merged to mozilla-central: https://hg.mozilla.org/mozilla-central/rev/45f68751c2a6677f127f1d1125aea72adce108af

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e640b7df22e4
Test playback after waiting for audio r=media-playback-reviewers,alwu

Comment 24

[amarc]

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

Comment 25

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Upstream PR merged by moz-wptsync-bot