search

anxdpanic / plugin.video.twitch

Watch your favorite gaming streams on Kodi
https://twitchaddon.page.link/forum
270 stars 79 forks source link

New embedded ad delivery causes black screen of death #439

Closed fragande closed 5 years ago

fragande commented 5 years ago

Twitch recently launched a new ad delivery system which seems to inject ads into the HLS stream. They are calling it SureStream. The problem is that this seems to break the add-on, as every time an ad is supposed to play the screen goes black and stays that way. One or two times an ad has actually played, but screen stays black after. I have not yet been able to capture an instance of this in the log as I've just enabled full logging, will update the post when I do (if there's anything of value in it).

The issue doesn't seem to be with the HLS stream itself as it works fine using Streamlink (the ad plays and stream continues after).

EDIT: Seems like segments are marked as advertisements with SCTE-35 flags (whatever that means...). Could it be that some component of the add-on can't handle these segments properly?

EDIT2: This is what kodi.log looks like when this happens:

06:34:35.659 T:1226285984   DEBUG: AddOnLog: InputStream Adaptive: Download https://video-edge-3457d8.cph01.abs.hls.ttvnw.net/v1/segment/CugDaK(...).ts finished, average download speed: 2481669.0000
06:34:35.660 T:1268229024   DEBUG: CurlFile::ParseAndCorrectUrl() adding custom header option 'Authorization: ***********'
06:34:35.660 T:1268229024   DEBUG: CurlFile::ParseAndCorrectUrl() ignoring header option 'Client-ID: 67ebpfhyoicab5kr0y7pzocsfohs7ty'
06:34:35.660 T:1268229024   DEBUG: CurlFile::Open(0x3d4dba8) https://video-weaver.cph01.hls.ttvnw.net/v1/playlist/CtsDPEK2(...).m3u8 finished
06:34:35.680 T:1226285984   DEBUG: CurlFile::ParseAndCorrectUrl() adding custom header option 'Connection: keep-alive'
06:34:35.680 T:1226285984   DEBUG: CurlFile::Open(0x52778570) https://video-edge-3457d8.cph01.abs.hls.ttvnw.net/v1/segment/CugDAMM(...).ts
06:34:36.091 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:34:36.235 T:1226285984   DEBUG: AddOnLog: InputStream Adaptive: Download https://video-edge-3457d8.cph01.abs.hls.ttvnw.net/v1/segment/CugDAMM(...).ts finished, average download speed: 2418888.0000
06:34:36.429 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:34:36.608 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:34:38.440 T:1243063200 WARNING: Previous line repeats 3 times.
06:34:38.440 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:34:38.658 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:34:40.451 T:1243063200 WARNING: Previous line repeats 3 times.
06:34:40.451 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:34:40.741 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:34:42.461 T:1243063200 WARNING: Previous line repeats 3 times.
06:34:42.461 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:34:42.808 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:34:44.472 T:1243063200 WARNING: Previous line repeats 3 times.
06:34:44.472 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:34:44.858 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:34:46.483 T:1243063200 WARNING: Previous line repeats 3 times.
06:34:46.483 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:34:46.941 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:34:48.494 T:1243063200 WARNING: Previous line repeats 2 times.
06:34:48.494 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:34:48.509 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:34:50.504 T:1243063200 WARNING: Previous line repeats 3 times.
06:34:50.504 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:34:50.575 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:34:52.515 T:1243063200 WARNING: Previous line repeats 3 times.
06:34:52.515 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:34:52.625 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:34:54.526 T:1243063200 WARNING: Previous line repeats 3 times.
06:34:54.526 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:34:54.725 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:34:56.536 T:1243063200 WARNING: Previous line repeats 3 times.
06:34:56.536 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:34:56.791 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:34:58.547 T:1243063200 WARNING: Previous line repeats 3 times.
06:34:58.547 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:34:58.841 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:00.558 T:1243063200 WARNING: Previous line repeats 3 times.
06:35:00.558 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:00.941 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:02.568 T:1243063200 WARNING: Previous line repeats 3 times.
06:35:02.569 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:02.991 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:04.579 T:1243063200 WARNING: Previous line repeats 3 times.
06:35:04.579 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:05.041 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:05.793 T:1944871024 WARNING: Previous line repeats 1 times.
06:35:05.793 T:1944871024    INFO: CheckIdle - Closing session to https://video-weaver.cph01.hls.ttvnw.net (easy=0x55e93ec8, multi=0x667c17f0)
06:35:06.074 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:06.309 T:1944871024    INFO: CheckIdle - Closing session to https://video-edge-3457d8.cph01.abs.hls.ttvnw.net (easy=0x56f8f928, multi=0x54b58280)
06:35:06.574 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:06.590 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:06.805 T:1583346592   DEBUG: [plugin.video.youtube] HTTPServer: Request uri path |/ping|
06:35:06.805 T:1583346592   DEBUG: [plugin.video.youtube] HTTPServer: Connection from |127.0.| Local range: |True|
06:35:06.811 T:1815081888   DEBUG: [plugin.video.youtube] HTTPServer: Ping |127.0.0.1:50152| |204|
06:35:07.124 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:08.600 T:1243063200 WARNING: Previous line repeats 2 times.
06:35:08.600 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:08.674 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:10.611 T:1243063200 WARNING: Previous line repeats 3 times.
06:35:10.611 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:10.741 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:12.622 T:1243063200 WARNING: Previous line repeats 3 times.
06:35:12.622 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:12.791 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:14.632 T:1243063200 WARNING: Previous line repeats 3 times.
06:35:14.632 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:14.874 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:16.643 T:1243063200 WARNING: Previous line repeats 3 times.
06:35:16.643 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:16.941 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:18.654 T:1243063200 WARNING: Previous line repeats 3 times.
06:35:18.654 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:18.991 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:20.664 T:1243063200 WARNING: Previous line repeats 3 times.
06:35:20.664 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:21.074 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:22.675 T:1243063200 WARNING: Previous line repeats 3 times.
06:35:22.675 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:23.141 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:24.686 T:1243063200 WARNING: Previous line repeats 2 times.
06:35:24.686 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:24.691 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:26.696 T:1243063200 WARNING: Previous line repeats 3 times.
06:35:26.697 T:1243063200   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
06:35:26.741 T:1361048480 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
06:35:28.707 T:1243063200 WARNING: Previous line repeats 3 times.

And more of the same message until I press the stop button. Don't know if inputstream.adative is to "blame" for this or not. Currently logging with it turned off.

EDIT3: Yes, it does seem like the problem lies with inputstream.adaptive. Turning it off results in the ad playing normally and the stream resuming afterwards. Now the question is if inputstream.adaptive is the culprit in itself or if there's a problem with the way the Twitch add-on is interacting with it.

anxdpanic commented 5 years ago

I am only experiencing it with InputStream Adaptive as well, do you know of any channels where I might experience this more often than others?

fragande commented 5 years ago

I am only experiencing it with InputStream Adaptive as well, do you know of any channels where I might experience this more often than others?

Not really, but I'm getting an ad immediately every time I'm opening a (partnered I'm guessing) stream when enough time has passed. There seems to be a time-since-last-ad-check, I'm guessing 15-30 min. After the initial ad it seems like it's up to the streamer to play ads or not, I'm not getting random ones I don't think. One of Twitch's own channels like Twitchpresents or Twitchrivals are probably a safe bet. Let me know if there's something I can assist with, like specific logging or similar.

fragande commented 5 years ago

A clue, maybe, from the streamlink GitHub page:

In the HLS stream, the start and end of an ad sequence is annotated with the #EXT-X-DISCONTINUITY tag. This is meant for telling the player to reset its decoding/rendering state. That does of course only work if a player is reading the HLS stream directly and implements it correctly.

I don't know anything about how inputstream.adaptive actually works, but my impression is that it's an "extra layer" between the player and stream content. Maybe this explains why the ad isn't handled properly with it enabled but works fine when the stream is passed directly to the Kodi video player. Just guessing though.

anxdpanic commented 5 years ago

I did some quick tests and seem to have at least temporarily resolved the issue. From streamlink I notice they also found that changing the platform to _ worked, but that doesn't seem to be the case anymore. However changing the platform to ps4 changes server_ads from true to false in the token, and I haven't seen any ads since.

fragande commented 5 years ago

From initial (limited) testing it seems to work, I have not seen an ad yet. As it seems Twitch are hellbent on injecting these ads on all platforms now I'm guessing this will be patched as the platform="_" was, but for the time being this seems like a possible workaround.

Would it be possible to simply ignore the segments between the #EXT-X-DISCONTINUITY markers (resulting in a blank screen or stuck on last frame) or would this cause all sorts of other problems?

anxdpanic commented 5 years ago

From what I was reading, ignoring segments between #EXT-X-DISCONTINUITY would cause a pause on the last frame or similar until ad was over(as the segments for the stream during that time are replaced by the ad), would also have to be done in InputStream Adaptive.

I don't expect ignoring segments between #EXT-X-DISCONTINUITY would be accepted for InputStream Adaptive, but I will try to get the black screen reported so it can be resolved for the future.

fragande commented 5 years ago

I see. Well this workaround is very appreciated for the time being. Thank you very much for your efforts.

cmsimike commented 5 years ago

Thank you! I will try this tonight.

anxdpanic commented 5 years ago

I've updated the beta zip, https://github.com/MrSprigster/Twitch-on-Kodi/releases/tag/2.4.3-dev

cmsimike commented 5 years ago

Sadly I didn't get a chance to try this out last night but I will re-double my efforts tonight. As always, thank you @anxdpanic !

regseb commented 5 years ago

@anxdpanic I tested plugin.video.twitch-2.4.4.3.3.beta2 on Kodi 17.6 (OSMC 2018.12-1) and it works. Thank you.

cmsimike commented 5 years ago

Looks good over here!

anxdpanic commented 5 years ago

Thanks for confirming 👍 Closed by 87bb915ee6b2dd46f37b60c77f49f4b592623eef