1352934 - Background suspended Netflix cannot resume

Status: RESOLVED FIXED

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

Description

[Chris Pearce [:cpearce (Not reading bugmail)]]

If suspending background video decoding is enabled, and I blur a tab playing Netflix, and then the video decoder is suspended, and then I focus the tab, Netflix playback fails.

STR:
1. Ensure suspending background video decoding is enabled (Nightly build).
2. Open Netflix and begin playing a video.
3. Open a new tab (CTRL+T).
4. Wait until the background video decoder suspends.
5. Refocus the Netflix tab.

Expected result:
Netflix should keep playing.

Observed result:
Netflix tab stops playing when tab is focused.

Comment 1

[Blake Wu [:bwu][:blakewu]]

Kaku would be very interested in this bug. :-)

Comment 2

[Blake Wu [:bwu][:blakewu]]

Chris, 
Did you see any error code on Netflix page? I wonder if this is similar to what I hit in bug 1350453.

Comment 3

[Chris Pearce [:cpearce (Not reading bugmail)]]

Yes, I'm seeing F7375. They likely are related.

Comment 4

[Chris Pearce [:cpearce (Not reading bugmail)]]

I'm happy for Kaku to take this bug. Let me know if you need any help Kaku.

I looked briefly, and here's what I discovered:

If I set media.eme.video.blank=true (to bypass the CDM video decoding) and I still see the failure. So that indicates that the failure is not originating inside the CDM, as we don't use the CDM decode path when media.eme.video.blank=true.

My ClearKey demo at https://people-mozilla.org/~cpearce/mse-clearkey/ works as expected, so my *guess* is that there's something in Netflix's player that can observe the shutdown/restart of the decoder and whatever it's observing is causing it to error.

Maybe NSPR logs would show something useful?

Comment 6

[Tzuhao Kuo [:kaku]]

(In reply to Chris Pearce (:cpearce) from comment #4)
> Maybe NSPR logs would show something useful?
Yes, it does. I observed a pattern every time before the Netflix playback fails: 
1. Switch the Netflix tab back to the foreground.
2. HTMLMediaElement dispatches a "mozexitvideosuspend" event.
3. HTMLMediaElement dispatches a "seeking" event.
4. HTMLMediaElement calls MediaDecoder::Pause().
5. Netflix shows error.

While resuming a suspend video element, we fire a video-only seek operation for seeking to the right video position. (http://searchfox.org/mozilla-central/rev/b8cce081200129a1307e2a682f121135b5ca1d19/dom/media/MediaDecoderStateMachine.cpp#2039)

I think it is this unexpected seeking event makes Netflix player panic. So, I modify the seeking operation to be unobservable, and it works, the Netflix player feels comfortable now and it keeps working.

The seeking operation WAS unobservable before Bug 1309494. I changed it because I want the "canplay" event, which will be dispatched after the seeking operation is done, to notify our video controller to cancel the throbber(which will be shown if the decoder resuming cannot be done in 250 ms).

But, no worry, we can change the seeking operatoin back to unobservable thanks to bug 1350852. Now, we rely on a specific "mozvideoonlyseekcompleted" event to cancel the throbber, so we no longer need the "canplay" event.

A patch is following.

Comment 7

[Tzuhao Kuo [:kaku]]

Attachment: Bug 1352934 - make the seek operation at StateObject::HandleResumeVideoDecoding() unobservable;

The seeking operation WAS unobservable before Bug 1309494.
It was changed to be observable because I want the "canplay" event, which will be dispatched after the seeking operation is done,
to notify our video controller to cancel the throbber(which will be shown if the decoder resuming cannot be done in 250 ms).

Now, we can change the seeking operatoin back to unobservable thanks to bug 1350852.
In bug 1350852, we dispatche a specific "mozvideoonlyseekcompleted" event to cancel the throbber.

Review commit: https://reviewboard.mozilla.org/r/127076/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/127076/

Comment 8

[Tzuhao Kuo [:kaku]]

Try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=7c62c2404cd8ca70e793ade329e64f2f870a1233
https://treeherder.mozilla.org/#/jobs?repo=try&revision=2c8aaa971ab341510abfd3ea6f145d7209a34ded

Comment 9

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8855202 [details]
Bug 1352934 - make the seek operation at StateObject::HandleResumeVideoDecoding() unobservable;

https://reviewboard.mozilla.org/r/127076/#review129834

Comment 10

[Blake Wu [:bwu][:blakewu]]

Kaku, Cool! You are really fast to find the root cause. 

Chris, 
Do you know if there is any test case in automation to test Netflix? I am thinking a way to avoid any possible regression on Netflix.

Comment 11

[Tzuhao Kuo [:kaku]]

Try looks good. Thanks for the review!

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b86a04a468b3
make the seek operation at StateObject::HandleResumeVideoDecoding() unobservable; r=jwwang

Comment 13

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

https://hg.mozilla.org/mozilla-central/rev/b86a04a468b3

Comment 14

[Chris Pearce [:cpearce (Not reading bugmail)]]

Thanks Kaku. Are any other branches affected?

Comment 15

[Chris Pearce [:cpearce (Not reading bugmail)]]

(In reply to Blake Wu [:bwu][:blakewu] from comment #10)
> Kaku, Cool! You are really fast to find the root cause. 
> 
> Chris, 
> Do you know if there is any test case in automation to test Netflix? I am
> thinking a way to avoid any possible regression on Netflix.

We have the external-media-tests, but they don't have a background playback case so they won't have discovered this regression. We recently decided to stop investing in those tests however, as they've required a lot of work to keep running and haven't delivered much value.

Comment 16

[Tzuhao Kuo [:kaku]]

(In reply to Chris Pearce (:cpearce) from comment #14)
> Thanks Kaku. Are any other branches affected?

No, we only turn on the suspend-vide-decoder flag in Nightly.

Comment 17

[Blake Wu [:bwu][:blakewu]]

(In reply to Chris Pearce (:cpearce) from comment #15)
> (In reply to Blake Wu [:bwu][:blakewu] from comment #10)
> > Kaku, Cool! You are really fast to find the root cause. 
> > 
> > Chris, 
> > Do you know if there is any test case in automation to test Netflix? I am
> > thinking a way to avoid any possible regression on Netflix.
> 
> We have the external-media-tests, but they don't have a background playback
> case so they won't have discovered this regression. We recently decided to
> stop investing in those tests however, as they've required a lot of work to
> keep running and haven't delivered much value.
I thought external-media-tests is useful since they test the real world and should be able to increase our testing coverage. I am going to bother you or Bryce to know more background about it. :-)

Comment 18

[Andrei Vaida [:avaida]]

Would manual QA be of value here? I'm not sure if all the steps described in Comment 0 can be simulated manually though, so we'd need to clarify that first if the answer is yes.

Comment 19

[Mr. Beedell, Roke Julian Lockhart (RJLB) [:beedell.roke_julian_lockhart]]

Attachment: A Screenshot Of Apparent Reproduction In 141.0

I believe that this remains reproducible: I see F7375 if I resume a Netflix tab from suspension in firefox-141.0-2.fc42.x86_64. If nobody else does, apologies.

I do see github.com/xxxily/h5player/issues/317 from 2021, but it's not very actionable corroboration, considering its context and lack of detail.

Comment 20

[Alastor Wu [:alwu]]

When this issue happens, do you know what key system you were using for video? pressing CTRL+SHIFT+ALT+D on video will show you a debug panel on which you can find the key system. Thanks!

Comment 21

[Mr. Beedell, Roke Julian Lockhart (RJLB) [:beedell.roke_julian_lockhart]]

I didn't save the tab. However, if I re-visit it netflix.com/watch/80115466, I see:

Version: 6.0051.090.911
Esn: NFCDFF-LX-LR2WM6Q90YD7W1D6M04QK42H4JMR76
PBCID: 6.MJS79OdqYzxW1C5LnNZglGaaGAUlOPcirhi5hFCYfLE
UserAgent: Mozilla/5.0 (X11; Linux x86_64; rv:141.0) Gecko/20100101 Firefox/141.0

MovieId: 80115466
PackageId: 2187278
Xid: 175373648663267680 (175373648663267680)
Position: 0.669
Duration: 6359.353
PlayerDuration: 6359.353
Volume: 100%
Segment: 80115466:main
Segment Position: 0.669

Player state: Normal
Buffering state: Normal
Rendering state: Paused

Playing bitrate (a/v): 128 / 766 (1920x1080)
Playing/Buffering vmaf: 91/91
Buffering bitrate (a/v): 128 / 766
Buffer size in Bytes (a/v): 0 / 0
Buffer size in Bytes: 0
Buffer size in Seconds (a/v): 239.518 / 239.779
Downloadables (a/v): 466031447 / 509148875
Current CDN (a/v/t): c162.lhr004.ix.nflxvideo.net, Id: 78267 / c120.lhr004.ix.nflxvideo.net, Id: 56802 / ?

Audio Track: ja, Id: A:2:1;2;ja;1;0;, Channels: 2.0, Codec: audio/mp4;codecs=mp4a.40.5 (he-aac)
Audio Tags: 
Video Track: Codec: video/mp4;codecs=avc1.4d0028 (avc)
Video Tags: AL1,EVE,MCCLEAREN_VP9,POI,ladder
Timed Text Track: en, Profile: simplesdh, Id: T:2:0;1;en;0;0;0;, DownloadableId: 445191064

Framerate: 23.976
Current Dropped Frames: 
Total Frames: 17
Total Dropped Frames: 0
Total Corrupted Frames: undefined
Main Thread stall/sec: DISABLED
KeySystem: com.widevine.alpha.SW_SECURE_DECODE
KeyStatus: AAAAAAgIrW4AAAAAAAAAAA==,AAAAAAgIrXAAAAAAAAAAAA==, ,, usable,usable
VideoDiag: readyState=4,currentTime=0.668875,pbRate=1,videoBuffered=37.913,videoRanges=0-37.912875,audioBuffered=32.043,audioRanges=0-32.042666,duration=6359.3530
HDR support: false (disabled)

Throughput: 13556 kbps

Hopefully, it hasn't changed itself since. I can't envision why it would.

Comment 22

[Alastor Wu [:alwu]]

Do you have consistent steps to reproduce this issue? Does it happen 100% of the time when resuming Netflix after suspension (by "suspension," I assume you mean putting the whole system to sleep and then logging back in)? Thanks!

Comment 23

[Mr. Beedell, Roke Julian Lockhart (RJLB) [:beedell.roke_julian_lockhart]]

That was weird phrasal on my part. I was actually referring to having the browser reinitialise (in my case, due to qdbus org.kde.LogoutPrompt /LogoutPrompt logoutAndShutdown). I forget that outside of Fenix and Chromium, tabs aren't generally suspended when not in use, except during OOM events.

Regardless, in retrospect, this was probably caused by github.com/MALSync/MALSync/issues/3134. I'll presume it is, since both my current, and a new, profile haven't reproduced this otherwise, even after suspending with qdbus-qt6 org.kde.kglobalaccel /component/org_kde_powerdevil invokeShortcut 'Sleep' and resuming (or "Quit").