Recent failed recordings.

[CDinger]

I have experienced 2 recent episodes where several recordings failed. Yesterday it was 2 episodes of Young Sheldon and Saturday Night Live. I believe the logs will indicate the prior failures, as I don't remember the shows at this moment. Between the 2 episodes, I didn't do anything and everything was okay until yesterday.

See attached logs.

Let me know if you need more, evidently my full zip is too large and won't upload. I zipped just the nrecord* logs.
Craig

[CDinger]

Attached are device adapter logs

[mvallevand]

There were driver errors on the same tuner so there doesn't appear to be much NextPVR could do to work around this. The same channel was working earlier on this tuner and there was nothing unusual about these requests so I would check with your h/w manufacturer.

Code:

2022-12-03 18:59:00:241 [DEBUG] KQCA (sid=4)
2022-12-03 18:59:00:241 [DEBUG] on request adapter3, frontend0
2022-12-03 18:59:00:242 [INFO] Tuning: 599028615 Hz
2022-12-03 18:59:00:242 [INFO] Changing frequencies
2022-12-03 18:59:00:244 [INFO] Tuning: 599028615 Hz
2022-12-03 18:59:00:244 [ERROR] dvb_fe_set_parms failed
2022-12-03 18:59:00:244 [ERROR] Failed to start stream

Martin

[CDinger]

Thanks for your help Martin.

After looking at your response, I went to NextPVR settings>devices and tried a channel scan on each adapter. Adapter 3 didn't scan, but adapters 0, 1, and 2 all scanned. Without rebooting or anything else I restarted nextpvr-server and all adapters scan and record. I guess it doesn't prove anything but, it makes me think it is something within NextPVR. It could be that my tuner has a problem with adapter3. My tuner is Hauppauge QuadTV. Currently, device-adapter3 is first priority, so I will move device-adapter3 down in priority and see if the problem happens with a different device-adapter.

Craig

[mvallevand]

No for me that shows the opposite, since I wouldn't expect the scan to work. NextPVR locks the tuner from the moment it does the first recording even when not primed and it loops through the same logic steps and all of them seem to indicate that NextPVR wasn't doing anything "new" for the first failure. I was looking to see if this was a a multi-rec on the same mux but it seemed very clean.

I do suspect there is something in the session with DeviceHostLinux and libdvbv5 and the /dev/dvb driver so sub might be able to close the server on this error so that the next call restarts DeviceHostLinux rather than having a permanent error.

Martin

[CDinger]

okay, I disabled device-adapter3 and I will see what happens.

[mvallevand]

Personally I don't think it is related to adapter3 it might even exasperate the problem using fewer tuners

Martin

[CDinger]

I have continued to have intermittent failed recording. In the past, I have deleted the failed recording and restarted NextPVR and all would be good for a couple of weeks or more. A day or 2 ago I had a failed recording but didn't delete it. Tonight I had 3 failed recordings. NextPVR was actively recording, but would have a couple hour break before the next show. I waited for the show to end, then dove into trying to figure out what happened.

I looked in the recording directory and found that the *.ts file existed for all 4 failed shows. I found a number of ERRORS in nrecord.log.3

Code:

2023-01-13 02:44:39.112 [ERROR][96]     Newtonsoft.Json.JsonReaderException: Error reading JArray from JsonReader. Current JsonReader item is not an array: StartObject. Path '', line 1, position 1.
2023-01-13 02:44:39.511 [ERROR][207]    System.Net.WebException: The remote server returned an error: (403) Forbidden.
2023-01-13 02:44:39.511 [ERROR][207]    SD http code: Forbidden
2023-01-13 02:44:39.511 [ERROR][207]    {"response":"INVALID_USER","code":4003,"serverID":"20141201.web","message":"Invalid username or token has expired.","datetime":"2023-01-13T10:44:39Z"}
2023-01-13 02:44:39.511 [ERROR][207]    Invalid token. Will get new token and retry...
2023-01-13 02:44:42.489 [ERROR][207]    System.Net.WebException: The remote server returned an error: (403) Forbidden.
2023-01-13 02:44:42.489 [ERROR][207]    SD http code: Forbidden
2023-01-13 02:44:42.490 [ERROR][207]    {"response":"INVALID_USER","code":4003,"serverID":"20141201.web","message":"Invalid username or token has expired.","datetime":"2023-01-13T10:44:42Z"}
2023-01-13 02:44:42.490 [ERROR][207]    Invalid token. Will get new token and retry...
2023-01-13 02:44:46.082 [ERROR][81]     Newtonsoft.Json.JsonReaderException: Error reading JArray from JsonReader. Current JsonReader item is not an array: StartObject. Path '', line 1, position 1.
2023-01-13 02:44:46.367 [ERROR][207]    System.Net.WebException: The remote server returned an error: (403) Forbidden.
2023-01-13 02:44:46.367 [ERROR][207]    SD http code: Forbidden
2023-01-13 02:44:46.368 [ERROR][207]    {"response":"INVALID_USER","code":4003,"serverID":"20141201.web","message":"Invalid username or token has expired.","datetime":"2023-01-13T10:44:46Z"}
2023-01-13 02:44:46.368 [ERROR][207]    Invalid token. Will get new token and retry...
2023-01-13 02:44:48.820 [ERROR][207]    System.Net.WebException: The remote server returned an error: (403) Forbidden.
2023-01-13 02:44:48.820 [ERROR][207]    SD http code: Forbidden
2023-01-13 02:44:48.821 [ERROR][207]    {"response":"INVALID_USER","code":4003,"serverID":"20141201.web","message":"Invalid username or token has expired.","datetime":"2023-01-13T10:44:48Z"}
2023-01-13 02:44:48.821 [ERROR][207]    Invalid token. Will get new token and retry...
2023-01-13 02:44:50.904 [ERROR][96]     Newtonsoft.Json.JsonReaderException: Error reading JArray from JsonReader. Current JsonReader item is not an array: StartObject. Path '', line 1, position 1.
2023-01-13 02:44:56.497 [ERROR][207]    Channel not found. OID=7946. Name=Telex

I believe the more telling ones are

Code:

2023-01-13 17:30:40.100 [ERROR][12]     Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The operation has timed out.
2023-01-13 17:32:20.110 [ERROR][12]     Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The operation has timed out.
2023-01-13 18:00:40.215 [ERROR][12]     Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The operation has timed out.
2023-01-13 18:02:20.226 [ERROR][12]     Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The operation has timed out.
2023-01-13 18:02:21.112 [ERROR][12]     Unexpected orphaned recording found (52399). Stopping it...
2023-01-13 18:30:40.158 [ERROR][12]     Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The operation has timed out.
2023-01-13 18:32:20.166 [ERROR][12]     Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The operation has timed out.
2023-01-13 18:32:21.847 [ERROR][12]     Unexpected orphaned recording found (52384). Stopping it...
2023-01-13 19:00:40.234 [ERROR][12]     Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The operation has timed out.
2023-01-13 19:02:20.246 [ERROR][12]     Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The operation has timed out.
2023-01-13 19:02:21.707 [ERROR][12]     Unexpected orphaned recording found (52368). Stopping it...
2023-01-13 19:30:40.062 [ERROR][12]     Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The operation has timed out.
2023-01-13 19:32:20.074 [ERROR][12]     Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The operation has timed out.
2023-01-13 19:32:20.868 [ERROR][12]     Unexpected orphaned recording found (52441). Stopping it...
2023-01-13 20:30:40.179 [ERROR][12]     Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The operation has timed out.
2023-01-13 20:32:20.189 [ERROR][12]     Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The operation has timed out.

I then copied the npvr.db3 file to my home directory and opened it with "DB Browser for SQLite". I found the 4 failed recordings and all the normal recordings in the "Scheduled Recording Table". I noticed that the "status" field was set to 3 for the failed recording but was set to 2 for all the others. I changed the 3 to a 2 for each failed recording and saved the file. I copied the file back to /var/opt/nextpvr/npvr.db3 and chown to nextpvr:nextpvr. Next I restarted NextPVR and there were no longer any failed recording. I can now watch all 3 shows in Kodi.

logs attached and I'm off to bed.

Thanks,

Craig

My system is
Debian 11 Bullseye
Hauppauge WinTV-QuadHD tuner
Intel® Core™ i3-10100 CPU @ 3.60GHz
16GB RAM
Firmware
v4l-cx23885-avcore-01.fw

[mvallevand]

Different problem. Number 1 is related I suspect to recent changes on SD where the IP can only be used once per time. If you have multiple NextPVR or other SD client make sure their EPG updates vary

No logs. Logs can only be 2MB and DeviceHostLinux logs can be spammy.

You can play failed recordings in Kodi but you have to access them through the Failed Recordings folder. However dong this or changing the status might not be enough if the duration is wrong, Kodi is very picky about the duration being correct.

Martin

[CDinger]

Martin,

You nailed it, I was accessing SD 2 times via multiple NextPVR

I don't know if they are still useful, but I trimmed old logs to get under 2MB

I need to stop assuming, I assumed if they were failed recordings that no recording existed.

Thanks,
Craig