Results 1 to 6 of 6

Thread: NextPVR Kodi Addon hangs after some time.

  1. #1
    Join Date
    Dec 2013
    Location
    Greece
    Posts
    50

    NextPVR Kodi Addon hangs after some time.

    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...
    Attached Files Attached Files

  2. #2
    Join Date
    Dec 2013
    Location
    Greece
    Posts
    50
    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=bad66160707d4216a 7279f9bec3ff8f9
    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?

  3. #3
    Join Date
    May 2006
    Location
    Canada
    Posts
    26,242
    You need to include all your logs including the Kodi debug log that second post seems normal enough.

    Martin

  4. #4
    Join Date
    Dec 2013
    Location
    Greece
    Posts
    50
    Quote Originally Posted by mvallevand View Post
    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...
    Attached Files Attached Files

  5. #5
    Join Date
    Dec 2013
    Location
    Greece
    Posts
    50
    Quote Originally Posted by aderlopas View Post
    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(Soc ket 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?

  6. #6
    Join Date
    Dec 2013
    Location
    Greece
    Posts
    50
    Quote Originally Posted by aderlopas View Post
    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(Soc ket 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...

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •