NextPVR Kodi Addon hangs after some time.

[aderlopas]

Hello,

I am using latest NPVR with latest nshared.dll and Kodi 18 latest nightly build on Android (20180408) with next PVR kodi addon, and after some time channel play hangs.
Kodi log shows it is retrying to read from socket and NPVR log shows:

2018-04-09 19:40:49.926 [ERROR][9] Live stream expired without 15 second renewal. (handle:190003)
2018-04-09 19:40:49.926 [INFO][9] DigitalRecorder.StopStream() handle: 3
2018-04-09 19:40:49.986 [INFO][9] No more streams active. Stopping device.
2018-04-09 19:40:49.986 [DEBUG][9] About to request async graph stop
2018-04-09 19:40:49.986 [DEBUG][29] Graph stopping... (async)
2018-04-09 19:40:50.285 [DEBUG][29] Graph reports state 'Stopped'
2018-04-09 19:40:50.285 [DEBUG][29] Graph stopped (async)
2018-04-09 19:40:50.285 [DEBUG][9] Async stop completed successfully


Any ideas?

Uploading full logs...

[aderlopas]

This is quite strange....tested with nextpvr locally with 4.1.1 , this is not happening.
Tested again from Kodi, on my Minix, the below error is shown after 1 hour as always:

2018-04-11 21:23:30.663 [DEBUG][27] Renew lease ok (0x190001)
2018-04-11 21:23:55.810 [ERROR][9] Live stream expired without 15 second renewal. (handle:190001)
2018-04-11 21:23:55.811 [INFO][9] DigitalRecorder.StopStream() handle: 1
2018-04-11 21:23:55.921 [INFO][9] No more streams active. Stopping device.
2018-04-11 21:23:55.921 [DEBUG][9] About to request async graph stop
2018-04-11 21:23:55.922 [DEBUG][23] Graph stopping... (async)
2018-04-11 21:23:56.204 [DEBUG][23] Graph reports state 'Stopped'
2018-04-11 21:23:56.204 [DEBUG][23] Graph stopped (async)
2018-04-11 21:23:56.205 [DEBUG][9] Async stop completed successfully


At the same time (and a bit before) the below request is made to npvr service:

2018-04-11 21:23:56.656 [DEBUG][17] Got Web Request (::ffff:192.168.178.53): /service method=recording.lastupdated&sid=bad66160707d4216a7279f9bec3ff8f9
2018-04-11 21:23:56.656 [DEBUG][17] method=recording.lastupdated
2018-04-11 21:23:56.656 [DEBUG][17] parameters:
2018-04-11 21:23:56.656 [DEBUG][17] method: recording.lastupdated
2018-04-11 21:23:56.656 [DEBUG][17] sid: bad66160707d4216a7279f9bec3ff8f9
2018-04-11 21:23:56.656 [DEBUG][17] client_ip: 192.168.178.53
2018-04-11 21:23:56.656 [DEBUG][17] host_callback: 192.168.178.41:8866
2018-04-11 21:23:56.656 [DEBUG][17] physical_path: C:\Users\Public\NPVR\web\
2018-04-11 21:23:56.656 [DEBUG][17] user_agent: Kodi/18.0-ALPHA2 (Linux; Android 5.1.1; NEO-X8H-PLUS Build/LMY47V) Android/5.1.1 Sys_CPU/armv7l App_Bitness/32 Version/18.0-ALPHA2-Git:20180410-76f19f6
2018-04-11 21:23:56.656 [DEBUG][17] range: bytes=0-
2018-04-11 21:23:56.656 [DEBUG][17] requested_path: /service
2018-04-11 21:23:56.656 [DEBUG][17] verb: GET
2018-04-11 21:23:56.656 [DEBUG][17] LastUpdated
2018-04-11 21:23:56.658 [DEBUG][17] <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
<last_update>1523466948</last_update>
</rsp>

Some time, before I see the below:

2018-04-11 21:23:20.581 [DEBUG][19] Sent 50000 bytes
2018-04-11 21:23:20.581 [DEBUG][19] Renewed lease... (190001)
2018-04-11 21:23:20.581 [DEBUG][19] About to send 50000 bytes
...
and last time before error below:

2018-04-11 21:23:30.663 [DEBUG][19] Sent 50000 bytes
2018-04-11 21:23:30.663 [DEBUG][19] Renewed lease... (190001)
2018-04-11 21:23:30.764 [DEBUG][19] About to send 50000 bytes
2018-04-11 21:23:30.764 [DEBUG][19] Sent 50000 bytes


A few minutes back I also see:

2018-04-11 21:22:58.613 [DEBUG][19] About to send 50000 bytes
2018-04-11 21:22:58.613 [DEBUG][19] Sent 50000 bytes
2018-04-11 21:22:58.715 [DEBUG][19] Not all bytes read@1 (only got: + 49728). About to do second chance. (file: C:\zip\Timeshift\live-STAR HD-4792-1-9.ts)
2018-04-11 21:22:58.715 [DEBUG][19] Not all bytes read@2
2018-04-11 21:22:58.715 [DEBUG][19] About to switch files. The current file is C:\zip\Timeshift\live-STAR HD-4792-1-9.ts
2018-04-11 21:22:58.715 [DEBUG][19] Switching to file(1): C:\zip\Timeshift\live-STAR HD-4792-1-10.ts
2018-04-11 21:22:58.720 [DEBUG][19] currentFiles.Count = 4
2018-04-11 21:22:58.720 [DEBUG][19] - C:\zip\Timeshift\live-STAR HD-4792-1-10.ts
2018-04-11 21:22:58.720 [DEBUG][19] - C:\zip\Timeshift\live-STAR HD-4792-1-9.ts
2018-04-11 21:22:58.720 [DEBUG][19] - C:\zip\Timeshift\live-STAR HD-4792-1-8.ts
2018-04-11 21:22:58.720 [DEBUG][19] - C:\zip\Timeshift\live-STAR HD-4792-1-7.ts
2018-04-11 21:22:58.720 [DEBUG][19] About to try deleting: C:\zip\Timeshift\live-STAR HD-4792-1-6.ts
2018-04-11 21:22:58.720 [DEBUG][19] About to send 50000 bytes
2018-04-11 21:22:58.720 [DEBUG][19] Sent 50000 bytes

Please note that I have disabled Timeshift in the addon.
Note my HD disk has 103GB free, and at that time, there is nothing logged in the Event Viewer.

Any ideas?

[mvallevand]

You need to include all your logs including the Kodi debug log that second post seems normal enough.

Martin

[aderlopas]

You need to include all your logs including the Kodi debug log that second post seems normal enough.

Martin

many thanks for your reply. Attaching logs...

[aderlopas]

many thanks for your reply. Attaching logs...

So this is what the logs show:

Kodi.log:

00:00:39.843 T:18446744072443571328 DEBUG: GLES: Extension Support Test - GL_EXT_texture_format_BGRA8888 YES
00:00:39.848 T:18446744071999835520 ERROR: AddOnLog: NextPVR PVR Client: Socket::read EAGAIN
00:00:40.068 T:18446744072443571328 ERROR: Previous line repeats 4 times.
00:00:40.068 T:18446744072443571328 DEBUG: GLES: Extension Support Test - GL_EXT_texture_format_BGRA8888 YES
00:00:40.109 T:18446744071999835520 ERROR: AddOnLog: NextPVR PVR Client: Socket::read EAGAIN
00:00:40.162 T:18446744071999835520 DEBUG: CVideoPlayer::SetCaching - caching state 0
00:00:40.166 T:18446744071999835520 DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000
00:01:02.415 T:18446744072443571328 INFO: CheckIdle - Closing session to http://192.168.178.41 (easy=0x9aff9000, multi=0x95c21600)
00:01:02.813 T:18446744072443571328 DEBUG: ------ Window Init (VideoOSD.xml) ------
00:01:02.850 T:18446744072443571328 DEBUG: Window VideoOSD.xml was already loaded
00:01:02.850 T:18446744072443571328 DEBUG: Alloc resources: 34.82ms
00:01:02.851 T:18446744072443571328 ERROR: Control 602 in window 12901 has been asked to focus, but it can't
00:01:02.855 T:18446744072443571328 DEBUG: ------ Window Init (DialogSeekBar.xml) ------
00:01:02.857 T:18446744072443571328 DEBUG: Window DialogSeekBar.xml was already loaded
00:01:02.857 T:18446744072443571328 DEBUG: Alloc resources: 1.04ms
00:01:02.866 T:18446744072443571328 DEBUG: ------ Window Init (Custom_1109_TopBarOverlay.xml) ------
00:01:02.868 T:18446744072443571328 DEBUG: Window Custom_1109_TopBarOverlay.xml was already loaded
00:01:02.869 T:18446744072443571328 DEBUG: Alloc resources: 0.02ms
00:01:02.873 T:18446744072443571328 DEBUG: GLES: Extension Support Test - GL_EXT_texture_format_BGRA8888 YES
00:01:03.447 T:18446744072443571328 DEBUG: Previous line repeats 7 times.
00:01:03.447 T:18446744072443571328 ERROR: Control 602 in window 12901 has been asked to focus, but it can't
00:01:04.281 T:18446744071813973760 ERROR: Previous line repeats 25 times.
00:01:04.282 T:18446744071813973760 DEBUG: Thread JobWorker 18446744071813973760 terminating (autodelete)
00:01:05.602 T:18446744071989910272 DEBUG: CVideoPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
00:01:05.603 T:18446744071989910272 INFO: CVideoPlayerVideo - Stillframe left, switching to normal playback
00:01:05.604 T:18446744071989910272 ERROR: CDVDVideoCodecAndroidMediaCodec::GetOutputPicture unknown index(-10000)


NRECORD.log:

2018-04-12 00:00:36.037 [DEBUG][29] Renew lease ok (0x190001)
2018-04-12 00:01:01.328 [ERROR][9] Live stream expired without 15 second renewal. (handle:190001)
2018-04-12 00:01:01.328 [INFO][9] DigitalRecorder.StopStream() handle: 1
2018-04-12 00:01:01.428 [INFO][9] No more streams active. Stopping device.
2018-04-12 00:01:01.428 [DEBUG][9] About to request async graph stop
2018-04-12 00:01:01.428 [DEBUG][39] Graph stopping... (async)
2018-04-12 00:01:01.741 [DEBUG][39] Graph reports state 'Stopped'
2018-04-12 00:01:01.741 [DEBUG][39] Graph stopped (async)
2018-04-12 00:01:01.741 [DEBUG][9] Async stop completed successfully
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter MPEG-2 Sections and Tables
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter BDA MPEG2 Transport Information Filter
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter MPEG-2 Demultiplexer
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter NPVR TS Mon
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter Capture
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter Tuner
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter Network Provider
2018-04-12 00:01:06.872 [INFO][25] DigitalRecorder.StopStream() handle: 1


Web.log:

2018-04-12 00:00:39.337 [DEBUG][5] About to send 50000 bytes
2018-04-12 00:01:05.855 [ERROR][5] Unexpected error streaming channel: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at NShared.Streaming.StreamingHelper.StreamNative(Socket conn, Dictionary`2 parameters)
2018-04-12 00:01:06.872 [DEBUG][5] StopStream(1638401)...
2018-04-12 00:01:06.872 [DEBUG][5] clientHandle[XBMC-3629490b28754c74b316030f5e2619a6] = 1638401
2018-04-12 00:01:06.872 [DEBUG][5] Calling StopStream()
2018-04-12 00:01:06.872 [DEBUG][5] StopStream() done
2018-04-12 00:01:06.872 [DEBUG][5] RollingFile.Close()
2018-04-12 00:01:06.872 [DEBUG][5] About to delete temp file: C:\zip\Timeshift\live-STAR HD-5500-1-9.ts
2018-04-12 00:01:06.872 [DEBUG][5] About to delete temp file: C:\zip\Timeshift\live-STAR HD-5500-1-8.ts
2018-04-12 00:01:06.872 [DEBUG][5] About to delete temp file: C:\zip\Timeshift\live-STAR HD-5500-1-7.ts
2018-04-12 00:01:06.872 [DEBUG][5] About to delete temp file: C:\zip\Timeshift\live-STAR HD-5500-1-6.ts
2018-04-12 00:01:06.872 [DEBUG][5] Cleaning up: C:\zip\Timeshift\live-STAR HD-5500-1.ts
2018-04-12 00:01:06.903 [DEBUG][5] Cleaning up: C:\zip\Timeshift\live-STAR HD-5500-1.ts
2018-04-12 00:01:06.935 [DEBUG][5] Cleaning up: C:\zip\Timeshift\live-STAR HD-5500-1.ts
2018-04-12 00:01:06.935 [DEBUG][5] Cleaning up: C:\zip\Timeshift\live-STAR HD-5500-1.ts
2018-04-12 00:01:06.935 [DEBUG][5] Cleaning up: C:\zip\Timeshift\live-STAR HD-5500-1.ts


Any ideas?

[aderlopas]

So this is what the logs show:

Kodi.log:

00:00:39.843 T:18446744072443571328 DEBUG: GLES: Extension Support Test - GL_EXT_texture_format_BGRA8888 YES
00:00:39.848 T:18446744071999835520 ERROR: AddOnLog: NextPVR PVR Client: Socket::read EAGAIN
00:00:40.068 T:18446744072443571328 ERROR: Previous line repeats 4 times.
00:00:40.068 T:18446744072443571328 DEBUG: GLES: Extension Support Test - GL_EXT_texture_format_BGRA8888 YES
00:00:40.109 T:18446744071999835520 ERROR: AddOnLog: NextPVR PVR Client: Socket::read EAGAIN
00:00:40.162 T:18446744071999835520 DEBUG: CVideoPlayer::SetCaching - caching state 0
00:00:40.166 T:18446744071999835520 DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000
00:01:02.415 T:18446744072443571328 INFO: CheckIdle - Closing session to http://192.168.178.41 (easy=0x9aff9000, multi=0x95c21600)
00:01:02.813 T:18446744072443571328 DEBUG: ------ Window Init (VideoOSD.xml) ------
00:01:02.850 T:18446744072443571328 DEBUG: Window VideoOSD.xml was already loaded
00:01:02.850 T:18446744072443571328 DEBUG: Alloc resources: 34.82ms
00:01:02.851 T:18446744072443571328 ERROR: Control 602 in window 12901 has been asked to focus, but it can't
00:01:02.855 T:18446744072443571328 DEBUG: ------ Window Init (DialogSeekBar.xml) ------
00:01:02.857 T:18446744072443571328 DEBUG: Window DialogSeekBar.xml was already loaded
00:01:02.857 T:18446744072443571328 DEBUG: Alloc resources: 1.04ms
00:01:02.866 T:18446744072443571328 DEBUG: ------ Window Init (Custom_1109_TopBarOverlay.xml) ------
00:01:02.868 T:18446744072443571328 DEBUG: Window Custom_1109_TopBarOverlay.xml was already loaded
00:01:02.869 T:18446744072443571328 DEBUG: Alloc resources: 0.02ms
00:01:02.873 T:18446744072443571328 DEBUG: GLES: Extension Support Test - GL_EXT_texture_format_BGRA8888 YES
00:01:03.447 T:18446744072443571328 DEBUG: Previous line repeats 7 times.
00:01:03.447 T:18446744072443571328 ERROR: Control 602 in window 12901 has been asked to focus, but it can't
00:01:04.281 T:18446744071813973760 ERROR: Previous line repeats 25 times.
00:01:04.282 T:18446744071813973760 DEBUG: Thread JobWorker 18446744071813973760 terminating (autodelete)
00:01:05.602 T:18446744071989910272 DEBUG: CVideoPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
00:01:05.603 T:18446744071989910272 INFO: CVideoPlayerVideo - Stillframe left, switching to normal playback
00:01:05.604 T:18446744071989910272 ERROR: CDVDVideoCodecAndroidMediaCodec::GetOutputPicture unknown index(-10000)


NRECORD.log:

2018-04-12 00:00:36.037 [DEBUG][29] Renew lease ok (0x190001)
2018-04-12 00:01:01.328 [ERROR][9] Live stream expired without 15 second renewal. (handle:190001)
2018-04-12 00:01:01.328 [INFO][9] DigitalRecorder.StopStream() handle: 1
2018-04-12 00:01:01.428 [INFO][9] No more streams active. Stopping device.
2018-04-12 00:01:01.428 [DEBUG][9] About to request async graph stop
2018-04-12 00:01:01.428 [DEBUG][39] Graph stopping... (async)
2018-04-12 00:01:01.741 [DEBUG][39] Graph reports state 'Stopped'
2018-04-12 00:01:01.741 [DEBUG][39] Graph stopped (async)
2018-04-12 00:01:01.741 [DEBUG][9] Async stop completed successfully
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter MPEG-2 Sections and Tables
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter BDA MPEG2 Transport Information Filter
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter MPEG-2 Demultiplexer
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter NPVR TS Mon
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter Capture
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter Tuner
2018-04-12 00:01:01.741 [DEBUG][9] Removing filter Network Provider
2018-04-12 00:01:06.872 [INFO][25] DigitalRecorder.StopStream() handle: 1


Web.log:

2018-04-12 00:00:39.337 [DEBUG][5] About to send 50000 bytes
2018-04-12 00:01:05.855 [ERROR][5] Unexpected error streaming channel: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at NShared.Streaming.StreamingHelper.StreamNative(Socket conn, Dictionary`2 parameters)
2018-04-12 00:01:06.872 [DEBUG][5] StopStream(1638401)...
2018-04-12 00:01:06.872 [DEBUG][5] clientHandle[XBMC-3629490b28754c74b316030f5e2619a6] = 1638401
2018-04-12 00:01:06.872 [DEBUG][5] Calling StopStream()
2018-04-12 00:01:06.872 [DEBUG][5] StopStream() done
2018-04-12 00:01:06.872 [DEBUG][5] RollingFile.Close()
2018-04-12 00:01:06.872 [DEBUG][5] About to delete temp file: C:\zip\Timeshift\live-STAR HD-5500-1-9.ts
2018-04-12 00:01:06.872 [DEBUG][5] About to delete temp file: C:\zip\Timeshift\live-STAR HD-5500-1-8.ts
2018-04-12 00:01:06.872 [DEBUG][5] About to delete temp file: C:\zip\Timeshift\live-STAR HD-5500-1-7.ts
2018-04-12 00:01:06.872 [DEBUG][5] About to delete temp file: C:\zip\Timeshift\live-STAR HD-5500-1-6.ts
2018-04-12 00:01:06.872 [DEBUG][5] Cleaning up: C:\zip\Timeshift\live-STAR HD-5500-1.ts
2018-04-12 00:01:06.903 [DEBUG][5] Cleaning up: C:\zip\Timeshift\live-STAR HD-5500-1.ts
2018-04-12 00:01:06.935 [DEBUG][5] Cleaning up: C:\zip\Timeshift\live-STAR HD-5500-1.ts
2018-04-12 00:01:06.935 [DEBUG][5] Cleaning up: C:\zip\Timeshift\live-STAR HD-5500-1.ts
2018-04-12 00:01:06.935 [DEBUG][5] Cleaning up: C:\zip\Timeshift\live-STAR HD-5500-1.ts


Any ideas?

Have seen the sudden skip back to start being an issue in various kodi forums:

00:00:40.162 T:18446744071999835520 DEBUG: CVideoPlayer::SetCaching - caching state 0
00:00:40.166 T:18446744071999835520 DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000

Strange thing is that it does not happen with same version of Kodi on Windows 10 (another remote PC) it only happens with my android amlogic devices...