1845213 - The mismatching of the buffered ranged and the buffered data in MSE causes looping failed

Status: VERIFIED FIXED

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

Description

[Alastor Wu [:alwu]]

STR.

1. go to https://videojs.com/advanced/?video=big-buck-bunny
2. click "loop"
3. seek to somewhere near to the end

Expected.
4. video should look back to keep playing

Actual.
4. video stuck

Comment 1

[Alastor Wu [:alwu]]

I will explain what happened later. The root cause of this bug would probably the reason causing crashes like bug 1842496.

Comment 2

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

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

Comment 3

[Alastor Wu [:alwu]]

MSE buffered range mismatching with the actual data

For the site like video.js, we fixed the looping issue before in bug 1829086 (added tests as well) but now there is a new issue causing looping failed again.

As some websites can't support seamless looping (they won't append data in time), we would fallback to the non-seamless looping here when both tracks are ended. The problem is the Media Format Reader somehow performed seeking to the beginning successfully (it shouldn't), making mIsReachingAudioEOS become true so that we can't fallback to the non-seamless looping.

The reason of being able to perform seeking is because the mismatching of buffered range and buffered data in the track buffer manager. In the media source demuxer, we only want to perform seeking if the seeking target is in the buffered range. If not, then we would reject the promise with waiting for data.

When loading this video, and performing a seek to the end. That triggers the frame removal algorithm, which supposes to clean all the buffered range which we had before. I added some logs, then found following situation,

RemoveFrames: Removing [(0.000000, 0.009313), (0.009333, 39.838667)] from bufferedRange [(0.000000, 39.838667)]
RemoveFrames: After removing frames, audio/mp4a-latm data sz=0, highestStartTimestamp= 0, bufferedRange=[(0.009313, 0.009333)], sanitizedBufferedRanges=[(0.009313, 0.009333)]

The audio buffer actually didn't contain any data, but our buffered range is still (0.009313, 0.009333), it should be (0,0). When I debugged the crash for bug 1842496, I was so confused why we couldn't get the next sample. But now I understand that is because the buffered range was incorrect, so we won't be able to find any data after seeking.

Root cause for causing mismatch

After more investigation, I noticed that the buffered range is a continuous range (0.000000, 39.838667) but the removing range has two intervals, which seems weird because they should have exact same interval sets. I found that the root cause for causing this mismatch is because we modify the sample's time to a wrong time.

By checking the log of sample appending, I found that the data stored in our buffer was actually wrong

Expected : [0,9333], [9333,30666], [30666,52000]...
Actual :  [0,1], [1,9313], [9333,30666], [30666,52000]...

[0,1] was added from here, but the next sample should be [1,9333], not [1,9313]. That 9313 was calculated by adding the duration of interval, but the interval's start and end have different base tick (1000000 vs 48000), which causing the calculation error. As the minimum unit of the base 48000 would be 20ms, exactly the difference between the current value and the expected value.

Making mStart with the same base with the sample->mTime fixes the problem, and also doesn't cause regression for bug 1222851 (in which we introduce that silent frame). But that is just a workaround. The proper fix is to round inbase in TimeUnit::FromSeconds() to reduce the rounding error.

Eg. Doing {448/48,000} - {1/1,000,000} in TimeUnit::FromSeconds(), inbase would be 447.95200. We should use cast it to 448 to have minimum rounding error, instead of 447.

Comment 4

[Alastor Wu [:alwu]]

Attachment: Bug 1845213 - part1 : add more logs.

Depends on D184273

Comment 5

[Alastor Wu [:alwu]]

Attachment: Bug 1845213 - part2 : round up the inbase to make the result more precise.

Eg. {448/48,000} - {1/1,000,000} without rounding, the result would be
{447/48,000}, which loses around 20ms precision.

More details can be seen in [1]

[1] https://bugzilla.mozilla.org/show_bug.cgi?id=1845213#c3

Depends on D184444

Comment 6

[Alastor Wu [:alwu]]

Attachment: Bug 1845213 - part3 : add assertion to ensure that buffer and buffered range should match if all data get removed.

Depends on D184445

Comment 7

[Alastor Wu [:alwu]]

Attachment: Bug 1845213 - part5 : make the dummy silent data duration to zero.

This silent data is used to generate preroll silence in bug 1222851, the
sample would keep decoder outputting correct sample, and the fake data
we added would be eventually dropped by the AudioTrimmer.

No matter what length that sample is, it would always be dropped by the
AudioTrimmer. Then we can simply make that sample have zero duration.

In addition, now it's not appropreiate to use microsecond when
calculating the audio time. Substracting even only one microsecond to
audio sample time, which has a different base, would cause rounding
error. So we should avoid doing that.

Comment 8

[Alastor Wu [:alwu]]

Attachment: Bug 1845213 - part4 - add more log to check TimeUnit's base.

Depends on D184651

Comment 9

[Alastor Wu [:alwu]]

Attachment: Bug 1845213 - part6 : add assertion to ensure the time interval matches the sample's start and end time.

Depends on D184782

Comment 10

[Alastor Wu [:alwu]]

Attachment: Bug 1845213 - part7 : timestampOffset should match the sample time's base.

Depends on D184845

Comment 11

[Alastor Wu [:alwu]]

Attachment: Bug 1845213 - part4 - add more log to check TimeUnit's base.

Depends on D184651

Comment 12

[Alastor Wu [:alwu]]

Attachment: Bug 1845213 - part8 : intersection should be converted to the sample's base before truncation.

This fixes the incorrect buffer mismatching (hitting the assertion
we added in prev patches) after truncation for tests
mediasource-append-buffer.html and test_NoAudioLoopBackData.html.

Depends on D184846

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3d24fe88db0d
part1 : add more logs. r=padenot
https://hg.mozilla.org/integration/autoland/rev/2d3d0f6297de
part2 : round up the inbase to make the result more precise. r=padenot
https://hg.mozilla.org/integration/autoland/rev/4c4bf3ad44a8
part3 : add assertion to ensure that buffer and buffered range should match if all data get removed. r=padenot
https://hg.mozilla.org/integration/autoland/rev/2e2468c5c300
part4 - add more log to check TimeUnit's base. r=padenot
https://hg.mozilla.org/integration/autoland/rev/a2b6728d47c6
part5 : make the dummy silent data duration to zero. r=padenot
https://hg.mozilla.org/integration/autoland/rev/869cd7982fca
part6 : add assertion to ensure the time interval matches the sample's start and end time. r=padenot
https://hg.mozilla.org/integration/autoland/rev/0489f3e6696b
part7 : timestampOffset should match the sample time's base. r=padenot
https://hg.mozilla.org/integration/autoland/rev/c8559eff750d
part8 : intersection should be converted to the sample's base before truncation. r=padenot

Comment 14

[Iulian Moraru]

Backed out for causing build bustages on MediaSourceDemuxer.cpp.

• Push with failures

• Failure log

• Backout link

[task 2023-07-31T22:42:30.507Z] 22:42:30     INFO -  gmake[4]: Entering directory '/builds/worker/workspace/obj-build/dom/media/mediasource'
[task 2023-07-31T22:42:30.510Z] 22:42:30     INFO -  /builds/worker/fetches/sccache/sccache /builds/worker/fetches/clang/bin/clang++ -isysroot /builds/worker/fetches/MacOSX13.3.sdk -mmacosx-version-min=10.12 -stdlib=libc++ --target=x86_64-apple-darwin -o MediaSourceDemuxer.o -c  -I/builds/worker/workspace/obj-build/dist/stl_wrappers -fvisibility=hidden -fvisibility-inlines-hidden -U_FORTIFY_SOURCE -D_FORTIFY_SOURCE=2 -fstack-protector-strong -DNDEBUG=1 -DTRIMMED=1 -DMOZ_HAS_MOZGLUE -DMOZILLA_INTERNAL_API -DIMPL_LIBXUL -DSTATIC_EXPORTABLE_JS_API -I/builds/worker/checkouts/gecko/dom/media/mediasource -I/builds/worker/workspace/obj-build/dom/media/mediasource -I/builds/worker/workspace/obj-build/ipc/ipdl/_ipdlheaders -I/builds/worker/checkouts/gecko/ipc/chromium/src -I/builds/worker/workspace/obj-build/dist/include -I/builds/worker/workspace/obj-build/dist/include/nspr -I/builds/worker/workspace/obj-build/dist/include/nss -DMOZILLA_CLIENT -include /builds/worker/workspace/obj-build/mozilla-config.h -fno-sized-deallocation -fno-aligned-new -fcrash-diagnostics-dir=/builds/worker/artifacts -fno-exceptions -fPIC -fno-rtti -ffunction-sections -fdata-sections -fno-exceptions -fno-math-errno -pipe -gdwarf-4 -Xclang -load -Xclang /builds/worker/workspace/obj-build/build/clang-plugin/libclang-plugin.so -Xclang -add-plugin -Xclang moz-check -O3 -fno-omit-frame-pointer -funwind-tables -Werror -Wall -Wbitfield-enum-conversion -Wdeprecated-this-capture -Wempty-body -Wformat-type-confusion -Wignored-qualifiers -Wpointer-arith -Wshadow-field-in-constructor-modified -Wsign-compare -Wtautological-constant-in-range-compare -Wtype-limits -Wno-error=tautological-type-limit-compare -Wunreachable-code -Wunreachable-code-return -Wunused-but-set-parameter -Wno-invalid-offsetof -Wclass-varargs -Wempty-init-stmt -Wfloat-overflow-conversion -Wfloat-zero-conversion -Wloop-analysis -Wno-range-loop-analysis -Wc++2a-compat -Wenum-compare-conditional -Wenum-float-conversion -Wno-error=deprecated -Wno-error=deprecated-anon-enum-enum-conversion -Wno-error=deprecated-enum-enum-conversion -Wno-error=deprecated-pragma -Wno-error=deprecated-this-capture -Wcomma -Wimplicit-fallthrough -Wduplicate-method-arg -Wduplicate-method-match -Wmissing-method-return-type -Wobjc-signed-char-bool -Wsemicolon-before-method-body -Wsuper-class-method-mismatch -Wstring-conversion -Wno-inline-new-delete -Wno-error=deprecated-declarations -Wno-error=array-bounds -Wno-error=free-nonheap-object -Wno-error=atomic-alignment -Wno-error=deprecated-builtins -Wformat -Wformat-security -Wno-psabi -Wthread-safety -Werror=unguarded-availability-new -Wno-error=builtin-macro-redefined -Wno-unknown-warning-option -fno-strict-aliasing -ffp-contract=off  -MD -MP -MF .deps/MediaSourceDemuxer.o.pp   /builds/worker/checkouts/gecko/dom/media/mediasource/MediaSourceDemuxer.cpp
[task 2023-07-31T22:42:30.510Z] 22:42:30    ERROR -  /builds/worker/checkouts/gecko/dom/media/mediasource/MediaSourceDemuxer.cpp:384:3: error: use of undeclared identifier 'GetMediaSourceLog'
[task 2023-07-31T22:42:30.510Z] 22:42:30     INFO -    MSE_DEBUG("DoSeek, original target=%" PRId64 "%s, seekTime=%" PRId64
[task 2023-07-31T22:42:30.510Z] 22:42:30     INFO -    ^
[task 2023-07-31T22:42:30.511Z] 22:42:30     INFO -  /builds/worker/checkouts/gecko/dom/media/mediasource/MediaSourceDemuxer.cpp:23:13: note: expanded from macro 'MSE_DEBUG'
[task 2023-07-31T22:42:30.511Z] 22:42:30     INFO -    DDMOZ_LOG(GetMediaSourceLog(), mozilla::LogLevel::Debug, "::%s: " arg, \
[task 2023-07-31T22:42:30.511Z] 22:42:30     INFO -              ^
[task 2023-07-31T22:42:30.511Z] 22:42:30    ERROR -  /builds/worker/checkouts/gecko/dom/media/mediasource/MediaSourceDemuxer.cpp:384:3: error: use of undeclared identifier 'GetMediaSourceLog'
[task 2023-07-31T22:42:30.511Z] 22:42:30     INFO -  /builds/worker/checkouts/gecko/dom/media/mediasource/MediaSourceDemuxer.cpp:23:13: note: expanded from macro 'MSE_DEBUG'
[task 2023-07-31T22:42:30.511Z] 22:42:30     INFO -    DDMOZ_LOG(GetMediaSourceLog(), mozilla::LogLevel::Debug, "::%s: " arg, \
[task 2023-07-31T22:42:30.511Z] 22:42:30     INFO -              ^
[task 2023-07-31T22:42:30.512Z] 22:42:30    ERROR -  /builds/worker/checkouts/gecko/dom/media/mediasource/MediaSourceDemuxer.cpp:402:5: error: use of undeclared identifier 'GetMediaSourceLog'
[task 2023-07-31T22:42:30.512Z] 22:42:30     INFO -      MSE_DEBUG("Can't find seekTime %" PRId64
[task 2023-07-31T22:42:30.512Z] 22:42:30     INFO -      ^
[task 2023-07-31T22:42:30.512Z] 22:42:30     INFO -  /builds/worker/checkouts/gecko/dom/media/mediasource/MediaSourceDemuxer.cpp:23:13: note: expanded from macro 'MSE_DEBUG'
[task 2023-07-31T22:42:30.512Z] 22:42:30     INFO -    DDMOZ_LOG(GetMediaSourceLog(), mozilla::LogLevel::Debug, "::%s: " arg, \
[task 2023-07-31T22:42:30.512Z] 22:42:30     INFO -              ^
[task 2023-07-31T22:42:30.512Z] 22:42:30    ERROR -  /builds/worker/checkouts/gecko/dom/media/mediasource/MediaSourceDemuxer.cpp:402:5: error: use of undeclared identifier 'GetMediaSourceLog'
[task 2023-07-31T22:42:30.513Z] 22:42:30     INFO -  /builds/worker/checkouts/gecko/dom/media/mediasource/MediaSourceDemuxer.cpp:23:13: note: expanded from macro 'MSE_DEBUG'
[task 2023-07-31T22:42:30.513Z] 22:42:30     INFO -    DDMOZ_LOG(GetMediaSourceLog(), mozilla::LogLevel::Debug, "::%s: " arg, \
[task 2023-07-31T22:42:30.513Z] 22:42:30     INFO -              ^
[task 2023-07-31T22:42:30.513Z] 22:42:30     INFO -  4 errors generated.
[task 2023-07-31T22:42:30.513Z] 22:42:30    ERROR -  gmake[4]: *** [/builds/worker/checkouts/gecko/config/rules.mk:659: MediaSourceDemuxer.o] Error 1
[task 2023-07-31T22:42:30.513Z] 22:42:30     INFO -  gmake[4]: Leaving directory '/builds/worker/workspace/obj-build/dom/media/mediasource'
[task 2023-07-31T22:42:30.513Z] 22:42:30     INFO -  gmake[4]: Target 'target-objects' not remade because of errors.
[task 2023-07-31T22:42:30.514Z] 22:42:30    ERROR -  gmake[3]: *** [/builds/worker/checkouts/gecko/config/recurse.mk:72: dom/media/mediasource/target-objects] Error 2
[task 2023-07-31T22:42:30.514Z] 22:42:30     INFO -  gmake[4]: Entering directory '/builds/worker/workspace/obj-build/dom/media/webm'

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3241b87d217e
part1 : add more logs. r=padenot
https://hg.mozilla.org/integration/autoland/rev/de21e15f438f
part2 : round up the inbase to make the result more precise. r=padenot
https://hg.mozilla.org/integration/autoland/rev/11d2d1f6205c
part3 : add assertion to ensure that buffer and buffered range should match if all data get removed. r=padenot
https://hg.mozilla.org/integration/autoland/rev/32d708d3ccd6
part4 - add more log to check TimeUnit's base. r=padenot
https://hg.mozilla.org/integration/autoland/rev/72e93e8c1a79
part5 : make the dummy silent data duration to zero. r=padenot
https://hg.mozilla.org/integration/autoland/rev/b09469b6a769
part6 : add assertion to ensure the time interval matches the sample's start and end time. r=padenot
https://hg.mozilla.org/integration/autoland/rev/b0ad2b902d38
part7 : timestampOffset should match the sample time's base. r=padenot
https://hg.mozilla.org/integration/autoland/rev/2fab9105e443
part8 : intersection should be converted to the sample's base before truncation. r=padenot

Comment 16

[Iulian Moraru]

Backed out for causing mochitest-media failures on test_seamless_looping_shorter_audio_than_video.html.

• Push with failures

• Failure log

• Backout link

[task 2023-08-01T04:37:39.446Z] 04:37:39     INFO -  TEST-PASS | dom/media/test/test_seamless_looping_shorter_audio_than_video.html | Reason cannot be empty
[task 2023-08-01T04:37:39.446Z] 04:37:39     INFO -  add_task | Entering testSeamlessLoopingShorterAudioTrack
[task 2023-08-01T04:37:39.446Z] 04:37:39     INFO -  create video and play it
[task 2023-08-01T04:37:39.446Z] 04:37:39     INFO -  Buffered messages finished
[task 2023-08-01T04:37:39.446Z] 04:37:39  WARNING -  TEST-UNEXPECTED-FAIL | dom/media/test/test_seamless_looping_shorter_audio_than_video.html | NotSupportedError: The media resource indicated by the src attribute or assigned media provider object was not suitable. - Should not throw any errors
[task 2023-08-01T04:37:39.447Z] 04:37:39     INFO -      nextTick/<@SimpleTest/SimpleTest.js:2165:26
[task 2023-08-01T04:37:39.447Z] 04:37:39     INFO -      async*nextTick@SimpleTest/SimpleTest.js:2182:11
[task 2023-08-01T04:37:39.447Z] 04:37:39     INFO -      setTimeout handler*SimpleTest_setTimeoutShim@SimpleTest/SimpleTest.js:920:41
[task 2023-08-01T04:37:39.447Z] 04:37:39     INFO -      add_task@SimpleTest/SimpleTest.js:2096:17
[task 2023-08-01T04:37:39.447Z] 04:37:39     INFO -      @dom/media/test/test_seamless_looping_shorter_audio_than_video.html:16:9
[task 2023-08-01T04:37:39.447Z] 04:37:39     INFO -  TEST-OK | dom/media/test/test_seamless_looping_shorter_audio_than_video.html | took 468ms
[task 2023-08-01T04:37:39.447Z] 04:37:39     INFO -  TEST-START | dom/media/test/test_videoPlaybackQuality_totalFrames.html

Comment 17

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

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

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/5a45000b88bb
part1 : add more logs. r=padenot
https://hg.mozilla.org/integration/autoland/rev/b6c7c93d0406
part2 : round up the inbase to make the result more precise. r=padenot
https://hg.mozilla.org/integration/autoland/rev/f864adb5de76
part3 : add assertion to ensure that buffer and buffered range should match if all data get removed. r=padenot
https://hg.mozilla.org/integration/autoland/rev/e5f844ae8776
part4 - add more log to check TimeUnit's base. r=padenot
https://hg.mozilla.org/integration/autoland/rev/cd1bbc502a41
part5 : make the dummy silent data duration to zero. r=padenot
https://hg.mozilla.org/integration/autoland/rev/16a313a5b0e3
part6 : add assertion to ensure the time interval matches the sample's start and end time. r=padenot
https://hg.mozilla.org/integration/autoland/rev/e5c9f9d3fc20
part7 : timestampOffset should match the sample time's base. r=padenot
https://hg.mozilla.org/integration/autoland/rev/287a084c2e9e
part8 : intersection should be converted to the sample's base before truncation. r=padenot

Comment 19

[Cristina Horotan [:chorotan]]

https://hg.mozilla.org/mozilla-central/rev/5a45000b88bb
https://hg.mozilla.org/mozilla-central/rev/b6c7c93d0406
https://hg.mozilla.org/mozilla-central/rev/f864adb5de76
https://hg.mozilla.org/mozilla-central/rev/e5f844ae8776
https://hg.mozilla.org/mozilla-central/rev/cd1bbc502a41
https://hg.mozilla.org/mozilla-central/rev/16a313a5b0e3
https://hg.mozilla.org/mozilla-central/rev/e5c9f9d3fc20
https://hg.mozilla.org/mozilla-central/rev/287a084c2e9e

Comment 20

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

The patch landed in nightly and beta is affected.
:alwu, is this bug important enough to require an uplift?

• If yes, please nominate the patch for beta approval.
• If no, please set status-firefox117 to wontfix.

For more information, please visit BugBot documentation.

Comment 21

[Alastor Wu [:alwu]]

I'd like to just let them ride with Fx118.

Comment 22

[Ardelean Oana, Desktop Test Engineering [:oardelean]]

Reproducible on a 2023-07-24 Nightly build on macOS 12.
Verified as fixed on Firefox 118.0b2(20230829180158) and Nightly 119.0a1(20230830212731) on macOS 12, Windows 10, Ubuntu 22.
Video does not get stuck at the end and reloads from the beginning if Loop is active.