knewc 2.9.0 Release Dual Mode

[BrettB]

Hey, Martin.

2 times this morning I had this knewc 2.9.0 Alpha 1 just "die" after stopping playback, and I ended up back at the main Kodi menu.

Here are links to log file sets:
Latest: https://bowmantech-my.sharepoint.com/:u:...Q?e=QuycxH

First (this should all be earlier in the above logs): https://bowmantech-my.sharepoint.com/:u:...A?e=2snIbq

I did take a quick look at the kodi.log for each one right at the end (since I'd pulled each of these just after the problem happened). And I didn't see any errors, etc. from knewc. I'm hoping you see something.

[BrettB]

Hey, Martin.

2 times this morning I had this knewc 2.9.0 Alpha 1 just "die" after stopping playback, and I ended up back at the main Kodi menu.

Here are links to log file sets:
Latest

First set (these should all be included above)

I did take a quick look at the kodi.log for each one right at the end (since I'd pulled each of these just after the problem happened). And I didn't see any errors, etc. from knewc. I'm hoping you see something.

[BrettB]

One other thing that I noticed a couple of times this morning is that as a new recording was beginning to play, sometimes (always?) a dialog box (from kodi, not NextPVR GUI) would briefly popup as the video was beginning to play. One of the times earlier, I was able to very briefly see some text in either the header or the body of the pop-up and it had the show name of a totally different show. (Possibly the show I had watched previously.)

I've attached an even later copy of this kodi.log for you. When I looked at it during the time I last saw this pop-up, I saw 2 instances of window de-inits:

Code:

2020-09-26 12:50:20.237 T:3011437904  DEBUG: ------ Window Deinit (DialogConfirm.xml) ------
...
2020-09-26 12:50:20.699 T:3011437904  DEBUG: ------ Window Deinit (DialogBusy.xml) ------

I don't know if those are related, but they are the only things that I see referencing windows/dialogs in that time period.

[mvallevand]

The good news is my suspicion the NextPVR or the network was timing out was correct, the bad news is unfortunately I didn't trap all the timeout exits with a prompt to retry. The second piece of the fix is UI client should start on the screen you timed out on so you shouldn't need to restart the RPi anymore

The telltale signs are these

2020-09-26 11:30:00.747 T:2252604272 DEBUG: http://192.168.143.10:8866/control?time=...b4a08b815e
2020-09-26 11:30:10.761 T:2252604272 DEBUG: timed out

2020-09-26 12:18:48.167 T:2187322224 DEBUG: http://192.168.143.10:8866/control?time=...1613630a24
2020-09-26 12:18:58.179 T:2187322224 DEBUG: timed out

Sub probably need to look a the code during that timeout to see why he is reloading the recordings so often with no request from

Code:

2020-09-26 12:18:48.276    [DEBUG][31]    Recordings.RELOAD_RECORDINGS
2020-09-26 12:18:48.853    [DEBUG][31]    Recordings.RELOAD_RECORDINGS
2020-09-26 12:18:49.368    [DEBUG][31]    Recordings.RELOAD_RECORDINGS
2020-09-26 12:18:49.867    [DEBUG][31]    Recordings.RELOAD_RECORDINGS
2020-09-26 12:18:50.351    [DEBUG][31]    Recordings.RELOAD_RECORDINGS
2020-09-26 12:18:56.466    [DEBUG][31]    Recordings.RELOAD_RECORDINGS
2020-09-26 12:18:56.466    [DEBUG][31]    Recordings.RELOAD_RECORDINGS
...

It is also possible that this log message would have been the screen but it came after the timeout. It shouldn't take NextPV almost 20 seconds to render a screen so maybe that reload logic can be fixed things will improve.

2020-09-26 12:19:06.855 [DEBUG][31] DoCompositeRendering() took 77.9995ms

I am aware of that brief dialog and have fixed it for alpha 2. I will also add a new retry dialog.

Martin

[BrettB]

The good news is my suspicion the NextPVR or the network was timing out was correct, the bad news is unfortunately I didn't trap all the timeout exits with a prompt to retry.  The second piece of the fix is UI client should start on the screen you timed out on so you shouldn't need to restart the RPi anymore
 
The telltale signs are these

2020-09-26 11:30:00.747 T:2252604272  DEBUG: http://192.168.143.10:8866/control?time=...b4a08b815e
2020-09-26 11:30:10.761 T:2252604272  DEBUG: timed out

2020-09-26 12:18:48.167 T:2187322224  DEBUG: http://192.168.143.10:8866/control?time=...1613630a24
2020-09-26 12:18:58.179 T:2187322224  DEBUG: timed out

Sub probably need to look a the code during that timeout to see why he is reloading the recordings so often with no request from

Code:

2020-09-26 12:18:48.276 [DEBUG][31] Recordings.RELOAD_RECORDINGS
2020-09-26 12:18:48.853 [DEBUG][31] Recordings.RELOAD_RECORDINGS
2020-09-26 12:18:49.368 [DEBUG][31] Recordings.RELOAD_RECORDINGS
2020-09-26 12:18:49.867 [DEBUG][31] Recordings.RELOAD_RECORDINGS
2020-09-26 12:18:50.351 [DEBUG][31] Recordings.RELOAD_RECORDINGS
2020-09-26 12:18:56.466 [DEBUG][31] Recordings.RELOAD_RECORDINGS
2020-09-26 12:18:56.466 [DEBUG][31] Recordings.RELOAD_RECORDINGS
...

It is also possible that this log message would have been the screen but it came after the timeout.  It shouldn't take NextPV almost 20 seconds to render a screen so maybe that reload logic can be fixed things will improve.

2020-09-26 12:19:06.855 [DEBUG][31] DoCompositeRendering() took 77.9995ms

I am aware of that brief dialog and have fixed it for alpha 2.  I will also add a new retry dialog.

Martin

Thanks, Martin. I'll watch for the alpha 2 when you post it.

I have had a feeling that some of the delays were related to recording lists. I do have a decent number of recordings (1,700+) spread over 5 drives. I've also had the feeling that somehow it might be related to having to spin up some of those less used recording drives. (I've got the verification settings turned off, so it shouldn't be needing to actually read from the drives every time the recordings reload, but it has the feel like it might be at some times.) Hopefully, sub can take a look at those excessive reloads and the 20 second screen render time.

[mvallevand]

Would this be on a slow drive?

2020-09-26 11:29:59.785 [DEBUG][7] Playing video file: G:\NPVR Recordings4\SEAL Team\Season 03\SEAL.Team.S03E19.In.the.Blind.ts

That was likely more just a slow > 10 second file open and not sub reloading recording. I guess 10 seconds was to optimistic even though it seems like an eternity.

Martin

[BrettB]

Would this be on a slow drive?

2020-09-26 11:29:59.785 [DEBUG][7] Playing video file: G:\NPVR Recordings4\SEAL Team\Season 03\SEAL.Team.S03E19.In.the.Blind.ts

That was likely more just a slow > 10 second file open and not sub reloading recording.  I guess 10 seconds was to optimistic even though it seems like an eternity.

Martin

Drive G is an external, USB 3 WD hard drive. And it has older/less used recordings on it. I'm also quite sure that it has its own drive spin down logic/control outside of Windows.

[mvallevand]

So I guess I need to bump the 10 seconds up too. We can tell how long the wait is for the time from the command is received to when it opens the edl file

2020-09-26 11:29:59.785 [DEBUG][7] Playing video file: G:\NPVR Recordings4\SEAL Team\Season 03\SEAL.Team.S03E19.In.the.Blind.ts
...
2020-09-26 11:30:18.302 [DEBUG][7] Loading commercial skip points

However with the delay loading your RPi fell back to http play so you would have had no comskip

2020-09-26 11:32:08.499 T:2170028912 DEBUG: G:/NPVR Recordings4/SEAL Team/Season 03/SEAL.Team.S03E19.In.the.Blind.ts
2020-09-26 11:32:08.509 T:2170028912 DEBUG: not found
2020-09-26 11:32:08.510 T:2170028912 DEBUG: /live?recording=38829&client=sdl-KNEW50xb827ebd2d752&sid=f7ce024048a5460382491c1613630a24

Martin

[BrettB]

However with the delay loading your RPi  fell back to http play so you would have had no comskip

2020-09-26 11:32:08.499 T:2170028912  DEBUG: G:/NPVR Recordings4/SEAL Team/Season 03/SEAL.Team.S03E19.In.the.Blind.ts
2020-09-26 11:32:08.509 T:2170028912  DEBUG: not found
2020-09-26 11:32:08.510 T:2170028912  DEBUG: /live?recording=38829&client=sdl-KNEW50xb827ebd2d752&sid=f7ce024048a5460382491c1613630a24

Martin

Ah. That explains it. I sort of noticed that it wasn't auto-skipping commercials, but I didn't pay much attention. I figured it was just that comskip hadn't detected some of them.

[VCR58]

Hi Martin, I'm having trouble with knewc running with my nextpvr linux server. Knewc says that it is "Unable to load newa data". Looks like it starts to load some data but it always fails. Kodi nextpvr is configured to use the linux server and I am currently recording the Stanly Cup finals. If I configure knewc to use the windows nextpvr server it works ok.

Rex