recording service not running at recording time

[arlingtoner]

Sometimes a scheduled recording on my Windows 11 Pro system with an HDHomerun Flex 4K works and sometimes it does not, failing with "recording service not running at recording time." I am using a laptop and all of its power settings when it is plugged in are set to "sleep" as is the state for when the lid is closed. Services show NextPVR Service running and started automatically. Powercfg shows three waketimers set for reasonable times, that is, for what the Web App says I have recordings scheduled, and one head scratcher (set for 2:44 AM tomorrow). Here is a snippet from nrecord.log that I could use help interpreting. It shows a recording starting when it should yet it being marked as failing after the fact? Anyway, any advice about what I should be looking at or experimenting with or changing are welcome.

2024-01-13 08:06:00.471 [DEBUG][37] Dropping out (leaseGoodUntil 8:05:59 AM)
2024-01-13 08:30:48.542 [DEBUG][10] DefaultDirectoryChoice: first
2024-01-13 08:30:48.543 [DEBUG][10] Preferred filename is 'This.Old.House.S45E09.Lexington:.Phased.Out'
2024-01-13 08:30:48.545 [DEBUG][10] allocating recording target filename: C:\Users\Public\Videos\This Old House\Season 45\This.Old.House.S45E09.Lexington.Phased.Out.ts
2024-01-13 08:30:48.546 [DEBUG][10] About to start recording (871 on 21): C:\Users\Public\Videos\This Old House\Season 45\This.Old.House.S45E09.Lexington.Phased.Out.ts
2024-01-13 08:30:48.546 [DEBUG][10] (Recording is due to be stopped at 1/13/2024 9:00 AM)
2024-01-13 08:30:48.546 [DEBUG][10] Free space 795907506176  (C:\)
2024-01-13 08:30:48.546 [DEBUG][10] HDHomeRunRecorder.StartStream()
2024-01-13 08:30:48.547 [DEBUG][10] ipaddress is 192.168.0.175
2024-01-13 08:30:48.547 [DEBUG][10] building graph
2024-01-13 08:30:48.547 [DEBUG][10] About to load channel from tuning
2024-01-13 08:30:48.551 [DEBUG][10] source@1
2024-01-13 08:30:48.551 [DEBUG][10] Requesting: http://192.168.0.175:5004/tuner0/v57.4
2024-01-13 08:30:48.553 [DEBUG][10] ConnectToURL: http://192.168.0.175:5004/.../v57.4?....  [fj0t7sReVsfZJKqULyCGl1Uw+ceGxPUE9E/bDcHQYiOtKbXeb/5MeC9bcsXQSxCy/gm96Cj7UjwXHyYo7UhycXiGDzHf6SBhNrGg/97tV0dOc7aOVLshfDlRxwoq1dppGUqloujyNeo47KbWaAY7ZYoNWjVziUkc3jpXU8Rky/Cei9cTKWkzEczP4nhrL/WnulfVJdAv/PpqTTXiyvgN1yN1BsASeqtXprw99j085Zhwix6vft3031DIO6TSDtfSYuTKgpp0qLVBcPu+ASaZL6FsMom6q8Hbk0nxFYygaUnapDgzJDjx50JM/d1Fiqg0h2DJd4ihsG1lzszALxRMyTeQy9blCHoZS7jq6jOdwos3kbXg/PUAFH/KdG6v8Ca61V++GfWIf8PeXcx/1AFhLqLIDKkI55FkFxtPBKSFTwA=]
2024-01-13 08:31:41.940 [DEBUG][10] connected to: http://192.168.0.175:5004/.../v57.4?....  [lgD0GsaovL15Pi3kzv3mIc5u4imDqQnX6KnjMLhqn3h19rCrucC6OksyEwuiNCr8iuXSsg+Uz+kdxrPwCplTN1uyZsFDqK0la0XEKIm8H+B3KRz8ZkEiBiqMpL+/BENiNRVa/wm+IgjFg/NwOgYHW2WM0gt+2S2ex0IyRpLpKooQRrtZfPW2qk7bpAh2gddjs3rrwbWZHFzlK9mgUEmAwbBQTuPL9VttntmC0AFZ95LgsWbP2ahV0Ol+4w7OqqqLZs7qz7cEu3XuwE7nHCtMGOdh1AEadKu3IpMixBBynKiuhoZkgR1KuHB9Zjid/qtSpcvOVQSsaAqixXiZs/idfkP91w9vg0MeuVrR9uMT3/t3/B8vNlr3bikKKs+sr6jNWXrsmsBjpdKlkYDeuJJQjKVw3Vd094B1QXFIL+oKqKI=]
2024-01-13 08:31:41.940 [DEBUG][10] content-type: video/mpeg
2024-01-13 08:31:41.941 [DEBUG][10] Creating writer: C:\Users\Public\Videos\This Old House\Season 45\This.Old.House.S45E09.Lexington.Phased.Out.ts
2024-01-13 08:31:41.941 [DEBUG][22] HTTP input source starting
2024-01-13 08:31:42.085 [DEBUG][10] Created Mutex: Global\NPVR-mutex-6b2efaa19e8b06c9b5027d5756dc6907
2024-01-13 08:31:42.086 [DEBUG][10] Created map: C:\Users\Public\Videos\This Old House\Season 45\This.Old.House.S45E09.Lexington.Phased.Out.ts.map
2024-01-13 08:31:42.088 [DEBUG][10] StartStream [C:\Users\Public\Videos\This Old House\Season 45\This.Old.House.S45E09.Lexington.Phased.Out.ts] allocated handle: 4
2024-01-13 08:31:42.088 [DEBUG][10] StartStream() returned handle=4
2024-01-13 08:31:42.088 [DEBUG][10] Allocated Handle: 4
2024-01-13 08:31:42.088 [DEBUG][10] Started recording (871:4:C:\Users\Public\Videos\This Old House\Season 45\This.Old.House.S45E09.Lexington.Phased.Out.ts)
2024-01-13 08:31:42.106 [DEBUG][10] Starting thumbnail extraction for C:\Users\Public\Videos\This Old House\Season 45\This.Old.House.S45E09.Lexington.Phased.Out.ts
2024-01-13 08:51:48.542 [DEBUG][10] Running: C:\Program Files\NextPVR\Other\ffmpeg.exe -re -y -i "C:\Users\Public\Videos\This Old House\Season 45\This.Old.House.S45E09.Lexington.Phased.Out.ts" -vf fps=1/10,scale=220:124 -f mjpeg -flush_packets 1 "C:\Users\Public\Videos\This Old House\Season 45\This.Old.House.S45E09.Lexington.Phased.Out.thumbnails"
2024-01-13 08:51:48.579 [DEBUG][47] Starting timing extraction for C:\Users\Public\Videos\This Old House\Season 45\This.Old.House.S45E09.Lexington.Phased.Out.ts
2024-01-13 08:51:48.580 [DEBUG][10] No C:\Users\Public\NPVR-data\scripts\ParallelProcessing.bat
2024-01-13 08:52:48.610 [DEBUG][10] Active...staying awake
2024-01-13 09:00:31.241 [DEBUG][10] Marking recording (871) as 'Recording service not running at recording time'
2024-01-13 09:00:31.334 [DEBUG][10] Looking for alternative airings of This Old House: Lexington: Phased Out (EP000044441449)
2024-01-13 09:00:31.339 [DEBUG][10] LoadListingByAdvancedRules(channel=7177,advancedRules=unique_id='EP000044441449')
2024-01-13 09:00:31.346 [DEBUG][10] - trying 1/13/2024 3:00 PM
2024-01-13 09:00:31.347 [DEBUG][10] about to record:

[sub]

Yeah, that's very strange.

I thinking it's something to do with nearly full minute disappearing into trying to connect to your HDHR. I'm guessing there was some type of error/timeout happening in there, and it's not reporting it correctly.

2024-01-13 08:30:48.553 [DEBUG][10] ConnectToURL: http://192.168.0.175:5004/.../v57.4?....
2024-01-13 08:31:41.940 [DEBUG][10] Connected to: http://192.168.0.175:5004/.../v57.4?....

[mvallevand]

What is weird to me is the minutes to start thumbnail extraction.

Maybe check http://192.168.0.175/log.html and save and zip the results, there might be a clue there.

Martin

[arlingtoner]

Interesting point by sub. The system that failed to record at 8:30 local successfully recorded a program at 5:00. Then it took less than a second to connect. Also, my take on the 8:30 problem is that the recording was successfully started, but ended early, after only 16 minutes. I'm way over my head here, so I'll stop this and simply attach two files. The zip of the logs (the successful recording is in nrecord.log.1) and a couple days worth of the log.html file, as I suspect that you aren't interested in what the system was doing weeks ago. I've also annotated that file with what I believe are the external events going on during the times captured.

Thanks for your help on this.

[mvallevand]

I don't see the logs in the file. If the zip file is bigger than 2MB you need to use an external link. if you still have my email address you can send it to me.

Martin

[arlingtoner]

My post (#4) says it has a 574.01 KB attachment. It doesn't say anything about the 5KB ASCII attachment of log.html. I tried uploading the latter again but in a separate post, but it didn't show up there either, so I deleted the post.

[mvallevand]

Did you zip it first?

[mvallevand]

I have the logs and what it looks like is your NextPVR server is not using a fixed IP.

Definitely odd

20240113-13:30:32 Tuner: tuner0 tuning 57.4 WGBYDT4 (8vsb:213MHz-6) The 8:30 recording successfully starts, but
20240113-13:30:33 Tuner: tuner0 streaming http to 192.168.0.165:54213 ends early for some reason?
20240113-13:46:10 Tuner: tuner0 http stream ended (remote closed)

and NextPVR didn't log any error when it dropped. Can you watch 57.4 live maybe it is a weak signal or impacted by weather there were no attempts to get it in that short log.

Marin

[mvallevand]

Why did you reschedule This.Old.House.S45E09.Lexington.Phased.Out.ts at 07:05 since it was recorded overnight? If you see the message "Alternative Airing - after failed original", the file is actually still good. When you played the earlier overnight version at 8am was it bad quality so you deleted it?

Edit: rechecking your annotated note "The recording was successful (I've watched it) but something in the Web App made me think it wasn't, perhaps a reschedule" I see you deleted it but but it doesn't explain rescheduling it.

Look like you have another 3rd version being recorded right now.

Martin

[arlingtoner]

> ...what it looks like is your NextPVR server is not using a fixed IP.

That is true as none of my devices use fixed IP addresses. The NextPVR server is running on a laptop that may be shut down long enough to lose the lease on its IP address. Although I don't actively track the IP addresses of my devices, I don't recall seeing much change among my modest collection of devices that are generally connected on turned on. Why does the IP address of the NextPVR server matter?

In the logs I sent, the NextPVR server has the same IP address throughout, in particular, both for the successful 4:00 local time recording and unsuccessful 8:30 recording and the time in between.

To my eyes, in the logs, the successful recording and the unsuccessful one start identically, except for the different number of the handle returned by StartStream() and the failure having an "Active...staying awake" (where did that come from?) before its recording time is up.

The successful one simply notes that it is past the time of recording and shuts things down ("Stopping recording (867 on 21)" - where did the "21" come from?). The unsuccessful one instead simply says "Marking recording (871) as 'Recording service not running at recording time'". Is there a way to find out what caused it to say that?

I've watched 57.4 lots and have never seen a problem with its signal. In fact, the 57.x are probably the strongest signal that I have.

In an attempt to get more information, I attempted to record another half hour program broadcast this afternoon on 57.4. No problems.


> Did you zip it first?

No. At this instance, my spidy-sense feels like I should have known that I needed to. Did I get that right?