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