Emil Ghitta, QA [:emilghitta] Reporter
	Description • 6 years ago

[Affected versions]:
Firefox 63.0a1 (BuildId:20180831100058).
Firefox 62.0 (BuildId:20180827144429).
Firefox 61.0.2 (BuildId:20180807170231).
Firefox 60.1.0esr (BuildId:20180621121604).

[Affected platforms]:
Windows 10 64bit.
macOS 10.13.4
Ubuntu 16.04 64bit.

[Steps to reproduce]:
1. Launch Firefox.
2. Access the following link: shorturl.at/lyEG9
3. Activate the loop option.
4. Play the audio.
5. Seek the audio at 2:52 and let it finish.

[Expected result]:
The audio starts over and the seekbar's position is at 0:00.

[Actual result]:
The audio starts over but the seekbar's position is at 0:40.

[Regression range]:
This seems to be a regression.

Last good revision: 8de0513ff33dbd095d218775952a65c55f9cb77b
First bad revision: a612dc93c5989ea0d12123b721940312f7a04cfc

12:24.23 INFO: Pushlog:
https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=8de0513ff33dbd095d218775952a65c55f9cb77b&tochange=a612dc93c5989ea0d12123b721940312f7a04cfc

[Notes]
For further information regarding this issue please observe the attached screencast.
Please note that, sometimes, the seekbar is not jumping back to 0:00 nor 0:40 (remains stuck at the end) but the audio loops successfully.

	Emil Ghitta, QA [:emilghitta] Reporter
	Comment 1 • 6 years ago

Hi Chun,

I'm not sure, but from the generated pushlog Bug 654787 may have caused this regression.

Can you please have a look?

Thanks!

	C.M.Chang[:chunmin] Assignee
	Comment 2 • 6 years ago

(In reply to Emil Ghitta, QA [:emilghitta] from comment #0)
Thanks for the testing!

> [Steps to reproduce]:
> 1. Launch Firefox.
> 2. Access the following link: shorturl.at/lyEG9
I can not find any audio element in the link. Can you update it?
> 3. Activate the loop option.
> 4. Play the audio.
> 5. Seek the audio at 2:52 and let it finish.

	Emil Ghitta, QA [:emilghitta] Reporter
	Comment 3 • 6 years ago

Sure thing Chun. Try: https://goo.gl/tuporf

	C.M.Chang[:chunmin] Assignee
	Comment 4 • 6 years ago

(In reply to Emil Ghitta, QA [:emilghitta] from comment #3)
> Sure thing Chun. Try: https://goo.gl/tuporf
Thanks the update. Nice catch!

	C.M.Chang[:chunmin] Assignee
	Comment 5 • 6 years ago

The root cause is that the time data in last audio frame extracted by `FlacTrackDemuxer`[0] is wrong. 

By running `$ MOZ_LOG="MediaDemuxer:5" ./mach run https://goo.gl/tuporf`, we can get the time info of the last audio frame in the `FlacTrackDemuxer`[1]. The log is attached below[2]. In brief, the time of the last audio frame is smaller than its previous one. The time of the second last frame is around 174, but the time of the last audio frame is around 133. 

When looping is on, the time is always adjusted by `ReaderProxy::AdjustByLooping`. `ReaderProxy::AdjustByLooping` uses the time of the last audio frame as the ending time of the stream to adjust the playback position[3]. The correct ending time of the audio is around 174, but we use the incorrect time 133 to calculate it. That's why the time on the playback bar is wrong.

After the looped audio starts, the clock time `T`[4] is over 174. The adjusted time should be calculated by `T = T % 174`. However, we use `T = T % 133` so the playback bar starts from around 40.




[0] https://searchfox.org/mozilla-central/rev/de7676288a78b70d2b9927c79493adbf294faad5/dom/media/flac/FlacDemuxer.cpp#858
[1] https://searchfox.org/mozilla-central/rev/de7676288a78b70d2b9927c79493adbf294faad5/dom/media/flac/FlacDemuxer.cpp#939
[2] Log for `FlacTrackDemuxer`
-------------------------

...

(second last audio frame)

[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetSamples(1) Begin offset=14934303 mParsedFramesDuration=174.602448 mTotalFrameLen=14673230
[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] FindNext() Begin offset=14934303 mParsedFramesDuration=174.602448 mTotalFrameLen=14673230
[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] FindNext() End time=174.602448 offset=14934320 mParsedFramesDuration=174.602448 mTotalFrameLen=14673245
[Child 2618: MediaPDecoder #1]: D/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetNextFrame() Begin(time=174.602448 offset=14934296 size=15)
[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetSamples() End mSamples.Length=1 aNumSamples=-1 offset=14934320 mParsedFramesDuration=174.602448 mTotalFrameLen=14673245

(last audio frame)

[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetSamples(1) Begin offset=14934320 mParsedFramesDuration=174.602448 mTotalFrameLen=14673245
[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] FindNext() Begin offset=14934320 mParsedFramesDuration=174.602448 mTotalFrameLen=14673245
[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] FindNext() End time=133.305034 offset=14934328 mParsedFramesDuration=174.602448 mTotalFrameLen=14673262
[Child 2618: MediaPDecoder #1]: D/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetNextFrame() Begin(time=133.305034 offset=14934311 size=17)
[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetSamples() End mSamples.Length=1 aNumSamples=-1 offset=14934328 mParsedFramesDuration=174.602448 mTotalFrameLen=14673262

(EOS: end of stream)

[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetSamples(1) Begin offset=14934328 mParsedFramesDuration=174.602448 mTotalFrameLen=14673262
[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] FindNext() Begin offset=14934328 mParsedFramesDuration=174.602448 mTotalFrameLen=14673262
[Child 2618: MediaPDecoder #1]: D/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetNextFrame() EOS
[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetSamples() End mSamples.Length=0 aNumSamples=0 offset=14934328 mParsedFramesDuration=174.602448 mTotalFrameLen=14673262

(start looping)

[Child 2618: MediaPDecoder #2]: D/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] Reset()
[Child 2618: MediaPDecoder #2]: D/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] Reset()
[Child 2618: MediaPDecoder #2]: D/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] FastSeek(0.000000) avgFrameLen=84038.122994 mParsedFramesDuration=174.602448 offset=261066
[Child 2618: MediaPDecoder #2]: D/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] ScanUntil(0.000000 avgFrameLen=84038.122994 mParsedFramesDuration=174.602448 offset=0
[Child 2618: MediaPDecoder #2]: D/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] FastSeek(0.000000) avgFrameLen=84038.122994 mParsedFramesDuration=174.602448 offset=261066
[Child 2618: MediaPDecoder #2]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetSamples(1) Begin offset=261066 mParsedFramesDuration=174.602448 mTotalFrameLen=14673262
[Child 2618: MediaPDecoder #2]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] FindNext() Begin offset=261066 mParsedFramesDuration=174.602448 mTotalFrameLen=14673262
[Child 2618: MediaPDecoder #2]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] FindNext() End time=0.000000 offset=264217 mParsedFramesDuration=174.602448 mTotalFrameLen=14673262
[Child 2618: MediaPDecoder #2]: D/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetNextFrame() Begin(time=0.000000 offset=261066 size=3145)
[Child 2618: MediaPDecoder #2]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetSamples() End mSamples.Length=1 aNumSamples=-1 offset=264217 mParsedFramesDuration=174.602448 mTotalFrameLen=14673262

[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetSamples(1) Begin offset=264217 mParsedFramesDuration=174.602448 mTotalFrameLen=14673262
[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] FindNext() Begin offset=264217 mParsedFramesDuration=174.602448 mTotalFrameLen=14673262
[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] FindNext() End time=0.104489 offset=267387 mParsedFramesDuration=174.602448 mTotalFrameLen=14673262
[Child 2618: MediaPDecoder #1]: D/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetNextFrame() Begin(time=0.104489 offset=264211 size=3170)
[Child 2618: MediaPDecoder #1]: V/MediaDemuxer FlacTrackDemuxer[0x11c7fb2e0] GetSamples() End mSamples.Length=1 aNumSamples=-1 offset=267387 mParsedFramesDuration=174.602448 mTotalFrameLen=14673262

...

-------------------------

[3] https://searchfox.org/mozilla-central/rev/de7676288a78b70d2b9927c79493adbf294faad5/dom/media/ReaderProxy.cpp#317
[4] https://searchfox.org/mozilla-central/rev/de7676288a78b70d2b9927c79493adbf294faad5/dom/media/MediaDecoderStateMachine.cpp#3547-3551

	C.M.Chang[:chunmin] Assignee
	Comment 6 • 6 years ago

This file is marked `fixed-blocksize`[0] at its header[1] but the blocksize of the last frame is less than its previous one. It's actually *variable*! Not sure if it's common. The sample-index is calculated by `frame-count * blocksize`, where frame-count is a regularly counted in this file from 0 to n. The sample-index of last audio is smaller than its previous one since its blocksize is too small. The time of the media-data is calculated by the sample-index so we get a wrong value.

[0] https://xiph.org/flac/format.html#frame_header_notes
[1] https://searchfox.org/mozilla-central/rev/de7676288a78b70d2b9927c79493adbf294faad5/dom/media/flac/FlacDemuxer.cpp#56,112

	C.M.Chang[:chunmin] Assignee
	Comment 7 • 6 years ago

This patch can solve the problem for this file. Haven't test it on other files yet.

	C.M.Chang[:chunmin] Assignee
	Comment 8 • 6 years ago

(In reply to Chun-Min Chang[:chunmin] from comment #7)
> Created attachment 9008899 [details] [diff] [review]
> Use index of previous frame to calculate the minimal index
> 
> This patch can solve the problem for this file. Haven't test it on other
> files yet.

The index for the samples in a fixed-blocksize stream is calculated by `frames_number(n) * blocksize(n)`. Unfortunately, the blocksize of the last frame might be smaller than its previous one. For example, the last blocksize for one stream with fixed blocksize 100 might be 80. If it has 10 frames(from number 0 to 9), then its last index will be calculated by 9 * 80 = 720. It's real value should be 8*100 + 80 = 880. `frames_number(n) * blocksize(n)` works fine from 0 to 8: 0*100 = 0, 1*100 = 100, 2*100=200, ... etc, but doesn't work for 9.

A safer way to calculate this is by accumulation: 0, 0 + 100 = 100, 100+100 = 200, ..., 700+100=800, 800+80=880. To do this, we need to know the previous index value and accumulate it with current blocksize. However, it doesn't work when seeking. The last index we have is very likely neither the index of previous frame, nor the index of next frame. In that case, we need to re-calculate the index from the info of the raw data by `frames_number(n) * blocksize(n)`. Thus, the approach now is:

index = frames_number(n) * blocksize(n)
if not seeking:
  minimal_index = previous_index + blocksize(n)
  index = max(index, minimal_index)

The minimal_index above is an accumulated index value. It's used to make sure index >= minimal_index. When seeking, the index is calculated by the raw info, as usual. I guess it works for most of the time. But if it's possible to seek to the last frame, then the `index` is still a wrong value.

	C.M.Chang[:chunmin] Assignee
	Comment 10 • 6 years ago

TODO: Correct the 

Still use `mLastAudioEndTime` as `mLoopingOffset` now. If `mLastAudioEndTime` is a wrong value (returned from Demuxer), then we cannot get a correct offset to adjust the AudioData[0]. In that case, the MediaQueue::Duration() will get a wrong value[1]. It will affect the calculation about how many data we need to decode in advance.

[0] https://searchfox.org/mozilla-central/rev/dd965445ec47fbf3cee566eff93b301666bda0e1/dom/media/ReaderProxy.cpp#62-64
[1] https://searchfox.org/mozilla-central/rev/dd965445ec47fbf3cee566eff93b301666bda0e1/dom/media/MediaQueue.h#107

	C.M.Chang[:chunmin] Assignee
	Comment 12 • 6 years ago

Depends on D6425

	C.M.Chang[:chunmin] Assignee
	Comment 13 • 6 years ago

Depends on D6426

	Jean-Yves Avenard [:jya]
	Comment 14 • 6 years ago

Comment on attachment 9010751 [details]
Bug 1487797 - Part 2: Make sure the time of audio data are monotonically increasing

Jean-Yves Avenard [:jya] has approved the revision.

	C.M.Chang[:chunmin] Assignee
	Comment 15 • 6 years ago

Depends on D6426

	Jean-Yves Avenard [:jya]
	Comment 16 • 6 years ago

Comment on attachment 9010752 [details]
Bug 1487797 - Part 3: Make sure the time of media data in media queue are monotonically increasing

Jean-Yves Avenard [:jya] has approved the revision.

	Jean-Yves Avenard [:jya]
	Comment 17 • 6 years ago

Comment on attachment 9010750 [details]
Bug 1487797 - Part 1: Set end-time, instead of start-time, to the last-audio-end-time in ReaderProxy

Jean-Yves Avenard [:jya] has approved the revision.

	C.M.Chang[:chunmin] Assignee
	Comment 18 • 6 years ago

I am going to move the part 3 to another bug since it may be out of topic. To make sure the seekbar works while looping, part 1 and 2 should be enough.

	Pulsebot
	Comment 19 • 6 years ago

Pushed by aiakab@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/c629e51dda10
Part 1: Set end-time, instead of start-time, to the last-audio-end-time in ReaderProxy r=jya

	Pulsebot
	Comment 20 • 6 years ago

Pushed by aiakab@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e9549537063a
Part 2: Make sure the time of audio data are monotonically increasing r=jya

	Pulsebot
	Comment 21 • 6 years ago

Pushed by aiakab@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/5dcf18a41fc2
"The seekbar is incorrectly displaying FLAC's audio progress after loop" []
https://hg.mozilla.org/integration/mozilla-inbound/rev/38cba148ab07
Part 1: Set end-time instead of start-time to the last-audio-time in ReaderProxy
https://hg.mozilla.org/integration/mozilla-inbound/rev/74ade0131f9f
Part 2: Make sure the duration in ReaderProxy is equal to or larger than the duration in MDSM

	Noemi Erli[:noemi_erli]
	Comment 22 • 6 years ago

Backed out 3 changesets (Bug 1487797) for failures in builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/StateMirroring.h

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&resultStatus=testfailed,busted,exception&classifiedState=unclassified&selectedJob=202333622&revision=74ade0131f9f7a8337630f8a58d54c3b8e91e75a

Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=202333622&repo=mozilla-inbound&lineNumber=4909

Backout: https://hg.mozilla.org/integration/mozilla-inbound/rev/4db3213f93037371a98f5a6438be87e9ec9c934e

	Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)
	Comment 23 • 6 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/c629e51dda10
https://hg.mozilla.org/mozilla-central/rev/e9549537063a

	C.M.Chang[:chunmin] Assignee
	Comment 24 • 6 years ago

The pushed patches were WIP patches. They are not the patches reviewed.
According the comment 23, I think the correct patches were landed.

	Noemi Erli[:noemi_erli]
	Comment 25 • 6 years ago

Backed out 2 changesets (Bug 1487797) for introducing regressions a=backout

Backout: https://hg.mozilla.org/mozilla-central/rev/b569fad5a51ff187f7a03e584ba3e5910e0f19

	Julien Cristau [:jcristau]
	Comment 26 • 6 years ago

Why was this nominated for tracking?

	C.M.Chang[:chunmin] Assignee
	Comment 27 • 6 years ago

- Use bool to track if we are in seeking
- Cancel the data promise requested before firing seeking
- Replace lastAudioEndTime by maxAudioEndTime
- Fallback to normal looping if user seeks to EOS directly

TODO: 
- Add tests

	C.M.Chang[:chunmin] Assignee
	Comment 29 • 6 years ago

Depends on D9043

	C.M.Chang[:chunmin] Assignee
	Comment 30 • 6 years ago

I found most of the flac files in this website have the same issue. 

http://www.hyperion-records.co.uk/testfiles.asp

The last end time in those files are all smaller than their previous one. Their blocksizes in the last frames are smaller then their previous one, even if it's marked `fixed`. Our calculation for index counts on the blocksize from the frame we parse, but the blocksize is not always true.

	Noemi Erli[:noemi_erli]
	Comment 31 • 6 years ago

(In reply to Julien Cristau [:jcristau] from comment #26)
> Why was this nominated for tracking?

This backout was requested by :jya in the #developers room:
"jya> Aryx: can we backout the change from bug 1487797?
12:08 AM we won't have time to properly fix it for 64 and it introduced regressions"

	C.M.Chang[:chunmin] Assignee
	Comment 34 • 6 years ago

(In reply to Chun-Min Chang[:chunmin] from comment #27)
> TODO: 
> - Add tests
I tried to make a file by ffmpeg. However, the generated files are broken. They are not seekable and lead to decoder errors. Use the source provided by the bug report directly for now.

	C.M.Chang[:chunmin] Assignee
	Comment 35 • 6 years ago

Comment on attachment 9017691 [details] [diff] [review]
[WIP] Draft

Move to bug 1496474. Only fix the flac's indexing problem here.

	Julien Cristau [:jcristau]
	Comment 36 • 6 years ago

Sounds like this is for 65 then.

	C.M.Chang[:chunmin] Assignee
	Comment 37 • 6 years ago

Note: Even we fix the timestamp error in FLAC file, this problem may happen for chained ogg files. See bug 1091422 and the workaround in our code[0, 1].

[0] https://searchfox.org/mozilla-central/rev/9cb3e241502a2d47e2d5057ca771324a446b6695/dom/media/MediaDecoderStateMachine.cpp#3201
[1] https://searchfox.org/mozilla-central/rev/9cb3e241502a2d47e2d5057ca771324a446b6695/dom/media/MediaDecoderStateMachine.cpp#2815-2817

	Pulsebot
	Comment 40 • 6 years ago

Pushed by rvandermeulen@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e8ea25fee7b2
P1. Move sample index from FrameHeader to Frame. r=jya
https://hg.mozilla.org/integration/autoland/rev/b50e31d758b1
P2. Make sure the sample index of FLAC's frame is monotonically increasing. r=jya

	Daniel Varga [:dvarga]
	Comment 41 • 6 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/e8ea25fee7b2
https://hg.mozilla.org/mozilla-central/rev/b50e31d758b1

	Daniel Cicas [:dcicas], Release QA
	Comment 42 • 5 years ago

I reproduced this issue using Fx 63.0a1, build ID: 20180831100058, on Windows 10 x64, Ubuntu 18.04 x64 and macOS x 10.13.

I can confirm this issue is fixed, I verified using Fx 65.0b8, build ID:  20190103150357, on Windows 10 x64, macOS X 10.13 and Ubuntu 18.04 x64.