Youtube stream stalls on buffering with sendtokodi

First of all, big thanks to the team for the amazing work you’ve been doing with RPi4. This works great (and by the way much better than LibreElec that tends to send CPU to overheating).

I have been facing an issue - very easy to reproduce - that I was not able to solve with a deep web search so submitting here for help. I have been using sendtokodi addon with stream sources like arte.tv and it works like a charm. Each and every time I want to use it with youtube.com instead, it launches the stream and immediately stalls on the first few frames showing ‘Buffering…’ on the screen. You’ll find below two logs excerpts the first one with arte.tv (which works) and the same one with youtube.com (which stalls). Any help welcome.

Thank you

RPI4, MOST CURRENT VERSION OF EVERYTHING, FRESH BOOT

FIRST LOG | ARTE.TV | WORKS FINE
2021-12-23 21:34:18.829 T:3416 INFO : initializing python engine.
2021-12-23 21:34:19.058 T:877 INFO : Python interpreter stopped
2021-12-23 21:34:21.022 T:469 INFO : Skipped 9 duplicate messages…
2021-12-23 21:34:21.022 T:469 INFO : CActiveAESink::OpenSink - initialize sink
2021-12-23 21:34:21.022 T:469 INFO : CAESinkALSA::Initialize - Attempting to open device “@”
2021-12-23 21:34:21.026 T:469 INFO : CAESinkALSA::Initialize - Opened device “sysdefault”
2021-12-23 21:34:21.028 T:469 INFO : CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2021-12-23 21:34:21.028 T:469 INFO : CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE3
2021-12-23 21:34:26.238 T:3416 INFO : CPythonInvoker(8, /home/osmc/.kodi/addons/plugin.video.sendtokodi/service.py): script successful
ly run
2021-12-23 21:34:26.250 T:488 INFO : JSONRPC Server: New connection added
2021-12-23 21:34:26.468 T:3416 INFO : Python interpreter stopped
2021-12-23 21:34:26.529 T:423 INFO : VideoPlayer::OpenFile: plugin://plugin.video.sendtokodi/?https://www.arte.tv/en/videos/083921-00
0-A/crime-in-the-kremlin/ {“ydlOpts”:{}}
2021-12-23 21:34:26.585 T:3419 INFO : Creating InputStream
2021-12-23 21:34:27.026 T:3419 INFO : Creating Demuxer
2021-12-23 21:34:28.798 T:3419 INFO : Opening stream: 0 source: 256
2021-12-23 21:34:28.798 T:3419 INFO : [WHITELIST] Searching the whitelist for: width: 1280, height: 720, fps: 25.000, 3D: false
2021-12-23 21:34:28.798 T:3419 ERROR : ** T99 ** 1280/720 vs. 1920/1080 - 25.000000 vs. 50.000000, flags: 0x0
2021-12-23 21:34:28.798 T:3419 ERROR : ** T99 ** 1280/720 vs. 1920/1080 - 25.000000 vs. 59.940063, flags: 0x0
2021-12-23 21:34:28.798 T:3419 ERROR : ** T99 ** 1280/720 vs. 1920/1080 - 25.000000 vs. 60.000000, flags: 0x0
2021-12-23 21:34:28.799 T:3419 INFO : Skipped 1 duplicate messages…
2021-12-23 21:34:28.799 T:3419 INFO : Display resolution ADJUST : 1920x1080 @ 50.000000 Hz (21) (weight: 0.000)
2021-12-23 21:34:28.804 T:423 INFO : VideoPlayer: OnLostDisplay received
2021-12-23 21:34:28.804 T:423 WARNING : CDVDMessageQueue(audio)::Put MSGQ_NOT_INITIALIZED
2021-12-23 21:34:28.804 T:423 WARNING : CDVDMessageQueue(video)::Put MSGQ_NOT_INITIALIZED
2021-12-23 21:34:28.805 T:423 INFO : GLES: Maximum texture width: 4096
2021-12-23 21:34:28.806 T:3419 INFO : Creating video codec with codec id: 27
2021-12-23 21:34:28.806 T:3419 INFO : CDVDVideoCodecDRMPRIME::Open - using decoder V4L2 mem2mem H.264 decoder wrapper
2021-12-23 21:34:28.821 T:3419 INFO : Creating video thread
2021-12-23 21:34:28.822 T:3422 INFO : running thread: video_thread
2021-12-23 21:34:28.822 T:3419 INFO : Opening stream: 1 source: 256
2021-12-23 21:34:28.822 T:3419 INFO : Finding audio codec for: 86018
2021-12-23 21:34:28.824 T:3419 INFO : CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-12-23 21:34:28.824 T:3419 INFO : Creating audio thread
2021-12-23 21:34:28.824 T:3423 INFO : running thread: CVideoPlayerAudio::Process()
2021-12-23 21:34:28.866 T:423 INFO : VideoPlayer: OnResetDisplay received
2021-12-23 21:34:28.877 T:3423 INFO : CVideoPlayerAudio: display reset occurred, checking for passthrough
2021-12-23 21:34:28.879 T:3423 INFO : CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-12-23 21:34:28.879 T:3423 INFO : Creating audio stream (codec id: 86018, channels: 2, sample rate: 48000, no pass-through)
2021-12-23 21:34:28.882 T:469 INFO : CActiveAESink::OpenSink - initialize sink
2021-12-23 21:34:29.081 T:469 INFO : CAESinkALSA::Initialize - Attempting to open device “Default”
2021-12-23 21:34:29.082 T:469 INFO : CAESinkALSA - Unable to open device “Default” for playback
2021-12-23 21:34:29.082 T:469 ERROR : CAESinkALSA::Initialize - failed to initialize device “Default”
2021-12-23 21:34:29.082 T:469 INFO : CAESinkALSA::Initialize - Attempting to open device “@”
2021-12-23 21:34:29.086 T:469 INFO : CAESinkALSA::Initialize - Opened device “sysdefault”
2021-12-23 21:34:29.088 T:469 INFO : CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2021-12-23 21:34:29.088 T:469 INFO : CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE3
2021-12-23 21:34:29.172 T:423 INFO : [WHITELIST] Searching the whitelist for: width: 1280, height: 720, fps: 25.000, 3D: false
2021-12-23 21:34:29.172 T:423 ERROR : ** T99 ** 1280/720 vs. 1920/1080 - 25.000000 vs. 50.000000, flags: 0x0
2021-12-23 21:34:29.172 T:423 ERROR : ** T99 ** 1280/720 vs. 1920/1080 - 25.000000 vs. 59.940063, flags: 0x0
2021-12-23 21:34:29.172 T:423 ERROR : ** T99 ** 1280/720 vs. 1920/1080 - 25.000000 vs. 60.000000, flags: 0x0
2021-12-23 21:34:29.173 T:423 INFO : Skipped 1 duplicate messages…
2021-12-23 21:34:29.173 T:423 INFO : Display resolution ADJUST : 1920x1080 @ 50.000000 Hz (21) (weight: 0.000)
2021-12-23 21:34:34.228 T:423 ERROR : Control 511 in window 10025 has been asked to focus, but it can’t
2021-12-23 21:34:34.229 T:423 INFO : CVideoPlayer::CloseFile()
2021-12-23 21:34:34.229 T:423 INFO : VideoPlayer: waiting for threads to exit
2021-12-23 21:34:34.236 T:3419 INFO : CVideoPlayer::OnExit()
2021-12-23 21:34:34.236 T:3419 INFO : Closing stream player 1
2021-12-23 21:34:34.236 T:3419 INFO : Waiting for audio thread to exit
2021-12-23 21:34:34.242 T:3423 INFO : thread end: CVideoPlayerAudio::OnExit()
2021-12-23 21:34:34.242 T:3419 INFO : Closing audio device
2021-12-23 21:34:34.292 T:3419 INFO : Deleting audio codec
2021-12-23 21:34:34.292 T:469 INFO : CActiveAESink::OpenSink - initialize sink
2021-12-23 21:34:34.293 T:3419 INFO : Closing stream player 2
2021-12-23 21:34:34.293 T:3419 INFO : waiting for video thread to exit
2021-12-23 21:34:34.316 T:3422 WARNING : OutputPicture - timeout waiting for buffer
2021-12-23 21:34:34.316 T:3422 INFO : thread end: video_thread
2021-12-23 21:34:34.316 T:3419 INFO : deleting video codec
2021-12-23 21:34:34.328 T:3420 INFO : Deleting settings information for files plugin://plugin.video.sendtokodi/?https://www.arte.tv/en/videos/083921-000-A/crime-in-the-kremlin/ {“ydlOpts”:{}}
2021-12-23 21:34:34.334 T:423 INFO : VideoPlayer: finished waiting
2021-12-23 21:34:34.334 T:423 INFO : CVideoPlayer::CloseFile()
2021-12-23 21:34:34.334 T:423 INFO : VideoPlayer: waiting for threads to exit
2021-12-23 21:34:34.334 T:423 INFO : VideoPlayer: finished waiting
2021-12-23 21:34:34.373 T:3428 INFO : initializing python engine.
2021-12-23 21:34:34.468 T:423 INFO : GLES: Maximum texture width: 4096
2021-12-23 21:34:34.491 T:469 INFO : CAESinkALSA::Initialize - Attempting to open device “Default”
2021-12-23 21:34:34.492 T:469 INFO : CAESinkALSA - Unable to open device “Default” for playback
2021-12-23 21:34:34.492 T:469 ERROR : CAESinkALSA::Initialize - failed to initialize device “Default”
2021-12-23 21:34:34.493 T:469 INFO : CAESinkALSA::Initialize - Attempting to open device “@”
2021-12-23 21:34:34.497 T:469 INFO : CAESinkALSA::Initialize - Opened device “sysdefault”
2021-12-23 21:34:34.499 T:469 INFO : CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2021-12-23 21:34:34.499 T:469 INFO : CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE3
2021-12-23 21:34:34.895 T:3428 INFO : [plugin.video.netflix (7)] The debug logging is set as DISABLED
2021-12-23 21:34:35.347 T:488 INFO : JSONRPC Server: Disconnection detected
2021-12-23 21:34:36.449 T:3428 INFO : CPythonInvoker(9, /home/osmc/.kodi/addons/plugin.video.netflix/addon.py): script successfully run
END OF FIRST LOG

SECOND LOG | YOUTUBE.COM | STALLS AFTER THE FIRST FEW FRAMES
2021-12-23 21:34:57.778 T:3437 INFO : initializing python engine.
2021-12-23 21:34:58.088 T:3428 INFO : Python interpreter stopped
2021-12-23 21:35:03.062 T:3437 INFO : CPythonInvoker(10, /home/osmc/.kodi/addons/plugin.video.sendtokodi/service.py): script successfully run
2021-12-23 21:35:03.291 T:423 INFO : VideoPlayer::OpenFile: plugin://plugin.video.sendtokodi/?François Villeroy de Galhau (Banque de France): Inflation, croissance, la BCE encore crédible ? - YouTube {“ydlOpts”:{}}
2021-12-23 21:35:03.299 T:3437 INFO : Python interpreter stopped
2021-12-23 21:35:03.452 T:3439 INFO : Creating InputStream
2021-12-23 21:35:03.897 T:3439 INFO : Creating Demuxer
2021-12-23 21:35:04.221 T:488 INFO : JSONRPC Server: New connection added
2021-12-23 21:35:09.228 T:3439 INFO : Opening stream: 0 source: 256
2021-12-23 21:35:09.228 T:3439 INFO : [WHITELIST] Searching the whitelist for: width: 1280, height: 720, fps: 25.000, 3D: false
2021-12-23 21:35:09.229 T:3439 ERROR : ** T99 ** 1280/720 vs. 1920/1080 - 25.000000 vs. 50.000000, flags: 0x0
2021-12-23 21:35:09.229 T:3439 ERROR : ** T99 ** 1280/720 vs. 1920/1080 - 25.000000 vs. 59.940063, flags: 0x0
2021-12-23 21:35:09.229 T:3439 ERROR : ** T99 ** 1280/720 vs. 1920/1080 - 25.000000 vs. 60.000000, flags: 0x0
2021-12-23 21:35:09.230 T:3439 INFO : Skipped 1 duplicate messages…
2021-12-23 21:35:09.230 T:3439 INFO : Display resolution ADJUST : 1920x1080 @ 50.000000 Hz (21) (weight: 0.000)
2021-12-23 21:35:09.261 T:423 INFO : VideoPlayer: OnLostDisplay received
2021-12-23 21:35:09.262 T:423 WARNING : CDVDMessageQueue(audio)::Put MSGQ_NOT_INITIALIZED
2021-12-23 21:35:09.262 T:423 WARNING : CDVDMessageQueue(video)::Put MSGQ_NOT_INITIALIZED
2021-12-23 21:35:09.262 T:423 INFO : GLES: Maximum texture width: 4096
2021-12-23 21:35:09.264 T:3439 INFO : Creating video codec with codec id: 27
2021-12-23 21:35:09.264 T:3439 INFO : CDVDVideoCodecDRMPRIME::Open - using decoder V4L2 mem2mem H.264 decoder wrapper
2021-12-23 21:35:09.279 T:3439 INFO : Creating video thread
2021-12-23 21:35:09.279 T:3441 INFO : running thread: video_thread
2021-12-23 21:35:09.281 T:3439 INFO : Opening stream: 1 source: 256
2021-12-23 21:35:09.281 T:3439 INFO : Finding audio codec for: 86018
2021-12-23 21:35:09.281 T:3439 INFO : CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-12-23 21:35:09.281 T:3439 INFO : Creating audio thread
2021-12-23 21:35:09.282 T:3442 INFO : running thread: CVideoPlayerAudio::Process()
2021-12-23 21:35:09.324 T:423 INFO : VideoPlayer: OnResetDisplay received
2021-12-23 21:35:09.336 T:3442 INFO : CVideoPlayerAudio: display reset occurred, checking for passthrough
2021-12-23 21:35:09.337 T:3442 INFO : CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-12-23 21:35:09.338 T:3442 INFO : Creating audio stream (codec id: 86018, channels: 2, sample rate: 44100, no pass-through)
2021-12-23 21:35:09.353 T:469 INFO : CActiveAESink::OpenSink - initialize sink
2021-12-23 21:35:09.552 T:469 INFO : CAESinkALSA::Initialize - Attempting to open device “Default”
2021-12-23 21:35:09.554 T:469 INFO : CAESinkALSA - Unable to open device “Default” for playback
2021-12-23 21:35:09.555 T:469 ERROR : CAESinkALSA::Initialize - failed to initialize device “Default”
2021-12-23 21:35:09.555 T:469 INFO : CAESinkALSA::Initialize - Attempting to open device “@”
2021-12-23 21:35:09.559 T:469 INFO : CAESinkALSA::Initialize - Opened device “sysdefault”
2021-12-23 21:35:09.561 T:469 INFO : CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2021-12-23 21:35:09.561 T:469 INFO : CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE3
2021-12-23 21:35:09.916 T:423 INFO : [WHITELIST] Searching the whitelist for: width: 1280, height: 720, fps: 25.000, 3D: false
2021-12-23 21:35:09.916 T:423 ERROR : ** T99 ** 1280/720 vs. 1920/1080 - 25.000000 vs. 50.000000, flags: 0x0
2021-12-23 21:35:09.916 T:423 ERROR : ** T99 ** 1280/720 vs. 1920/1080 - 25.000000 vs. 59.940063, flags: 0x0
2021-12-23 21:35:09.917 T:423 ERROR : ** T99 ** 1280/720 vs. 1920/1080 - 25.000000 vs. 60.000000, flags: 0x0
2021-12-23 21:35:09.917 T:423 INFO : Skipped 1 duplicate messages…
2021-12-23 21:35:09.917 T:423 INFO : Display resolution ADJUST : 1920x1080 @ 50.000000 Hz (21) (weight: 0.000)
2021-12-23 21:35:11.835 T:468 WARNING : ActiveAE - large audio sync error: -1042.222607
2021-12-23 21:35:12.398 T:468 WARNING : ActiveAE - large audio sync error: -1092.138322
2021-12-23 21:35:12.402 T:468 WARNING : ActiveAE - large audio sync error: -1092.138229
2021-12-23 21:35:12.402 T:468 WARNING : ActiveAE - large audio sync error: -1092.137414
2021-12-23 21:35:12.403 T:468 WARNING : ActiveAE - large audio sync error: -1092.137507
2021-12-23 21:35:12.465 T:468 WARNING : ActiveAE - large audio sync error: -1142.201042
2021-12-23 21:35:12.515 T:468 WARNING : ActiveAE - large audio sync error: -1142.253977
2021-12-23 21:35:12.565 T:468 WARNING : ActiveAE - large audio sync error: -1142.155191
2021-12-23 21:35:12.615 T:468 WARNING : ActiveAE - large audio sync error: -1142.201865
2021-12-23 21:35:12.665 T:468 WARNING : ActiveAE - large audio sync error: -1142.199098
2021-12-23 21:35:12.715 T:468 WARNING : ActiveAE - large audio sync error: -1142.265050
2021-12-23 21:35:12.765 T:468 WARNING : ActiveAE - large audio sync error: -1142.160636
2021-12-23 21:35:12.815 T:468 WARNING : ActiveAE - large audio sync error: -1142.215496
2021-12-23 21:35:12.914 T:3442 INFO : CVideoPlayerAudio::Process - stream stalled
2021-12-23 21:35:17.426 T:423 ERROR : Control 511 in window 10025 has been asked to focus, but it can’t
2021-12-23 21:35:17.427 T:423 INFO : CVideoPlayer::CloseFile()
2021-12-23 21:35:17.428 T:423 INFO : VideoPlayer: waiting for threads to exit
2021-12-23 21:35:17.654 T:3439 INFO : CVideoPlayer::OnExit()
2021-12-23 21:35:17.654 T:3439 INFO : Closing stream player 1
2021-12-23 21:35:17.654 T:3439 INFO : Waiting for audio thread to exit
2021-12-23 21:35:17.654 T:3442 INFO : thread end: CVideoPlayerAudio::OnExit()
2021-12-23 21:35:17.654 T:3439 INFO : Closing audio device
2021-12-23 21:35:17.665 T:3439 INFO : Deleting audio codec
2021-12-23 21:35:17.666 T:3439 INFO : Closing stream player 2
2021-12-23 21:35:17.666 T:3439 INFO : waiting for video thread to exit
2021-12-23 21:35:17.712 T:3441 INFO : thread end: video_thread
2021-12-23 21:35:17.713 T:3439 INFO : deleting video codec
2021-12-23 21:35:17.715 T:469 INFO : CActiveAESink::OpenSink - initialize sink
2021-12-23 21:35:17.728 T:3420 INFO : Deleting settings information for files plugin://plugin.video.sendtokodi/?François Villeroy de Galhau (Banque de France): Inflation, croissance, la BCE encore crédible ? - YouTube {“ydlOpts”:{}}
2021-12-23 21:35:17.915 T:469 INFO : CAESinkALSA::Initialize - Attempting to open device “Default”
2021-12-23 21:35:17.916 T:469 INFO : CAESinkALSA - Unable to open device “Default” for playback
2021-12-23 21:35:17.916 T:469 ERROR : CAESinkALSA::Initialize - failed to initialize device “Default”
2021-12-23 21:35:17.916 T:469 INFO : CAESinkALSA::Initialize - Attempting to open device “@”
2021-12-23 21:35:17.920 T:469 INFO : CAESinkALSA::Initialize - Opened device “sysdefault”
2021-12-23 21:35:17.921 T:469 INFO : CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2021-12-23 21:35:17.921 T:469 INFO : CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE3
2021-12-23 21:35:17.925 T:423 INFO : VideoPlayer: finished waiting
2021-12-23 21:35:17.925 T:423 INFO : CVideoPlayer::CloseFile()
2021-12-23 21:35:17.925 T:423 INFO : VideoPlayer: waiting for threads to exit
2021-12-23 21:35:17.925 T:423 INFO : VideoPlayer: finished waiting
2021-12-23 21:35:17.951 T:3445 INFO : initializing python engine.
2021-12-23 21:35:18.046 T:423 INFO : GLES: Maximum texture width: 4096
2021-12-23 21:35:18.452 T:3445 INFO : [plugin.video.netflix (9)] The debug logging is set as DISABLED
2021-12-23 21:35:19.898 T:488 INFO : JSONRPC Server: Disconnection detected
2021-12-23 21:35:20.078 T:3445 INFO : CPythonInvoker(11, /home/osmc/.kodi/addons/plugin.video.netflix/addon.py): script successfully run
END OF SECOND LOG

Hard to tell without full logs with debug logging enabled.

Thanks Sam. I’ll come back with full debug logs.

Does it work when you start the same Video directly from Youtube Addon?

@sam_nazarko, here are the full logs.
https://paste.osmc.tv/lejitapuzo

@fzinken thanks for the suggestion. The Youtube addon is not installed. (I prefer Sendtokodi that is much more versatile.) I’ll try this when I have the opportunity and report back.

Interesting, I just was thinking sendtokodi just sends the respective info to Kodi (e.g. like Yatse does) and then let the respective addon play the content but seems sendtokodi grabs the content via youtube-dl and then sents it to Kodi.
In this case for me the problem very likely is on the client not on Kodi/OSMC

@sam_nazarko, have the full logs yielded any clue? Anything I should try differently? Thank you.

I would suggest contacting the add-on developer.