1648549 - Assertion failure: GetState() != s->GetState() || GetState() == DECODER_STATE_SEEKING_ACCURATE ... at /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:291

Status: RESOLVED WORKSFORME

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

Description

[Tyson Smith [:tsmith]]

Attachment: testcase.html

Found with m-c 20200623-d48aa0f0aa0b

Assertion failure: GetState() != s->GetState() || GetState() == DECODER_STATE_SEEKING_ACCURATE || GetState() == DECODER_STATE_SEEKING_FROMDORMANT || GetState() == DECODER_STATE_SEEKING_NEXTFRAMESEEKING || GetState() == DECODER_STATE_SEEKING_VIDEOONLY, at /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:291

38|0|libxul.so|decltype (ReturnTypeHelper(&mozilla::MediaDecoderStateMachine::LoopingDecodingState::Enter)) mozilla::MediaDecoderStateMachine::StateObject::SetState<mozilla::MediaDecoderStateMachine::LoopingDecodingState>()|hg:hg.mozilla.org/mozilla-central:dom/media/MediaDecoderStateMachine.cpp:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|287|0x2f
38|1|libxul.so|mozilla::MediaDecoderStateMachine::LoopingChanged()|hg:hg.mozilla.org/mozilla-central:dom/media/MediaDecoderStateMachine.cpp:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|3686|0x2f
38|2|libxul.so|mozilla::detail::RunnableFunction<mozilla::WatchManager<mozilla::MediaDecoderStateMachine>::PerCallbackWatcher::Notify()::{lambda()#1}>::Run()|hg:hg.mozilla.org/mozilla-central:xpcom/threads/nsThreadUtils.h:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|575|0x7e
38|3|libxul.so|mozilla::SimpleTaskQueue::DrainTasks()|hg:hg.mozilla.org/mozilla-central:xpcom/threads/TaskDispatcher.h:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|43|0x11
38|4|libxul.so|non-virtual thunk to mozilla::TaskQueue::DrainDirectTasks()|hg:hg.mozilla.org/mozilla-central:xpcom/threads/TaskQueue.cpp:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|0|0x31
38|5|libxul.so|mozilla::AutoTaskDispatcher::TaskGroupRunnable::Run()|hg:hg.mozilla.org/mozilla-central:xpcom/threads/TaskDispatcher.h:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|225|0x3a
38|6|libxul.so|mozilla::TaskQueue::Runner::Run()|hg:hg.mozilla.org/mozilla-central:xpcom/threads/TaskQueue.cpp:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|158|0x11
38|7|libxul.so|nsThreadPool::Run()|hg:hg.mozilla.org/mozilla-central:xpcom/threads/nsThreadPool.cpp:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|299|0x11
38|8|libxul.so|nsThread::ProcessNextEvent(bool, bool*)|hg:hg.mozilla.org/mozilla-central:xpcom/threads/nsThread.cpp:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|1234|0xe
38|9|libxul.so|NS_ProcessNextEvent(nsIThread*, bool)|hg:hg.mozilla.org/mozilla-central:xpcom/threads/nsThreadUtils.cpp:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|501|0xc
38|10|libxul.so|mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*)|hg:hg.mozilla.org/mozilla-central:ipc/glue/MessagePump.cpp:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|302|0xa
38|11|libxul.so|MessageLoop::RunInternal()|hg:hg.mozilla.org/mozilla-central:ipc/chromium/src/base/message_loop.cc:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|315|0x17
38|12|libxul.so|MessageLoop::Run()|hg:hg.mozilla.org/mozilla-central:ipc/chromium/src/base/message_loop.cc:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|290|0x8
38|13|libxul.so|nsThread::ThreadFunc(void*)|hg:hg.mozilla.org/mozilla-central:xpcom/threads/nsThread.cpp:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|447|0x8
38|14|libnspr4.so|_pt_root|hg:hg.mozilla.org/mozilla-central:nsprpub/pr/src/pthreads/ptthread.c:d48aa0f0aa0bbe69f8eae663be2f5671c41af27c|201|0x7
38|15|libpthread.so.0||||0x76db
38|16|libc.so.6||||0x12188f

Comment 1

[Tyson Smith [:tsmith]]

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

Comment 2

[Jason Kratzer [:jkratzer]]

Bugmon Analysis:
Verified bug as reproducible on mozilla-central 20200625161839-324d5257f6f7.
The bug appears to have been introduced in the following build range:
> Start: fea1e502ea281a9b86b821957e622f0b0d081ce7 (20200612094620)
> End: 86419b2114e5ad91785281094c5323851a642b51 (20200612055215)
> Pushlog: https://hg.mozilla.org/mozilla-unified/pushloghtml?fromchange=fea1e502ea281a9b86b821957e622f0b0d081ce7&tochange=86419b2114e5ad91785281094c5323851a642b51

Comment 3

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

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

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

At assertion time

print GetState() 
$1 = mozilla::MediaDecoderStateMachine::DECODER_STATE_LOOPING_DECODING
...
print mMaster->mStateObj->GetState() 
$7 = mozilla::MediaDecoderStateMachine::DECODER_STATE_LOOPING_DECODING

comment 2 indicates this is regressed by bug 1644009. Looks like the state change is triggered off draining direct tasks (stack frame 4 of comment 0). Something is not working as expected with our new direct tasks and we're having bad state transitions.

Comment 4

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

Fix regressions -> regressed by.

Comment 5

[Jim Mathies [:jimm]]

Hey Jean-Yves, looks like a regression from the threading work. Should we track this and try to get a fix in?

Comment 6

[Jean-Yves Avenard [:jya]]

Tyson, were you able to reproduce this issue with central before 20200623-d48aa0f0aa0b ?

I wonder if it's just a coincidence that it was found in the version found after my changes.

it shouldn't have affected the actual behaviour ; I just moved the code to a difference class.

Comment 7

[Tyson Smith [:tsmith]]

The bisection in comment 2 appears to be accurate.

Comment 8

[Tim Spurway [:tspurway]]

Jean-Yves, does this have any user facing effect that we should care about for 79?

Comment 9

[Ryan VanderMeulen [:RyanVM]]

Too late for 79.

Comment 10

[Jean-Yves Avenard [:jya]]

I don't believe bug 1644009 caused a regression as such; timing may have changed slightly due to different compilation options. I'm surprised it didn't assert before, really it should

It just shows a normal operating mode that could cause an assertion.

Here we have a web page that creates a looping audio element with a single audio frame.

We start decoding, we set the StateObject to DecodingFirstFrameState ; as the loop attribute is set; the next state is set to be LoopingDecodingState.

We decode that first frame, and now we transition from DecodingFirstFrameState to LoopingDecodingState ; we reach the end of the decoding and so we seek to the beginning and we transition to AccurateSeekingState with the next state being LoopingDecodingState
At that time we have the main thread onload toggling the loop attribute ; this triggers a call to SetState<LoopingDecodingState> ; we're already in LoopingDecodingState -> Assert as SetState expects the state to always change.

https://pernos.co/debug/5SRVAdxjHRwkB_DctxH__g/index.html#f{m[BJtA,6M0_,t[Ajg,Wrg_,f{e[BJtA,6Mg_,s{af9Jm1wAA,bARU,oEtIrLg,uErqQ2A___

:alwu, this is your code; do you want to have a look?

DirectTask dispatching is behaving as it should; it's a change of value in a mirrored attribute and the handler for those changes run exactly as it should from what I could tell.

Comment 11

[Alastor Wu [:alwu]]

Will take a look later, keep NI.

Comment 12

[Pascal Chevrel:pascalc (PTO until April 26)]

Is that still an issue we should track for out upcoming releases?

Comment 13

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

Alastor, do you have an opinion on this? From my perspective it would be good to avoid this, but my understanding is this assert isn't particularly dangerous for us to be hitting (it suggests we're firing an un-needed state change, rather than anything more concerning).

Comment 14

[Alastor Wu [:alwu]]

Yes, agree with bryce, this doesn't need to be tracked on upcoming release. And I would continue to work on this after finishing other higher priority tasks.

Comment 15

[Bugmon [:jkratzer for issues]]

Bugmon was unable reproduce this issue.
Removing bugmon keyword as no further action possible. Please review the bug and re-add the keyword for further analysis.

Comment 16

[Jason Kratzer [:jkratzer]]

A change to the Taskcluster build definitions over the weekend caused Bugmon to fail when reproducing issues. This issue has been corrected. Re-enabling bugmon.

Comment 17

[Bugmon [:jkratzer for issues]]

Testcase crashes using the initial build (mozilla-central 20220625095334-938b836107d7) but not with tip (mozilla-central 20230624091338-d9d61c7bc752.)

The bug appears to have been fixed in the following build range:

Start: 1dca837d8606ab27c721efb5bef3f2a0983b7f69 (20230521093941)
End: c412301a7e7c7bf7aea5a8acb208c24c7557f28c (20230521132053)
Pushlog: https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=1dca837d8606ab27c721efb5bef3f2a0983b7f69&tochange=c412301a7e7c7bf7aea5a8acb208c24c7557f28c

tsmith, can you confirm that the above bisection range is responsible for fixing this issue?
Removing bugmon keyword as no further action possible. Please review the bug and re-add the keyword for further analysis.

Comment 18

[Tyson Smith [:tsmith]]

I am unable to reproduce the issue with the attached test case using m-c 20230628-3b7b3970a884.