knewc problems with new server patch

[BrettB]

I just tried to watch Chicago Fire at 9:33pm, and knewc/NextPVR went sort of wonky. It didn't ever start actually playing. And I'm pretty sure that knewc actually died (or maybe just went into the background) and I was back at the Kodi menu. Then I tried (multiple times) to restart knewc, but it just kept timing out.

You can logs (kodi is in there too) here: https://bowmantech-my.sharepoint.com/:u:...Q?e=deYamh

[BrettB]

OK. After a few more minutes (at 21:44), we were able to relaunch knewc.

Maybe the tried before that were having problems when it was timing out and I said not to keep waiting. But the server was still sort of hung...

Here are updated logs: https://bowmantech-my.sharepoint.com/:u:...A?e=C84mTa

[mvallevand]

I believe this is the same as the issue crashing the linux server on stop. Anything else in the Windows event viewer at that time?

Code:

2021-01-06 21:34:32.644    [DEBUG][46]    PlaybackPositionHelper.GetLastPlaybackDate(D:\NPVR Recordings\Name That Tune\Season 01\Name.That.Tune.S01E01.Episode.1.ts)
2021-01-06 21:34:32.644    [DEBUG][46]    PlaybackPositionHelper.GetLastPlaybackDate(D:\NPVR Recordings\Who Wants to Be a Millionaire\Season 02\Who.Wants.to.Be.a.Millionaire.S02E11.In.the.Hot.Seat.Karamo.Brown.and.Special.Education.Teacher.Shadi.Seyedyousef.ts)
2021-01-06 21:34:32.722    [DEBUG][46]    DoCompositeRendering() took 109.1986ms
2021-01-06 21:34:32.846    [DEBUG][51]    DoCompositeRendering() took 124.7984ms
2021-01-06 21:34:32.846    [ERROR][12]    Unexpected error in DoCompositeRendering(): System.InvalidOperationException: Object is currently in use elsewhere.
   at System.Drawing.Graphics.FromImage(Image image)
   at NextPVRServer.Controllers.WebClientHelper.DoCompositeRendering(UIController uiController)
2021-01-06 21:34:32.846    [DEBUG][12]    DoCompositeRendering() took 0ms
2021-01-06 21:34:32.846    [ERROR][69]    Unexpected error in DoCompositeRendering(): System.InvalidOperationException: Object is currently in use elsewhere.
   at System.Drawing.Graphics.FromImage(Image image)
   at NextPVRServer.Controllers.WebClientHelper.DoCompositeRendering(UIController uiController)
2021-01-06 21:34:32.846    [DEBUG][69]    DoCompositeRendering() took 0ms
2021-01-06 21:35:16.744    [DEBUG][46]    Got request [192.168.143.33]: /index.html
2021-01-06 21:35:16.744    [DEBUG][46]    Logged in session from PLC: cf848634-50ba-43b3-8

After that I do see it timing out a few times in Kodi and then exiting knewc here

2021-01-06 21:34:20.805 T:2531214192 INFO: Python interpreter stopped

knewc has no control at that point. I don't know what was up a n Kodi but eventually it looks like you are in Kodi screensaver mode for several more minutes until you hit ok.

2021-01-06 21:39:20.461 T:2531214192 DEBUG: pimon hdmi screensaver: onInit
2021-01-06 21:43:26.378 T:2934961008 DEBUG: LIRC: - NEW 160 0 KEY_OK devinput (KEY_OK)

When you hit OK it looks like you got back into UI client mode. It looks like knewc is doing what is supposed to in timeout conditions.

Martin

[BrettB]

I believe this is the same as the issue crashing the linux server on stop.  Anything else in the Windows event viewer at that time?
....
After that I do see it timing out a few times in Kodi and then exiting knewc here

2021-01-06 21:34:20.805 T:2531214192    INFO: Python interpreter stopped

knewc has no control at that point.  I don't know what was up a n Kodi but eventually  it looks like you are in Kodi screensaver mode for several more minutes until you hit ok.

2021-01-06 21:39:20.461 T:2531214192  DEBUG: pimon hdmi screensaver: onInit
2021-01-06 21:43:26.378 T:2934961008  DEBUG: LIRC: - NEW 160 0 KEY_OK devinput (KEY_OK)

When you hit OK it looks like you got back into UI client mode.  It looks like knewc is doing what is supposed to in timeout conditions.

Nothing in the Windows event viewer. And the server didn't actually crash. In fact, there were at least a couple of recordings going on during that time.

And, yes, during that period around 21:33/21:34 when I kept getting the timeouts, I basically stopped and started gathering logs to send you. Then at 21:43, my roommate pressed the remote to reactivate the tv. So we figured we'd give it a try again. And that time it let us back in.

When I looked at the nrecord.log after we were able to get back in at 21:43, I did notice that during that "in-between time" one of the recordings had completed. I don't know if that had anything to do with the new connection working after that. I doubt it, but you never know.

[mvallevand]

I think there is more information here it looks like drive read timeouts.

2021-01-06 21:33:03.241 [DEBUG][12] Playing video file: D:\NPVR Recordings\Chicago Fire\Season 09\Chicago.Fire.S09E03.Smash.Therapy.ts
... you start to play the file and time out and get back in
2021-01-06 21:33:20.619 [DEBUG][69] Got request [192.168.143.26]: /public/Util/NPVR/Client/Instantiate

... however the response to that play came much later
2021-01-06 21:34:30.210 [ERROR][12] Unable to get media info. Make sure mediainfo runtime is available
2021-01-06 21:34:30.444 [DEBUG][12] comskip edl file does not exist locally for (D:\NPVR Recordings\Chicago Fire\Season 09\Chicago.Fire.S09E03.Smash.Therapy.ts)

knewc isn't expecting to wait 90 seconds for a file to open.

It looks like you had to similar issue with an earlier file but you may have edited your kodi log since I can't see how it handled it

2021-01-06 21:30:01.800 [ DEBUG][26] Playing video file: D:\NPVR Recordings\NCIS New Orleans\Season 07\NCIS.New.Orleans.S07E05.Operation.Drano,.Part.I.ts
2021-01-06 21:30:40.222 [DEBUG][26] Loading commercial skip points

[BrettB]

I think there is more information here it looks like drive read timeouts.

2021-01-06 21:33:03.241 [DEBUG][12] Playing video file: D:\NPVR Recordings\Chicago Fire\Season 09\Chicago.Fire.S09E03.Smash.Therapy.ts
... you start to play the file and time out and get back in
2021-01-06 21:33:20.619 [DEBUG][69] Got request [192.168.143.26]: /public/Util/NPVR/Client/Instantiate

... however the response to that play came  much later
2021-01-06 21:34:30.210 [ERROR][12] Unable to get media info. Make sure mediainfo runtime is available
2021-01-06 21:34:30.444 [DEBUG][12] comskip edl file does not exist locally for (D:\NPVR Recordings\Chicago Fire\Season 09\Chicago.Fire.S09E03.Smash.Therapy.ts)

knewc isn't expecting to wait 90 seconds for a file to open.

It looks like you had to similar issue with an earlier file but you may have edited your kodi log since I can't see how it handled it

2021-01-06 21:30:01.800 [ DEBUG][26] Playing video file: D:\NPVR Recordings\NCIS New Orleans\Season 07\NCIS.New.Orleans.S07E05.Operation.Drano,.Part.I.ts
2021-01-06 21:30:40.222 [DEBUG][26] Loading commercial skip points

I didn't (at least to me knowledge) edit my kodi log at all. However, when I first started having problems and getting the timeouts, I did select the option to not have knewc wait (i.e. go back to Kodi). And then I restarted knewc. So that "missing handling" might be because I had told knewc to not wait for the timeout.

If I'm recalling correctly, when I tried to play Chicago Fire, I had been doing something on the computer or something similar before that and wasn't actually playing anything just before that. However, the D: drive on the server is the current default recording drive, and there were multiple recordings going to it at that time. So it shouldn't have been spun down.

OK now I'm thinking about this more... Normally, I record several shows each night, let them fully record, let comskip run on them, etc. before I ever watch them. However, last night, I suspected that due to the coup attempt here, the regular programming had probably been pre-empted so I was trying to play some of these files (specifically Chicago Fire and Chicago Med?) to verify that they were the wrong shows. Then I went and did the "Forget" option so that when they do actually air, they will get recorded. It is very possible that comskip was either currently running for that file or was still waiting to run (I do limit it to 1 comskip instance at a time) when I tried to play it there. I do have a recollection that when I was playing some of those for verification, the OSD timeline wasn't showing and skip points. I've since deleted those "wrong show recordings", so can't verify whether or not there is an .edl file there now.

Ah, wait, I've got my postprocessing.log:

Code:

Wed 01/06/2021 21:05:00.66 -53257- Postprocessing.bat invoked for recording "D:\NPVR Recordings\Chicago Fire\Season 09\Chicago.Fire.S09E03.Smash.Therapy.ts" (OID 53257) from channel 811
Wed 01/06/2021 21:05:00.66 -53257-      ...  Sleeping a pseudo-random number of seconds (37) to avoid simultaneous execution
Wed 01/06/2021 21:05:00.66 -53317- Postprocessing.bat invoked for recording "D:\NPVR Recordings\Who Wants to Be a Millionaire\Season 02\Who.Wants.to.Be.a.Millionaire.S02E11.In.the.Hot.Seat.Karamo.Brown.and.Special.Education.Teacher.Shadi.Seyedyousef.ts" (OID 53317) from channel 805
Wed 01/06/2021 21:05:00.67 -53317-      ...  Sleeping a pseudo-random number of seconds (37) to avoid simultaneous execution
Wed 01/06/2021 21:05:00.69 -53346- Postprocessing.bat invoked for recording "D:\NPVR Recordings\Name That Tune\Season 01\Name.That.Tune.S01E01.Episode.1.ts" (OID 53346) from channel 809
Wed 01/06/2021 21:05:00.69 -53346-      ...  Sleeping a pseudo-random number of seconds (6) to avoid simultaneous execution
Wed 01/06/2021 21:05:06.26 -53346-    --- Launching comskip on "D:\NPVR Recordings\Name That Tune\Season 01\Name.That.Tune.S01E01.Episode.1.ts"
Wed 01/06/2021 21:05:37.29 -53317-    --- Launching comskip on "D:\NPVR Recordings\Who Wants to Be a Millionaire\Season 02\Who.Wants.to.Be.a.Millionaire.S02E11.In.the.Hot.Seat.Karamo.Brown.and.Special.Education.Teacher.Shadi.Seyedyousef.ts"
Wed 01/06/2021 21:05:37.30 -53257-    --- Launching comskip on "D:\NPVR Recordings\Chicago Fire\Season 09\Chicago.Fire.S09E03.Smash.Therapy.ts"
Wed 01/06/2021 21:22:14.46 -53346- PostProcessing.bat completed for "D:\NPVR Recordings\Name That Tune\Season 01\Name.That.Tune.S01E01.Episode.1.ts"
Wed 01/06/2021 21:35:39.19 -53317- PostProcessing.bat completed for "D:\NPVR Recordings\Who Wants to Be a Millionaire\Season 02\Who.Wants.to.Be.a.Millionaire.S02E11.In.the.Hot.Seat.Karamo.Brown.and.Special.Education.Teacher.Shadi.Seyedyousef.ts"
Wed 01/06/2021 21:35:40.45 -53257- PostProcessing.bat completed for "D:\NPVR Recordings\Chicago Fire\Season 09\Chicago.Fire.S09E03.Smash.Therapy.ts"

It looks like there were actually 3 comskips (including for Chicago Fire) running at the same time right there. I might have to look at my logic for preventing simultaneous runs.

I've got to go to work now. (Dang day job!) But I can look into this more later.

As always, thanks for all of your help, Martin!

[mvallevand]

That's good info the reason I thought you edited the logs is it jumped but the earlier show might even be in a kodi.old.log after a reboot (I note now the time was before the ntp time clicked in)

Sub probably needs to look at how the call to mediainfo works on a growing file.

Martin

[BrettB]

That's good info the reason I thought you edited the logs is it jumped but  the earlier show might even be in a kodi.old.log  after a reboot (I note now the time was before the ntp time clicked in)

Sub probably needs to look at how the call to mediainfo works on a growing file.

Martin

For completeness, here's a link to the kodi.old.log: https://bowmantech-my.sharepoint.com/:u:...w?e=a8bzbt At one point during this, kodi/knewc had "gone blank", and I SSHd into the Pi an rebooted it.

Also, just to clarify, I'm pretty sure that all of the recordings we tried playing/watching at that time had completed (i.e. the .ts file was complete), just the postprocessing comskip wasn't necessarily complete.

We did watch Stephen Colbert later last night while it was still recording. And a couple of times I tried to skip forward after the end point from when starting to watch so it would go backwards in the file. So then I restarted watching it. So I do have some samples in log files (unless the EPG update rolled them off) of that situation.