Bug 219354 – [GStreamer][MSE] SleepDisabler not reliably created when playing YouTube videos

• Status: RESOLVED
• Resolution: FIXED
• Component: Media

[Michael Catanzaro]

When starting a YouTube video that contains ads, click the Skip Ads button to begin video playback. A SleepDisabler should be created immediately, but instead the video usually starts playing without creating a SleepDisabler. A SleepDisabler is later created if I stop and then resume the video.

Note: this is tested with adblocker enabled, which may affect the reproducer since the YouTube ads are blocked.

Note also: SleepDisabler is currently broken due to bug #219010, but this issue is independent of that.

[Philippe Normand]

I can't reproduce this after fixing bug 219353.

[Michael Catanzaro]

One thing that changed since this bug was reported is that our adblocker no longer blocks YouTube ads. Retitling to "[GStreamer] SleepDisabler not reliably created when starting YouTube videos." Testing r279337, I see a SleepDisabler is usually not created at all nowadays, so this bug is not fixed. However, I notice it occasionally randomly does get created only for the duration of the ad. When the ad finishes, the SleepDisabler is destroyed (indicating bug #219353 is indeed fixed) but no new one gets created for the actual video.

[Michael Catanzaro]

Simple debug patch:

diff --git a/Source/WebCore/PAL/pal/system/glib/SleepDisablerGLib.cpp b/Source/WebCore/PAL/pal/system/glib/SleepDisablerGLib.cpp
index 6f922e118afd..0b1dc294539b 100644
--- a/Source/WebCore/PAL/pal/system/glib/SleepDisablerGLib.cpp
+++ b/Source/WebCore/PAL/pal/system/glib/SleepDisablerGLib.cpp
@@ -41,6 +41,7 @@ SleepDisablerGLib::SleepDisablerGLib(const char* reason, Type type)
     , m_cancellable(adoptGRef(g_cancellable_new()))
     , m_reason(reason)
 {
+WTFLogAlways("%s", __FUNCTION__);
     // We ignore Type because we always want to inhibit both screen lock and
     // suspend, but only when idle. There is no reason for WebKit to ever block
     // a user from manually suspending the computer, so inhibiting idle
@@ -96,6 +97,7 @@ SleepDisablerGLib::SleepDisablerGLib(const char* reason, Type type)
 
 SleepDisablerGLib::~SleepDisablerGLib()
 {
+WTFLogAlways("%s", __FUNCTION__);
     if (m_cancellable)
         g_cancellable_cancel(m_cancellable.get());
     else if (m_screenSaverCookie || m_inhibitPortalRequestObjectPath)

[Philippe Normand]

(In reply to Michael Catanzaro from comment #2)
> One thing that changed since this bug was reported is that our adblocker no
> longer blocks YouTube ads. Retitling to "[GStreamer] SleepDisabler not
> reliably created when starting YouTube videos." Testing r279337, I see a
> SleepDisabler is usually not created at all nowadays, so this bug is not
> fixed. However, I notice it occasionally randomly does get created only for
> the duration of the ad. When the ad finishes, the SleepDisabler is destroyed
> (indicating bug #219353 is indeed fixed) but no new one gets created for the
> actual video.

Is this with Ephy TP or ToT?
I checked ToT MiniBrowser. Cannot reproduce this.

[Michael Catanzaro]

(In reply to Philippe Normand from comment #4)
> Is this with Ephy TP or ToT?
> I checked ToT MiniBrowser. Cannot reproduce this.

This was r279337 with Epiphany, built with jhbuild.

I will try testing MiniBrowser too, though I doubt it will be any different.

[Michael Catanzaro]

The bug occurs in MiniBrowser too. Sometimes the SleepDisabler is created when the advertisement begins. Sometimes it is mysteriously created about 20 seconds after the ad already began playing. The SleepDisabler seems to never be created for normal video playback. It is only ever created for the ads, which is why I posted that link to a video with ads, because there's no SleepDisabler at all for other videos.

If created, it seems the SleepDisabler is always destroyed reliably when the ad ends, so at least I can confirm bug #219353 is now fixed.

Let's see if I can get a gst log....

[Michael Catanzaro]

(In reply to Michael Catanzaro from comment #6)
> It is only ever created for the ads,
> which is why I posted that link to a video with ads, because there's no
> SleepDisabler at all for other videos.

Um, sorry, best I can tell all youtube videos are playing ads nowadays, so I didn't post any particular link after all, then forgot to remove that sentence from my post.

Here is the video I'm testing with: https://www.youtube.com/watch?v=T8wEW5WeMxg

I hesitate to admit that I watched this far, but around 11:30 in the video, WebKit did eventually decide to create a SleepDisabler. So something is causing SleepDisabler creation to be severely delayed, but it does seem to *eventually* happen.

[Michael Catanzaro]

Created attachment 432404 [details]
gst.log (no ads and no SleepDisabler)

[Philippe Normand]

The current GStreamer player doesn't have much to do directly with this I'm afraid. We'd need to instrument the media element code:

- is updateSleepDisabling() being called?
- if so, is shouldDisableSleep() returning something different than SleepType::None?

[Michael Catanzaro]

(In reply to Philippe Normand from comment #9)
> We'd need to instrument the media element code:

No problem!

> - is updateSleepDisabling() being called?

Yes, a lot.

> - if so, is shouldDisableSleep() returning something different than
> SleepType::None?

No, it always returns SleepType::None (0 in the prints below) except once when playing the ad:

$ jhbuild run epiphany
updateSleepDisabling: m_player=(nil) 0
updateSleepDisabling: m_player=(nil) 0
updateSleepDisabling: m_player=(nil) 0
updateSleepDisabling: m_player=(nil) 0
updateSleepDisabling: m_player=0x7faf940f7910 0
updateSleepDisabling: m_player=0x7faf940f7bc8 0
updateSleepDisabling: m_player=(nil) 0
updateSleepDisabling: m_player=(nil) 0
updateSleepDisabling: m_player=0x7faf9015acb0 0
updateSleepDisabling: m_player=(nil) 0
updateSleepDisabling: m_player=(nil) 0
updateSleepDisabling: m_player=0x7faf98d541d0 0
updateSleepDisabling: m_player=0x7faf98d542b8 0
updateSleepDisabling: m_player=0x7faf98d542b8 0
updateSleepDisabling: m_player=0x7faf98d542b8 0
updateSleepDisabling: m_player=0x7faf98d542b8 0
updateSleepDisabling: m_player=0x7faf5894cd98 0
updateSleepDisabling: m_player=0x7faf57777000 0
updateSleepDisabling: m_player=(nil) 0
updateSleepDisabling: m_player=(nil) 0
updateSleepDisabling: m_player=0x7faf57777570 0
updateSleepDisabling: m_player=0x7faf57777658 0
updateSleepDisabling: m_player=0x7faf57777658 0
updateSleepDisabling: m_player=0x7faf57777658 0
updateSleepDisabling: m_player=0x7faf57777658 0
updateSleepDisabling: m_player=0x7faf57777658 0
updateSleepDisabling: m_player=0x7faf57777658 0
SleepDisablerGLib
updateSleepDisabling: m_player=0x7faf57777658 1
~SleepDisablerGLib
updateSleepDisabling: m_player=0x7faf577771d0 0
updateSleepDisabling: m_player=(nil) 0
updateSleepDisabling: m_player=(nil) 0
updateSleepDisabling: m_player=0x7faf577772b8 0
updateSleepDisabling: m_player=0x7faf57777658 0
updateSleepDisabling: m_player=0x7faf57777658 0
updateSleepDisabling: m_player=0x7faf57777658 0
updateSleepDisabling: m_player=0x7faf57777658 0
updateSleepDisabling: m_player=(nil) 0
updateSleepDisabling: m_player=(nil) 0

Note that m_player changing to NULL during video playback seems weird. We had another bug report for that, but I can't find it anymore.

I added even more debug in shouldDisableSleep, on all the codepaths that return SleepType::None:

shouldDisableSleep: m_sentEvent=0 m_player=(nil) m_player->paused=0 loop()=0
updateSleepDisabling: m_player=(nil) 0
shouldDisableSleep: m_sentEvent=0 m_player=(nil) m_player->paused=0 loop()=0
updateSleepDisabling: m_player=(nil) 0
shouldDisableSleep: m_sentEvent=0 m_player=(nil) m_player->paused=0 loop()=0
updateSleepDisabling: m_player=(nil) 0
shouldDisableSleep: m_sentEvent=0 m_player=(nil) m_player->paused=0 loop()=0
updateSleepDisabling: m_player=(nil) 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f811efd2910 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f811efd2910 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f811efd2bc8 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f811efd2bc8 0
shouldDisableSleep: m_sentEvent=0 m_player=(nil) m_player->paused=0 loop()=0
updateSleepDisabling: m_player=(nil) 0
shouldDisableSleep: m_sentEvent=0 m_player=(nil) m_player->paused=0 loop()=0
updateSleepDisabling: m_player=(nil) 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f811b22dae0 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f811b22dae0 0
shouldDisableSleep: m_sentEvent=0 m_player=(nil) m_player->paused=0 loop()=0
updateSleepDisabling: m_player=(nil) 0
shouldDisableSleep: m_sentEvent=0 m_player=(nil) m_player->paused=0 loop()=0
updateSleepDisabling: m_player=(nil) 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f811b22de80 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f811b22de80 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f811e21d000 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f811e21d000 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f811e21d000 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f811e21d000 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f811e21d000 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f811e21d000 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f811e21d000 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f811e21d000 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f811e21d000 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f811e21d000 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f811e21d000 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f811e21d000 0
SleepDisablerGLib
updateSleepDisabling: m_player=0x7f811e21d000 1
shouldDisableSleep: m_sentEvent=0 m_player=0x7f80e91c5570 m_player->paused=1 loop()=0
~SleepDisablerGLib
updateSleepDisabling: m_player=0x7f80e91c5570 0
shouldDisableSleep: m_sentEvent=0 m_player=(nil) m_player->paused=0 loop()=0
updateSleepDisabling: m_player=(nil) 0
shouldDisableSleep: m_sentEvent=0 m_player=(nil) m_player->paused=0 loop()=0
updateSleepDisabling: m_player=(nil) 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f80ea525cb0 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f80ea525cb0 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f80ea525d98 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f80ea525d98 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f80ea525d98 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f80ea525d98 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f80ea525d98 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f80ea525d98 0
shouldDisableSleep: m_sentEvent=0 m_player=0x7f80ea525d98 m_player->paused=1 loop()=0
updateSleepDisabling: m_player=0x7f80ea525d98 0
shouldDisableSleep: m_sentEvent=0 m_player=(nil) m_player->paused=0 loop()=0
updateSleepDisabling: m_player=(nil) 0
shouldDisableSleep: m_sentEvent=0 m_player=(nil) m_player->paused=0 loop()=0
updateSleepDisabling: m_player=(nil) 0

Clearly the problem is that m_player=(nil) when MSE is enabled, which is really weird. That's why the check fails. I thought we had another old bug for this, but I can't find it. I see I mentioned this same problem in bug #192530 though, so that's proof that it's not a new surprise.

[Michael Catanzaro]

> I see I mentioned this same problem in bug #192530 though, so that's proof that it's not a new surprise.

Wrong again, the problem I mentioned there is that updateSleepDisabling was not being called. Now we can see in the prints above that is is being called. So question is why is m_player valid when the video is initially paused, then destroyed later when the video is playing?

[Philippe Normand]

Very weird! If m_player is null there's no MediaPlayerPrivate and you're dealing with a ghost media element... I'm not sure what's going on there.

[Michael Catanzaro]

Hm, maybe that's not too surprising actually, because I didn't print out the value of "this". It could be that the current media player is the 0x7f80ea525d98 and all we're seeing below that is the older media player becoming stale. If so, then this would likely be identical to bug #192530.

[Michael Catanzaro]

(In reply to Michael Catanzaro from comment #13)
> Hm, maybe that's not too surprising actually, because I didn't print out the
> value of "this". It could be that the current media player is the
> 0x7f80ea525d98 and all we're seeing below that is the older media player
> becoming stale.

Yes, that explains it:

$ jhbuild run epiphany
HTMLMediaElement: this=0x7fa36b25f9d0
updateSleepDisabling: this=0x7fa36b25f9d0 m_player=(nil) shouldDisableSleep=0
HTMLMediaElement: this=0x7fa36ae0c3d0
updateSleepDisabling: this=0x7fa36b25f9d0 m_player=(nil) shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=(nil) shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36b25f9d0 m_player=(nil) shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa35f7a09f8 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa35f7a0cb0 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36b25f9d0 m_player=(nil) shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36b25f9d0 m_player=(nil) shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa35b046d98 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36b25f9d0 m_player=(nil) shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36b25f9d0 m_player=(nil) shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa3676a71d0 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa3676a72b8 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa3676a72b8 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa3676a72b8 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa3676a72b8 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa3676a72b8 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa320c5d658 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36b25f9d0 m_player=(nil) shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36b25f9d0 m_player=(nil) shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa320c5d910 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa320c5d9f8 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa320c5d9f8 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa320c5d9f8 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36ae0c3d0 m_player=0x7fa320c5d9f8 shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36b25f9d0 m_player=(nil) shouldDisableSleep=0
updateSleepDisabling: this=0x7fa36b25f9d0 m_player=(nil) shouldDisableSleep=0

Now we can see there are two HTMLMediaElements. 0x7fa36ae0c3d0 is presumably the "real" player for the actual video. 0x7fa36b25f9d0 never actually had any m_player, at least not during any of the calls to HTMLMediaElement::updateSleepDisabling.

Interestingly, I added prints in their destructors as well, but they didn't print, so the HTMLMediaElements are both leaked! Shame.

[Michael Catanzaro]

Anyway my guess is this is exactly bug #192530. The video is actually playing, but m_player is paused for some reason.

[Paul Bryan]

I'm seeing not-disabling-sleep behaviour with other video sites (e.g. Nebula). Is this the issue, or should I file a different one?

[Michael Catanzaro]

It's very probably this issue. No need to report a new bug.

[Philippe Normand]

Pull request: https://github.com/WebKit/WebKit/pull/28770

[EWS]

Committed 279943@main (6a650e644b1c): <https://commits.webkit.org/279943@main>

Reviewed commits have been landed. Closing PR #28770 and removing active labels.