| Summary: | [GStreamer] SleepDisabler not reliably created when playing YouTube videos, may be created long after video playback starts. HTMLMediaElement::m_player is unexpectedly nullptr! | ||||||
|---|---|---|---|---|---|---|---|
| Product: | WebKit | Reporter: | Michael Catanzaro <mcatanzaro> | ||||
| Component: | Media | Assignee: | Nobody <webkit-unassigned> | ||||
| Status: | NEW --- | ||||||
| Severity: | Normal | CC: | bugs-noreply, mcatanzaro, pbryan, pnormand | ||||
| Priority: | P2 | Keywords: | DoNotImportToRadar | ||||
| Version: | WebKit Nightly Build | ||||||
| Hardware: | PC | ||||||
| OS: | Linux | ||||||
| See Also: |
https://bugs.webkit.org/show_bug.cgi?id=186971 https://bugs.webkit.org/show_bug.cgi?id=219355 https://bugs.webkit.org/show_bug.cgi?id=219353 https://bugs.webkit.org/show_bug.cgi?id=192530 |
||||||
| Attachments: |
|
||||||
|
Description
Michael Catanzaro
2020-11-30 06:48:38 PST
I can't reproduce this after fixing bug 219353. 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. 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)
(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. (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. 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.... (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. Created attachment 432404 [details]
gst.log (no ads and no SleepDisabler)
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? (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. > 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?
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. 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. (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. Anyway my guess is this is exactly bug #192530. The video is actually playing, but m_player is paused for some reason. 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? It's very probably this issue. No need to report a new bug. |