[Failed: Recording service not running at recording time]

[Poocher]

Hi,
I have researched this for awhile and I cannot figure out what the issue is. I have a new computer PC with Windows 10 Pro now. NPVR used to work flawlessly on Windows 10 Home. The latest failed recording happened on Sept 18 where it was supposed to start at 19:00. I have attached the log from that day.

I have some recording that work and some that do not. When it does not, I believe the NPVR service is not waking the computer from sleep. The service was set to "Automatic (delayed start).

Here is a part of the log near the time the recording should have started. 
20240918-16:25:41 Recording: sending discover using local ip [2601:441:8201:387f:891f:b9e7:38a:af0c] (ifindex 4)
20240918-16:25:41 Recording: sending discover using local ip [fe80::fcfa:5859:aa83:e096] (ifindex 4)
20240918-16:25:41 Recording: sending discover using local ip 192.168.1.144 (ifindex 4)
20240918-16:25:41 Recording: sending discover using local ip [2601:441:8201:387f:891f:b9e7:38a:af0c] (ifindex 4)
20240918-16:25:41 Recording: sending discover using local ip [fe80::fcfa:5859:aa83:e096] (ifindex 4)
20240918-16:25:41 Recording: sending discover using local ip 192.168.1.144 (ifindex 4)
20240918-16:25:41 Recording: discover response from 8374EC14-802B-44B7-B840-E9FDC6A54B2F http://[::1]:49769
20240918-16:25:41 Recording: discover response from 8374EC14-802B-44B7-B840-E9FDC6A54B2F http://127.0.0.1:49769
20240918-16:25:41 Recording: discover response from 8374EC14-802B-44B7-B840-E9FDC6A54B2F http://[2601:441:8201:387f:891f:b9e7:38a:af0c]:49769
20240918-16:25:41 Recording: discover response from 8374EC14-802B-44B7-B840-E9FDC6A54B2F http://[fe80::fcfa:5859:aa83:e096]:49769
20240918-16:25:41 Recording: discover response from 8374EC14-802B-44B7-B840-E9FDC6A54B2F http://192.168.1.144:49769
20240918-16:25:41 Recording: discover response from 1040ACAE http://[2601:441:8201:387f:218:ddff:fe04:aca]:80
20240918-16:25:41 Recording: discover response from 1040ACAE http://[fe80::218:ddff:fe04:aca]:80
20240918-16:25:41 Recording: discover response from 1040ACAE http://192.168.1.211:80
20240918-16:25:41 Recorded: recorded sync to record-api.hdhomerun.com
20240918-16:25:41 Recording: event download from record-api.hdhomerun.com
20240918-16:25:41 Recording: 1040ACAE lineup request success (found 115 channels)
20240918-16:25:43 System: server time = Wed Sep 18 16:25:43 2024 (correction of 1s)
20240918-16:25:43 Recorded: recorded sync success
20240918-16:25:43 System: server time = Wed Sep 18 16:25:43 2024 (correction of 1s)
20240918-16:25:43 Recording: myhdhomerun_record authorization error or not subscribed to dvr service
20240918-16:25:43 Recording: event download failed
20240918-16:25:43 Recording: disk space available = 1434GB
20240918-16:25:43 Recording: current time = Wed Sep 18 16:25:43 2024 (correction of 1s)
20240918-16:25:43 Recording: no timer events planned
20240918-16:26:45 Status: Resource: nbk=2 dmk=356
20240918-16:28:45 Status: Resource: nbk=2 dmk=356
20240918-16:30:45 Status: Resource: nbk=2 dmk=356
20240918-18:20:17 Status: Resource: nbk=2 dmk=356
20240918-18:20:17 Recording: sending discover using local ip [2601:441:8201:387f:891f:b9e7:38a:af0c] (ifindex 4)

Power Plan info: Balanced
Networking connectivity in Standby - managed by Windows
Sleep
- Sleep after - 30 minutes
- Allow hybrid sleep - On
- Hibernate after - Never
- Allow wake timers - Enable

Please point me in the right direction to resolve this.

Cheers!

[mvallevand]

That looks more like a Silicondust log then NextPVR.

Martin

[Poocher]

Sorry. I got the logs from the NPVR UI form. 

Here is a piece of one:
"id": 983,
    "name": "Survivor",
    "desc": "Eighteen new castaways are abandoned on the breathtaking islands of Fiji, where they must learn to adapt or they will be voted out; tribes must quickly pick up the pieces in the first challenge of the season to earn a pot, machete and flint.",
    "subtitle": "S47E01 - One Glorious and Perfect Episode",
    "group": "Survivor_00367078",
    "startTime": 1726704000,
    "duration": 7140,
    "firstrun": true,
    "season": 47,
    "episode": 1,
    "original": "2024-09-18T05:00:00",
    "significance": "Season Premiere",
    "epgEventId": 1554659,
    "status": "failed",

Or msybe this piece?
"id": 989,
    "name": "America's Got Talent",
    "desc": "Undiscovered talent of all ages -- singers, dancers, magicians, comics, musicians, ventriloquists and more -- appear before celebrity judges who decide which contestants move on in the competition each week. With the guidance of the show's host, the audience learns the backstories of these amazing people as they strive to make it to the finale, where one talented performer wins a life-changing $1 million prize. A select few join the most memorable and extraordinary acts from previous years, along with favorite...snip...
2024-09-19 19:00:52.177 [DEBUG][74] Got request [::1]: /services/service (system.space)
2024-09-19 19:00:52.177 [DEBUG][74] method=system.space
2024-09-19 19:00:52.177 [DEBUG][74] parameters:
2024-09-19 19:00:52.177 [DEBUG][74]   method: system.space
2024-09-19 19:00:52.177 [DEBUG][74]   format: json
2024-09-19 19:00:52.177 [DEBUG][74]   random: 0.3156209691958973
2024-09-19 19:00:52.177 [DEBUG][74]   sid: d6a0c4fc-5cf3-4e98-a037-89d2d318884f
2024-09-19 19:00:52.177 [DEBUG][74]   client_ip: ::1
2024-09-19 19:00:52.177 [DEBUG][74]   user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36
2024-09-19 19:00:52.177 [DEBUG][74]   host_callback: ...
2024-09-19 19:00:52.177 [DEBUG][161] Got request [::1]: /services/service (recording.list)
2024-09-19 19:00:52.177 [DEBUG][161] method=recording.list
2024-09-19 19:00:52.177 [DEBUG][161] parameters:
2024-09-19 19:00:52.177 [DEBUG][161]   method: recording.list
2024-09-19 19:00:52.177 [DEBUG][161]   filter: recent
2024-09-19 19:00:52.177 [DEBUG][161]   format: json
2024-09-19 19:00:52.177 [DEBUG][74] Available Space:
2024-09-19 19:00:52.177 [DEBUG][161]   sid: d6a0c4fc-5cf3-4e98-a037-89d2d318884f
2024-09-19 19:00:52.177 [DEBUG][74] (Default) - 2000381014016/1434342617088
2024-09-19 19:00:52.177 [DEBUG][161]   client_ip: ::1
2024-09-19 19:00:52.177 [DEBUG][74] [{"name":"Default","total":2000381014016,"free":1434342617088}]
2024-09-19 19:00:52.177 [DEBUG][161]   user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36
2024-09-19 19:00:52.177 [DEBUG][161]   host_callback: ...
2024-09-19 19:00:52.177 [DEBUG][17] Got request [::1]: /services/service (recording.list)
2024-09-19 19:00:52.177 [DEBUG][161] GetRecordingsList()
2024-09-19 19:00:52.177 [DEBUG][17] method=recording.list
2024-09-19 19:00:52.177 [DEBUG][17] parameters:
2024-09-19 19:00:52.178 [DEBUG][17]   method: recording.list
2024-09-19 19:00:52.178 [DEBUG][17]   filter: pendingSummary
2024-09-19 19:00:52.178 [DEBUG][17]   format: json
2024-09-19 19:00:52.178 [DEBUG][17]   sid: d6a0c4fc-5cf3-4e98-a037-89d2d318884f
2024-09-19 19:00:52.178 [DEBUG][17]   client_ip: ::1
2024-09-19 19:00:52.178 [DEBUG][17]   user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36
2024-09-19 19:00:52.178 [DEBUG][17]   host_callback: ...
2024-09-19 19:00:52.178 [DEBUG][17] GetRecordingsList()
2024-09-19 19:00:52.178 [DEBUG][161] GetRecordingsList@2
2024-09-19 19:00:52.178 [DEBUG][17] GetRecordingList@1.5)
2024-09-19 19:00:52.178 [DEBUG][161] Matched 10 recordings
2024-09-19 19:00:52.178 [DEBUG][17] GetRecordingsList@2
2024-09-19 19:00:52.178 [DEBUG][17] Matched 5 recordings
2024-09-19 19:00:52.179 [DEBUG][161] GetRecordingsList@exit
2024-09-19 19:00:52.179 [DEBUG][17] GetRecordingsList@exit
2024-09-19 19:00:52.179 [DEBUG][161] {
"recordings": [
  {
    "id": 983,
    "name": "Survivor",
    "desc": "Eighteen new castaways are abandoned on the breathtaking islands of Fiji, where they must learn to adapt or they will be voted out; tribes must quickly pick up the pieces in the first challenge of the season to earn a pot, machete and flint.",
    "subtitle": "S47E01 - One Glorious and Perfect Episode",
    "group": "Survivor_00367078",
    "startTime": 1726704000,
    "duration": 7140,
    "firstrun": true,
    "season": 47,
    "episode": 1,
    "original": "2024-09-18T05:00:00",
    "significance": "Season Premiere",
    "epgEventId": 1554659,
    "status": "failed",
    "size": 0,
    "quality": "QUALITY_DEFAULT",
    "channel": "WCCO-DT",
    "channelId": 7153,
    "blue": false,
    "green": false,
    "yellow": false,
    "red": false,
    "prePadding": 0,
    "postPadding": 0,
    "rating": "TVPG",
    "genres": ["Competition reality","Action","Adventure"],
    "reason": "Recording service not running at recording time",
    "recurring": true,
    "recurringParent": 63
  },
  {
    "id": 971,
    "name": "America's Got Talent",
    "desc": "The top 10 acts perform one last time for their chance to win $1 million and be named the most talented act in America.",
    "subtitle": "S19E19 - Finale Performances",
    "group": "America's Got Talent_00829878",
    "startTime": 1726617600,
    "duration": 7200,
    "firstrun": true,
    "season": 19,
    "episod...snip...
2024-09-19 19:00:52.179 [DEBUG][17] {
"recordings": [
  {
    "id": 976,
    "name": "America's Got Talent",
    "size": 0,
    "quality": "QUALITY_DEFAULT",
    "channel": "WCCO-DT",
    "channelId": 7153,
    "blue": false,
    "green": false,
    "yellow": false,
    "red": false,
    "prePadding": 0,
    "postPadding": 0,
    "rating": "TVPG",
    "genres": ["Competition reality","Action","Adventure"],
    "reason": "Recording service not running at recording time",
    "recurring": true,
    "recurringParent": 63

I tried to attach the files but it does not seem to work

[mvallevand]

Get the zip file from the Web Settings page and attach those.

Martin

[Poocher]

Thank you Martin!

I see an X so I am not sure if it uploaded or not.
  logs-20240921-0757.zip (Size: 655.37 KB / Downloads: 2)

[Poocher]

Most recent failed recording are:
Sept 17: 19:00-21:00, American Got Talent
Sept 18: 19:00-20:59, Survivor

Thank you so much for your help!

There was a successful recording yesterday. I made one change where I changed the service to "Automatic" from "Automatic (Delayed Start). I do not know if this made a difference as I have had some successful recordings in the past.

[mvallevand]

It did record one show in the logs but the logs don't go back to the when there were failures. However this message on that recording (original date the 17th)

"reason": "Alternative Airing - after failed original",

would mean the services was running but signal or some other error prevented the recording so it wouldn't be service related.

You'd need to catch the error and zip the log the next day if possible.


Martin

[Poocher]

Thanks for the information. Martin! This was my first post as NPVR has worked flawlessly for so many years.

I scheduled some shows to record and I will monitor the results.

[Poocher]

So far so good. Changing the Startup Type value for the NextPVR service may have been the ticket to resolve this.
When NPVR was installed the value was "Automatic (Delayed Start)". I changed the value to "Automatic".
No failed recordings since making that change to the service.

[mvallevand]

Actually the default is "Automatic". I could understand why adding delayed start would help in certain situations, eg. when drivers or the network aren't ready, but starting before that shouldn't improve anything but start up time.

Martin