Closed Bug 1335263 Opened 8 years ago Closed 7 years ago

Audio Element emits 'timeupdate' past the track's duration when using Media Source Extensions

Categories

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

Product:
Core
Component:
Audio/Video: Playback
Version:
50 Branch
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE
Tracking Flags:
Tracking Status
platform-rel --- +

People

(Reporter: evan_layman, Unassigned)

Details

(Whiteboard: [need info reporter 2017-02-01][platform-rel-Amazon][platform-rel-AmazonMusic]) 

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/55.0.2883.95 Safari/537.36

Steps to reproduce:

1. Play an MPD stream (audio/mp4) using Media Source Extensions to create an audio buffer
2. Let it play to the end

Might be related to similar issue on Chrome: https://bugs.chromium.org/p/chromium/issues/detail?id=475244



Actual results:

Sometimes the audioElement emits 'timeupdate' with time > buffered duration:
Example: 

Buffered range (in seconds): 0 to 229.804557
timeupdate emitted: 229.80738

Subsequently, the audioElement emits 'waiting' event (since it doesn't have any buffer) instead of 'ended' event (maybe b/c the logic checks == duration rather than >= duration?)


Expected results:

audioElement doesn't emit 'timeupdate' > duration
audioElement emits 'ended' event (This is the main issue, the timeupdate isn't too critical)
Component: Untriaged → Web Audio
Product: Firefox → Core
Evan is there possibly a page were this can easily be reproduced?
Flags: needinfo?(evan_layman)
Whiteboard: [need info reporter 2017-02-01]
Hi Nils,

I will see if I can provide you with a way to easily reproduce. I have noticed that it reproduces sometimes also when 'timeupdate' emits a time ~5ms before the duration/buffered time. The 'ended' event never occurs. I think it's the same issue. It only reproduces sometimes with the same MPD stream.
You can reproduce the issue on the Amazon Music Web Player: music.amazon.com
You will need an Amazon Music Unlimited, or Prime subscribed account

1. Sign in with your Unlimited or Prime account
2. Search for "U2" in the search box
3. Scroll down to the section labeled "Tracks"
4. Click play on "Beatiful Day" track
5. Scrub near the end of the track by hovering over the transport (top player information) and clicking near the end of the moving scrubber
6. Wait for track to reach 0:01 or 0:00

Sometimes it hangs there, other times it completes.
How and when the events are firing is really JW's expertise, adding him and ni?
Flags: needinfo?(jwwang)
I don't have an account to access the music.

Can you try to repro the issue with |MOZ_LOG=MediaDecoder:4 ./mach run| to catch some logs?
Flags: needinfo?(jwwang)
(In reply to evan_layman from comment #0)
> User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6)
> AppleWebKit/537.36 (KHTML, like Gecko) Chrome/55.0.2883.95 Safari/537.36
> 
> Steps to reproduce:
> 
> 1. Play an MPD stream (audio/mp4) using Media Source Extensions to create an
> audio buffer
> 2. Let it play to the end
> 
> Might be related to similar issue on Chrome:
> https://bugs.chromium.org/p/chromium/issues/detail?id=475244
> 
> 
> 
> Actual results:
> 
> Sometimes the audioElement emits 'timeupdate' with time > buffered duration:
> Example: 
> 
> Buffered range (in seconds): 0 to 229.804557
> timeupdate emitted: 229.80738

I'm assuming the time you are referring to is "currentTime" ?


> 
> Subsequently, the audioElement emits 'waiting' event (since it doesn't have
> any buffer) instead of 'ended' event (maybe b/c the logic checks == duration
> rather than >= duration?)
> 
> 
> Expected results:
> 
> audioElement doesn't emit 'timeupdate' > duration
> audioElement emits 'ended' event (This is the main issue, the timeupdate
> isn't too critical)

Has endOfStream() been called on the mediasource object?

Can you create an narrower test page where you can reproduce the issue?
(In reply to JW Wang [:jwwang] [:jw_wang] from comment #5)
> I don't have an account to access the music.
> 
> Can you try to repro the issue with |MOZ_LOG=MediaDecoder:4 ./mach run| to
> catch some logs?

Hi JW,

Here is what I see in the output when I reproduce it:

[Main Thread]: D/MediaDecoder Decoder=182123800 FirstFrameLoaded, channels=2 rate=44100 hasAudio=1 hasVideo=0 mPlayState=LOADING mIsDormant=0
[Main Thread]: D/MediaDecoder Decoder=182123800 ChangeState LOADING => PLAYING
[MediaPlayback #7]: D/MediaDecoder Decoder=182123800 MaybeStartPlayback() starting playback
[MediaPlayback #7]: D/MediaDecoder VideoSink=125e6e110 [Start]
[Main Thread]: D/MediaDecoder Decoder=1244cc400 ChangeState ENDED => SHUTDOWN
[MediaPlayback #8]: D/MediaDecoder Decoder=1244cc400 MDSM state: COMPLETED -> SHUTDOWN
[MediaPlayback #8]: D/MediaDecoder Decoder=1244cc400 MediaDecoderStateMachine::Reset
[MediaPlayback #8]: D/MediaDecoder VideoSink=1246cc7f0 [Shutdown]
[MediaPlayback #8]: D/MediaDecoder Decoder=1244cc400 Shutdown started
[MediaPlayback #8]: D/MediaDecoder Decoder=1244cc400 Shutting down state machine task queue
[MediaPlayback #6]: D/MediaDecoder Decoder=182123800 Changed state to SEEKING (to 245000000)
[MediaPlayback #6]: D/MediaDecoder Decoder=182123800 MDSM state: DECODING -> SEEKING
[MediaPlayback #6]: D/MediaDecoder Decoder=182123800 StopPlayback()
[MediaPlayback #6]: D/MediaDecoder Decoder=182123800 MediaDecoderStateMachine::Reset
[MediaPlayback #6]: D/MediaDecoder Decoder=182123800 Stop MediaSink
[MediaPlayback #6]: D/MediaDecoder VideoSink=125e6e110 [Stop]
[MediaPlayback #6]: D/MediaDecoder Decoder=182123800 Changed mNextFrameStatus to NEXT_FRAME_UNAVAILABLE_SEEKING
[MediaPlayback #5]: D/MediaDecoder Decoder=182123800 Changed state from SEEKING (to 245000000) to DECODING
[MediaPlayback #5]: D/MediaDecoder Decoder=182123800 Seek completed, mCurrentPosition=245000000
[MediaPlayback #5]: D/MediaDecoder Decoder=182123800 MDSM state: SEEKING -> DECODING
[MediaPlayback #5]: D/MediaDecoder Decoder=182123800 Changed mNextFrameStatus to NEXT_FRAME_UNAVAILABLE
[MediaPlayback #6]: D/MediaDecoder Decoder=182123800 Not starting playback [playStatePermits: 1, mIsAudioPrerolling: 1, mIsVideoPrerolling: 0, mAudioOffloading: 0]
[MediaPlayback #7]: D/MediaDecoder Decoder=182123800 Changed mNextFrameStatus to NEXT_FRAME_AVAILABLE
[MediaPlayback #8]: D/MediaDecoder Decoder=182123800 MaybeStartPlayback() starting playback
[MediaPlayback #8]: D/MediaDecoder VideoSink=125e6e110 [Start]
(In reply to Jean-Yves Avenard [:jya] from comment #6)
> (In reply to evan_layman from comment #0)
> > User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6)
> > AppleWebKit/537.36 (KHTML, like Gecko) Chrome/55.0.2883.95 Safari/537.36
> > 
> > Steps to reproduce:
> > 
> > 1. Play an MPD stream (audio/mp4) using Media Source Extensions to create an
> > audio buffer
> > 2. Let it play to the end
> > 
> > Might be related to similar issue on Chrome:
> > https://bugs.chromium.org/p/chromium/issues/detail?id=475244
> > 
> > 
> > 
> > Actual results:
> > 
> > Sometimes the audioElement emits 'timeupdate' with time > buffered duration:
> > Example: 
> > 
> > Buffered range (in seconds): 0 to 229.804557
> > timeupdate emitted: 229.80738
> 
> I'm assuming the time you are referring to is "currentTime" ?
> 
> 
Yes, currentTime is what I refer to in the 'timeupdate emitted:' log
> > 
> > Subsequently, the audioElement emits 'waiting' event (since it doesn't have
> > any buffer) instead of 'ended' event (maybe b/c the logic checks == duration
> > rather than >= duration?)
> > 
> > 
> > Expected results:
> > 
> > audioElement doesn't emit 'timeupdate' > duration
> > audioElement emits 'ended' event (This is the main issue, the timeupdate
> > isn't too critical)
> 
> Has endOfStream() been called on the mediasource object?
> 
> Can you create an narrower test page where you can reproduce the issue?
Yes endOfStream() has been called on mediasource.
(In reply to evan_layman from comment #7)
> (In reply to JW Wang [:jwwang] [:jw_wang] from comment #5)
> > I don't have an account to access the music.
> > 
> > Can you try to repro the issue with |MOZ_LOG=MediaDecoder:4 ./mach run| to
> > catch some logs?
> 
> Hi JW,
> 
> Here is what I see in the output when I reproduce it:

The log is not complete which doesn't show the end of playback.
Can you try again with |MOZ_LOG=MediaDecoder:4,MediaSample:4 ./mach run|? Thanks.
https://music.amazon.com/albums/B001NB1JVY/CATALOG?ie=UTF8&qid=1487213805&playNow=1&trackAsin=B001NB1K18&albumAsin=B001NB1JVY

Is this the song you were listening to? It is weird that I can't find any MediaDecoder logs while playing it.
It says "Flash must be installed and enabled to stream Amazon Music." How can I use MSE to play the music?
Hi JW,

Can you clarify which version of Firefox you are using? Can you share the navigator.userAgent here? We do whitelist and blacklist some browsers to use/not use MSE.

Thanks,

Evan
(In reply to evan_layman from comment #12)
> Hi JW,
> 
> Can you clarify which version of Firefox you are using? Can you share the
> navigator.userAgent here? We do whitelist and blacklist some browsers to
> use/not use MSE.
> 
> Thanks,
> 
> Evan

Mozilla/5.0 (X11; Linux x86_64; rv:54.0) Gecko/20100101 Firefox/54.0
https://music.amazon.com/albums/B001NB1JVY/CATALOG?ie=UTF8&qid=1487213805&playNow=1&trackAsin=B001NB1K18&albumAsin=B001NB1JVY

I got some logs when playing "Beautiful day".

Duration changed to 248.040000
state=COMPLETED mDecodedAudioEndTime=248058774
state=COMPLETED audioEndTime=248058774 videoEndTime=-1 duration=248040000 clockTime=248058774

The end time of the last audio sample is 248058774 which is greater than the duration=248040000 and therefore the final currentTime reported by the media element is greater than the initial duration.

I think this is a usual case for MSE, right?
Flags: needinfo?(jyavenard)
(In reply to JW Wang [:jwwang] [:jw_wang] from comment #14)
> https://music.amazon.com/albums/B001NB1JVY/
> CATALOG?ie=UTF8&qid=1487213805&playNow=1&trackAsin=B001NB1K18&albumAsin=B001N
> B1JVY
> 
> I got some logs when playing "Beautiful day".
> 
> Duration changed to 248.040000
> state=COMPLETED mDecodedAudioEndTime=248058774
> state=COMPLETED audioEndTime=248058774 videoEndTime=-1 duration=248040000
> clockTime=248058774
> 
> The end time of the last audio sample is 248058774 which is greater than the
> duration=248040000 and therefore the final currentTime reported by the media
> element is greater than the initial duration.
> 
> I think this is a usual case for MSE, right?

Effectively, the spec indicates that the duration of the element is equal to the last end time of the buffered samples.

Buffered range, duration and so on, is based on the demuxed time.
What is happening here is that the *decoded* time returned by the decoder doesn't match the demuxed time.

what platform are we on ? mac?

This could be related to bug 1321249, and that we do not trim the remainder of an AAC stream:
https://developer.apple.com/library/content/documentation/QuickTime/QTFF/QTFFAppenG/QTFFAppenG.html

I don't know how we can do that one either in a universally supported fashion.
Unless we just trim the decoder data so that it matches what's found in the demuxer.
Component: Web Audio → Audio/Video: Playback
Flags: needinfo?(jyavenard)
It makes sense to me that we receive an 'ended' event when the audio will not progress if it hits these edge cases. If that means trimming the decoder data, that might be a better customer experience than having hacky workarounds on the clients to end the song early.
platform-rel: --- → +
Whiteboard: [need info reporter 2017-02-01] → [need info reporter 2017-02-01][platform-rel-Amazon][platform-rel-AmazonMusic]
jw,jya: What's causing problems for Amazon here is that we're not emitting an "ended" event. Is there a way we can emit an "ended" event here, irrespective of the fact that the decoder has output more samples than we expect?

Why are we not emitting an "ended" event? The MDSM should be in COMPLETED state?
Flags: needinfo?(jyavenard)
Flags: needinfo?(jwwang)
(In reply to Chris Pearce (:cpearce) from comment #17)
> jw,jya: What's causing problems for Amazon here is that we're not emitting
> an "ended" event. Is there a way we can emit an "ended" event here,
> irrespective of the fact that the decoder has output more samples than we
> expect?
> 
> Why are we not emitting an "ended" event? The MDSM should be in COMPLETED
> state?

I can understand why timeupdate could be fired past duration. As currentTime is based on the decoded time.

The ended event however doesn't rely on currentTime, but only once we've decoded the last frame.

The only reason I can think of for ended to not be fired is that:
1- A decoding error occurred (and the error event was fired)
2- endOfStream wasn't called on the media source.

Without an easy way to reproduce, nor the ability to look at the code of Amazon's media player it's hard to know for sure.

My guess is that it's option 2. If you reach the end of the media and endOfStream wasn't called, the waiting event will be fired. As soon as endOfStream is called, ended will be fired.

I don't believe we have any issues with the ended event. We have various mochitests that ensure the scenario described works appropriately
Flags: needinfo?(jyavenard)
I can't repro on U2/Beautiful Day in Firefox beta 54. Evan, do you have a more reliable repro? Can you still repro?
Since we've added workaround in our code base to detect if we receive a timeupdate within 5ms from the duration, we will end the stream early, we can no longer reproduce this. I will see if we can create a test page for this.
Flags: needinfo?(evan_layman)
(In reply to evan_layman from comment #21)
> Since we've added workaround in our code base to detect if we receive a
> timeupdate within 5ms from the duration, we will end the stream early, we
> can no longer reproduce this. I will see if we can create a test page for
> this.

This is a very peculiar approach to rely on timeupdate to do anything. Timeupdate is fired at random +/- 250ms as per spec. 

You should use the ended event to determine if the current source has ended.
please reopen if this is still happening
Status: UNCONFIRMED → RESOLVED
Closed: 7 years ago
Resolution: --- → INCOMPLETE
Flags: needinfo?(suro001)
You need to log in before you can comment on or make changes to this bug.