1246358 - YouTube video cannot be replayed if playback completes while it is in a background tab

Status: VERIFIED FIXED

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

Description

[Trevor Rowbotham [:rowbot]]

This is on Windows 10 using the latest x64 nightly.

Last good revision: ce6b2fdabc3ecd709abf5de6dbe963edd44d18fb
First bad revision: f2f8fc172f4c62334e9a92bcf10e00fe877387d5
Pushlog: https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=ce6b2fdabc3ecd709abf5de6dbe963edd44d18fb&tochange=f2f8fc172f4c62334e9a92bcf10e00fe877387d5

Last good revision: 39f872a217ff48786cfda71241a679b5d36e1408
First bad revision: 950702b82f19c5327efab387bdbdbac80700c80d
Pushlog: https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=39f872a217ff48786cfda71241a679b5d36e1408&tochange=950702b82f19c5327efab387bdbdbac80700c80d

STR:
1) Visit https://www.youtube.com/watch?v=JLf9q36UsBk
2) Turn off Autoplay so that a suggested video isn't played immediately after playback completes.
3) Open or switch to another tab and let the video play to completion while it is in a background tab.

Note: There is about 17 seconds of silence at the end of the video in Step 1, so be careful if you are using audio as a cue to know when to switch back to the tab containing the video.

Actual Results:
YouTube player displays a message staying "An error has occurred. Please try again later.".  The browser console says that the media cannot be decoded.

Expected Results:
Suggested videos should be shown and clicking on the Replay button should cause the video to replay.



Adapter Description	NVIDIA GeForce GTX 660
Adapter Drivers	nvd3dumx,nvwgf2umx,nvwgf2umx,nvwgf2umx nvd3dum,nvwgf2um,nvwgf2um,nvwgf2um
Adapter RAM	2048
Asynchronous Pan/Zoom	wheel input enabled; touch input enabled
Device ID	0x11c0
Direct2D Enabled	true
DirectWrite Enabled	true (10.0.10586.0)
Driver Date	1-22-2016
Driver Version	10.18.13.6175
GPU #2 Active	false
GPU Accelerated Windows	1/1 Direct3D 11 (OMTC)
Subsys ID	30693842
Supports Hardware H264 Decoding	Yes
Vendor ID	0x10de
WebGL Renderer	Google Inc. -- ANGLE (NVIDIA GeForce GTX 660 Direct3D11 vs_5_0 ps_5_0)
windowLayerManagerRemote	true
AzureCanvasBackend	direct2d 1.1
AzureContentBackend	direct2d 1.1
AzureFallbackCanvasBackend	cairo
AzureSkiaAccelerated	0

Comment 1

[Jean-Yves Avenard [:jya]]

The issue is an Opus decode error as we attempt to seek to the end of the video coming back of dormant.

Used to work prior bug 1243608 because we would seek the audio to the video time...

Comment 2

[Jean-Yves Avenard [:jya]]

A tad easier step to reproduce, and so you dont have to wait and hear the question to know if we're out of the wood about 3 million times:

- Go to https://www.youtube.com/watch?v=JLf9q36UsBk&feature=youtu.be&t=254 (note that about 1 in 5 this will immediately cause the decode error)
- Go to another tab in the same window
- Wait 1 minute to ensure dormant more kick in (or set media.decoder.heuristic.dormant.timeout to 10000, so you only wait 10s)
- Go back into the previous tab:

Console will show, with PlatformDecoderModule:5 error

[MediaPDecoder #7]: D/PlatformDecoderModule OpusDataDecoder(6000018b9da0)::DoDecode: Opus decoder skipping 312 of 960 frames
[MediaPDecoder #7]: D/PlatformDecoderModule OpusDataDecoder(6000018b9da0)::DoDecode: OpusDecoder discardpadding 16208333
[MediaPDecoder #7]: D/PlatformDecoderModule OpusDataDecoder(6000018b9da0)::DoDecode: Opus error, discard padding larger than packet
[57847] WARNING: Decoder=1a1b4d5c0 Decode error, changed state to ERROR: file /Users/jyavenard/Work/Mozilla/mozilla-central/dom/media/MediaDecoderStateMachine.cpp, line 1917

The error is this:
https://dxr.mozilla.org/mozilla-central/source/dom/media/platforms/agnostic/OpusDecoder.cpp#222

We have seeked to the last audio frame of the file and attempting to decode that last frame will cause a decode error.
This last opus frame has a size of 3 bytes only: 252, 255, 254

Thomas, should we just ignore this error?
Or maybe when seeking in an Opus track should we always return the frame just before the frame we just seeked to (unless it's the first)?

Comment 3

[Trevor Rowbotham [:rowbot]]

(In reply to Jean-Yves Avenard [:jya] from comment #2)
> so you dont have to wait and hear the question to know if we're out of the wood about 3 million times:

heh, I ended up muting the video each time after about the 5th build in mozregression, I probably should have mentioned that in the STR, sorry about that :(.  I kind of figured it had something to do with the decoder becoming dormant, but didn't think to look for a pref that would change the timeout on it.

Comment 4

[Jean-Yves Avenard [:jya]]

It's great you found this bug so early.. Typically those are found when it's too late (release)
The audio track in this video is shorter than the video, which is why YouTube attempt to seek past the end.

The time when I got the error immediately upon opening the video appears to be from graphics, a failure to initialise a frame. That one is intermittent.

Comment 5

[Jean-Yves Avenard [:jya]]

Attachment: [opus] Don't error if we fail to decode the last frame. r=TD-Linux

If we attempt to only decode the last opus frame, it will not produce any output. Simply ignore it rather than erroring.

Comment 6

[Thomas Daede [:TD-Linux]]

Comment on attachment 8716683 [details] [diff] [review]
[opus] Don't error if we fail to decode the last frame. r=TD-Linux

Review of attachment 8716683 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good as a quick fix, I would however like to understand why this is happening and make a test case for it.

::: dom/media/platforms/agnostic/OpusDecoder.cpp
@@ +213,5 @@
>    if (aDiscardPadding > 0) {
> +    // Padding discard is only supposed to happen on the final packet.
> +    // Record the discard so we can return an error if another packet is
> +    // decoded.
> +    mPaddingDiscarded = true;

If this is being caused by DiscardPadding being longer than a single Opus packet (but shorter than a matroska Block), then shouldn't the error caused by this be hit next? Or maybe something else is causing it?

@@ +223,5 @@
>        NS_WARNING("Int overflow in DiscardPadding");
>        return -1;
>      }
>      if (discardFrames.value() > frames) {
>        // Discarding more than the entire packet is invalid.

I'd prefer to clarify this comment. Also this debug message would be more useful with the actual DiscardFrames value printed, like the OPUS_DEBUG after it.

Comment 7

[Jean-Yves Avenard [:jya]]

(In reply to Thomas Daede from comment #6)
> Comment on attachment 8716683 [details] [diff] [review]
> [opus] Don't error if we fail to decode the last frame. r=TD-Linux
> 
> Review of attachment 8716683 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks good as a quick fix, I would however like to understand why this is
> happening and make a test case for it.

This is happening when you attempt to seek to a specific location in the media element.

The MSE track buffer upon seeking will search for the first frame containing the seek time (well, technically to the first keyframe found prior the seek time, but as opus frames are all keyframes). It happens to be the last opus frame in the track buffer.

Reproducing this case in a script would be rather simple.

Comment 8

[Jean-Yves Avenard [:jya]]

(In reply to Thomas Daede from comment #6)
> If this is being caused by DiscardPadding being longer than a single Opus
> packet (but shorter than a matroska Block), then shouldn't the error caused
> by this be hit next? Or maybe something else is causing it?

You're right.

If we have multiple opus packet in a single webm block, all packets in that block will have the discard padding set.

Luckily, YouTube doesn't encode their webm that way so it's not a case we need to consider for YouTube.

I will open a new bug to handle this case.

Not sure of the best way to handle this however... Should we just ignore the extra padding, or maybe modify the WebMDemuxer to only set the extra padding value on the first packet of the block?

Comment 9

[Jean-Yves Avenard [:jya]]

(In reply to Trevor Rowbotham from comment #3)
> (In reply to Jean-Yves Avenard [:jya] from comment #2)
> > so you dont have to wait and hear the question to know if we're out of the wood about 3 million times:
> 
> heh, I ended up muting the video each time after about the 5th build in
> mozregression, I probably should have mentioned that in the STR, sorry about
> that :(.  I kind of figured it had something to do with the decoder becoming
> dormant, but didn't think to look for a pref that would change the timeout
> on it.

Luckily I found this video right after:
https://www.youtube.com/watch?v=69Of9-NCQSY

I now understand this song much better :D

Comment 10

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/c3ac85cea6a3

Comment 11

[Phil Ringnalda (:philor)]

Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/45554120ac30 for https://treeherder.mozilla.org/logviewer.html#?job_id=21242426&repo=mozilla-inbound - apparently test_invalid_reject_play.html is testing for exactly what you stopped doing.

Comment 12

[Jean-Yves Avenard [:jya]]

Comment on attachment 8716683 [details] [diff] [review]
[opus] Don't error if we fail to decode the last frame. r=TD-Linux

turned out that the issue is because the MSE track buffer doesn't take into account pre-rolling when seeking.

So will craft something simpler that always seek slightly before the target wen the track is opus.

Comment 13

[Jean-Yves Avenard [:jya]]

Attachment: [MSE] Take pre-roll time into consideration when seeking.

Comment 14

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/89670b4ab9f3

Comment 15

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/89670b4ab9f3

Comment 16

[Trevor Rowbotham [:rowbot]]

Confirmed fixed with 2016-02-10 nightly.  Looks like you are out of the woods ;)

Comment 17

[Jean-Yves Avenard [:jya]]

Comment on attachment 8716851 [details] [diff] [review]
[MSE] Take pre-roll time into consideration when seeking.

Approval Request Comment
[Feature/regressing bug #]:1246358
[User impact if declined]: Youtube error. Youtube is now serving us Opus audio , attempting to seek in the video could lead to an error and playback will stop.
[Describe test coverage new/current, TreeHerder]: in aurora for several weeks
[Risks and why]: low, implementing the sec, en central for several weeks
[String/UUID change made/needed]: none

Comment 18

[Liz Henry (:lizzard) (relman/hg->git project)]

Comment on attachment 8716851 [details] [diff] [review]
[MSE] Take pre-roll time into consideration when seeking.

Fix for video playback issues. 
This should land for beta 5 which goes to build on Thursday.

Comment 19

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-beta/rev/df6596843fe3