search

add-ons / plugin.video.vrt.nu

Kodi add-on to watch content from VRT MAX
https://www.facebook.com/groups/kodivlaanderen
GNU General Public License v3.0
110 stars 20 forks source link

Playback stops after some minutes #887

Closed lebeno closed 3 years ago

lebeno commented 3 years ago

Describe the bug

Playback of vrt.nu content starts and works with audio and video perfectly in sync but after only a few minutes the playback stops. First noticed this when playing the Eurovision song contest (live). I thought is was due to congestion, but today (a few days later) the same problem playing "Het journaal 19u", an hour after broadcasting of this program ended. The log shows "stream stalled" after about 11,5 minutes of playback.

To Reproduce

Steps to reproduce the behavior:

  1. Go to Add-ons > VRT NU
  2. Click on Meest recent
  3. Scroll down to Het journaal - Het journaal 19u 20210525
  4. After a few minutes of playing it stops

Expected behavior

The program should play without stopping until the end of the program.

Additional context

Log (if available)

2021-05-25 20:33:49.126 T:3011146336  NOTICE: VideoPlayer::OpenFile: plugin://plugin.video.vrt.nu/play/id/vid-4dea24da-1abb-4620-87ba-44d7c0464b72/pbs-pub-8c7ce249-91b0-4c0c-9ee8-6d51590717fb
2021-05-25 20:33:49.128 T:2148447088  NOTICE: Creating InputStream
2021-05-25 20:33:49.304 T:2148447088  NOTICE: Creating Demuxer
2021-05-25 20:33:49.304 T:2148447088  NOTICE: Opening stream: 1001 source: 256
2021-05-25 20:33:49.327 T:2148447088  NOTICE: Creating video codec with codec id: 27
2021-05-25 20:33:49.342 T:2148447088  NOTICE: Creating video thread
2021-05-25 20:33:49.342 T:2160092016  NOTICE: running thread: video_thread
2021-05-25 20:33:49.389 T:2148447088  NOTICE: Opening stream: 1002 source: 256
2021-05-25 20:33:49.403 T:2148447088  NOTICE: Finding audio codec for: 86018
2021-05-25 20:33:49.405 T:2148447088  NOTICE: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-05-25 20:33:49.405 T:2148447088  NOTICE: Creating audio thread
2021-05-25 20:33:49.406 T:2235433840  NOTICE: running thread: CVideoPlayerAudio::Process()
2021-05-25 20:33:49.583 T:2235433840  NOTICE: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-05-25 20:33:49.583 T:2235433840  NOTICE: Creating audio stream (codec id: 86018, channels: 2, sample rate: 48000, no pass-through)
2021-05-25 20:33:50.120 T:2160092016 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2021-05-25 20:45:13.716 T:2235433840  NOTICE: CVideoPlayerAudio::Process - stream stalled
2021-05-25 20:45:25.753 T:2260611952   ERROR: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-25 20:45:25.753 T:2260611952   ERROR: CCurlFile::Open failed with code 0 for https://ondemand-cf.lwc.vrtcdn.be/content/vod/vid-4dea24da-1abb-4620-87ba-44d7c0464b72-CDN_4/vid-4dea24da-1abb-4620-87ba-44d7c0464b72-CDN_4_nodrm_acb18bb0-9e09-4887-a7e2-34863d1b915a.ism/dash/vid-4dea24da-1abb-4620-87ba-44d7c0464b72-CDN_4_nodrm_acb18bb0-9e09-4887-a7e2-34863d1b915a-video=2033062-522000.dash:
2021-05-25 20:45:26.991 T:2160092016 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2021-05-25 20:45:45.773 T:2243826544 WARNING: Previous line repeats 36 times.
2021-05-25 20:45:45.774 T:2243826544   ERROR: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-25 20:45:45.774 T:2243826544   ERROR: CCurlFile::Open failed with code 0 for https://ondemand-cf.lwc.vrtcdn.be/content/vod/vid-4dea24da-1abb-4620-87ba-44d7c0464b72-CDN_4/vid-4dea24da-1abb-4620-87ba-44d7c0464b72-CDN_4_nodrm_acb18bb0-9e09-4887-a7e2-34863d1b915a.ism/dash/vid-4dea24da-1abb-4620-87ba-44d7c0464b72-CDN_4_nodrm_acb18bb0-9e09-4887-a7e2-34863d1b915a-audio=96001-41760768.dash:
2021-05-25 20:45:45.775 T:2990379888 WARNING: ActiveAE - large audio sync error: -11837.666979
2021-05-25 20:45:45.835 T:2235433840  NOTICE: CVideoPlayerAudio::Process - stream stalled
2021-05-25 20:45:45.874 T:2148447088  NOTICE: CVideoPlayer::OnExit()
2021-05-25 20:45:45.874 T:2148447088  NOTICE: VideoPlayer: eof, waiting for queues to empty
2021-05-25 20:45:45.875 T:2148447088  NOTICE: Closing stream player 1
2021-05-25 20:45:45.875 T:2148447088  NOTICE: CDVDMessageQueue(audio)::WaitUntilEmpty
2021-05-25 20:45:45.875 T:2148447088  NOTICE: Waiting for audio thread to exit
2021-05-25 20:45:45.875 T:2235433840   ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true
2021-05-25 20:45:45.876 T:2235433840  NOTICE: thread end: CVideoPlayerAudio::OnExit()
2021-05-25 20:45:45.876 T:2148447088  NOTICE: Closing audio device
2021-05-25 20:45:45.876 T:2148447088  NOTICE: Deleting audio codec
2021-05-25 20:45:45.877 T:2148447088  NOTICE: Closing stream player 2
2021-05-25 20:45:45.877 T:2148447088  NOTICE: CDVDMessageQueue(video)::WaitUntilEmpty
2021-05-25 20:45:45.877 T:2148447088  NOTICE: waiting for video thread to exit
2021-05-25 20:45:45.878 T:2160092016   ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true
2021-05-25 20:45:45.878 T:2160092016  NOTICE: thread end: video_thread
2021-05-25 20:45:45.878 T:2148447088  NOTICE: deleting video codec
2021-05-25 20:45:45.965 T:3011146336  NOTICE: CVideoPlayer::CloseFile()
2021-05-25 20:45:45.995 T:3011146336  NOTICE: VideoPlayer: waiting for threads to exit
2021-05-25 20:45:45.995 T:3011146336  NOTICE: VideoPlayer: finished waiting
2021-05-25 20:45:45.996 T:3011146336  NOTICE: CVideoPlayer::CloseFile()
2021-05-25 20:45:45.996 T:3011146336  NOTICE: VideoPlayer: waiting for threads to exit
2021-05-25 20:45:45.996 T:3011146336  NOTICE: VideoPlayer: finished waiting
2021-05-25 20:45:46.011 T:3011146336   ERROR: Control 55 in window 10025 has been asked to focus, but it can't
2021-05-25 20:45:46.378 T:2546893680  NOTICE: AddOnLog: PVR IPTV Simple Client: LoadEPG EPG Loaded - 28 (ms)
2021-05-25 20:45:46.380 T:2313155440   ERROR: EXCEPTION: Invalid setting type
mediaminister commented 3 years ago

CVideoPlayerAudio::Process - stream stalled is a very common error on RPi devices. I guess this is related to memory problems in LibreELEC or InputStream Adaptive.

You can try to lower the maximal bandwith in VRT NU Add-on Playback settings to lower memory usage.

Using a newer version of LibreELEC or InputStream Adaptive may also fix this problem.

lebeno commented 3 years ago

When I go to Addons > InputStream adaptive en check Updates, I am already on the latest version: 2.4.7.1 If there is a newer version, how would I be able to install a newer version of it on Kodi?

My Raspberry Pi 4 has 2GB RAM with 1.3GB available/free, so this should not be a memory issue?

To what value should I limit the maximal bandwidth of the vrt.nu plugin?

LibreElec 10 is still in ALPHA for Raspberry Pi. So I guess not a valid upgrade yet? This newer version could introduce other issues?

I am planning to cancel our TV subscription but then I would really like Kodi/LibreElec/vrt.nu to work :-) Are there any other steps i can take to mitigate this issue or should I move to other hardware? Should I then avoid ARM and go for x86?

lebeno commented 3 years ago

I know I am barking up the wrong tree here, but I am not a developer with knowledge of all the components needed to stream online video with Kodi. I do know that all my local content (series, movies) plays without any problems (accessed via NFS on my NAS). I only have problems with streaming online content. For example, also playing TV Oost has the same problem: playback stops after a few minutes

Starting playback:

2021-05-30 16:02:09.131 T:3011261024  NOTICE: VideoPlayer::OpenFile: pvr://channels/tv/Alle kanalen/pvr.iptvsimple_1233996591.pvr
2021-05-30 16:02:09.134 T:2341364592  NOTICE: Creating InputStream
2021-05-30 16:02:09.644 T:2341364592  NOTICE: Creating Demuxer
2021-05-30 16:02:15.253 T:2341364592  NOTICE: Opening stream: 13 source: 256
2021-05-30 16:02:15.253 T:2341364592  NOTICE: Creating video codec with codec id: 27
2021-05-30 16:02:15.265 T:2341364592  NOTICE: Creating video thread
2021-05-30 16:02:15.265 T:2374935408  NOTICE: running thread: video_thread
2021-05-30 16:02:15.313 T:2341364592  NOTICE: Opening stream: 14 source: 256
2021-05-30 16:02:15.313 T:2341364592  NOTICE: Finding audio codec for: 86018
2021-05-30 16:02:15.315 T:2341364592  NOTICE: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-05-30 16:02:15.315 T:2341364592  NOTICE: Creating audio thread
2021-05-30 16:02:15.316 T:2296050544  NOTICE: running thread: CVideoPlayerAudio::Process()
2021-05-30 16:02:15.330 T:2296050544  NOTICE: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-05-30 16:02:15.330 T:2296050544  NOTICE: Creating audio stream (codec id: 86018, channels: 2, sample rate: 48000, no pass-through)
2021-05-30 16:02:16.240 T:2374935408 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

Stops after a few minutes:

2021-05-30 16:06:34.941 T:2990375792 WARNING: Previous line repeats 3 times.
2021-05-30 16:06:34.941 T:2990375792 WARNING: ActiveAE - large audio sync error: -89451.110357
2021-05-30 16:06:34.990 T:2990375792 WARNING: ActiveAE - large audio sync error: -89451.702671
2021-05-30 16:06:38.972 T:2990375792 WARNING: ActiveAE - large audio sync error: -89323.256873
2021-05-30 16:06:39.020 T:2990375792 WARNING: ActiveAE - large audio sync error: -89323.677725
2021-05-30 16:10:16.795 T:2990375792 WARNING: ActiveAE - large audio sync error: -89453.484114
2021-05-30 16:10:16.844 T:2990375792 WARNING: ActiveAE - large audio sync error: -89453.923911
2021-05-30 16:10:34.994 T:2990375792 WARNING: ActiveAE - large audio sync error: -89448.162991
2021-05-30 16:10:35.041 T:2990375792 WARNING: ActiveAE - large audio sync error: -89447.908807
2021-05-30 16:13:47.477 T:2990375792 WARNING: ActiveAE - large audio sync error: -89439.356415
2021-05-30 16:13:47.526 T:2990375792 WARNING: ActiveAE - large audio sync error: -89439.651099
2021-05-30 16:14:28.719 T:2990375792 WARNING: ActiveAE - large audio sync error: -89437.250056
2021-05-30 16:14:28.771 T:2990375792 WARNING: ActiveAE - large audio sync error: -89437.765963
2021-05-30 16:14:31.766 T:2990375792 WARNING: ActiveAE - large audio sync error: -89380.831331
2021-05-30 16:14:31.814 T:2990375792 WARNING: ActiveAE - large audio sync error: -89380.823110
2021-05-30 16:15:12.918 T:2296050544  NOTICE: CVideoPlayerAudio::Process - stream stalled
2021-05-30 16:15:26.090 T:2374935408 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2021-05-30 16:15:44.938 T:2341364592 WARNING: Previous line repeats 36 times.
2021-05-30 16:15:44.938 T:2341364592  NOTICE: CVideoPlayer::OnExit()
2021-05-30 16:15:44.938 T:2341364592  NOTICE: VideoPlayer: eof, waiting for queues to empty
2021-05-30 16:15:44.938 T:2341364592  NOTICE: Closing stream player 1
2021-05-30 16:15:44.938 T:2341364592  NOTICE: CDVDMessageQueue(audio)::WaitUntilEmpty
2021-05-30 16:15:44.938 T:2341364592  NOTICE: Waiting for audio thread to exit
2021-05-30 16:15:44.938 T:2296050544   ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true
2021-05-30 16:15:44.939 T:2296050544  NOTICE: thread end: CVideoPlayerAudio::OnExit()
2021-05-30 16:15:44.939 T:2341364592  NOTICE: Closing audio device
2021-05-30 16:15:44.939 T:2341364592  NOTICE: Deleting audio codec
2021-05-30 16:15:44.940 T:2341364592  NOTICE: Closing stream player 2
2021-05-30 16:15:44.940 T:2341364592  NOTICE: waiting for video thread to exit
2021-05-30 16:15:44.956 T:2374935408  NOTICE: thread end: video_thread
2021-05-30 16:15:44.957 T:2341364592  NOTICE: deleting video codec
2021-05-30 16:15:45.023 T:3011261024  NOTICE: CVideoPlayer::CloseFile()
2021-05-30 16:15:45.065 T:3011261024  NOTICE: VideoPlayer: waiting for threads to exit
2021-05-30 16:15:45.065 T:3011261024  NOTICE: VideoPlayer: finished waiting
2021-05-30 16:15:45.065 T:3011261024  NOTICE: CVideoPlayer::CloseFile()
2021-05-30 16:15:45.065 T:3011261024  NOTICE: VideoPlayer: waiting for threads to exit
2021-05-30 16:15:45.065 T:3011261024  NOTICE: VideoPlayer: finished waiting

Any pointers to what I should be looking? What component is the problem her?

mediaminister commented 3 years ago

"Stream stalled" is not a VRT NU Add-on problem. "Stream stalled" means Kodi's video buffer is empty. But it's very difficult to find the cause, it can be anything: a software or driver problem or a problem with the internet connection.

You can expirement with the following settings:

1) In VRT NU Add-on Playback settings you can switch Widevine DRM on or off to get a different stream format from VRT NU servers.

2) You can try to use different video cache settings in Kodi: https://kodi.wiki/view/HOW-TO:Modify_the_video_cache

3) Try LibreELEC 10.0 BETA

To what value should I limit the maximal bandwidth of the vrt.nu plugin?

You start at the maximum of 30720 (3 Mbps) and try. If it fails again, try the next value, etc...

LibreElec 10 is still in ALPHA for Raspberry Pi. So I guess not a valid upgrade yet? This newer version could introduce other issues?

It's already in Beta 3, so I guess it can work very well.

I am planning to cancel our TV subscription but then I would really like Kodi/LibreElec/vrt.nu to work :-)

Yes, but Kodi is not officially supported by VRT NU. This add-on is a volunteer project, there is no warranty this keeps working.

lebeno commented 3 years ago

Thank you for the suggestions, I will try them.

I just installed LibreELEC 10.0 BETA, did a restore of settings backup (kodi automatically rebooted and performed database and add-on migration) and still the same problem. I will capture the network traffic with tcpdump to check if the network or internet is the problem (data just not getting through fast enough).

2021-05-30 18:59:09.253 T:1030     INFO <general>: CActiveAESink::OpenSink - initialize sink
2021-05-30 18:59:09.253 T:1030     INFO <general>: CAESinkALSA::Initialize - Attempting to open device "default"
2021-05-30 18:59:09.265 T:1030     INFO <general>: CAESinkALSA::Initialize - Opened device "default"
2021-05-30 18:59:09.269 T:1030     INFO <general>: CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2021-05-30 18:59:09.269 T:1030     INFO <general>: CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE3
2021-05-30 18:59:21.885 T:1023     INFO <general>: Loading skin file: MyPVRGuide.xml, load type: KEEP_IN_MEMORY
2021-05-30 18:59:26.199 T:1023     INFO <general>: Loading skin file: DialogPVRInfo.xml, load type: LOAD_EVERY_TIME
2021-05-30 18:59:30.518 T:1023     INFO <general>: AddOnLog: pvr.iptvsimple: pvr.iptvsimple - GetEPGTagStreamProperties - EPG Catchup URL: plugin://plugin.video.vrt.nu/play/whatson/763527086527
2021-05-30 18:59:30.549 T:1539     INFO <general>: initializing python engine.
2021-05-30 18:59:31.863 T:1023     INFO <general>: VideoPlayer::OpenFile: pvr://guide/0016/2021-05-29 22:00:00.epg
2021-05-30 18:59:31.864 T:1541     INFO <general>: Creating InputStream
2021-05-30 18:59:31.865 T:1541     INFO <general>: AddOnLog: inputstream.adaptive: SetVideoResolution (1920 x 1080)
2021-05-30 18:59:31.917 T:1539     INFO <general>: CPythonInvoker(19, /storage/.kodi/addons/plugin.video.vrt.nu/resources/lib/addon_entry.py): script successfully run
2021-05-30 18:59:32.004 T:1541     INFO <general>: AddOnLog: inputstream.adaptive: Successfully parsed manifest file. #Periods: 1, #Streams in first period: 3, Type: live, Download speed: 0.0000 Bytes/s
2021-05-30 18:59:32.004 T:1541     INFO <general>: Creating Demuxer
2021-05-30 18:59:32.004 T:1541     INFO <general>: Opening stream: 1001 source: 256
2021-05-30 18:59:32.235 T:1541     INFO <general>: Creating video codec with codec id: 27
2021-05-30 18:59:32.236 T:1541     INFO <general>: CDVDVideoCodecDRMPRIME::Open - using decoder V4L2 mem2mem H.264 decoder wrapper
2021-05-30 18:59:32.275 T:1541     INFO <general>: Creating video thread
2021-05-30 18:59:32.276 T:1545     INFO <general>: running thread: video_thread
2021-05-30 18:59:32.276 T:1541     INFO <general>: Opening stream: 1002 source: 256
2021-05-30 18:59:32.277 T:1541     INFO <general>: Finding audio codec for: 86018
2021-05-30 18:59:32.279 T:1541     INFO <general>: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-05-30 18:59:32.279 T:1541     INFO <general>: Creating audio thread
2021-05-30 18:59:32.279 T:1547     INFO <general>: running thread: CVideoPlayerAudio::Process()
2021-05-30 18:59:32.293 T:1547     INFO <general>: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-05-30 18:59:32.294 T:1547     INFO <general>: Creating audio stream (codec id: 86018, channels: 2, sample rate: 48000, no pass-through)
2021-05-30 18:59:32.323 T:1030     INFO <general>: CActiveAESink::OpenSink - initialize sink
2021-05-30 18:59:32.523 T:1030     INFO <general>: CAESinkALSA::Initialize - Attempting to open device "PI:HDMI"
2021-05-30 18:59:32.523 T:1030     INFO <general>: CAESinkALSA - Unable to open device "PI:HDMI" for playback
2021-05-30 18:59:32.523 T:1030    ERROR <general>: CAESinkALSA::Initialize - failed to initialize device "PI:HDMI"
2021-05-30 18:59:32.524 T:1030     INFO <general>: CAESinkALSA::Initialize - Attempting to open device "default"
2021-05-30 18:59:32.531 T:1030     INFO <general>: CAESinkALSA::Initialize - Opened device "default"
2021-05-30 18:59:32.534 T:1030     INFO <general>: CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2021-05-30 18:59:32.534 T:1030     INFO <general>: CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE3

...plays for a few seconds, then freezes:

2021-05-30 19:00:15.316 T:1547     INFO <general>: CVideoPlayerAudio::Process - stream stalled
2021-05-30 19:00:27.264 T:1544    ERROR <general>: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-30 19:00:27.264 T:1544    ERROR <general>: CCurlFile::Open failed with code 0 for https://remix-cf.lwc.vrtcdn.be/remix/92035f44-177d-44c0-a6c3-c21015dbff93/remix_aes.ism/remix_aes-audio=96000-video=2037854-8.ts:

2021-05-30 19:00:48.287 T:1544    ERROR <general>: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-30 19:00:48.288 T:1544    ERROR <general>: CCurlFile::Open failed with code 0 for https://remix-cf.lwc.vrtcdn.be/remix/92035f44-177d-44c0-a6c3-c21015dbff93/remix_aes.ism/remix_aes-audio=96000-video=2037854-8.ts:

2021-05-30 19:00:54.111 T:1023     INFO <general>: CVideoPlayer::CloseFile()
2021-05-30 19:00:54.111 T:1023     INFO <general>: VideoPlayer: waiting for threads to exit
2021-05-30 19:00:54.618 T:1139    ERROR <general>: EXCEPTION: XBMC is not playing any file
2021-05-30 19:01:09.310 T:1544    ERROR <general>: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-30 19:01:09.310 T:1544    ERROR <general>: CCurlFile::Open failed with code 0 for https://remix-cf.lwc.vrtcdn.be/remix/92035f44-177d-44c0-a6c3-c21015dbff93/remix_aes.ism/remix_aes-audio=96000-video=2037854-8.ts:

2021-05-30 19:01:30.332 T:1544    ERROR <general>: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-30 19:01:30.332 T:1544    ERROR <general>: CCurlFile::Open failed with code 0 for https://remix-cf.lwc.vrtcdn.be/remix/92035f44-177d-44c0-a6c3-c21015dbff93/remix_aes.ism/remix_aes-audio=96000-video=2037854-8.ts:

2021-05-30 19:01:51.352 T:1544    ERROR <general>: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-30 19:01:51.352 T:1544    ERROR <general>: CCurlFile::Open failed with code 0 for https://remix-cf.lwc.vrtcdn.be/remix/92035f44-177d-44c0-a6c3-c21015dbff93/remix_aes.ism/remix_aes-audio=96000-video=2037854-8.ts:

2021-05-30 19:02:12.374 T:1544    ERROR <general>: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-30 19:02:12.374 T:1544    ERROR <general>: CCurlFile::Open failed with code 0 for https://remix-cf.lwc.vrtcdn.be/remix/92035f44-177d-44c0-a6c3-c21015dbff93/remix_aes.ism/remix_aes-audio=96000-video=2037854-8.ts:

2021-05-30 19:02:33.396 T:1544    ERROR <general>: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-30 19:02:33.396 T:1544    ERROR <general>: CCurlFile::Open failed with code 0 for https://remix-cf.lwc.vrtcdn.be/remix/92035f44-177d-44c0-a6c3-c21015dbff93/remix_aes.ism/remix_aes-audio=96000-video=2037854-8.ts:

2021-05-30 19:02:54.419 T:1544    ERROR <general>: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-30 19:02:54.420 T:1544    ERROR <general>: CCurlFile::Open failed with code 0 for https://remix-cf.lwc.vrtcdn.be/remix/92035f44-177d-44c0-a6c3-c21015dbff93/remix_aes.ism/remix_aes-audio=96000-video=2037854-8.ts:

2021-05-30 19:03:15.442 T:1544    ERROR <general>: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-30 19:03:15.442 T:1544    ERROR <general>: CCurlFile::Open failed with code 0 for https://remix-cf.lwc.vrtcdn.be/remix/92035f44-177d-44c0-a6c3-c21015dbff93/remix_aes.ism/remix_aes-audio=96000-video=2037854-8.ts:

2021-05-30 19:03:36.464 T:1544    ERROR <general>: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-30 19:03:36.464 T:1544    ERROR <general>: CCurlFile::Open failed with code 0 for https://remix-cf.lwc.vrtcdn.be/remix/92035f44-177d-44c0-a6c3-c21015dbff93/remix_aes.ism/remix_aes-audio=96000-video=2037854-8.ts:

2021-05-30 19:03:57.486 T:1544    ERROR <general>: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-30 19:03:57.487 T:1544    ERROR <general>: CCurlFile::Open failed with code 0 for https://remix-cf.lwc.vrtcdn.be/remix/92035f44-177d-44c0-a6c3-c21015dbff93/remix_aes.ism/remix_aes-audio=96000-video=2037854-8.ts:

2021-05-30 19:03:57.487 T:1541     INFO <general>: CVideoPlayer::OnExit()
2021-05-30 19:03:57.487 T:1541     INFO <general>: Closing stream player 1
2021-05-30 19:03:57.487 T:1541     INFO <general>: Waiting for audio thread to exit
2021-05-30 19:03:57.487 T:1547    ERROR <general>: Got MSGQ_ABORT or MSGO_IS_ERROR return true
2021-05-30 19:03:57.487 T:1547     INFO <general>: thread end: CVideoPlayerAudio::OnExit()
2021-05-30 19:03:57.488 T:1541     INFO <general>: Closing audio device
2021-05-30 19:03:57.528 T:1541     INFO <general>: Deleting audio codec
2021-05-30 19:03:57.528 T:1541     INFO <general>: Closing stream player 2
2021-05-30 19:03:57.529 T:1541     INFO <general>: waiting for video thread to exit
2021-05-30 19:03:57.529 T:1545    ERROR <general>: Got MSGQ_ABORT or MSGO_IS_ERROR return true
2021-05-30 19:03:57.529 T:1545     INFO <general>: thread end: video_thread
2021-05-30 19:03:57.530 T:1541     INFO <general>: deleting video codec
2021-05-30 19:03:57.543 T:1541     INFO <general>: ADDON: Dll Destroyed - InputStream Adaptive
2021-05-30 19:03:57.544 T:1023     INFO <general>: VideoPlayer: finished waiting
2021-05-30 19:03:57.544 T:1023     INFO <general>: CVideoPlayer::CloseFile()
2021-05-30 19:03:57.544 T:1023     INFO <general>: VideoPlayer: waiting for threads to exit
2021-05-30 19:03:57.544 T:1023     INFO <general>: VideoPlayer: finished waiting
2021-05-30 19:03:57.577 T:1030     INFO <general>: CActiveAESink::OpenSink - initialize sink
2021-05-30 19:03:57.777 T:1030     INFO <general>: CAESinkALSA::Initialize - Attempting to open device "PI:HDMI"
2021-05-30 19:03:57.777 T:1030     INFO <general>: CAESinkALSA - Unable to open device "PI:HDMI" for playback
2021-05-30 19:03:57.777 T:1030    ERROR <general>: CAESinkALSA::Initialize - failed to initialize device "PI:HDMI"
2021-05-30 19:03:57.778 T:1030     INFO <general>: CAESinkALSA::Initialize - Attempting to open device "default"
2021-05-30 19:03:57.785 T:1030     INFO <general>: CAESinkALSA::Initialize - Opened device "default"
2021-05-30 19:03:57.787 T:1030     INFO <general>: CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2021-05-30 19:03:57.787 T:1030     INFO <general>: CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE3
2021-05-30 19:03:59.405 T:1613     INFO <general>: CDVDVideoCodecFFmpeg::Open() Using codec: H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
lebeno commented 3 years ago

After enabling Widevine in vrt.nu settings, playback did not even start:

2021-05-30 19:14:45.998 T:1023     INFO <general>: AddOnLog: pvr.iptvsimple: pvr.iptvsimple - GetChannelStreamProperties - Live Stream URL: plugin://plugin.video.vrt.nu/play/id/vualto_een_geo
2021-05-30 19:14:46.014 T:1539     INFO <general>: initializing python engine.
2021-05-30 19:14:46.797 T:1539  WARNING <general>: [script.module.inputstreamhelper] InputStreamHelper version 0.5.4+matrix.1 is running for the first time
2021-05-30 19:14:47.050 T:1023     INFO <general>: VideoPlayer::OpenFile: pvr://channels/tv/Alle%20kanalen/pvr.iptvsimple_1249540465.pvr
2021-05-30 19:14:47.051 T:1770     INFO <general>: Creating InputStream
2021-05-30 19:14:47.052 T:1770     INFO <general>: AddOnLog: inputstream.adaptive: SetVideoResolution (1920 x 1080)
2021-05-30 19:14:47.054 T:1770    ERROR <general>: GetDirectory - Error getting /usr/lib/kodi/addons/inputstream.adaptive/
2021-05-30 19:14:47.113 T:1539     INFO <general>: CPythonInvoker(19, /storage/.kodi/addons/plugin.video.vrt.nu/resources/lib/addon_entry.py): script successfully run
2021-05-30 19:14:47.203 T:1770     INFO <general>: AddOnLog: inputstream.adaptive: Successfully parsed manifest file. #Periods: 1, #Streams in first period: 3, Type: live, Download speed: 0.0000 Bytes/s
2021-05-30 19:14:47.208 T:1770    ERROR <general>: AddOnLog: inputstream.adaptive: Unable to load widevine shared library (/storage/.kodi/cdm/libwidevinecdm.so)
2021-05-30 19:14:47.208 T:1770    ERROR <general>: AddOnLog: inputstream.adaptive: OpenDRMSystem failed
2021-05-30 19:14:47.209 T:1770    ERROR <general>: CVideoPlayer::OpenInputStream - error opening [pvr://channels/tv/Alle%20kanalen/pvr.iptvsimple_1249540465.pvr]
2021-05-30 19:14:47.209 T:1770     INFO <general>: CVideoPlayer::OnExit()
2021-05-30 19:14:47.209 T:1770     INFO <general>: ADDON: Dll Destroyed - InputStream Adaptive
2021-05-30 19:14:47.247 T:1023     INFO <general>: CVideoPlayer::CloseFile()
2021-05-30 19:14:47.247 T:1023     INFO <general>: VideoPlayer: waiting for threads to exit
2021-05-30 19:14:47.247 T:1023     INFO <general>: VideoPlayer: finished waiting

Tried a re-install of Widevine CDM in InputStream Helper, succeeded but still no playback: Then tried Widevine CDM repair ("Herstel") and that did the job! Looks like streaming is working now for vrt.nu!

  1. Even in the previous LibreELEC 9.2.6 I had set the video cache to 100MB and buffermode 1, that file has survived the backup/restore so still in effect on LibreELEC 10.0 BETA.
mediaminister commented 3 years ago

Check this https://libreelec.tv/2021/05/le-9-2-7-10b4-fix-widevine/ if you have problems with Widevine on LE 10

lebeno commented 3 years ago

I just performed a fresh install of LibreELEC 9.2.7 on a new SD card, still having problems with vrt.nu playback.

I only installed these plugins: VRT NU, VTM GO, Regio TV and IPTV Manager.

2021-05-31 19:08:58.907 T:3011448896  NOTICE: VideoPlayer::OpenFile: pvr://channels/tv/All channels/pvr.iptvsimple_1543208579.pvr
2021-05-31 19:08:58.911 T:2463228672  NOTICE: Creating InputStream
2021-05-31 19:08:59.196 T:2463228672  NOTICE: Creating Demuxer
2021-05-31 19:08:59.197 T:2463228672  NOTICE: Opening stream: 1001 source: 256
2021-05-31 19:08:59.768 T:2463228672  NOTICE: Creating video codec with codec id: 27
2021-05-31 19:08:59.789 T:2463228672  NOTICE: Creating video thread
2021-05-31 19:08:59.789 T:2570973952  NOTICE: running thread: video_thread
2021-05-31 19:08:59.903 T:2463228672  NOTICE: Opening stream: 1002 source: 256
2021-05-31 19:08:59.968 T:2463228672  NOTICE: Finding audio codec for: 86018
2021-05-31 19:08:59.973 T:2463228672  NOTICE: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-05-31 19:08:59.973 T:2463228672  NOTICE: Creating audio thread
2021-05-31 19:08:59.973 T:2421265152  NOTICE: running thread: CVideoPlayerAudio::Process()
2021-05-31 19:08:59.973 T:2463228672  NOTICE: Opening stream: 1003 source: 256
2021-05-31 19:09:00.317 T:2421265152  NOTICE: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-05-31 19:09:00.317 T:2421265152  NOTICE: Previous line repeats 1 times.
2021-05-31 19:09:00.317 T:2421265152  NOTICE: Creating audio stream (codec id: 86018, channels: 2, sample rate: 48000, no pass-through)
2021-05-31 19:09:01.386 T:2570973952 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2021-05-31 19:10:55.645 T:2992505600 WARNING: Previous line repeats 4 times.
2021-05-31 19:10:55.645 T:2992505600 WARNING: ActiveAE - large audio sync error: -89432.223389
2021-05-31 19:15:11.838 T:2421265152  NOTICE: CVideoPlayerAudio::Process - stream stalled
2021-05-31 19:15:24.777 T:2429657856   ERROR: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-31 19:15:24.777 T:2429657856   ERROR: CCurlFile::Open failed with code 0 for https://live-radio-cf-vrt.akamaized.net/groupb/live/0f394a26-c87d-475e-8590-e9c6e79b28d9/live.isml/dash/live-audio_track_0_0_dut=128000-77879447361408.dash:
2021-05-31 19:15:30.988 T:2454835968   ERROR: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
2021-05-31 19:15:30.989 T:2454835968 WARNING: CCurlFile::FillBuffer - Reconnect, (re)try 1
mediaminister commented 3 years ago

Timeouts are not normal. Something must be wrong with your RPi setup, maybe a slow usb disk, slow network/internet connection,...

If you can't find the root cause, you could also try if increasing the curlclienttimeout helps: http://kodi.wiki/view/Advancedsettings.xml#network

lebeno commented 3 years ago

You are right, same problem playing vtm go, so no problem with this specific add-on. Playback stalls after 10 minutes (log below).

I will take my Raspberry Pi to another location and test it on another network/ISP.

2021-05-31 19:20:03.370 T:2531619584  NOTICE: [script.module.inputstreamhelper] InputStreamHelper version 0.5.4 is running for the first time
2021-05-31 19:20:04.331 T:2531619584   ERROR: [plugin.video.vtm.go] [resources.lib.vtmgo.vtmgostream] No manifest url found at https://dcs-live.apis.anvato.net/server/play/pzMdYIO4WalCWwb6p/manifest.mpd?encp=1E-RvVnplM2_PWXWhFvDVg:5hsQ3dqSB3EJ5xpJzXH4fDcHBeR4LriXq-P2yZYkAMogogHKYWh4j6V1dyLb3Mld-gcb9vfn5zYmrIfs77O3YPeqmLoO7iZJ6e-p37ZVmDedkejyRdZ-mOK_vCtn9jKPH8hLyqT473tw4CePkhhq35NrP1751TpbCbzRcaalfos9fqagiK9gZGCJUDt_ZkonI-3XgXf5KyQgieHvfKjN3iLMSGMfNTE_xrOHTEi6MsFNtyVZpKZb2BBrF6KloXpFaUDzfppAjEmUvXPcCEao9bYr2ZMf028KI5ZmXjKiMhSZ7PPGYusckmNYT1jMLyTeE4_F4RVeCIx3gyTbKbLUMhAqARCyQ49E8aLn3eLF3upxbHUN7pTWfFq7ku-CWet2m_vTqmiRL0uITf1k4o9POBSUhmS0iSi2EmcHC38rMfDh4uoXvXikZyZuDB83S0s-g13WL4kwHbZ7Zo1XnaTACImQ8Z6tIEUvpJW5wID0L5nm3vbZ6G46rcX2gkuY7ShDt7Hsb_1VcmusjBuYTX5AjMGXhItnTVowc1klerEfwSH12gR8zfm89rWSIxSqNi-5ZE0bjkz_yO0BvH0d46UFbgCiIJpRdNuZpGLIVSFKilkJ5D2EAhjPxNIrDDd2YE3Gns2ER6t80Oon2toLwQFtmzJvi4FzBOCVJU2-s3Fi3K_EuAflhtjscnFiJ6ja9W9qkur82QHDIqq0UnMCP6ANLvqOSs3LNDka4GVJeWqPmlNfkICYn8nGhoTPQWVXy7dNeBghGWJp1XOQjmXWMQ4hibg5t74yMxeP5ObqqfEu9ETuncPiigQVyd0uIDcJSJ94cH12LAL9p4kwzXoFPkCd0U2Z2fR6NjQdW8EX0b-uXoLKrQIQ2EzFeLAprWwsKv3fb-y2J4I1yHekuhyLTnXhQ0AOmbyAcpd6UAUssVZPUTwo6JY6mHNZKHCEkqbkpcO2ImlQ3ktYo-m2mYThfBdrH16_LF1bu8-B448ihvbXfUs&anvtrid=r8bETAoRRop3AVvoM68lNeV9J83020Yf&anvauth=tb=0~te=1622488894~sgn=514de6cb2a12220dfc11f2aace21aa6aae29192d22392d0b089bc8d90af0e56a&t=1622488804
2021-05-31 19:20:04.392 T:2531619584   ERROR: GetDirectory - Error getting /storage/.kodi/userdata/addon_data/plugin.video.vtm.go/temp/
2021-05-31 19:20:04.430 T:3011448896  NOTICE: VideoPlayer::OpenFile: pvr://channels/tv/All channels/pvr.iptvsimple_1555060908.pvr
2021-05-31 19:20:04.488 T:2463228672  NOTICE: Creating InputStream
2021-05-31 19:20:04.496 T:2463228672   ERROR: GetDirectory - Error getting /usr/lib/kodi/addons/inputstream.adaptive/
2021-05-31 19:20:08.509 T:2463228672  NOTICE: Creating Demuxer
2021-05-31 19:20:08.509 T:2463228672  NOTICE: Opening stream: 1001 source: 256
2021-05-31 19:20:08.535 T:2463228672  NOTICE: Creating video codec with codec id: 27
2021-05-31 19:20:08.604 T:2463228672  NOTICE: Opening stream: 1002 source: 256
2021-05-31 19:20:08.632 T:2463228672  NOTICE: Finding audio codec for: 86018
2021-05-31 19:20:08.632 T:2463228672  NOTICE: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-05-31 19:20:08.632 T:2463228672  NOTICE: Closing stream player 3
2021-05-31 19:20:08.632 T:2463228672  NOTICE: Opening stream: 1003 source: 256
2021-05-31 19:20:09.322 T:2421265152  NOTICE: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-05-31 19:20:09.324 T:2421265152  NOTICE: Previous line repeats 1 times.
2021-05-31 19:20:09.325 T:2421265152  NOTICE: Creating audio stream (codec id: 86018, channels: 2, sample rate: 44100, no pass-through)
2021-05-31 19:20:09.958 T:2570973952 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2021-05-31 19:22:04.785 T:2992505600 WARNING: ActiveAE - large audio sync error: -97345.516493
2021-05-31 19:22:08.828 T:2992505600 WARNING: ActiveAE - large audio sync error: -97293.475912
2021-05-31 19:22:17.877 T:2992505600 WARNING: ActiveAE - large audio sync error: -97341.271672
2021-05-31 19:22:48.691 T:2463228672   ERROR: AddOnLog: InputStream Adaptive: Decrypt Sample returns failure!
2021-05-31 19:24:39.326 T:2992505600   ERROR: Previous line repeats 3 times.
2021-05-31 19:24:39.326 T:2992505600 WARNING: ActiveAE - large audio sync error: -97296.846951
2021-05-31 19:26:22.425 T:2992505600 WARNING: ActiveAE - large audio sync error: -97345.243073
2021-05-31 19:26:25.470 T:2992505600 WARNING: ActiveAE - large audio sync error: -97293.125135
2021-05-31 19:27:40.223 T:2992505600 WARNING: ActiveAE - large audio sync error: -97347.354739
2021-05-31 19:30:13.967 T:2421265152  NOTICE: CVideoPlayerAudio::Process - stream stalled
dagwieers commented 3 years ago

@lebeno I am using a RPi 3B (not 3B+) with just 1GB RAM for our main display and we do not have any such playback issues. I do have to say that I used a wired network and I disabled the Wifi chipset and bluetooth in /flash/config.txt

dtoverlay=pi3-disable-bt
dtoverlay=pi3-disable-wifi

Other changes I did to ensure it works as expected using a long HDMI cable and to ensure HDMI is working even if there is nothing connected:

hdmi_force_hotplug=1
config_hdmi_boost=9

Also, having the latest firmware (bootcode.bin) can help, but that ships as part of LibreELEC and should therefore be fine. (On RPi4 you can update it individually from LibreELEC).

dagwieers commented 3 years ago

We do still have the following known issues :

lebeno commented 3 years ago

Definitely a problem with the internet here! During video conferencing we notice several dropouts and freezes per hour whilst pings also drop for a few seconds.

lebeno commented 3 years ago

update: The problem seems to be related to my specific internet/network setup. I have not succeeded in finding the culprit yet, but directly connecting my Raspberry Pi to the ISP's CPE (Proximus b-box 3) fixes the problem. The problem is probably manifested in my firewall or switch.

mediaminister commented 3 years ago

Glad to hear your problem is fixed!