in progress recording fails when service restarted

[Allan]

My backend crashed a couple of nights ago while a show was recording. 

My launchdaemon immediately restarted the backend, but the balance of the show failed to record. Subsequent scheduled recordings were fine without any human intervention - only the show then in progress failed to complete.

Log attached. It begins at the restart after the backend crash.

I wonder if it was a timing thing? Maybe the backend wasn't ready to record when it tried to continue the recording immediately after it restarted? If that was the case, I think I could work around it.

[mvallevand]

Seems like it did start on restart since the -0.ts file was created.

Code:

2025-04-06 00:27:55.225    [DEBUG][11]    Marking recording (0) as 'Recording service restarted during recording'
2025-04-06 00:27:55.231    [DEBUG][11]    About to start recording (5215 on 21): /volumes/TV/nextpvr/Saturday Night Live/Season 50/Saturday.Night.Live.S50E17.Jack.Black;.Elton.John.and.Brandi.Carlile-0.ts
2025-04-06 00:27:55.231    [DEBUG][11]    (Recording is due to be stopped at 2025-04-06 1:02 AM)
...
2025-04-06 01:04:00.233    [DEBUG][11]    Stopping recording (5215 on 21). Past end time of recording. 1
2025-04-06 01:04:00.234    [DEBUG][11]    No errors, but no data delivered

The recording problem seems to be with the legacy HDHR.

2025-04-06 01:03:12.662 [DEBUG][18] Have received 0 bytes from rtp source

Martin

[Allan]

Yes, it created a file for the resumed recording, but nothing was recorded.

Without intervention, the HDHR3 has provided the stream for two recordings since the failure. I don't understand where the legacy device issue comes into play.

This HDHR3 does most of my recording - NextPVR is configured to use it for the local Toronto channels because the HDHR4 gets overloaded by the (slightly amplified) signal strength necessary for the Buffalo stations. NextPVR is configured to use my HDHR4 for the more distant Buffalo area channels.

[mvallevand]

I know you like to battle words with me but I can only report what NextPVR reports. It says it received no data via rtp which explains everything.

UDP is unreliable so this request could have failed for unknown reasons but NextPVR appeared to do everything correctly unless perhaps your server IP .120 was wrong. You decided to send partial logs so we can't compare but again UDP is not going to guarantee delivery. Perhaps port 8020 was still in use for the previous instance and your restart was too fast.

Code:

2025-04-06 00:27:55.232    [DEBUG][11]    HDHomeRunRecorder.StartStream()
2025-04-06 00:27:55.232    [DEBUG][11]    ipaddress is 10.0.100.94
2025-04-06 00:27:55.232    [DEBUG][11]    building graph
2025-04-06 00:27:55.232    [DEBUG][11]    About to load channel from tuning
2025-04-06 00:27:55.234    [DEBUG][11]    10393C2F is at 10.0.100.94
2025-04-06 00:27:55.235    [DEBUG][11]    legacy tuning requesting auto:491000000
2025-04-06 00:27:55.460    [DEBUG][11]    legacy tuning requesting program 1
2025-04-06 00:27:55.659    [DEBUG][11]    legacy tuning requesting target rtp://10.0.100.120:8020
2025-04-06 00:27:55.843    [DEBUG][11]    Requesting: rtp://10.0.100.120:8020
2025-04-06 00:27:55.844    [DEBUG][11]    RTP input source starting

Martin

[Allan]

I am just providing information that, I hope, will be helpful to anyone who may be able to provide some guidance. I will strive to do better if you tell me what I said that you have taken as "battle words".

The log I provided is the entire file. It started when NextPVR restarted which, I understand, is its normal behaviour. 10.0.100.120 is the correct IP address.

This is the only time I have had a failure of this nature. I am not suggesting it was any defect or deficiency in NextPVR. I was, primarily, wondering if it might be a timing thing that there would be some way to address. For instance, could the HDHR have been stuck sending the original feed to the crashed process, and had to be reset or timed out? The launchdaemon restarted NextPVR almost instantly. Maybe it should wait a minute or two?

[mvallevand]

I am not sure how the launchdaemon detect the NextPVRService.dll "crash" bit it is certainly still possible the the 8020 port was open we'd have to have some idea of the natutre of the crash and the restart process. It might be something that could be scripted in PreStartup.sh.

There seemed to be other things going wrong before the crash since the original file had problems with the timestamps that might be an indicator of the why there was a crash, something for you to look at in the future.

2025-04-06 00:28:27.153 [WARN][7] clock jump of 38004.885167 seconds

Sending all the logs always is preferred. It lets us compare working and non working streaming. Also I never could figure out which UI client you were running on 10.0.100.98 since there appeared to be a bug in its reporting that needs s look.

2025-04-06 00:28:28.965 [DEBUG][9] - media: NaN

Martin

[Allan]

I was a bit lazy saying the launchdaemon does it - the launchctl process does it, as directed by the launchdaemon, which contains this key:

Code:

<key>KeepAlive</key>
<true/>

The NextPVRServer.dll crashed or otherwise terminated and launchctl relaunched it almost instantly (The earlier log, unfortunately was gone by the time I got to this, but the recording that was terminated prematurely shows that it was last modified at 00:27:49 and the new log shows it starting up at 00:27:50.138.)

How do you know there was an issue with the timestamp on the part 1 recording? I don't think I experienced a problem with it.

The most recent log (unrelated to this incident) is attached if that helps. There should be two recordings in this log.

x.98 is my LG tv. The app was the WebOS app.

[mvallevand]

There shouldn't be clock jump messages with good timestamps

Ok the LG client shouldn't report a NaN. I don't remember if macos has dmesg logs maybe check for libSkiaSharp errors they often crash the server.


Martin

[Allan]

Logging on macOS has become pretty opaque (to me anyway). There is a unified database that everything is logged to but you have to query it with terminal commands and I wouldn't know where to start looking for libSkiaSharp errors, if they are even logged.

The last log I uploaded that, I said, has two recordings, only has one. The second failed, but not for any mysterious reason (I had been having trouble with a recording conflict that should not have been a conflict, and was trying to fix it. Also, an HVAC contractor unplugged some stuff.)

Finally, if it is of interest, I am attaching the crashreport for dotnet from the incident we have been discussing.

[mvallevand]

That nrecord log helps a bit since to me it does indicate that there is no error trapped when it can't connect and start recording via UDP.

Hard to make much from that but thanks. It is an error code 2 but that is almost to be expected. I guess the best you can do is check if you are using the LG client since I really only see crashes with libSkiaSharp.

It does seem odd that so many threads had started

Code:

"symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",
          "symbol": "_pthread_start",

Martin