knewc Timeout Starting Recording Playback

[BrettB]

Martin,

I believe that you said you are going to be making a few tweaks to knewc, so I wanted to let you know about 2 situations where I still consistently get timeouts. Hopefully, you and/or sub can make some adjustments to improve these situations. This post is about the first one. EDIT: I'll post about the 2nd one when I get log files showing it.

When I go to play a recording stored on a drive (even an internal SATA drive) which Windows has spun down, knewc seems to always timeout.

Look in this kodi.log at 07:55:12. (Sorry the kodi.log file is so large. I haven't rebooted that RPi in a while.)

In the nrecord.log we see:

Code:

2021-10-21 07:55:12.444 [DEBUG][151] Got request [192.168.143.26]: /control
2021-10-21 07:55:12.444 [DEBUG][151] - time: 1634820912
2021-10-21 07:55:12.445 [DEBUG][151] - key: 13
2021-10-21 07:55:12.445 [DEBUG][151] - client: sdl-KNEW50xb827ebd2d752
2021-10-21 07:55:12.445 [DEBUG][151] - sid: 6a999423b5284182badc7c03f82ca425
2021-10-21 07:55:21.103 [DEBUG][151] fileSize 3072967912
2021-10-21 07:55:21.103 [DEBUG][151] duration 3659
2021-10-21 07:55:21.103 [DEBUG][151] Setting activity: /stream?client=default&seek=1069&f=D%3A%5CNPVR%20Recordings%5CNCIS%20Los%20Angeles%5CSeason%2013%5CNCIS.Los.Angeles.S13E01.Subject.17.ts
2021-10-21 07:55:21.103 [DEBUG][151] 10 extras
2021-10-21 07:55:21.110 [DEBUG][151] skin file? C:\Program Files\NextPVR\data\skin\Default\Players\Video.xml
2021-10-21 07:55:21.110 [DEBUG][151] Playing video file: D:\NPVR Recordings\NCIS Los Angeles\Season 13\NCIS.Los.Angeles.S13E01.Subject.17.ts

So, it looks like it took 9 seconds for NextPVR to get the fileSize.

On the knewc client, I get the timeout pop-up and click the option to not exit. (i.e. to keep waiting) But, all I get is a blank screen.

Code:

2021-10-21 07:55:22.404 T:2642404160  DEBUG: timed out
2021-10-21 07:55:22.405 T:3011929472  DEBUG: ------ Window Init (DialogConfirm.xml) ------
2021-10-21 07:55:25.105 T:2934960960  DEBUG: LIRC: - NEW 160 0 KEY_OK devinput (KEY_OK)
2021-10-21 07:55:25.115 T:3011929472  DEBUG: HandleKey: 11 (0x0b, obc244) pressed, action is Select
2021-10-21 07:55:25.392 T:3011929472  DEBUG: ------ Window Deinit (DialogConfirm.xml) ------
2021-10-21 07:55:25.700 T:2858808128  DEBUG: http://192.168.143.10:8866/activity?format=json&updates=1&client=sdl-KNEW50xb827ebd2d752&sid=6a999423b5284182badc7c03f82ca425
2021-10-21 07:55:25.711 T:2858808128  DEBUG: {u'needsRendering': False}

The only way that I have found to "recover" is to hit the Exit/Back button which takes me back to the recording list. However, it has the significant problem of then resetting the resume point to 0, so I can no longer resume!

Code:

2021-10-21 07:56:17.381 T:2858808128  DEBUG: http://192.168.143.10:8866/activity?format=json&updates=1&client=sdl-KNEW50xb827ebd2d752&sid=6a999423b5284182badc7c03f82ca425
2021-10-21 07:56:17.392 T:2858808128  DEBUG: {u'needsRendering': False}
2021-10-21 07:56:17.395 T:2934960960  DEBUG: LIRC: - NEW ae 0 KEY_EXIT devinput (KEY_EXIT)
2021-10-21 07:56:17.405 T:3011929472  DEBUG: HandleKey: menu (0xd8) pressed, action is Back
2021-10-21 07:56:17.406 T:2642404160  DEBUG: http://192.168.143.10:8866/control?time=1634820977&key=27&client=sdl-KNEW50xb827ebd2d752&sid=6a999423b5284182badc7c03f82ca425
2021-10-21 07:56:17.685 T:2642404160  DEBUG: http://192.168.143.10:8866/activity?format=json&client=sdl-KNEW50xb827ebd2d752&sid=6a999423b5284182badc7c03f82ca425
2021-10-21 07:56:17.695 T:2642404160  DEBUG: {u'action': u'stop'}
2021-10-21 07:56:17.695 T:2642404160  DEBUG: http://192.168.143.10:8866/control?media=stop&client=sdl-KNEW50xb827ebd2d752&sid=6a999423b5284182badc7c03f82ca425
2021-10-21 07:56:17.750 T:3011929472  DEBUG: ffmpeg[B3866580]: [swscaler] No accelerated colorspace conversion found from yuv420p to bgra.
2021-10-21 07:56:18.392 T:2858808128  DEBUG: http://192.168.143.10:8866/activity?format=json&updates=1&client=sdl-KNEW50xb827ebd2d752&sid=6a999423b5284182badc7c03f82ca425
2021-10-21 07:56:18.407 T:2858808128  DEBUG: {u'needsRendering': False}

I can then immediately play the file again, and this time it will work since the drive has spun up.

Code:

2021-10-21 07:56:24.462 T:2858808128  DEBUG: http://192.168.143.10:8866/activity?format=json&updates=1&client=sdl-KNEW50xb827ebd2d752&sid=6a999423b5284182badc7c03f82ca425
2021-10-21 07:56:24.474 T:2858808128  DEBUG: {u'needsRendering': False}
2021-10-21 07:56:25.211 T:2934960960  DEBUG: LIRC: - NEW 160 0 KEY_OK devinput (KEY_OK)
2021-10-21 07:56:25.218 T:3011929472  DEBUG: HandleKey: 11 (0x0b, obc244) pressed, action is Select
2021-10-21 07:56:25.220 T:2642404160  DEBUG: http://192.168.143.10:8866/control?time=1634820985&key=13&client=sdl-KNEW50xb827ebd2d752&sid=6a999423b5284182badc7c03f82ca425
2021-10-21 07:56:26.695 T:2642404160  DEBUG: http://192.168.143.10:8866/activity?format=json&client=sdl-KNEW50xb827ebd2d752&sid=6a999423b5284182badc7c03f82ca425
2021-10-21 07:56:26.705 T:2642404160  DEBUG: {u'recording_title': u'NCIS: Los Angeles', u'recording_description': u'Callen suspects Hetty of keeping secrets about his past; Joelle surfaces in her quest to capture Katya; NCIS must track down an informant whose life is in danger; Kensi and Deeks work to expand their family.', u'url': u'/stream?client=default&f=D%3A%5CNPVR%20Recordings%5CNCIS%20Los%20Angeles%5CSeason%2013%5CNCIS.Los.Angeles.S13E01.Subject.17.ts', u'recording_size': u'3072967912', u'screen': u'Recordings', u'supports_server_skip': u'true', u'recording_name': u'NCIS: Los Angeles', u'file': u'D:\\NPVR Recordings\\NCIS Los Angeles\\Season 13\\NCIS.Los.Angeles.S13E01.Subject.17.ts', u'recording_id': u'78080', u'recording_subtitle': u'Subject 17', u'recording_duration': u'3661.7132225'}
2021-10-21 07:56:26.710 T:2642404160  DEBUG: Details R
2021-10-21 07:56:26.710 T:2642404160  DEBUG: getRecording v5 start
2021-10-21 07:56:26.712 T:2642404160  DEBUG: http://192.168.143.10:8866/service?method=recording.list&recording_id=78080&sid=6a999423b5284182badc7c03f82ca425
2021-10-21 07:56:26.727 T:2642404160  DEBUG: getRecording v5 end
2021-10-21 07:56:26.828 T:2642404160  DEBUG: True
2021-10-21 07:56:26.858 T:2404651840  DEBUG: #XBMCPlayer#
2021-10-21 07:56:26.858 T:2404651840  DEBUG: started player

[mvallevand]

Unfortunately it times out on the JSON activity call which is the play request, and sub only sends it once. So NextPVR is in in video state and UI client is not and as result the "back" acts like a stop at position 0.

NextPVR probably shouldn't move into video state when the JSON TCP response is aborted but oddly nothing is in the logs showing the error, so I'm not sure if that is because of the logging or bad network layer. Your interim option would be to increase the timeout but as you have seen sometimes the delay can be much more then this.

Martin