Closed Bug 1389304 Opened 2 years ago Closed 2 years ago

Assertion failure: aTime >= 0.0 (Cannot seek to a negative value.) in [@ mozilla::MediaDecoder::Seek]

Categories

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

defect

Tracking

()

RESOLVED FIXED
mozilla57
Tracking Status
firefox-esr52 --- wontfix
firefox55 --- wontfix
firefox56 --- wontfix
firefox57 --- fixed

People

(Reporter: tsmith, Assigned: jya)

References

(Blocks 1 open bug)

Details

(Keywords: assertion, testcase)

Attachments

(5 files)

Attached video test_case.mp4
Assertion failure: aTime >= 0.0 (Cannot seek to a negative value.), at src/dom/media/MediaDecoder.cpp:654

#0 0x7f74e0ab53b5 in mozilla::MediaDecoder::Seek(double, mozilla::SeekTarget::Type) src/dom/media/MediaDecoder.cpp:651:3
#1 0x7f74e0ab9551 in mozilla::MediaDecoder::DurationChanged() src/dom/media/MediaDecoder.cpp:1053:5
#2 0x7f74e0a3f6df in mozilla::ChannelMediaDecoder::DurationChanged() src/dom/media/ChannelMediaDecoder.cpp:376:17
#3 0x7f74e0b06acd in mozilla::WatchManager<mozilla::MediaDecoder>::PerCallbackWatcher::DoNotify() src/obj-firefox/dist/include/mozilla/StateWatching.h:279:9
#4 0x7f74e0b07225 in mozilla::detail::RunnableMethodImpl<mozilla::WatchManager<mozilla::MediaDecoder>::PerCallbackWatcher*, void (mozilla::WatchManager<mozilla::MediaDecoder>::PerCallbackWatcher::*)(), true, (mozilla::RunnableKind)0>::Run() src/obj-firefox/dist/include/nsThreadUtils.h:1172:13
#5 0x7f74dc85336e in mozilla::AutoTaskDispatcher::DrainDirectTasks() src/obj-firefox/dist/include/mozilla/TaskDispatcher.h:105:10
#6 0x7f74dc853d10 in mozilla::AutoTaskDispatcher::TaskGroupRunnable::Run() src/obj-firefox/dist/include/mozilla/TaskDispatcher.h:206:9
#7 0x7f74dc851700 in mozilla::EventTargetWrapper::Runner::Run() src/xpcom/threads/AbstractThread.cpp:154:32
#8 0x7f74dc87c550 in nsThread::ProcessNextEvent(bool, bool*) src/xpcom/threads/nsThread.cpp:1446:14
#9 0x7f74dc882190 in NS_ProcessNextEvent(nsIThread*, bool) src/xpcom/threads/nsThreadUtils.cpp:480:10
#10 0x7f74dd3e6bf5 in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) src/ipc/glue/MessagePump.cpp:97:21
#11 0x7f74dd337c87 in MessageLoop::RunInternal() src/ipc/chromium/src/base/message_loop.cc:326:10
#12 0x7f74dd337b19 in MessageLoop::Run() src/ipc/chromium/src/base/message_loop.cc:299:3
#13 0x7f74e1bcd1aa in nsBaseAppShell::Run() src/widget/nsBaseAppShell.cpp:156:27
#14 0x7f74e4d86041 in nsAppStartup::Run() src/toolkit/components/startup/nsAppStartup.cpp:287:30
#15 0x7f74e4ee7a02 in XREMain::XRE_mainRun() src/toolkit/xre/nsAppRunner.cpp:4632:22
#16 0x7f74e4ee964a in XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) src/toolkit/xre/nsAppRunner.cpp:4796:8
#17 0x7f74e4eea538 in XRE_main(int, char**, mozilla::BootstrapConfig const&) src/toolkit/xre/nsAppRunner.cpp:4891:21
#18 0x4ecb38 in do_main(int, char**, char**) src/browser/app/nsBrowserApp.cpp:236:22
#19 0x4ec450 in main src/browser/app/nsBrowserApp.cpp:309:16
#20 0x7f74fb63482f in __libc_start_main /build/glibc-bfm8X4/glibc-2.23/csu/../csu/libc-start.c:291
#21 0x41e184 in _start (m-c-1502378433-asan-debug/firefox+0x41e184)
Flags: in-testsuite?
That was tricky to find: The issue is with MediaDecoderStateMachine::BufferedRangeUpdated() setting a negative duration if the end of the buffered range(s) is negative and there is no known duration yet. Working on a simple fix now.
Assignee: nobody → gsquelart
How did the reader compute a negative range?
In this case, the fuzzed file gives us:
- Buffered intervals starting at 1,509,297us and ending at 2,600,634us
- A first sample with a timecode of 14,024,000us
Based on that, MediaFormatReader::UpdateBuffered() shifts the intervals into negative numbers!

I'm not sure whether demuxers, MFR, or MDSM, should check for that and prevent it ASAP. JW or Jean-Yves, what do you think?
(My proposed fix only prevents using this negative end-of-buffered-intervals as duration.)
Attached file test.html
This test case outputs:
[1]: start=-11.446586 end=-11.423366

It is bad for media.seekable to return negative intervals.
Comment on attachment 8897300 [details]
Bug 1389304 - Don't update duration to negative buffer end -

https://reviewboard.mozilla.org/r/168604/#review173932

::: dom/media/MediaDecoderStateMachine.cpp:3142
(Diff revision 1)
>      return;
>    }
>  
>    bool exists;
>    media::TimeUnit end{ mBuffered.Ref().GetEnd(&exists) };
> -  if (!exists) {
> +  if (!exists || !end.IsPositive()) {

this doesn't make sense to me (the original code that is)

Duration should always be a difference with something else.

Or if we assume that buffered range are normalised, then me must make sure they are so.

This is just a workaround. Better fix the actual problem (either making buffered range normalised and shifted by the absolute start time value, and if that's already done, don't generate buggy buffered range.
Attachment #8897300 - Flags: review?(jyavenard) → review-
No problems, thanks for the review Jean-Yves.

Now, I think you may be the best person to efficiently get this done right. ;-)
Assignee: gsquelart → nobody
Mass change P1->P2 to align with new Mozilla triage process
Priority: P1 → P2
Comment on attachment 8908051 [details]
Bug 1389304 - Sanitize the obtained buffered ranges obtained from TrackDemuxer in MFR.

https://reviewboard.mozilla.org/r/179750/#review184950

The first demuxed sample timestamp are ...
mVideo.mFirstDemuxedSampleTime is 14,024,000. (And the following timestamps of demuxed video are all smaller than this ...)
mAuido.mFirstDemuxedSampleTime is 9223372036854775807. (Demux failure, error : EOS)

But the buffered time intervals got from TrackDemuxer are ...
V : Start   (66,400) to End(14,057,200)
A : Start(1,509,297) to End (2,600,634)

This leads to an intersected TimeIntervals which starts from (1,509,297) to (2,600,634).
Then MFR shifts this intervals by subtracting mVideo.mFirstDemuxedSampleTime and
it results to a mBuffered range Start(-12,514,703) to End(-11,423,366)

I think at least we could correct the abnormal interval here ASAP.

On linux, VLC can play this file though, but Chrome cannot (no first frame)
Comment on attachment 8908051 [details]
Bug 1389304 - Sanitize the obtained buffered ranges obtained from TrackDemuxer in MFR.

https://reviewboard.mozilla.org/r/179752/#review185502

::: dom/media/MediaFormatReader.cpp:3111
(Diff revision 1)
>      intervals = mVideo.mTimeRanges;
>    }
>  
> -  if (!intervals.Length() || intervals.GetStart() == TimeUnit::Zero()) {
> -    // IntervalSet already starts at 0 or is empty, nothing to shift.
> -    mBuffered = intervals;
> +  if (intervals.Length() && intervals.GetStart() != TimeUnit::Zero()) {
> +    // We need to shift IntervalSet which is not empty and does not start at 0.
> +    intervals = intervals.Shift(TimeUnit::Zero() - mInfo.mStartTime);

Before reviewing this, I'd like to understand exactly what the problem is and how can mInfo.mStartTime be greater than the buffered range start time.

It should never be as mInfo.mStartTime is min(video_startTime, audio_startTime)

I would much prefer to have mInfo.mStartTime being fixed, rather than having a work around like this that go around the issue that mInfo.mStartTime isn't the right value (and is too big)
(In reply to Jean-Yves Avenard [:jya] from comment #11)
> Comment on attachment 8908051 [details]
> Bug 1389304 - Sanitize the obtained buffered ranges obtained from
> TrackDemuxer in MFR.
> 
> https://reviewboard.mozilla.org/r/179752/#review185502
> 
> ::: dom/media/MediaFormatReader.cpp:3111
> (Diff revision 1)
> >      intervals = mVideo.mTimeRanges;
> >    }
> >  
> > -  if (!intervals.Length() || intervals.GetStart() == TimeUnit::Zero()) {
> > -    // IntervalSet already starts at 0 or is empty, nothing to shift.
> > -    mBuffered = intervals;
> > +  if (intervals.Length() && intervals.GetStart() != TimeUnit::Zero()) {
> > +    // We need to shift IntervalSet which is not empty and does not start at 0.
> > +    intervals = intervals.Shift(TimeUnit::Zero() - mInfo.mStartTime);
> 
> Before reviewing this, I'd like to understand exactly what the problem is
> and how can mInfo.mStartTime be greater than the buffered range start time.
> 

The seek time which is used for MediaDecoder is based on the timestamp from buffered range (MFR::mBuffered).
The buffered range is adjusted based on the buffered bytes in TrackDemuxer and mInfo.mStartTime.
And we take the minimal value of first successfully-demuxed {A,V}sample timestamp as mInfo.mStartTime.

As I explained in comment 10, the timestamp of demuxed video sample is  14,024,000(kf:1) => 99,600(kf:0) => 66,400(kf:0) => 166,000(kf:0) => ...

The problem is that MFR shifts the MFR::mBuffered according to the mInfo.mStartTime if the buffered range doesn't start from zero. And MFR bumped into this case is that MFR has both buffered range from audio & video(assuming these are correct), but it cannot demux audio at all and the demuxed video timestamp is extremely large.


> It should never be as mInfo.mStartTime is min(video_startTime,
> audio_startTime)

Either we could
1) Calculate mInfo.StartTime according to not only the first demuxed sample but also taking the samples in buffered range into account. This means that MFR would delay the call to MaybeResolveMetadataPromise a little bit after it has viewed some samples. Is this fix you preferred ?
or
2) Make MFR::mBuffered be able to start from non-zero as the duration could still be correctly calculated.

> 
> I would much prefer to have mInfo.mStartTime being fixed, rather than having
> a work around like this that go around the issue that mInfo.mStartTime isn't
> the right value (and is too big)
Comment on attachment 8908051 [details]
Bug 1389304 - Sanitize the obtained buffered ranges obtained from TrackDemuxer in MFR.

https://reviewboard.mozilla.org/r/179752/#review185884

The core reason on why it's wrong to start with should be fixed.
not paper around it
Attachment #8908051 - Flags: review?(jyavenard) → review-
Assignee: nobody → jyavenard
See Also: → 1401102
Comment on attachment 8909653 [details]
Bug 1389304 - Don't include samples that won't be demuxed in range calculation.

https://reviewboard.mozilla.org/r/181166/#review186334

::: media/libstagefright/binding/MoofParser.cpp:679
(Diff revision 1)
>      int32_t ctsOffset = 0;
>      if (flags & 0x800) {
>        ctsOffset = reader->Read32();
>      }
>  
> +    if (sampleSize) {

Should this fix be applied to other media format parser ?
Attachment #8909653 - Flags: review?(kikuo) → review+
Comment on attachment 8909653 [details]
Bug 1389304 - Don't include samples that won't be demuxed in range calculation.

https://reviewboard.mozilla.org/r/181166/#review186334

> Should this fix be applied to other media format parser ?

II have already lodged a. Bug to make sure the rust demuxer doesn't generate aa table with empty samples
Comment on attachment 8909653 [details]
Bug 1389304 - Don't include samples that won't be demuxed in range calculation.

https://reviewboard.mozilla.org/r/181166/#review186334

> II have already lodged a. Bug to make sure the rust demuxer doesn't generate aa table with empty samples

I was wondering that won't this problem happen in webm, ogg, etc ... ?
Comment on attachment 8909653 [details]
Bug 1389304 - Don't include samples that won't be demuxed in range calculation.

https://reviewboard.mozilla.org/r/181166/#review186334

> I was wondering that won't this problem happen in webm, ogg, etc ... ?

Those don't use tables to store samples. Just one sample after the other.
Pushed by jyavenard@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a766b936e0b1
Don't include samples that won't be demuxed in range calculation. r=kikuo
https://hg.mozilla.org/mozilla-central/rev/a766b936e0b1
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
Can we land the test from this bug?
Flags: needinfo?(jyavenard)
Per IRC discussion, NI myself to land the crashtest.
Flags: needinfo?(jyavenard) → needinfo?(ryanvm)
See Also: → 1414444
Try looks happy with bug 1409946 landed now. Landing the testcase.
Flags: needinfo?(ryanvm)
Flags: in-testsuite?
Flags: in-testsuite+
You need to log in before you can comment on or make changes to this bug.