Understanding how Nrecord.exe controls sleep / wake?

[2leftfeet]

next time it wakes, run this command and provide us with the results: in administrator command prompt > powercfg /lastwake

[j2gbpvr]

Wake History Count - 1
Wake History [0]
Wake Source Count - 1
Wake Source [0]
Type: Wake Timer
Owner: [SERVICE] \Device\HarddiskVolume1\Program Files (x86)\NPVR\NRecord.exe

[2leftfeet]

Well, npvr seems to be causing it, but why ?

[jksmurf]

sub do you need a further trial from me or are the logs from the original posts sufficient? I can reset my unattended sleep timeout to 2mins and try to record some things if you like.

[BrettB]

It would be helpful if you could include all of the logs (including the ndigitalhost-* ones). I'm looking at this section of the logs you included:

Code:

2015-10-12 06:59:00.257    [DEBUG][10]    DefaultDirectoryChoice: first
2015-10-12 06:59:00.304    [DEBUG][10]    allocating recording target filename: D:\Temp2\¡Despierta América!_20151012_07001100.ts
2015-10-12 06:59:00.304    [DEBUG][10]    About to start recording (1456 on 20): D:\Temp2\¡Despierta América!_20151012_07001100.ts...
2015-10-12 06:59:00.304    [DEBUG][10]    Free space 3570663739392  (D:\)
2015-10-12 06:59:00.304    [DEBUG][10]    Starting digital host
2015-10-12 06:59:01.926    [DEBUG][10]    Allocating IPC channel
2015-10-12 06:59:01.926    [DEBUG][10]    Registering channel
2015-10-12 06:59:01.926    [DEBUG][10]    About to get: ipc://DigitalHost-20/RecorderRemote
2015-10-12 06:59:01.926    [DEBUG][10]    Got: ipc://DigitalHost-20/RecorderRemote
2015-10-12 06:59:01.926    [DEBUG][10]    Asking NDigitalHost to start: D:\Temp2\¡Despierta América!_20151012_07001100.ts
2015-10-12 06:59:02.373    [DEBUG][10]    Temp at 10/12/2015 6:59:12 AM
2015-10-12 06:59:02.373    [DEBUG][10]    Started recording (1456:1:D:\Temp2\¡Despierta América!_20151012_07001100.ts)
2015-10-12 06:59:02.394    [DEBUG][10]    No C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat
2015-10-12 06:59:02.394    [DEBUG][10]    DefaultDirectoryChoice: first
2015-10-12 06:59:02.394    [DEBUG][10]    allocating recording target filename: D:\Temp2\CBS This Morning_20151012_07000900.ts
2015-10-12 06:59:02.394    [DEBUG][10]    About to start recording (1457 on 22): D:\Temp2\CBS This Morning_20151012_07000900.ts...
2015-10-12 06:59:02.394    [DEBUG][10]    Free space 3570663739392  (D:\)
2015-10-12 06:59:02.394    [DEBUG][10]    Starting digital host
2015-10-12 06:59:04.046    [DEBUG][10]    Allocating IPC channel
2015-10-12 06:59:04.046    [DEBUG][10]    Registering channel
2015-10-12 06:59:04.046    [DEBUG][10]    About to get: ipc://DigitalHost-22/RecorderRemote
2015-10-12 06:59:04.046    [DEBUG][10]    Got: ipc://DigitalHost-22/RecorderRemote
2015-10-12 06:59:04.046    [DEBUG][10]    Asking NDigitalHost to start: D:\Temp2\CBS This Morning_20151012_07000900.ts
2015-10-12 06:59:04.526    [DEBUG][10]    Temp at 10/12/2015 6:59:14 AM
2015-10-12 06:59:04.526    [DEBUG][10]    Started recording (1457:1:D:\Temp2\CBS This Morning_20151012_07000900.ts)
2015-10-12 06:59:04.536    [DEBUG][10]    No C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat
2015-10-12 08:57:24.063    [DEBUG][52]    Resuming...
2015-10-12 08:57:24.143    [DEBUG][10]    Recording service noted the system was resuming...
2015-10-12 08:57:24.143    [DEBUG][10]    No C:\Users\Public\NPVR\Scripts\Wakeup.bat
2015-10-12 08:57:25.483    [DEBUG][6]    cycling MVP servers
2015-10-12 08:57:44.923    [DEBUG][21]    CancelRecording(1457)
2015-10-12 08:57:44.923    [DEBUG][21]    queueing (1457) for cancellation
2015-10-12 08:57:45.195    [DEBUG][10]    recording service dequeued request to cancel (1457)
2015-10-12 08:57:45.209    [DEBUG][10]    StopStream(1)
2015-10-12 08:57:46.009    [DEBUG][10]    StoreMetaData@1
2015-10-12 08:57:46.012    [DEBUG][10]    StoreMetaData@2
2015-10-12 08:57:46.012    [DEBUG][10]    StoreMetaData@3
2015-10-12 08:57:46.012    [DEBUG][10]    StoreMetaData@4
2015-10-12 08:57:46.012    [DEBUG][10]    StoreMetaData@5
2015-10-12 08:57:46.014    [DEBUG][10]    StoreMetaData@6
2015-10-12 08:57:46.014    [DEBUG][10]    StoreMetaData@7
2015-10-12 08:57:46.015    [DEBUG][10]    StoreMetaData@8
2015-10-12 08:57:46.016    [DEBUG][10]    StoreMetaData@exit
2015-10-12 08:57:46.017    [DEBUG][10]    No C:\Users\Public\NPVR\Scripts\PostCancel.bat
2015-10-12 08:57:56.828    [DEBUG][10]    Reloading recording schedule
2015-10-12 08:57:56.829    [DEBUG][10]    CancelAllWakeupRequests
2015-10-12 08:57:56.829    [DEBUG][10]    Cancelling wake up request for for 'RecordingOID1456-backup'

There it appears to me that tuner OID 20 (ndigitalhost-20) was supposed to be recording something from 07:00 am to 11:00am. Did that recording (D:\Temp2\¡Despierta América!_20151012_07001100.ts) actually get created and contain 4 hours of recording? What about recording 1457 (D:\Temp2\CBS This Morning_20151012_07000900.ts)? Did it actually get created and contain 2 full hours of recording? If so, then the computer should not have slept at all during that time period. But this log indicates that there was a resume at 08:57:24.063. Then it says that it is cancelling recording 1457 which was supposed to be going until 09:00 (plus whatever post-padding you specified).

[BrettB]

Still not sure why it wakes after one minute, then every 3 minutes due to 2 minute sleep period.
Does not do it every time. Started doing it once a week and now almost every day.
Does not show in logs. Restart Recording Service always stops the inadvertent wake cycles.
I decided to add a task to the event log to restart the recording service.

1. Open Event Viewer, Windows, Logs, System
2. Select Power-Troubleshooter Event ID 1
3. Select Attach Task To This Event..., Next, Next, Start a Program, Browse..., restartnpvr.bat, Next, Finish.
4. Open Task Scheduler, Select Task, In Properties/Triggers, Select Run with highest privileges

restartnpvr.bat
timeout /t 10
net stop "NPVR Recording Service"
net start "NPVR Recording Service"

If I'm understanding you correctly, you are trying to have Windows automatically restart the NPVR Recording Service every time that it wakes from sleep. So, NPVR has scheduled a wakeup for 2 minutes before it is supposed to begin a recording (plus a backup 1 minute before). But then when the pc wakes up, you're shutting down the recording service and restarting it. Thus causing NPVR to have to reload the scheduled recordings and recreate all of the wake up events (including ones for the next recording which is now less than 2 minutes away--so it is actually scheduling a wakeup for in the past). See these lines in your logs:

Code:

2015-10-12 06:57:46.208    [DEBUG][10]    Requesting wake up for 'RecordingOID1456' at 10/12/2015 6:57 AM

and

Code:

2015-10-12 06:57:46.208    [DEBUG][10]    Requesting wake up for 'RecordingOID1457' at 10/12/2015 6:57 AM

I've got to say that this process of restarting the recording service just as it is trying to start a recording just seems crazy to me. :confused:

[jksmurf]

BrettB you seem to have a pretty good handle on what's going on with Windows wake processes, care to have a look at my original logs / comment ?

[j2gbpvr]

I didn't save all the logs from this morning and they've been overwritten.
Recording (D:\Temp2\¡Despierta América!_20151012_07001100.ts) was complete from 6:59 to 11:01 and the computer did not sleep at 8:57 am.
I did manually cancel (D:\Temp2\CBS This Morning_20151012_07000900.ts) at 8:57 am so that (D:\Temp2\Hoy_20151012_09001150.ts) could start at 8:59 am on the same tuner.
Not able to set post-padding to -1.
I had to set post-padding to 11 on (D:\Temp2\Hoy_20151012_09001150.ts) to get it to record to 12:01 pm.
It went to sleep at 12:02:22 and woke up at 12:03:23 in event viewer.
It would have continued a 3 minute sleep and wake cycle until the next record time but my task to restart the recording service clears whatever causes the inadvertent wake after only one minute of sleep.
I only added the restart task to clear the inadvertent wakes and let it run for all wakes.
Did not have it before this all started.

[sub]

sub do you need a further trial from me or are the logs from the original posts sufficient?

I still can't see where NextPVR could be causing this, so nothing really to do at this stage. I'll keep an eye on these posts though, to see if enough of a pattern is identified to suggest what are of the app is likely to be causing it.

[BrettB]

OK. This thread is difficult to follow since we've got 2 different users (jksmurf and j2gbpvr) posting some logs and making changes to systems as we try to troubleshoot.

For the moment, I'm going to continue looking at j2gbpvr's situation.

Recording (D:\Temp2\¡Despierta América!_20151012_07001100.ts) was complete from 6:59 to 11:01 and the computer did not sleep at 8:57 am.
I did manually cancel (D:\Temp2\CBS This Morning_20151012_07000900.ts) at 8:57 am so that (D:\Temp2\Hoy_20151012_09001150.ts) could start at 8:59 am on the same tuner.

This log definitely seems to indicate that the Recording Service at least thought that the computer was resuming at 08:57:24. Of course, it wouldn't indicate when/if Windows went to sleep. Are you sure that there are not any power events in the Windows event log between 06:59 and 08:57?

Code:

2015-10-12 08:57:24.063    [DEBUG][52]    Resuming...
2015-10-12 08:57:24.143    [DEBUG][10]    Recording service noted the system was resuming...
2015-10-12 08:57:24.143    [DEBUG][10]    No C:\Users\Public\NPVR\Scripts\Wakeup.bat
2015-10-12 08:57:25.483    [DEBUG][6]    cycling MVP servers
2015-10-12 08:57:44.923    [DEBUG][21]    CancelRecording(1457)
2015-10-12 08:57:44.923    [DEBUG][21]    queueing (1457) for cancellation

Also, I seriously doubt that it is just coincidence that this "Resuming..." was 20 seconds before you manually cancelled recording 1457. How did you do that cancellation? Did you run the NPVR client on the same machine? Or were you using some other client (the NEWA web interface or an NMT, etc.)? Again, having all of the logs so that we could see where this cancellation request came from would be most helpful.

I had to set post-padding to 11 on (D:\Temp2\Hoy_20151012_09001150.ts) to get it to record to 12:01 pm.
It went to sleep at 12:02:22 and woke up at 12:03:23 in event viewer.

Why were you trying to get it to record until 12:01pm?

What are your Windows settings for going to sleep? Your last recording didn't complete until

Code:

2015-10-12 12:01:01.028    [DEBUG][10]    No C:\Users\Public\NPVR\Scripts\PostProcessing.bat

12:01:01 and you said that it went to sleep at 12:02:22--just over 1 minute after the recording finished. That seems like a very short period of time for the sleep to kick in. With the original recording wake timer set for 2 minutes before the recording start time, sleep after 1 minute of inactivity would put it back to sleep before the recording began. But with your automatic recording service restart now, you are "forcing" additional activity during that time period.

Also, your logs aren't showing a wake request for the EPG update which is odd. What time is that supposed to be scheduled for? And what are your EPG sources?