search

matthuisman / slyguy.addons

Github mirror of SlyGuy add-ons
https://www.matthuisman.nz/2020/02/slyguy-kodi-repository.html
285 stars 78 forks source link

[TVNZ|ThreeNow] Slow loading of live view and on demand #738

Closed Firesphere closed 4 months ago

Firesphere commented 4 months ago

As of the last few days, a week maybe?, TVNZ and ThreeNow take very long to start playback. It used to be a few seconds, now it sometimes takes over a minute, but at least 30 seconds.

If you have any ideas or pointers on where to look further, that would be great :) I'll keep digging until I find something more useful.

System info: LibreELEC (official): 12.0.0 (RPi5.aarch64) 64 bit, Pi5, 4G version, active cooler, cable network. It's the latest stable release (come to think of it, might that be related? It hasn't been marked stable for that long... not sure, but maybe just as long as I've been seeing this problem? Gotta dig further)

matthuisman commented 4 months ago

you must be using "smart urls" if its attempting to use a dns resolver

Firesphere commented 4 months ago

Hmmm, where/what should I disable for that? I'm not seeing it in the configs of either this add-on or the commons

matthuisman commented 4 months ago

please provide a full kodi debug log

matthuisman commented 4 months ago

is this using IPTV NZ addon or is this using the dedicated TVNZ / Three addons? That may explain the issue.

A full log gives me all this info from the start

Firesphere commented 4 months ago

It's happening on the IPTV NZ addon as well as the dedicated TVNZ/Three add-ons. I'll get a full log tonight (hopefully), otherwise tomorrow night.

Firesphere commented 4 months ago

Logs! Resolv.conf:

cat /etc/resolv.conf
# Generated by Connection Manager
search fritz.box 
nameserver 192.168.178.45

As expected to me.

Logs:

2024-05-15 18:53:54.865 T:1248    debug <general>: CLibInputKeyboard::ProcessKey - using delay: 500ms repeat: 33ms
2024-05-15 18:53:54.866 T:866249   debug <general>: Thread Timer start, auto delete: false
2024-05-15 18:53:54.871 T:1243    debug <general>: Keyboard: scancode: 0x1c, sym: 0x0d, unicode: 0x0d, modifier: 0x0
2024-05-15 18:53:55.066 T:866249   debug <general>: Thread Timer 140732312514304 terminating
2024-05-15 18:53:55.088 T:1243    debug <general>: Keyboard: scancode: 0x1c, sym: 0x0d, unicode: 0x0d, modifier: 0x0
2024-05-15 18:53:55.088 T:1243    debug <general>: HandleKey: return (0xf00d) pressed, window 10700, action is Select
2024-05-15 18:53:55.088 T:1243    debug <general>: AddOnLog: pvr.iptvsimple: pvr.iptvsimple - FormatDateTimeNowOnly - "plugin://plugin.video.nz.freeview/?_=play&slug=mjh-three&_is_live=1&_noresume=.pvr"
2024-05-15 18:53:55.088 T:1251     info <general>: CActiveAESink::OpenSink - initialize sink
2024-05-15 18:53:55.088 T:1243    debug <general>: AddOnLog: pvr.iptvsimple: pvr.iptvsimple - FormatDateTimeNowOnly - "plugin://plugin.video.nz.freeview/?_=play&slug=mjh-three&_is_live=1&_noresume=.pvr"
2024-05-15 18:53:55.088 T:1243     info <general>: AddOnLog: pvr.iptvsimple: pvr.iptvsimple - GetChannelStreamProperties - Live Stream URL: plugin://plugin.video.nz.freeview/?_=play&slug=mjh-three&_is_live=1&_noresume=.pvr
2024-05-15 18:53:55.088 T:1251    debug <general>: CActiveAESink::OpenSink - trying to open device ALSA:hdmi:CARD=vc4hdmi0,DEV=0
2024-05-15 18:53:55.088 T:1251     info <general>: CAESinkALSA::Initialize - Attempting to open device "hdmi:CARD=vc4hdmi0,DEV=0"
2024-05-15 18:53:55.090 T:1251     info <general>: CAESinkALSA::Initialize - Opened device "hdmi:CARD=vc4hdmi0,DEV=0,AES0=0x04,AES1=0x82,AES2=0x00,AES3=0x00"
2024-05-15 18:53:55.090 T:1251     info <general>: CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2024-05-15 18:53:55.090 T:1251     info <general>: CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE3
2024-05-15 18:53:55.090 T:1251    debug <general>: CAESinkALSA::InitializeHW - Request: periodSize 2205, bufferSize 8820
2024-05-15 18:53:55.090 T:1251    debug <general>: CAESinkALSA::InitializeHW - Got: periodSize 2205, bufferSize 8820
2024-05-15 18:53:55.090 T:1251    debug <general>: CAESinkALSA::InitializeHW - Setting timeout to 200 ms
2024-05-15 18:53:55.090 T:1251    debug <general>: CAESinkALSA::GetChannelLayout - Input Channel Count: 2 Output Channel Count: 2
2024-05-15 18:53:55.090 T:1251    debug <general>: CAESinkALSA::GetChannelLayout - Requested Layout: FL, FR
2024-05-15 18:53:55.090 T:1251    debug <general>: CAESinkALSA::GetChannelLayout - Got Layout: FL, FR (ALSA: FL FR)
2024-05-15 18:53:55.090 T:1251    debug <general>: CActiveAESink::OpenSink - ALSA Initialized:
2024-05-15 18:53:55.090 T:1251    debug <general>:   Output Device : vc4-hdmi-0 (vc4hdmi0)
2024-05-15 18:53:55.090 T:1251    debug <general>:   Sample Rate   : 44100
2024-05-15 18:53:55.090 T:1251    debug <general>:   Sample Format : AE_FMT_S24NE3
2024-05-15 18:53:55.090 T:1251    debug <general>:   Channel Count : 2
2024-05-15 18:53:55.090 T:1251    debug <general>:   Channel Layout: FL, FR
2024-05-15 18:53:55.090 T:1251    debug <general>:   Frames        : 2205
2024-05-15 18:53:55.090 T:1251    debug <general>:   Frame Size    : 6
2024-05-15 18:53:55.100 T:1243    debug <general>: CScriptRunner: running add-on script IPTV NZ('plugin://plugin.video.nz.freeview/', '1822', '?_=play&slug=mjh-three&_is_live=1&_noresume=.pvr')
2024-05-15 18:53:55.100 T:866250   debug <general>: Thread LanguageInvoker start, auto delete: false
2024-05-15 18:53:55.100 T:866250   debug <general>: initializing python engine.
2024-05-15 18:53:55.100 T:866250   debug <general>: CPythonInvoker(2117, /storage/.kodi/addons/plugin.video.nz.freeview/default.py): start processing
2024-05-15 18:53:55.110 T:866250   debug <general>: -->Python Interpreter Initialized<--
2024-05-15 18:53:55.110 T:866250   debug <general>: 

2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117, /storage/.kodi/addons/plugin.video.nz.freeview/default.py): the source file to load is "/storage/.kodi/addons/plugin.video.nz.freeview/default.py"
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117): full python path:
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117):   custom python path:
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117):     /storage/.kodi/addons/plugin.video.nz.freeview
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117):     /storage/.kodi/addons/script.module.slyguy/resources/modules
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117):     /storage/.kodi/addons/slyguy.dependencies/resources/modules
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117):   default python path:
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117):     /usr/lib/python311.zip
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117):     /usr/lib/python3.11
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117):     /usr/lib/python3.11/lib-dynload
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117):     /usr/lib/python3.11/site-packages
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117): adding args:
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117):  plugin://plugin.video.nz.freeview/
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117):  1822
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117):  ?_=play&slug=mjh-three&_is_live=1&_noresume=.pvr
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117):  resume:false
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117, /storage/.kodi/addons/plugin.video.nz.freeview/default.py): entering source directory /storage/.kodi/addons/plugin.video.nz.freeview
2024-05-15 18:53:55.110 T:866250   debug <general>: CPythonInvoker(2117, /storage/.kodi/addons/plugin.video.nz.freeview/default.py): instantiating addon using automatically obtained id of "plugin.video.nz.freeview" dependent on version 0.0.0 of the xbmc.python api
2024-05-15 18:53:55.120 T:866251   debug <general>: Thread ScriptObs start, auto delete: false
2024-05-15 18:53:55.173 T:866250   debug <general>: plugin.video.nz.freeview - sys.path: ['/storage/.kodi/addons/plugin.video.nz.freeview', '/storage/.kodi/addons/script.module.slyguy/resources/modules', '/storage/.kodi/addons/slyguy.dependencies/resources/modules', '/usr/lib/python311.zip', '/usr/lib/python3.11', '/usr/lib/python3.11/lib-dynload', '/usr/lib/python3.11/site-packages']
2024-05-15 18:53:55.304 T:866250   debug <general>: plugin.video.nz.freeview - OpenSSL 3.2.1 30 Jan 2024
2024-05-15 18:53:55.309 T:866250   debug <general>: plugin.video.nz.freeview - SIGNAL: before_dispatch
2024-05-15 18:53:55.309 T:866250   debug <CAddonSettings[0@plugin.video.nz.freeview]>: trying to load setting definitions from old format...
2024-05-15 18:53:55.310 T:866250    info <CSettingsManager>: Skipped 1 duplicate messages..
2024-05-15 18:53:55.310 T:866250   debug <CSettingsManager>: requested setting (_addon_md5) was not found.
2024-05-15 18:53:55.310 T:866250   debug <CSettingsManager>: requested setting (_arch) was not found.
2024-05-15 18:53:55.310 T:866250   debug <CSettingsManager>: requested setting (_last_updates_check) was not found.
2024-05-15 18:53:55.310 T:866250   debug <CSettingsManager>: requested setting (_mac) was not found.
2024-05-15 18:53:55.310 T:866250   debug <CSettingsManager>: requested setting (_updates) was not found.
2024-05-15 18:53:55.310 T:866250   debug <CSettingsManager>: requested setting (_wv_last_check) was not found.
2024-05-15 18:53:55.310 T:866250   debug <CSettingsManager>: requested setting (_wv_latest_hash) was not found.
2024-05-15 18:53:55.311 T:866250   debug <general>: plugin.video.nz.freeview - Cache data loaded
2024-05-15 18:53:55.311 T:866250   debug <general>: plugin.video.nz.freeview - Router Parsed: 'plugin://plugin.video.nz.freeview/?_=play&slug=mjh-three&_is_live=1&_noresume=.pvr' => play {'slug': 'mjh-three', '_noresume': '.pvr', '_url': 'plugin://plugin.video.nz.freeview/?_=play&slug=mjh-three&_is_live=1&_noresume=.pvr', '_is_live': True}
2024-05-15 18:53:55.312 T:866250   debug <general>: plugin.video.nz.freeview - Cache Set: XllIFt
2024-05-15 18:53:55.312 T:866250   debug <CSettingsManager>: requested setting (proxy_server) was not found.
2024-05-15 18:53:55.312 T:866250   debug <general>: plugin.video.nz.freeview - Attempt 1/1: GET https://i.mjh.nz/nz/tv.json.gz
2024-05-15 18:53:55.320 T:1243    debug <general>: ------ Window Init (DialogBusy.xml) ------
2024-05-15 18:54:00.469 T:866252   debug <general>: Thread JobWorker start, auto delete: true
2024-05-15 18:54:00.469 T:866252   debug <general>: [threads] name: 'JobWorker' priority: '1'
2024-05-15 18:54:25.318 T:866250   error <general>: plugin.video.nz.freeview - The DNS operation timed out after 30.000536680221558 seconds
                                                   Traceback (most recent call last):
                                                     File "/storage/.kodi/addons/script.module.slyguy/resources/modules/slyguy/session.py", line 169, in getaddrinfo
                                                       host = self.session_data['resolver'][1].query(host, source=self.session_data['interface_ip'])[0].to_text()
                                                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                                     File "/storage/.kodi/addons/slyguy.dependencies/resources/modules/dns/resolver.py", line 997, in query
                                                       timeout = self._compute_timeout(start, lifetime)
                                                                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                                     File "/storage/.kodi/addons/slyguy.dependencies/resources/modules/dns/resolver.py", line 804, in _compute_timeout
                                                       raise Timeout(timeout=duration)
                                                   dns.exception.Timeout: The DNS operation timed out after 30.000536680221558 seconds
2024-05-15 18:54:25.318 T:866250   error <general>: plugin.video.nz.freeview - Failed to resolve. Falling back to dns lookup
2024-05-15 18:54:25.333 T:866250   debug <general>: plugin.video.nz.freeview - DNS Resolver: i.mjh.nz -> 172.67.186.9
2024-05-15 18:54:25.423 T:866250   debug <general>: plugin.video.nz.freeview - SSL Cipher: i.mjh.nz - ('TLS_AES_256_GCM_SHA384', 'TLSv1.3', 256)
2024-05-15 18:54:25.472 T:866250   debug <general>: plugin.video.nz.freeview - Cache Set: VAcDlc
2024-05-15 18:54:25.475 T:866250   debug <CSettingsManager>: requested setting (use_ia_hls) was not found.
2024-05-15 18:54:25.476 T:866250   debug <general>: plugin.video.nz.freeview - Cache Hit: XllIFt
2024-05-15 18:54:25.476 T:866250    info <CSettingsManager>: Skipped 1 duplicate messages..
2024-05-15 18:54:25.476 T:866250   debug <CSettingsManager>: requested setting (proxy_server) was not found.
2024-05-15 18:54:25.476 T:866250   debug <general>: plugin.video.nz.freeview - Attempt 1/1: HEAD https://i.mjh.nz/three.m3u8
2024-05-15 18:54:30.470 T:866252   debug <general>: Thread JobWorker 140729851047680 terminating (autodelete)
2024-05-15 18:54:55.481 T:866250   error <general>: plugin.video.nz.freeview - The DNS operation timed out after 30.00108814239502 seconds
                                                   Traceback (most recent call last):
                                                     File "/storage/.kodi/addons/script.module.slyguy/resources/modules/slyguy/session.py", line 169, in getaddrinfo
                                                       host = self.session_data['resolver'][1].query(host, source=self.session_data['interface_ip'])[0].to_text()
                                                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                                     File "/storage/.kodi/addons/slyguy.dependencies/resources/modules/dns/resolver.py", line 997, in query
                                                       timeout = self._compute_timeout(start, lifetime)
                                                                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                                     File "/storage/.kodi/addons/slyguy.dependencies/resources/modules/dns/resolver.py", line 804, in _compute_timeout
                                                       raise Timeout(timeout=duration)
                                                   dns.exception.Timeout: The DNS operation timed out after 30.00108814239502 seconds
2024-05-15 18:54:55.481 T:866250   error <general>: plugin.video.nz.freeview - Failed to resolve. Falling back to dns lookup
2024-05-15 18:54:55.483 T:866250   debug <general>: plugin.video.nz.freeview - DNS Resolver: i.mjh.nz -> 172.67.186.9
2024-05-15 18:54:55.575 T:866250   debug <general>: plugin.video.nz.freeview - SSL Cipher: i.mjh.nz - ('TLS_AES_256_GCM_SHA384', 'TLSv1.3', 256)
2024-05-15 18:54:55.625 T:866250   debug <CSettingsManager>: requested setting (audio_whitelist) was not found.
2024-05-15 18:54:55.625 T:866250   debug <CSettingsManager>: requested setting (subs_whitelist) was not found.
2024-05-15 18:54:55.625 T:866250   debug <CSettingsManager>: requested setting (audio_description) was not found.
2024-05-15 18:54:55.625 T:866250   debug <CSettingsManager>: requested setting (subs_forced) was not found.
2024-05-15 18:54:55.625 T:866250   debug <CSettingsManager>: requested setting (subs_non_forced) was not found.
2024-05-15 18:54:55.626 T:866250   debug <general>: plugin.video.nz.freeview - Cache Set: +KvvAp
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (proxy_server) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (vp9) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (av1) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (hevc) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (enable_h265) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (h265) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (enable_hdr) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (hdr10) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (dolby_vision) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (atmos_enabled) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (dolby_atmos) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (ac3_enabled) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (ac3) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (ec3_enabled) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (ec3) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (default_language) was not found.
2024-05-15 18:54:55.626 T:866250   debug <CSettingsManager>: requested setting (default_subtitle) was not found.
2024-05-15 18:54:55.626 T:866250   debug <general>: plugin.video.nz.freeview - SIGNAL: after_dispatch
2024-05-15 18:54:55.628 T:866250   debug <general>: plugin.video.nz.freeview - SIGNAL: on_close
2024-05-15 18:54:55.628 T:866250   debug <general>: CPythonInvoker(2117, /storage/.kodi/addons/plugin.video.nz.freeview/default.py): script successfully run
2024-05-15 18:54:55.655 T:1243    debug <general>: ------ Window Deinit (DialogBusy.xml) ------
2024-05-15 18:54:55.655 T:866251   debug <general>: Thread ScriptObs 140729989787392 terminating
2024-05-15 18:54:55.655 T:1243    debug <general>: connect replacing configured host 192.168.178.45 with resolved host 192.168.178.45
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerCoreFactory::GetPlayers(http://127.0.0.1:52103/https://fv23-three.fullscreen.nz/index.m3u8|referer=%20&seekable=0&user-agent=Mozilla/5.0%20%28Windows%20NT%2010.0%3B%20Win64%3B%20x64%29%20AppleWebKit/537.36%20%28KHTML%2C%20like%20Gecko%29%20Chrome/98.0.4758.102%20Safari/537.36)
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: considering rule: system rules
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: matches rule: system rules
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: considering rule: mms/udp
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: considering rule: lastfm/shout
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: considering rule: rtmp
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: considering rule: rtsp
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: considering rule: streams
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: matches rule: streams
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: considering rule: aacp/sdp
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: considering rule: mp2
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: considering rule: dvd
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: considering rule: discimage
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: considering rule: sdp/asf
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: considering rule: nsv
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerSelectionRule::GetPlayers: considering rule: radio
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerCoreFactory::GetPlayers: matched 0 rules with players
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (VideoPlayer)
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerCoreFactory::GetPlayers: for video=true, audio=false
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerCoreFactory::GetPlayers: for video=true, audio=true
2024-05-15 18:54:55.679 T:1243    debug <general>: CPlayerCoreFactory::GetPlayers: added 1 players
2024-05-15 18:54:55.679 T:866277   debug <general>: Thread RefClock start, auto delete: false
2024-05-15 18:54:55.679 T:866277   debug <general>: CVideoSyncGbm::Setup setting up
2024-05-15 18:54:55.679 T:866277    info <general>: CVideoSyncGbm::Setup: opened (fd:0 crtc:86 seq:12713946 ns:423802525485884:423798798298651)
2024-05-15 18:54:55.679 T:866277   debug <general>: CVideoSyncGbm::GetFps: fps:30
2024-05-15 18:54:55.679 T:866277   debug <general>: CVideoReferenceClock: Detected refreshrate: 30.000 hertz
2024-05-15 18:54:55.679 T:866277   debug <general>: [threads] name: 'RefClock' priority: '-1'
2024-05-15 18:54:55.679 T:866277   debug <general>: CVideoSyncGbm::Run: started 0
2024-05-15 18:54:55.680 T:1243    debug <general>: Radio UECP (RDS) Processor - new CDVDRadioRDSData
2024-05-15 18:54:55.680 T:1243    debug <general>: Audio ID3 tag processor - new CVideoPlayerAudioID3
2024-05-15 18:54:55.680 T:1243     info <general>: VideoPlayer::OpenFile: pvr://channels/tv/All%20channels@-1/1@pvr.iptvsimple_1101255766.pvr
2024-05-15 18:54:55.680 T:866278   debug <general>: Thread VideoPlayer start, auto delete: false
2024-05-15 18:54:55.680 T:1243    debug <general>: OnPlayBackStarted: CApplication::OnPlayBackStarted
2024-05-15 18:54:55.681 T:866279   debug <general>: Thread JobWorker start, auto delete: true
2024-05-15 18:54:55.681 T:866279   debug <general>: [threads] name: 'JobWorker' priority: '1'
2024-05-15 18:54:55.681 T:866278    info <general>: Creating InputStream
2024-05-15 18:54:55.681 T:866279   debug <general>: connect replacing configured host 192.168.178.45 with resolved host 192.168.178.45
2024-05-15 18:54:55.681 T:866278    info <general>: Creating Demuxer
2024-05-15 18:54:55.681 T:866278   debug <general>: CDVDDemuxFFmpeg::GetFFMpegOptionsFromInput() adding custom header option 'referer:  '
2024-05-15 18:54:55.681 T:866278   debug <general>: CDVDDemuxFFmpeg::GetFFMpegOptionsFromInput() adding ffmpeg option 'seekable: 0'
2024-05-15 18:54:55.681 T:866278   debug <general>: CDVDDemuxFFmpeg::GetFFMpegOptionsFromInput() adding ffmpeg option 'user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.102 Safari/537.36'
2024-05-15 18:54:55.681 T:866278   debug <general>: easy_acquire - Created session to http://127.0.0.1
2024-05-15 18:54:55.682 T:866280   debug <general>: script.module.slyguy - REQUEST IN: https://fv23-three.fullscreen.nz/index.m3u8 (GET)
2024-05-15 18:54:55.683 T:866280   debug <general>: script.module.slyguy - Session created from proxy data
2024-05-15 18:54:55.684 T:866280   debug <general>: script.module.slyguy - REQUEST OUT: https://fv23-three.fullscreen.nz/index.m3u8 (GET)
2024-05-15 18:54:55.688 T:866279   debug <general>: Loading settings for pvr://channels/tv/All%20channels@-1/1@pvr.iptvsimple_1101255766.pvr
2024-05-15 18:54:55.736 T:1243    debug <general>: CPlayerGUIInfo::InitCurrentItem(pvr://channels/tv/All%20channels@-1/1@pvr.iptvsimple_1101255766.pvr)
2024-05-15 18:54:55.736 T:866281   debug <general>: Thread JobWorker start, auto delete: true
2024-05-15 18:54:55.736 T:866281   debug <general>: [threads] name: 'JobWorker' priority: '1'
2024-05-15 18:54:55.736 T:1243    debug <general>: CVideoGUIInfo::InitCurrentItem(pvr://channels/tv/All%20channels@-1/1@pvr.iptvsimple_1101255766.pvr)
2024-05-15 18:54:55.736 T:1243    debug <general>: CPlayerGUIInfo::InitCurrentItem(pvr://channels/tv/All%20channels@-1/1@pvr.iptvsimple_1101255766.pvr)
2024-05-15 18:54:55.736 T:1244    debug <UPNP::BuildObject>: Building didl for plain object 'pvr://channels/tv/All%20channels@-1/1@pvr.iptvsimple_1101255766.pvr' (encoded value: 'cHZyOi8vY2hhbm5lbHMvdHYvQWxsJTIwY2hhbm5lbHNALTEvMUBwdnIuaXB0dnNpbXBsZV8xMTAxMjU1NzY2LnB2cg==')
2024-05-15 18:54:55.742 T:1309    debug <general>: connect replacing configured host 192.168.178.45 with resolved host 192.168.178.45
2024-05-15 18:54:55.752 T:866280   debug <general>: script.module.slyguy - DNS Resolver: fv23-three.fullscreen.nz -> 18.65.244.108
2024-05-15 18:54:55.835 T:866280   debug <general>: script.module.slyguy - SSL Cipher: fv23-three.fullscreen.nz - ('TLS_AES_128_GCM_SHA256', 'TLSv1.3', 128)
2024-05-15 18:54:55.836 T:1243    debug <general>: ------ Window Init (DialogBusy.xml) ------
2024-05-15 18:54:55.874 T:866280   debug <general>: script.module.slyguy - RESPONSE IN: https://fv23-three.fullscreen.nz/index.m3u8 (200)
2024-05-15 18:54:55.874 T:866280   debug <general>: script.module.slyguy - RESPONSE OUT: https://fv23-three.fullscreen.nz/index.m3u8 (200)
2024-05-15 18:54:55.875 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Skip ('#EXT-X-VERSION:3')
2024-05-15 18:54:55.875 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Skip ('#EXT-X-INDEPENDENT-SEGMENTS')
2024-05-15 18:54:55.875 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Opening 'http://127.0.0.1:52103/https://fv23-three.fullscreen.nz/index_9.m3u8' for reading
2024-05-15 18:54:55.876 T:866282   debug <general>: script.module.slyguy - REQUEST IN: https://fv23-three.fullscreen.nz/index_9.m3u8 (GET)
2024-05-15 18:54:55.876 T:866282   debug <general>: script.module.slyguy - REQUEST OUT: https://fv23-three.fullscreen.nz/index_9.m3u8 (GET)
2024-05-15 18:54:55.881 T:866282   debug <general>: script.module.slyguy - DNS Resolver: fv23-three.fullscreen.nz -> 18.65.244.108
2024-05-15 18:54:55.965 T:866282   debug <general>: script.module.slyguy - SSL Cipher: fv23-three.fullscreen.nz - ('TLS_AES_128_GCM_SHA256', 'TLSv1.3', 128)
2024-05-15 18:54:56.004 T:866282   debug <general>: script.module.slyguy - RESPONSE IN: https://fv23-three.fullscreen.nz/index_9.m3u8 (206)
2024-05-15 18:54:56.005 T:866282   debug <general>: script.module.slyguy - RESPONSE OUT: https://fv23-three.fullscreen.nz/index_9.m3u8 (206)
2024-05-15 18:54:56.005 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Skip ('#EXT-X-VERSION:3')
2024-05-15 18:54:56.005 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Skip ('#EXT-X-DISCONTINUITY-SEQUENCE:64')
2024-05-15 18:54:56.005 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Opening 'http://127.0.0.1:52103/https://fv23-three.fullscreen.nz/index_9_3781600.ts?m=1692137281' for reading
2024-05-15 18:54:56.006 T:866283   debug <general>: script.module.slyguy - REQUEST IN: https://fv23-three.fullscreen.nz/index_9_3781600.ts?m=1692137281 (GET)
2024-05-15 18:54:56.006 T:866283   debug <general>: script.module.slyguy - REQUEST OUT: https://fv23-three.fullscreen.nz/index_9_3781600.ts?m=1692137281 (GET)
2024-05-15 18:54:56.044 T:866283   debug <general>: script.module.slyguy - RESPONSE IN: https://fv23-three.fullscreen.nz/index_9_3781600.ts?m=1692137281 (206)
2024-05-15 18:54:56.044 T:866283   debug <general>: script.module.slyguy - RESPONSE OUT: https://fv23-three.fullscreen.nz/index_9_3781600.ts?m=1692137281 (206)
2024-05-15 18:54:56.076 T:866278   debug <general>: CDVDDemuxFFmpeg::GetFFMpegOptionsFromInput() adding custom header option 'referer:  '
2024-05-15 18:54:56.076 T:866278   debug <general>: CDVDDemuxFFmpeg::GetFFMpegOptionsFromInput() adding ffmpeg option 'seekable: 0'
2024-05-15 18:54:56.076 T:866278   debug <general>: CDVDDemuxFFmpeg::GetFFMpegOptionsFromInput() adding ffmpeg option 'user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.102 Safari/537.36'
2024-05-15 18:54:56.077 T:866284   debug <general>: script.module.slyguy - REQUEST IN: https://fv23-three.fullscreen.nz/index.m3u8 (GET)
2024-05-15 18:54:56.077 T:866284   debug <general>: script.module.slyguy - REQUEST OUT: https://fv23-three.fullscreen.nz/index.m3u8 (GET)
2024-05-15 18:54:56.083 T:866284   debug <general>: script.module.slyguy - DNS Resolver: fv23-three.fullscreen.nz -> 18.65.244.72
2024-05-15 18:54:56.170 T:866284   debug <general>: script.module.slyguy - SSL Cipher: fv23-three.fullscreen.nz - ('TLS_AES_128_GCM_SHA256', 'TLSv1.3', 128)
2024-05-15 18:54:56.208 T:866284    info <general>: Skipped 3 duplicate messages..
2024-05-15 18:54:56.208 T:866284   debug <general>: script.module.slyguy - RESPONSE IN: https://fv23-three.fullscreen.nz/index.m3u8 (200)
2024-05-15 18:54:56.209 T:866284   debug <general>: script.module.slyguy - RESPONSE OUT: https://fv23-three.fullscreen.nz/index.m3u8 (200)
2024-05-15 18:54:56.209 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Skip ('#EXT-X-VERSION:3')
2024-05-15 18:54:56.209 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Skip ('#EXT-X-INDEPENDENT-SEGMENTS')
2024-05-15 18:54:56.209 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Opening 'http://127.0.0.1:52103/https://fv23-three.fullscreen.nz/index_9.m3u8' for reading
2024-05-15 18:54:56.210 T:866285   debug <general>: script.module.slyguy - REQUEST IN: https://fv23-three.fullscreen.nz/index_9.m3u8 (GET)
2024-05-15 18:54:56.210 T:866285   debug <general>: script.module.slyguy - REQUEST OUT: https://fv23-three.fullscreen.nz/index_9.m3u8 (GET)
2024-05-15 18:54:56.215 T:866285   debug <general>: script.module.slyguy - DNS Resolver: fv23-three.fullscreen.nz -> 18.65.244.85
2024-05-15 18:54:56.301 T:866285   debug <general>: script.module.slyguy - SSL Cipher: fv23-three.fullscreen.nz - ('TLS_AES_128_GCM_SHA256', 'TLSv1.3', 128)
2024-05-15 18:54:56.340 T:866285    info <general>: Skipped 3 duplicate messages..
2024-05-15 18:54:56.340 T:866285   debug <general>: script.module.slyguy - RESPONSE IN: https://fv23-three.fullscreen.nz/index_9.m3u8 (206)
2024-05-15 18:54:56.341 T:866285   debug <general>: script.module.slyguy - RESPONSE OUT: https://fv23-three.fullscreen.nz/index_9.m3u8 (206)
2024-05-15 18:54:56.341 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Skip ('#EXT-X-VERSION:3')
2024-05-15 18:54:56.341 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Skip ('#EXT-X-DISCONTINUITY-SEQUENCE:64')
2024-05-15 18:54:56.341 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Opening 'http://127.0.0.1:52103/https://fv23-three.fullscreen.nz/index_9_3781601.ts?m=1692137281' for reading
2024-05-15 18:54:56.342 T:866286   debug <general>: script.module.slyguy - REQUEST IN: https://fv23-three.fullscreen.nz/index_9_3781601.ts?m=1692137281 (GET)
2024-05-15 18:54:56.342 T:866286   debug <general>: script.module.slyguy - REQUEST OUT: https://fv23-three.fullscreen.nz/index_9_3781601.ts?m=1692137281 (GET)
2024-05-15 18:54:56.379 T:866286   debug <general>: script.module.slyguy - RESPONSE IN: https://fv23-three.fullscreen.nz/index_9_3781601.ts?m=1692137281 (206)
2024-05-15 18:54:56.379 T:866286   debug <general>: script.module.slyguy - RESPONSE OUT: https://fv23-three.fullscreen.nz/index_9_3781601.ts?m=1692137281 (206)
2024-05-15 18:54:56.411 T:866278   debug <general>: Open - avformat_find_stream_info starting
2024-05-15 18:54:56.599 T:866278   debug <general>: Open - av_find_stream_info finished
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]: Input #0, hls, from 'http://127.0.0.1:52103/https://fv23-three.fullscreen.nz/index.m3u8':
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]:   Duration: N/A, start: 57649.237156, bitrate: N/A
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]:   Program 0 
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]:     Metadata:
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]:       variant_bitrate : 8461492
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]:   Stream #0:0: Video: h264 (Main) ([27][0][0][0] / 0x001B), yuv420p(tv, bt709), 1920x1080 [SAR 1:1 DAR 16:9], 25 fps, 25 tbr, 90k tbn
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]:     Metadata:
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]:       variant_bitrate : 8461492
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]:   Stream #0:1: Audio: aac (LC) ([15][0][0][0] / 0x000F), 48000 Hz, stereo, fltp
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]:     Metadata:
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]:       variant_bitrate : 8461492
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]:   Stream #0:2: Data: scte_35
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]:     Metadata:
2024-05-15 18:54:56.599 T:866278    info <general>: ffmpeg[0x290f2fc0]:       variant_bitrate : 8461492
2024-05-15 18:54:56.599 T:866278   debug <general>: CDVDDemuxFFmpeg::AddStream ID: 0
2024-05-15 18:54:56.599 T:866278   debug <general>: CDVDDemuxFFmpeg::AddStream ID: 1
2024-05-15 18:54:56.599 T:866278   debug <general>: CDVDDemuxFFmpeg::AddStream ID: 2
2024-05-15 18:54:56.599 T:866278    info <general>: Opening stream: 0 source: 256
2024-05-15 18:54:56.600 T:866278    info <general>: [WHITELIST] Searching the whitelist for: width: 1920, height: 1080, fps: 25.000, 3D: false
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] Using the default whitelist because the user whitelist is empty
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] Searching for an exact resolution with an exact refresh rate
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] No match for an exact resolution with an exact refresh rate
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] Searching for an exact resolution with double the refresh rate
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] No match for an exact resolution with double the refresh rate
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] Searching for an exact resolution with a 3:2 pulldown refresh rate
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] No match for a resolution with a 3:2 pulldown refresh rate
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] Searching for a desktop resolution with an exact refresh rate
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] No match for a desktop resolution with an exact refresh rate
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] Searching for a desktop resolution with double the refresh rate
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] No match for a desktop resolution with double the refresh rate
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] Searching for a desktop resolution with a 3:2 pulldown refresh rate
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] No match for a desktop resolution with a 3:2 pulldown refresh rate
2024-05-15 18:54:56.600 T:866278   debug <general>: [WHITELIST] No resolution matched
2024-05-15 18:54:56.600 T:866278    info <general>: Display resolution ADJUST : 3840x2160 @ 30.000000 Hz (16) (weight: 0.000)
2024-05-15 18:54:56.623 T:866278    info <general>: Creating video codec with codec id: 27
2024-05-15 18:54:56.623 T:866278    info <general>: CDVDVideoCodecDRMPRIME::Open - using decoder V4L2 mem2mem H.264 decoder wrapper
2024-05-15 18:54:56.623 T:866278   error <general>: ffmpeg[0x290f2fc0]: [h264_v4l2m2m] Could not find a valid device
2024-05-15 18:54:56.623 T:866278   error <general>: ffmpeg[0x290f2fc0]: [h264_v4l2m2m] can't configure decoder
2024-05-15 18:54:56.623 T:866278    info <general>: CDVDVideoCodecDRMPRIME::Open - unable to open codec
2024-05-15 18:54:56.624 T:866278    info <general>: CDVDVideoCodecDRMPRIME::Open - using decoder H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
2024-05-15 18:54:56.625 T:866278   debug <general>: CVideoPlayerVideo::OpenStream - open stream with codec id: 27
2024-05-15 18:54:56.625 T:866278    info <general>: Creating video thread
2024-05-15 18:54:56.625 T:866291   debug <general>: Thread VideoPlayerVideo start, auto delete: false
2024-05-15 18:54:56.625 T:866291    info <general>: running thread: video_thread
2024-05-15 18:54:56.625 T:866291   debug <general>: CVideoPlayerVideo - CDVDMsg::GENERAL_PAUSE: false
2024-05-15 18:54:56.625 T:866278    info <general>: Opening stream: 1 source: 256
2024-05-15 18:54:56.625 T:866278    info <general>: Finding audio codec for: 86018
2024-05-15 18:54:56.626 T:866278    info <general>: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2024-05-15 18:54:56.626 T:866278    info <general>: Creating audio thread
2024-05-15 18:54:56.626 T:866292   debug <general>: Thread VideoPlayerAudio start, auto delete: false
2024-05-15 18:54:56.626 T:866292    info <general>: running thread: CVideoPlayerAudio::Process()
2024-05-15 18:54:56.626 T:866278   debug <general>: CVideoPlayer::SetCaching - caching state 2
2024-05-15 18:54:56.626 T:866278   debug <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2024-05-15 18:54:56.626 T:866278   debug <general>: CVideoPlayer::HandleMessages - player 2 reported state: 0
2024-05-15 18:54:56.626 T:866278   debug <general>: CDVDClock::SetSpeedAdjust - adjusted:-0.050000
2024-05-15 18:54:56.626 T:866281   debug <general>: OnAVChange: CApplication::OnAVChange
2024-05-15 18:54:56.627 T:866291   debug <general>: CVideoPlayerVideo - Stillframe left, switching to normal playback
2024-05-15 18:54:56.638 T:866292   debug <general>: CVideoPlayerAudio - CDVDMsg::GENERAL_PAUSE: false
2024-05-15 18:54:56.638 T:866292   debug <general>: CDVDAudio::Pause - pausing audio stream
2024-05-15 18:54:56.638 T:866278   debug <general>: CVideoPlayer::HandleMessages - player 1 reported state: 0
2024-05-15 18:54:56.639 T:866292    info <general>: Creating audio stream (codec id: 86018, channels: 2, sample rate: 48000, no pass-through)
2024-05-15 18:54:56.639 T:866292   debug <general>: CVideoPlayerAudio:: synctype set to 1: resample
2024-05-15 18:54:56.642 T:1251     info <general>: CActiveAESink::OpenSink - initialize sink
2024-05-15 18:54:56.642 T:1251    debug <general>: CActiveAESink::OpenSink - trying to open device ALSA:hdmi:CARD=vc4hdmi0,DEV=0
2024-05-15 18:54:56.642 T:1251     info <general>: CAESinkALSA::Initialize - Attempting to open device "hdmi:CARD=vc4hdmi0,DEV=0"
2024-05-15 18:54:56.649 T:1251     info <general>: CAESinkALSA::Initialize - Opened device "hdmi:CARD=vc4hdmi0,DEV=0,AES0=0x04,AES1=0x82,AES2=0x00,AES3=0x02"
2024-05-15 18:54:56.649 T:1251     info <general>: CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2024-05-15 18:54:56.649 T:1251     info <general>: CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE3
2024-05-15 18:54:56.649 T:1251    debug <general>: CAESinkALSA::InitializeHW - Request: periodSize 2400, bufferSize 9600
2024-05-15 18:54:56.649 T:1251    debug <general>: CAESinkALSA::InitializeHW - Got: periodSize 2400, bufferSize 9600
2024-05-15 18:54:56.649 T:1251    debug <general>: CAESinkALSA::InitializeHW - Setting timeout to 200 ms
2024-05-15 18:54:56.649 T:1251    debug <general>: CAESinkALSA::GetChannelLayout - Input Channel Count: 2 Output Channel Count: 2
2024-05-15 18:54:56.649 T:1251    debug <general>: CAESinkALSA::GetChannelLayout - Requested Layout: FL, FR
2024-05-15 18:54:56.649 T:1251    debug <general>: CAESinkALSA::GetChannelLayout - Got Layout: FL, FR (ALSA: FL FR)
2024-05-15 18:54:56.649 T:1251    debug <general>: CActiveAESink::OpenSink - ALSA Initialized:
2024-05-15 18:54:56.649 T:1251    debug <general>:   Output Device : vc4-hdmi-0 (vc4hdmi0)
2024-05-15 18:54:56.649 T:1251    debug <general>:   Sample Rate   : 48000
2024-05-15 18:54:56.649 T:1251    debug <general>:   Sample Format : AE_FMT_S24NE3
2024-05-15 18:54:56.649 T:1251    debug <general>:   Channel Count : 2
2024-05-15 18:54:56.649 T:1251    debug <general>:   Channel Layout: FL, FR
2024-05-15 18:54:56.649 T:1251    debug <general>:   Frames        : 2400
2024-05-15 18:54:56.649 T:1251    debug <general>:   Frame Size    : 6
2024-05-15 18:54:56.650 T:1250    debug <general>: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
2024-05-15 18:54:56.669 T:1309     info <general>: Skipped 1 duplicate messages..
2024-05-15 18:54:56.669 T:1309    debug <general>: connect replacing configured host 192.168.178.45 with resolved host 192.168.178.45
2024-05-15 18:54:56.671 T:866291   error <general>: ffmpeg[0x257dc910]: [deinterlace_v4l2m2m] Could not find a valid device
2024-05-15 18:54:56.671 T:866291   error <general>: ffmpeg[0x257dc910]: [Parsed_deinterlace_v4l2m2m_0] Failed to configure output pad on Parsed_deinterlace_v4l2m2m_0
2024-05-15 18:54:56.671 T:866291   error <general>: CDVDVideoCodecDRMPRIME::FilterOpen - avfilter_graph_config:  Invalid argument (-22)
2024-05-15 18:54:56.671 T:866291   debug <general>: CDVDVideoCodecDRMPRIME::FilterTest - found deinterlacing filter bwdif
2024-05-15 18:54:56.671 T:866291   debug <general>: CRenderManager::Configure - change configuration. 1920x1080. display: 1920x1080. framerate: 25.00.
2024-05-15 18:54:56.673 T:866278   debug <general>: CVideoPlayer::HandleMessages - player started 1
2024-05-15 18:54:56.673 T:866278   debug <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2024-05-15 18:54:56.673 T:866281   debug <general>: OnAVChange: CApplication::OnAVChange
2024-05-15 18:54:56.691 T:1243    debug <general>: DeleteRenderer - deleting renderer
2024-05-15 18:54:56.691 T:1243    debug <general>: LinuxRendererGLES: Cleaning up GLES resources
2024-05-15 18:54:56.691 T:1243    debug <general>: SetHDR: setting connector colorspace to Default
2024-05-15 18:54:56.691 T:1243    debug <general>: CDRMPlane::SupportsFormatAndModifier - found plane format (YU12) and modifier (LINEAR)
2024-05-15 18:54:56.691 T:1243    debug <general>: CRenderManager::Configure - 5
2024-05-15 18:54:56.694 T:1243    debug <general>: CVideoLayerBridgeDRMPRIME::Configure - setting max bpc to 8 (true)
2024-05-15 18:54:56.694 T:1243    debug <general>: CDRMUtils::DrmFbDestroyCallback - removing framebuffer: 298
2024-05-15 18:54:56.694 T:1243    debug <general>: CDRMAtomic::FlipPage - Execute modeset at next commit
2024-05-15 18:54:56.704 T:866278   debug <general>: CVideoPlayer::HandleMessages - player started 2
2024-05-15 18:54:56.704 T:866278   debug <general>: VideoPlayer::Sync - Audio - pts: 286666.000000, cache: 517286.411650, totalcache: 800000.011921
2024-05-15 18:54:56.704 T:866278   debug <general>: VideoPlayer::Sync - Video - pts: 40000.000000, cache: 50000.000000, totalcache: 100000.000000
2024-05-15 18:54:56.704 T:866291   debug <general>: CVideoPlayerVideo - CDVDMsg::GENERAL_RESYNC(-913334.011921)
2024-05-15 18:54:56.704 T:866292   debug <general>: CVideoPlayerAudio - CDVDMsg::GENERAL_RESYNC(-913334.011921), level: 35, cache: 514720.762650
2024-05-15 18:54:56.704 T:866281   debug <general>: OnAVChange: CApplication::OnAVChange
2024-05-15 18:54:56.704 T:866292   debug <general>: CDVDAudio::Resume - resume audio stream
2024-05-15 18:54:56.704 T:866301   debug <general>: Thread JobWorker start, auto delete: true
2024-05-15 18:54:56.704 T:866301   debug <general>: [threads] name: 'JobWorker' priority: '1'
2024-05-15 18:54:56.704 T:1250    debug <general>: ActiveAE - start sync of audio stream
2024-05-15 18:54:56.704 T:866301   debug <general>: OnAVStarted: CApplication::OnAVStarted
2024-05-15 18:54:56.705 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Opening 'http://127.0.0.1:52103/https://fv23-three.fullscreen.nz/index_9_3781602.ts?m=1692137281' for reading
2024-05-15 18:54:56.706 T:866302   debug <general>: script.module.slyguy - REQUEST IN: https://fv23-three.fullscreen.nz/index_9_3781602.ts?m=1692137281 (GET)
2024-05-15 18:54:56.707 T:866302   debug <general>: script.module.slyguy - REQUEST OUT: https://fv23-three.fullscreen.nz/index_9_3781602.ts?m=1692137281 (GET)
2024-05-15 18:54:56.723 T:1243    debug <general>: Activating window ID: 12005
2024-05-15 18:54:56.723 T:1243    debug <general>: ------ Window Deinit (MyPVRChannels.xml) ------
2024-05-15 18:54:56.723 T:1243    debug <general>: FreeVisualisation() done
2024-05-15 18:54:56.727 T:1243    debug <general>: ------ Window Init (VideoFullScreen.xml) ------
2024-05-15 18:54:56.729 T:1243     info <general>: [WHITELIST] Searching the whitelist for: width: 1920, height: 1080, fps: 25.000, 3D: false
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] Using the default whitelist because the user whitelist is empty
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] Searching for an exact resolution with an exact refresh rate
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] No match for an exact resolution with an exact refresh rate
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] Searching for an exact resolution with double the refresh rate
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] No match for an exact resolution with double the refresh rate
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] Searching for an exact resolution with a 3:2 pulldown refresh rate
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] No match for a resolution with a 3:2 pulldown refresh rate
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] Searching for a desktop resolution with an exact refresh rate
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] No match for a desktop resolution with an exact refresh rate
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] Searching for a desktop resolution with double the refresh rate
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] No match for a desktop resolution with double the refresh rate
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] Searching for a desktop resolution with a 3:2 pulldown refresh rate
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] No match for a desktop resolution with a 3:2 pulldown refresh rate
2024-05-15 18:54:56.729 T:1243    debug <general>: [WHITELIST] No resolution matched
2024-05-15 18:54:56.729 T:1243     info <general>: Display resolution ADJUST : 3840x2160 @ 30.000000 Hz (16) (weight: 0.000)
2024-05-15 18:54:56.732 T:1243    debug <general>: CDRMUtils::DrmFbDestroyCallback - removing framebuffer: 300
2024-05-15 18:54:56.744 T:866302   debug <general>: script.module.slyguy - RESPONSE IN: https://fv23-three.fullscreen.nz/index_9_3781602.ts?m=1692137281 (206)
2024-05-15 18:54:56.745 T:866302   debug <general>: script.module.slyguy - RESPONSE OUT: https://fv23-three.fullscreen.nz/index_9_3781602.ts?m=1692137281 (206)
2024-05-15 18:54:56.745 T:866281   debug <general>: OnAVChange: CApplication::OnAVChange
2024-05-15 18:54:56.755 T:1243    debug <general>: ------ Window Deinit (DialogBusy.xml) ------
2024-05-15 18:54:56.757 T:1243    debug <general>: CDRMUtils::DrmFbDestroyCallback - removing framebuffer: 301
2024-05-15 18:54:56.763 T:1279    debug <general>: [Hyperion Control] - received command: playVideo
2024-05-15 18:54:56.763 T:1279    debug <general>: [Hyperion Control] - Send to: http://192.168.178.77:8090/json-rpc payload: {'command': 'serverinfo'}
2024-05-15 18:54:56.775 T:1309    debug <general>: connect replacing configured host 192.168.178.45 with resolved host 192.168.178.45
2024-05-15 18:54:56.779 T:1279    debug <general>: [Hyperion Control] - Send to: http://192.168.178.77:8090/json-rpc payload: {'command': 'instance', 'subcommand': 'switchTo', 'instance': 0}
2024-05-15 18:54:56.790 T:1243    debug <general>: CDRMUtils::DrmFbDestroyCallback - removing framebuffer: 302
2024-05-15 18:54:56.822 T:1279    debug <general>: [Hyperion Control] - Send to: http://192.168.178.77:8090/json-rpc payload: {'command': 'componentstate', 'componentstate': {'component': 'V4L', 'state': True}}
2024-05-15 18:54:56.850 T:1250    debug <general>: ActiveAE::SyncStream - average error of 692.363554, start adjusting
2024-05-15 18:54:57.255 T:866291 warning <general>: OutputPicture - timeout waiting for buffer
2024-05-15 18:54:57.500 T:1250    debug <general>: ActiveAE::SyncStream - average error 26.494322, last average error: 692.363554
2024-05-15 18:54:57.600 T:1250    debug <general>: ActiveAE::SyncStream - average error of -23.005800, start adjusting
2024-05-15 18:54:57.600 T:1250    debug <general>: ActiveAE::SyncStream - average error -0.005800 below threshold of 30.000000
2024-05-15 18:54:58.724 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Opening 'http://127.0.0.1:52103/https://fv23-three.fullscreen.nz/index_9_3781603.ts?m=1692137281' for reading
2024-05-15 18:54:58.725 T:866303   debug <general>: script.module.slyguy - REQUEST IN: https://fv23-three.fullscreen.nz/index_9_3781603.ts?m=1692137281 (GET)
2024-05-15 18:54:58.725 T:866303   debug <general>: script.module.slyguy - REQUEST OUT: https://fv23-three.fullscreen.nz/index_9_3781603.ts?m=1692137281 (GET)
2024-05-15 18:54:58.763 T:866303   debug <general>: script.module.slyguy - RESPONSE IN: https://fv23-three.fullscreen.nz/index_9_3781603.ts?m=1692137281 (206)
2024-05-15 18:54:58.763 T:866303   debug <general>: script.module.slyguy - RESPONSE OUT: https://fv23-three.fullscreen.nz/index_9_3781603.ts?m=1692137281 (206)
2024-05-15 18:55:02.390 T:866291   debug <general>: CPtsTracker: detected pattern of length 1: 40000.00, frameduration: 40000.000000
2024-05-15 18:55:03.527 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Opening 'http://127.0.0.1:52103/https://fv23-three.fullscreen.nz/index_9.m3u8' for reading
2024-05-15 18:55:03.528 T:866325   debug <general>: script.module.slyguy - REQUEST IN: https://fv23-three.fullscreen.nz/index_9.m3u8 (GET)
2024-05-15 18:55:03.528 T:866325   debug <general>: script.module.slyguy - REQUEST OUT: https://fv23-three.fullscreen.nz/index_9.m3u8 (GET)
2024-05-15 18:55:03.566 T:866325   debug <general>: script.module.slyguy - RESPONSE IN: https://fv23-three.fullscreen.nz/index_9.m3u8 (206)
2024-05-15 18:55:03.566 T:866325   debug <general>: script.module.slyguy - RESPONSE OUT: https://fv23-three.fullscreen.nz/index_9.m3u8 (206)
2024-05-15 18:55:03.566 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Skip ('#EXT-X-VERSION:3')
2024-05-15 18:55:03.566 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Skip ('#EXT-X-DISCONTINUITY-SEQUENCE:64')
2024-05-15 18:55:03.566 T:866278    info <general>: ffmpeg[0x290f2fc0]: [hls] Opening 'http://127.0.0.1:52103/https://fv23-three.fullscreen.nz/index_9_3781604.ts?m=1692137281' for reading
2024-05-15 18:55:03.567 T:866326   debug <general>: script.module.slyguy - REQUEST IN: https://fv23-three.fullscreen.nz/index_9_3781604.ts?m=1692137281 (GET)
2024-05-15 18:55:03.568 T:866326   debug <general>: script.module.slyguy - REQUEST OUT: https://fv23-three.fullscreen.nz/index_9_3781604.ts?m=1692137281 (GET)
2024-05-15 18:55:03.605 T:866326   debug <general>: script.module.slyguy - RESPONSE IN: https://fv23-three.fullscreen.nz/index_9_3781604.ts?m=1692137281 (206)
2024-05-15 18:55:03.605 T:866326   debug <general>: script.module.slyguy - RESPONSE OUT: https://fv23-three.fullscreen.nz/index_9_3781604.ts?m=1692137281 (206)

If you need any more, I can do a clean reboot and get the logs from a clean reboot in debug mode.

Firesphere commented 4 months ago

A thing I noticed: If I restart the same channel, on livestreams, it's a lot faster. Switching channels take quite a while again.

Firesphere commented 4 months ago

I'm going through the logs now, and one thing stands out:

plugin.video.nz.freeview - Failed to resolve. Falling back to dns lookup

Is that Kodi attempting to treat plugin.video.nz.freeview as a domain instead of a local module?

I've added mjh.nz lookups to my pihole, to see if that makes a difference.

matthuisman commented 4 months ago

ok. i think this caused your issue: https://github.com/matthuisman/slyguy.addons/commit/31cae79a3c0936e098528ff84fc887e315112702

Would something on your network be blocking UDP DNS queries to 1.1.1.1 ? Its trying to resolve mjh.nz using 1.1.1.1, timing out and then using your computers dns resolver.

The reason for the above is some ISPs had started blocking mjh.nz at dns level so this forces its own dns for that domain.

But for some reason, it seems on your network it cant use 1.1.1.1 to resolve?

Work around is that intentionally i made it that you could use a urls.txt to override this with your own dns server

Or, i could swap it back to using DOH (dns over https)

But first, like to see why 1.1.1.1 doesnt work for you?

Firesphere commented 4 months ago

But first, like to see why 1.1.1.1 doesnt work for you?

Because no system except my 2 pihole systems are allowed to make DNS requests outside of my local network. Part of ad-blocking things, preventing things to use their internal, hardcoded DNS resolvers.

Probably not a common case for other users, but definitely something worth keeping in mind...

matthuisman commented 4 months ago

can you resolve cloudflare-dns.com OK ? pihole allows that?

matthuisman commented 4 months ago

script.module.slyguy -> v0.79.8 just pushed which switches it to DNS over HTTPS

That should fix your issue

matthuisman commented 4 months ago

even better yet: script.module.slyguy -> v0.79.9 pushed which uses https://1.1.1.1/dns-query to avoid the DNS lookup for cloudflare-dns.com

matthuisman commented 4 months ago

you will see i override dai.google.com which is often blocked by dns blockers. However, often HLS streams use these domain :) So this allows people using dns ad blockers to still play these streams without enabling that domain from everywhere else which may be using it for ads

Firesphere commented 4 months ago

can you resolve cloudflare-dns.com OK ? pihole allows that?

It should be okay.

I can't block DNS over HTTPS, obviously. Just wondering if DNS lookup over https could potentially be blocked by the canary domain? https://support.mozilla.org/en-US/kb/canary-domain-use-application-dnsnet I doubt it, but just checking.

Thanks for the quick fix!

matthuisman commented 4 months ago

the point is, an ISP should not be able to block the DNS :) They would need to block the 1.1.1.1 IP which im sure none would dare

galitus commented 4 months ago

Hey,

sorry for reactivating this thread/report, but I use disney+ from your repository (thanks by the way for the amazing addon) and now I have the same timeout problem because my server is also the gateway with a bind dns server running on it AND I blocked all traffic to 8.8.8.8, 1.1.1.1, etc. My server is always asking the root domain for the right dns answer, so no ISP provider or somebody could block it. Why did I do it? Because to circumvent kids to bypass child protection through the DNS server I set up and use. I also don't like to share my dns request with a specific dns provider. : )

So, my question would be, if there is a way to add an opt out option to your workaround for ISP blocks? I understand why you do it. But still my question stays. : )

Thanks in advance!

matthuisman commented 4 months ago

its a workaround for ISP DNS blocks, I dont want to affect home users :)

There is a way to override the DNS for those domains using the urls.txt, but its a bit cumbersome.

Ill add a Slyguy Common setting to disable it.

galitus commented 4 months ago

Big thanks for your effort and work and fast reply.

Yeah, i know where you are coming from (ISP DNS blocks) and I think you did great in creating this workaround. So, big thanks in advance for a adding a way to disable it in the future for someone like me, who don't need it. :+1:

matthuisman commented 4 months ago

slyguy common -> settings -> advanced -> disable built-in dns overrides added in script.module.slyguy -> v0.80.2