Kodi sometimes cannot play channels

[aderlopas]

Hi, 

Sometimes Kodi cannot play the channels, for no apparent reason...

I see in kodi.log the below:
------------------------------------------------
2021-10-31 19:26:55.591 T:18134    INFO <general>: Loading skin file: DialogPVRInfo.xml, load type: LOAD_EVERY_TIME
2021-10-31 19:26:56.894 T:18134    INFO <general>: VideoPlayer::OpenFile: pvr://channels/tv/All%20channels/pvr.nextpvr_7160.pvr
2021-10-31 19:26:56.899 T:18255    INFO <general>: Creating InputStream
2021-10-31 19:26:56.900 T:18255  ERROR <general>: AddOnLog: pvr.nextpvr: Unknown live streaming state 0 0 1
2021-10-31 19:26:56.901 T:18255    INFO <general>: AddOnLog: pvr.nextpvr: Calling Open(http://192.168.178.77:8866/live?channelo...4e966cf328) on tsb!
2021-10-31 19:27:04.073 T:18255  ERROR <general>: Open - Unhandled exception
2021-10-31 19:27:04.074 T:18255  ERROR <general>: Open - Error opening http://192.168.178.77:8866/live?channelo...timeout=10
2021-10-31 19:27:04.074 T:18255  ERROR <general>: AddOnLog: pvr.nextpvr: Could not open streaming file
2021-10-31 19:27:04.445 T:18255  ERROR <general>: CVideoPlayer::OpenInputStream - error opening [pvr://channels/tv/All%20channels/pvr.nextpvr_7160.pvr]
2021-10-31 19:27:04.445 T:18255    INFO <general>: CVideoPlayer::OnExit()
2021-10-31 19:27:04.553 T:18134    INFO <general>: CVideoPlayer::CloseFile()
2021-10-31 19:27:04.563 T:18134    INFO <general>: VideoPlayer: waiting for threads to exit
2021-10-31 19:27:04.564 T:18134    INFO <general>: VideoPlayer: finished waiting
2021-10-31 19:27:04.598 T:18186  ERROR <general>: EXCEPTION Thrown (PythonToCppException) : -->Python callback/script returned the following error<--
                                                    - NOTE: IGNORING THIS CAN LEAD TO MEMORY LEAKS!
                                                  Error Type: <class 'NameError'>
                                                  Error Contents: name 'false' is not defined
                                                  Traceback (most recent call last):
                                                    File "/storage/emulated/0/Android/data/org.xbmc.kodi/files/.kodi/addons/script.metadata.editor/service.py", line 22, in onNotification
                                                      data = eval(data.replace(':true', ': True').replace(':false', ': False'))
                                                    File "<string>", line 2, in <module>
                                                  NameError: name 'false' is not defined
                                                  -->End of Python script error report<--

--------------------------------------------------

any ideas?
Attaching npvr logs...

[mvallevand]

You didn't include enough of the Kodi log to help diagnose and it is not debug anyway, but it looks like network traffic to the server was blocked for about 10 seconds. This is just the connection and not the turn around time. You might need to increase the prebuffer time to give the server a change reduce the server workload after the graph is created.

Martin

[aderlopas]

You didn't  include enough of the Kodi log to help diagnose and it is not debug anyway, but it looks like network traffic to the server was blocked for about 10 seconds.  This is just the connection and not the turn around time.  You might need to increase the prebuffer time to give the server a change reduce the server workload after the graph is created.

Martin

Hi Martin,

Thank you for the suggestion, 

I had set prebuffer to 1 so I changed it to 5 and still the same.
Network is fine and fast, but server might respond slow.
Can this be set to higher than 5?

Attaching the kodi.log.

[mvallevand]

Again, that is not a debug log and it doesn't show what I need to see. The prebuffer is really after data is started flowing so more than a few seconds shouldn't need. The network delay Kodi is seeing doesn't even show up in the NextPVR logs.

These 50ms in NextPVR are 7 seconds in Kodi time

Code:

2021-10-31 19:26:45.687    [DEBUG][176]    Got request [192.168.178.43]: /live
2021-10-31 19:26:45.687    [DEBUG][176]    /live?channeloid=7163&client=f548a3d0e8f3480bb4b7b24e966cf328&sid=f548a3d0e8f3480bb4b7b24e966cf328
2021-10-31 19:26:45.687    [DEBUG][176]     - channeloid: 7163
2021-10-31 19:26:45.687    [DEBUG][176]     - client: f548a3d0e8f3480bb4b7b24e966cf328
2021-10-31 19:26:45.688    [DEBUG][176]     - sid: f548a3d0e8f3480bb4b7b24e966cf328
2021-10-31 19:26:45.688    [DEBUG][176]    range: bytes=0-
2021-10-31 19:26:45.688    [DEBUG][176]    RollingFile.Open(C:\Users\argyr\AppData\Local\Temp\live-OPEN BEYOND HD-9.ts) ..
2021-10-31 19:26:45.701    [DEBUG][176]    File is in live mode
2021-10-31 19:26:45.702    [DEBUG][176]    Range: 0-
2021-10-31 19:26:45.702    [DEBUG][176]    Start location: 0 (file-size: 1006176)
2021-10-31 19:26:45.702    [DEBUG][176]    About to continue streaming until stream stops
2021-10-31 19:26:45.725    [DEBUG][176]    client disconnected

Martin

[aderlopas]

Again, that is not a debug log and it doesn't show what I need to see.  The prebuffer is really after data is started flowing so more than a few seconds shouldn't need.  The network delay Kodi is seeing doesn't even show up in the NextPVR logs.

These 50ms in NextPVR are 7 seconds in Kodi time

Code:

2021-10-31 19:26:45.687    [DEBUG][176]    Got request [192.168.178.43]: /live
2021-10-31 19:26:45.687    [DEBUG][176]    /live?channeloid=7163&client=f548a3d0e8f3480bb4b7b24e966cf328&sid=f548a3d0e8f3480bb4b7b24e966cf328
2021-10-31 19:26:45.687    [DEBUG][176]     - channeloid: 7163
2021-10-31 19:26:45.687    [DEBUG][176]     - client: f548a3d0e8f3480bb4b7b24e966cf328
2021-10-31 19:26:45.688    [DEBUG][176]     - sid: f548a3d0e8f3480bb4b7b24e966cf328
2021-10-31 19:26:45.688    [DEBUG][176]    range: bytes=0-
2021-10-31 19:26:45.688    [DEBUG][176]    RollingFile.Open(C:\Users\argyr\AppData\Local\Temp\live-OPEN BEYOND HD-9.ts) ..
2021-10-31 19:26:45.701    [DEBUG][176]    File is in live mode
2021-10-31 19:26:45.702    [DEBUG][176]    Range: 0-
2021-10-31 19:26:45.702    [DEBUG][176]    Start location: 0 (file-size: 1006176)
2021-10-31 19:26:45.702    [DEBUG][176]    About to continue streaming until stream stops
2021-10-31 19:26:45.725    [DEBUG][176]    client disconnected

Martin

Thanks Martin, 

I'll run it with debug on then and upload logs.

Please note that this happens only with Timeshift, not with Realtime streaming.

[mvallevand]

Next time you test sub has asked for you to turn on verbose logging on the server first. Hold control on Settings->General to see this option button.

Martin

[aderlopas]

Next time you test sub has asked for you to turn on verbose logging on the server first.  Hold control on Settings->General to see this option button.

Martin

Thanks Martin, 

Control did not do anything for me, so I ensured loglevel is debug and extendedlogs is true in config.xml.

I am attaching both kodi debug and nextpvr logs.

Issue happened at 09:53

[mvallevand]

Sorry not Settings->General just Settings or Settings->About The level I wanted is verbose

Martin

[aderlopas]

Sorry not Settings->General just Settings or Settings->About  The level I wanted is verbose

Martin

Hi Martin, 

Thank you for the clarification.
I enabled it and I am uploading new logs.
Error is around 12:59 timestamp.

[mvallevand]

Thanks those logs are indeed extremely verbose NextPVR is logging every packet sent. There is a problem in the verbose log that sub might need to look at since I don't think this sequence should happen.

2021-11-01 12:59:28.759 [VERBOSE][8] RollingFile.Close()

2021-11-01 12:59:28.768 [DEBUG][88] Got request [192.168.178.43]: /service (channel.stream.stop)

Also I think you have EPG channel art turned on and that isn't going to work very well unless Schedules Direct is your source.

Martin