Wake timer in the past?

[erik]

I'm monitoring when the NPVR PC wakes and saw that after the last recording of the "day/night" has finishes and the system went to sleep it wakes within 10 seconds without any recording being requested.

This is the output from the system event log showing sleep/wake (I added a powerdebug even to show the cause of waking) in reverse order.

Code:

Information,16-6-2017 03:47:29,Microsoft-Windows-Power-Troubleshooter,1,None,"The system has returned from a low power state.

Sleep Time: ‎2017‎-‎06‎-‎16T01:46:27.587929700Z
Wake Time: ‎2017‎-‎06‎-‎16T01:47:28.865922800Z

Wake Source: Timer - NRecord.exe"
Information,16-6-2017 03:47:28,Microsoft-Windows-Kernel-Power,131,(33),"Firmware S3 times. ResumeCount: 6, FullResume: 494, AverageResume: 495"
Information,16-6-2017 03:47:28,Microsoft-Windows-Kernel-General,1,(5),"The system time has changed to ‎2017‎-‎06‎-‎16T01:47:28.500000000Z from ‎2017‎-‎06‎-‎16T01:46:29.684025500Z.

Change Reason: System time synchronized with the hardware clock."
Error,16-6-2017 03:46:29,Microsoft-Windows-Kernel-Power,137,None,The system firmware has changed the processor's memory type range registers (MTRRs) across a sleep state transition (S4). This can result in reduced resume performance.
Information,16-6-2017 03:46:29,Microsoft-Windows-Kernel-Power,107,(102),The system has resumed from sleep.
Information,16-6-2017 03:46:28,Microsoft-Windows-Kernel-Power,42,(64),"The system is entering sleep.

Sleep Reason: System Idle"
Information,16-6-2017 02:16:30,Microsoft-Windows-Power-Troubleshooter,1,None,"The system has returned from a low power state.

Sleep Time: ‎2017‎-‎06‎-‎15T23:22:53.719826800Z
Wake Time: ‎2017‎-‎06‎-‎16T00:16:29.877550600Z

Wake Source: Timer - NRecord.exe"
Information,16-6-2017 02:16:29,Microsoft-Windows-Kernel-Power,131,(33),"Firmware S3 times. ResumeCount: 5, FullResume: 495, AverageResume: 495"
Information,16-6-2017 02:16:29,Microsoft-Windows-Kernel-General,1,(5),"The system time has changed to ‎2017‎-‎06‎-‎16T00:16:29.500000000Z from ‎2017‎-‎06‎-‎15T23:22:55.628596400Z.

Change Reason: System time synchronized with the hardware clock."
Error,16-6-2017 01:22:55,Microsoft-Windows-Kernel-Power,137,None,The system firmware has changed the processor's memory type range registers (MTRRs) across a sleep state transition (S4). This can result in reduced resume performance.
Information,16-6-2017 01:22:55,Microsoft-Windows-Kernel-Power,107,(102),The system has resumed from sleep.

You will notice that the system sleeps at 03:46:28 and is awake again at 03:47:28 (after updating the system time) and the wake cause was a timer set by NRecord

Looking at the NRecord log for that first wakeup (the intended recording wake)

Code:

[...startup]
2017-06-16 02:16:36.213    [DEBUG][4]    OnStart()
2017-06-16 02:16:36.225    [DEBUG][4]    Checking if upgrade required
2017-06-16 02:16:36.235    [DEBUG][4]    master file is C:\Users\Public\NPVR\Config-master-dont-edit.xml
2017-06-16 02:16:36.255    [INFO][4]    Using local in-process recording service
2017-06-16 02:16:36.825    [DEBUG][4]    CaptureSource.LoadAll()
2017-06-16 02:16:36.888    [DEBUG][4]    RecordingServiceProxy@exit
2017-06-16 02:16:36.892    [INFO][4]    RecordingService.Startup()
2017-06-16 02:16:36.892    [INFO][4]    Starting remoting service (on port 8968)
2017-06-16 02:16:36.955    [DEBUG][10]    Requesting wake up for 'EPGWAKEUP-backup' at 6/16/2017 7:21 AM
2017-06-16 02:16:36.955    [INFO][13]    ServiceLocatorThread() starting
2017-06-16 02:16:36.955    [INFO][13]    ServiceLocatorThread() starting
2017-06-16 02:16:36.955    [DEBUG][10]    Requesting wake up for 'EPGWAKEUP' at 6/16/2017 7:21 AM
2017-06-16 02:16:36.965    [DEBUG][10]    Next EPG update time: 6/16/2017 7:21 AM
2017-06-16 02:16:36.965    [INFO][13]    ServiceLocatorThread() Hostname:  Lambiekje
2017-06-16 02:16:37.005    [INFO][9]    RecordingService starting...
2017-06-16 02:16:37.005    [DEBUG][9]    Doing database vacuum
2017-06-16 02:16:37.212    [INFO][13]    IP Address: 192.168.0.57
2017-06-16 02:16:37.212    [DEBUG][13]    Waiting for broadcast
2017-06-16 02:16:37.492    [INFO][4]    Starting web server on: 8866
2017-06-16 02:16:37.493    [INFO][4]    Setting working directory to: C:\Program Files (x86)\NPVR\
2017-06-16 02:16:37.493    [INFO][4]    Web root: C:\Users\Public\NPVR\web
2017-06-16 02:16:37.715    [DEBUG][9]    vacuuming done
2017-06-16 02:16:37.725    [DEBUG][5]    Deleting web temp files
2017-06-16 02:16:37.735    [DEBUG][9]    No C:\Users\Public\NPVR\Scripts\PostStartup.bat
2017-06-16 02:16:37.735    [DEBUG][9]    PurgeOldDeletes()
2017-06-16 02:16:37.735    [DEBUG][9]    Loading recording schedule
2017-06-16 02:16:37.775    [DEBUG][9]    CancelAllWakeupRequests
2017-06-16 02:16:37.775    [DEBUG][9]    Requesting wake up for 'RecordingOID21702-backup' at 6/16/2017 2:17 AM
2017-06-16 02:16:37.775    [DEBUG][9]    Requesting wake up for 'RecordingOID21702' at 6/16/2017 2:16 AM
2017-06-16 02:16:37.775    [DEBUG][9]    Requesting wake up for 'RecordingOID21708-backup' at 6/16/2017 7:37 PM
.... Cut .....
2017-06-16 02:18:04.402    [DEBUG][9]    Started recording (21702:1:K:\TV\Ripper Street\Ripper Street_20170616_02200315.ts)
2017-06-16 02:18:04.452    [DEBUG][9]    Starting: C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat "K:\TV\Ripper Street\Ripper Street_20170616_02200315.ts" 28 21702 61 "Ripper Street"
2017-06-16 02:18:04.492    [DEBUG][4]    catalog says:
<Catalog><Version>1</Version><Poster>C:\Users\Public\NPVR\media\shows\Ripper Street.jpg</Poster><Landscape>C:\Users\Public\NPVR\media\shows\Ripper Street.landscape.jpg</Landscape><FanArt>C:\Users\Public\NPVR\media\shows\Ripper Street.fanart.jpg</FanArt><Banner>C:\Users\Public\NPVR\media\shows\Ripper Street.banner.jpg</Banner></Catalog>
2017-06-16 03:23:00.190    [DEBUG][9]    Stopping recording (21702 on 61). Past end time of recording. 1
2017-06-16 03:23:00.240    [DEBUG][9]    StopStream(1)
2017-06-16 03:23:01.062    [DEBUG][9]    StoreMetaData@1
2017-06-16 03:23:01.081    [DEBUG][9]    StoreMetaData@2
.. cut...
2017-06-16 03:23:01.091    [DEBUG][9]    StoreMetaData@exit
2017-06-16 03:23:01.101    [DEBUG][9]    Starting: C:\Users\Public\NPVR\Scripts\PostProcessing.bat "K:\TV\Ripper Street\Ripper Street_20170616_02200315.ts" 28 21702 61 "Ripper Street"
2017-06-16 03:47:28.737    [DEBUG][22]    Resuming...
2017-06-16 03:47:30.185    [DEBUG][6]    cycling MVP servers
2017-06-16 03:47:31.265    [DEBUG][21]    OnStop()
2017-06-16 03:47:31.265    [DEBUG][21]    About to stop webserver
2017-06-16 03:47:31.375    [DEBUG][21]    webserver stopped
...cut ....
2017-06-16 03:47:31.385    [INFO][21]    DigitalRecorder.StopAllStreams()
2017-06-16 03:47:31.385    [INFO][21]    DigitalRecorder.StopAllStreams()
2017-06-16 03:47:33.387    [INFO][21]    Recording Service hadnt stopped after 2000ms, continuing anyway
2017-06-16 03:47:33.597    [DEBUG][21]    recording service stopped
2017-06-16 03:47:33.597    [DEBUG][21]    OnStop() complete...

you will notice the system sleeps at 3:47:33 but a wake timer has been set for 2:16 so the system wakes up immediately as also can be seen in the NRecord log for the second wake

Code:

[...startup]
2017-06-16 03:47:34.207    [DEBUG][4]    OnStart()
2017-06-16 03:47:34.217    [DEBUG][4]    Checking if upgrade required
2017-06-16 03:47:34.227    [DEBUG][4]    master file is C:\Users\Public\NPVR\Config-master-dont-edit.xml
2017-06-16 03:47:34.247    [INFO][4]    Using local in-process recording service
2017-06-16 03:47:34.630    [DEBUG][4]    CaptureSource.LoadAll()
2017-06-16 03:47:34.709    [DEBUG][4]    RecordingServiceProxy@exit
....cut.....

This is also visible in the NPVR.log file where you see a going to standby at 03:46:27.938 and a wake from standby at 03:47:28.808

Code:

2017-06-16 03:44:31.840    [DEBUG][1]    loading new bitmap data for: ListItemSelectedA Good Year
2017-06-16 03:44:31.842    [DEBUG][1]    loading new bitmap data for: ListSelectionMetaData
2017-06-16 03:44:41.866    [DEBUG][1]    loading new bitmap data for: ListSelectionMetaData
2017-06-16 03:46:27.938    [DEBUG][1]    System is going into standby/hibernate
2017-06-16 03:47:28.500    [DEBUG][1]    Recordings.RELOAD_RECORDINGS
2017-06-16 03:47:28.500    [DEBUG][1]    Recordings.RELOAD_RECORDINGS@1
2017-06-16 03:47:28.500    [DEBUG][1]    LoadList@0
2017-06-16 03:47:28.500    [DEBUG][1]    LoadList@1
2017-06-16 03:47:28.554    [DEBUG][1]    LoadList@2
2017-06-16 03:47:28.554    [DEBUG][1]    LoadList@3
2017-06-16 03:47:28.664    [DEBUG][1]    LoadList@setobjects
2017-06-16 03:47:28.664    [DEBUG][1]    catalog says:
<Catalog><Version>1</Version></Catalog>
2017-06-16 03:47:28.694    [DEBUG][1]    LoadList@exit
2017-06-16 03:47:28.694    [DEBUG][1]    Recordings.RELOAD_RECORDINGS@2
2017-06-16 03:47:28.694    [DEBUG][1]    catalog says:
<Catalog><Version>1</Version><Poster>C:\Users\Public\NPVR\media\shows\A Good Year.jpg</Poster><FanArt>C:\Users\Public\NPVR\media\shows\A Good Year.fanart.jpg</FanArt></Catalog>
2017-06-16 03:47:28.694    [DEBUG][1]    PlaybackPositionHelper.GetLastPlaybackDate(K:\TV\A Good Year\A Good Year_20170606_20302302.ts)
2017-06-16 03:47:28.694    [DEBUG][1]    PlaybackPositionHelper.GetPlaybackPosition(K:\TV\A Good Year\A Good Year_20170606_20302302.ts)
2017-06-16 03:47:28.746    [DEBUG][1]    Recordings.RELOAD_RECORDINGS@exit
2017-06-16 03:47:28.808    [DEBUG][1]    loading new bitmap data for: ListItemSelectedA Good Year
2017-06-16 03:47:28.808    [DEBUG][1]    loading new bitmap data for: ListSelectionMetaData
2017-06-16 03:47:28.808    [DEBUG][1]    Waking from standby/hibernate
2017-06-16 03:47:38.530    [DEBUG][1]    loading new bitmap data for: ListSelectionMetaData
2017-06-16 03:49:28.517    [DEBUG][1]    Recordings.RELOAD_RECORDINGS
2017-06-16 03:49:28.517    [DEBUG][1]    Recordings.RELOAD_RECORDINGS@1

Now the question I have is: why is there a wake timer set in the past?
2017-06-16 02:16:37.775 [DEBUG][9] Requesting wake up for 'RecordingOID21702' at 6/16/2017 2:16 AM
Would that cause an immediate wake after going to standby at 3:47:33?
Log files attached