Why is NextPVR waking my Windows 10 system from sleep?

[Graham]

Hi

Here are the logs covering the requested time period.  I stopped and restarted NextPVR Service around 6 PM local time on March 8.  T

nrecord.log.1 has this ...

2021-03-08 08:32:04.110 [DEBUG][173] Got request [192.168.2.102]: /service (setting.list)
2021-03-08 08:32:04.110 [DEBUG][173] method=setting.list
...
2021-03-08 08:32:04.110 [DEBUG][173]   client_ip: 192.168.2.102
2021-03-08 08:32:04.111 [DEBUG][173]   user_agent: Kodi/19.0 (Linux; Android 9.0; SHIELD Android TV Build/PPR1.180610.011) Android/9.0.0 Sys_CPU/aarch64 App_Bitness/64 Version/19.0-(19.0.0)-Git:20210218-f44fdfbf67
...
<rsp stat="ok">
  <Version>70230000</Version>
...  <TimeEpoch>1615210324</TimeEpoch>
</rsp>
2021-03-08 08:33:48.295 [DEBUG][101] [Suspend]
2021-03-08 08:33:48.295 [DEBUG][101] OnSleep...
2021-03-08 08:34:51.038 [DEBUG][164] [Resume]
2021-03-08 08:34:51.055 [DEBUG][164] OnResume...
2021-03-08 08:37:19.373 [DEBUG][164] [Suspend]
2021-03-08 08:37:19.373 [DEBUG][164] OnSleep...
...

Full disclosure ... I do not believe anything that is reported by the sleep functions in Windows unless it is corroborated by evidence from somewhere else ... I am not convinced that Windows is reporting the truth when it says that NextPVR is waking the machine ... There have been several similar threads in the past and it is my recollection that none of the issues were traced back to NextPVR ... But that was then and we remain open to all possibilities.

The "OnSleep" and OnResume" messages in the NextPVR log are at intervals of about one minute or so ... I don't know why these messages exist if Windows is set to sleep after ten miutes of inactivity.

Do the symptoms change if you shutdown Kodi on the Shield when Kodi is not being used?  Do the symptoms change if you set the Sleep inteval in Windows to twenty minutes instead of ten minutes?

[PapaJay]

Graham

First, the system is set to sleep after 20 minutes (I just double checked).  I did slept reliably on the weekend.  Last week and again starting on Monday, March 8 the battle between NextPVR and Windows kept the system awake overnight.  It did it again last night once MCEBuddy finished processing the recorded shows to covert them to mp4 - after MCEBuddy was done the battle began.

Last week in order to see what was going on without creating massive amounts of debug data, I changed the sleep interval to 60 minutes and I could see that after an hour of inactivity the system would go to sleep and within 2 or 3 minutes it was awake again with Windows stating that it was awoken by 'Timer -NextPVRService.exe'.


You said: The "OnSleep" and OnResume" messages in the NextPVR log are at intervals of about one minute or so ... I don't know why these messages exist if Windows is set to sleep after ten miutes of inactivity.  Per Sub these messages a logged when NextPVR is told that Windows is going to put the system to sleep and when the system wakes up (resumes).  When I checked the OnResume time in the NextPVR log to the time of the 'Timer - NextPVRService.exe'  wake event they are within a few seconds or less of each other.

I just check and the Kodi NextPVR client running on the Shield is reporting that 'the NextPVR Server is unreachable' which makes sense as the NextPVR server Windows system is asleep.  This is a behaiour change (a good change) in the Kodi 19 client - before the client would fail and I would have start the server and the disable and enable the add-on.  As requested I have just killed Kodi on the Shield (it has been dismissed) and the only time it will be run is when we are watching TV or recorded shows - this should prevent any interaction between the Kodi NextPVR client and the Kodi server.  Since the battle only seems to occur overnight I will not be able to report results until at least tomorrow.

Thanks everyone for your continued help.

[mvallevand]

Are you running MCEBuddy as a child process of NextPVR or independently? If it is linked I would check the hidden unattended idle sleep settings.

Martin

[PapaJay]

Martin

I run MCEBuddy independently. MCEBuddy monitors two directories for shows that have been recorded by NextPVR - one called Series and the other called Onetime. I did not know that MCEBuddy could be run as a child process.

What are 'hidden unattended idle sleep settings'. Are they Windows settings? Any idea how I check them?

Thanks

[mvallevand]

https://letmegooglethat.com/?q=unattended+sleep

Martin

[mvallevand]

Also speaking of those folders at least once they "disappeared"

Code:

2021-03-07 19:12:20.614    [DEBUG][104]    Got request [192.168.2.102]: /service (system.space)
2021-03-07 19:12:20.614    [DEBUG][104]    method=system.space
2021-03-07 19:12:20.614    [DEBUG][104]    parameters:
2021-03-07 19:12:20.614    [DEBUG][104]       method: system.space
2021-03-07 19:12:20.614    [DEBUG][104]       sid: 269415e0adc34c71b38d111742d7e606
2021-03-07 19:12:20.614    [DEBUG][104]       client_ip: 192.168.2.102
2021-03-07 19:12:20.614    [DEBUG][104]       user_agent: Kodi/19.0 (Linux; Android 9.0; SHIELD Android TV Build/PPR1.180610.011) Android/9.0.0 Sys_CPU/aarch64 App_Bitness/64 Version/19.0-(19.0.0)-Git:20210218-f44fdfbf67
2021-03-07 19:12:20.614    [DEBUG][104]       host_callback: 192.168.2.101:8866
2021-03-07 19:12:20.955    [DEBUG][110]    Unexpected error checking disk space (D:\NextPVR\Recordings\OneTime): System.Collections.Generic.KeyNotFoundException: The given key 'OneTime' was not present in the dictionary.
   at System.Collections.Generic.Dictionary`2.get_Item(TKey key)
   at NShared.Extend.SystemRequestHandler.<>c__DisplayClass15_1.<GetSpace>b__0()
2021-03-07 19:12:20.955    [DEBUG][32]    Unexpected error checking disk space (D:\NextPVR\Recordings\Series): System.Collections.Generic.KeyNotFoundException: The given key 'Series' was not present in the dictionary.
   at System.Collections.Generic.Dictionary`2.get_Item(TKey key)
   at NShared.Extend.SystemRequestHandler.<>c__DisplayClass15_1.<GetSpace>b__0()
2021-03-07 19:12:20.955    [DEBUG][104]    Available Space:
2021-03-07 19:12:20.955    [DEBUG][104]     (Default) - 2000396742656/240639172608
2021-03-07 19:12:20.955    [ERROR][104]    Unexpected error finding available space: System.Collections.Generic.KeyNotFoundException: The given key 'OneTime' was not present in the dictionary.
   at System.Collections.Generic.Dictionary`2.get_Item(TKey key)
   at NShared.Extend.SystemRequestHandler.GetSpace(Dictionary`2 parameters)
2021-03-07 19:12:20.956    [DEBUG][104]    <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="failed">
</rsp>

Martin

[Graham]

You said: The "OnSleep" and OnResume" messages in the NextPVR log are at intervals of about one minute or so ... I don't know why these messages exist if Windows is set to sleep after ten miutes of inactivity.  Per Sub these messages a logged when NextPVR is told that Windows is going to put the system to sleep and when the system wakes up (resumes).  When I checked the OnResume time in the NextPVR log to the time of the 'Timer - NextPVRService.exe'  wake event they are within a few seconds or less of each other.

Do you also see messages in the Event Viewer that show sleep and resume events that correspond to the NextPVR logs?  Thanks.

[PapaJay]

Hi

I am going to apologize for the long update up front.  But I have learned enough that I can do a lot of analysis on my own.  Here is a summary of what I have found.

First I am going to answer a few questions asked by Graham

1. You suggested that I stop Kodi ion the Shield when we were not watching TV.  We did that last night at approximately 11 PM, March 9 when we retired by dismissing the Kodi app on the Shield.  Dismissal is one method of killing an app on the Shield.  So it was not running overnight.  Results below.
   
2. You asked if I can correlate Event Viewer entries with entries in the NextPVR logs.  Yes.  I have a custom 'Power Events' view that I set up a few years back, and I can correlate NextPVR log entries [Suspend] OnSleep and [Resume] OnResume with Power Events (sleep and wake) - I can also correlate the NextPVR log entries to lines in the Sleep Study Report.  More on this below.
   

Now onto what happened last night and early this morning:

• I stopped Kodi on the Shield about 11 PM March 9 as we were retiring.
  
• NextPVR would have been busy recording the nation and local news until about 12:10 AM March 10
  
• At 11:30 PM, March 9 MCEBuddy would have started processing 2 hours of recorded TV to remove commercials and convert the recording to mp4. MCEBuddy finished processing the last show at 02:24:24. March 10 per its logs.
  
• At 02:26:12 Windows slept, but at 02:27:15 NextPVR Service.exe woke it - per both the Event Viewer and the Sleep Study Report.
  

Let me stop there for a moment.  I am not sure why Windows slept after less than 2 minutes of inactivity when Sleep is set at 20 minutes.  That said both the Event View and Sleep Study Report said NextPVRServer.exe woke HTPC up.  From the NextPVR nrecord log

2021-03-10 02:26:07.433 [DEBUG][122] [Suspend]
2021-03-10 02:26:07.433 [DEBUG][122] OnSleep...
2021-03-10 02:26:07.433 [DEBUG][122] stopping device process
2021-03-10 02:26:07.536 [DEBUG][122] stopping device process
2021-03-10 02:26:11.508 [DEBUG][172] <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
<Status>
<Device oid="38" identifier="Silicondust HDHomeRun Tuner 104F5A57-0    (ATSC)"> </Device>
<Device oid="40" identifier="Silicondust HDHomeRun Tuner 104F5A57-1    (ATSC)"> </Device>
</Status>
</rsp>

2021-03-10 02:27:15.006 [DEBUG][81] [Resume]
2021-03-10 02:27:15.210 [DEBUG][81] OnResume...
2021-03-10 02:29:38.664 [DEBUG][172] [Suspend]
2021-03-10 02:29:38.667 [DEBUG][172] OnSleep...
2021-03-10 02:30:42.086 [DEBUG][110] [Resume]
2021-03-10 02:30:42.191 [DEBUG][110] OnResume...
2021-03-10 02:33:10.200 [DEBUG][106] [Suspend]
2021-03-10 02:33:10.200 [DEBUG][106] OnSleep...
2021-03-10 02:34:12.858 [DEBUG][106] [Resume]
2021-03-10 02:34:12.864 [DEBUG][106] OnResume...

So per NextPVR it got a [Suspend] request at 02:26:07 and [Resume] at 02:27:15. 

Then the sleep / wake battle between Windows and NextPVR starts and continues until 07:48:02 at which point HTPC was awake for 20 minutes and 27 seconds, when it goes to sleep again at 08:08:30 for 1:03, and then wakes again at 08:09:33 and is awake due to NextPVRServer.exe for 29:27.  This is what the Event Viewer and Sleep Study say.

The NextPVR logs tell a slightly different story.  

• It [Resume] at 07:38:29 which matches Windows data
  
• At 07:38:02 there was a /service (session/initiate) from 192.168.2.102 which is the Shield when my wife started Kodi and hence the NextPVR client.  The NextPVR server then sent the channels, groups, EPG data, scheduled recordings, etc to the client, which make perfect sense.  This was not completed at 07:48:09:418 as far as I can tell from the logs.
  
• While this is going on there are several sleep / wake events in the battle between Windows and NextPVR per the NextPVR logs and Windows data.
  
• At 07:48:27:821, NextPVR server received a request from the client to play a recording.  This was us watching the national news.
  
• At 08:08:30:098 NextPVR logs a [Suspend] right in the middle of the national news playback - this sleep matches closely the time in Windows data.  We saw this on the TV. after about a minute it resumed playing (presumably after the buffered data was exhausted it stopped until the client could reconnect with the server).  The sleep that NextPVR logged matches the Windows data.
  
• We then watched the local news without incident.
  
• While this is going on the recurring recording list is being sent to the client.
  

At 8:39:01 the system slept again, but by then we had finished wathcing the news and we had stopped Kodi on the Shield.  The last entry in the NextPVR log was at 08:38:51.  There has been no reason since then for NextPVR to do anything as the next event is the EPG update at 07:05 PM.

Major observations:

• Windows clearly is not obeying the 20 minute sleep rule that is set.
  
• Windows put the system to sleep during play back.  I find it hard to believe there was no activity for 20 minutes - I can see in the NextPVR logs that data is being sent to the client, and to do this there must have been some disk activity, network activity and burned CPU.
  
• The sleep / wake battle only seems to occur during the night - whenever MCEBuddy has finishes processing until the we finish wathcing the news in the morning.
  

Additional observations

• We see no pauses when we are watching TV Shows through Kodi, TV shows being content that has been processed by MCEBuddy.  In this case the NextPVR client and NextPVR Server are not involved in the playback.
  
• Since moving to Kodi 19 and a new version of the NextPVR client, we have noticed weird behaviours - this was not the first time we saw the long pause in playback (first time I have looked into it was today).  We have also seen the audio and video get out of sync when we fast forward, and after a pause the playback is on FAST - we have to stop the playback and restart it to get it to play properly.
  

I am not throwing rocks.  Just reporting what we are seeing.

Based on what I have learned, here are my next steps:

1. Investigate Window's Power Config. I am not convinced sleep is working correctly.  I will need to build a plan of how to do this and report back.
   
2. Martin passed me a link for unattended sleep problems that seem to fit this case. I have read through this and will start to work my way through the steps. 
   

Thanks for you patience on this.  If I can figure it out I am willing to document solutions so that if anyone else hits this type of problem again, they may be able to solve it quickly.


NextPVR logs I have been looking at are attached.

PS. I was a trouble shooter for the software division of a large corporation.  Digging through this kind of stuff is what I did for 20 years before I retired.

[Graham]

 I am not sure why Windows slept after less than 2 minutes of inactivity when Sleep is set at 20 minutes.  That said both the Event View and Sleep Study Report said NextPVRServer.exe woke HTPC up.  From the NextPVR nrecord log

2021-03-10 02:26:07.433 [DEBUG][122] [Suspend]
2021-03-10 02:26:07.433 [DEBUG][122] OnSleep...
2021-03-10 02:26:07.433 [DEBUG][122] stopping device process
2021-03-10 02:26:07.536 [DEBUG][122] stopping device process
2021-03-10 02:26:11.508 [DEBUG][172] <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
<Status>
<Device oid="38" identifier="Silicondust HDHomeRun Tuner 104F5A57-0    (ATSC)"> </Device>
<Device oid="40" identifier="Silicondust HDHomeRun Tuner 104F5A57-1    (ATSC)"> </Device>
</Status>
</rsp>

2021-03-10 02:27:15.006 [DEBUG][81] [Resume]
2021-03-10 02:27:15.210 [DEBUG][81] OnResume...
2021-03-10 02:29:38.664 [DEBUG][172] [Suspend]

Here are some more wild guesses to keep you amused.

What happens if you power down the HDHR(s) ... perhaps they are sending data to the 'puter and confusing everthing.

Does your MCEBuddy process delete recording files (the .TS files created by NextPVR)?  Does NextPVR get upset because the content of its recording folder is not in sync with the data in the NextPVR database? I'm 99% sure that the answer is "no" because I'm pretty sure that NextPVR checks the content of recording folders on startup and not on resume.

[PapaJay]

Hi

I have spent since March 10, when I did my last update, trying to figure out what is going on.  Using suggestions from Graham, Martin, Sub and other information on this forum I put together a set of steps to try to isolate and find a solution to why NextPVR kept waking my PC in the middle of the night.  Here are the steps I took:

1. Tuesday, March 9 - slept Shield when we went to bed around 11 PM - per Windows Sleep Study and entries in the nrecord log, no change in behaviour - once MCEBuddy processing was finished, Windows and NextPVR got into a battle with Windows trying to sleep the PC and NextPVR waking it up with a timer event through the early hours of March 10
   
2. Wednesday, March 10 - powered off Shield (unplugged it) when we went to bed - again no change early morning March 11
   
3. Thursday, March 11 - during the day, reset and re-established Windows sleep values - sleep set to 20 minutes - no change early morning March 12
   
4. Friday, March 12 - investigated and did changed unattended sleep to 20 minutes - finally no battle early morning of March 13
   
5. Saturday, Mach 13 - no changes, no battle early morning March 14
   
6. Sunday, March 14 - left Shield powered up (plugged in) overnight, but asleep overnight - no battle early morning March 15
   

Conclusion: Martin suggested I look at the Windows unattended sleep.  It is controlled by a configuration variable called 'System unattended sleep timeout'.  This is a hidden variable and the Windows registry must be changed to make it visible.  Default is 2 minutes.  It is the timer that is used when a timed event triggers a Windows resume from sleep, or when a Wake on LAN magic packet received by the network adapter triggers resume from sleep.  The other Windows sleep value 'Sleep after' is the timer that is used when an attended event (mouse click, opening a laptop, etc.) wakes Windows.


I set 'System unattended sleep timeout' equal to my value for 'Sleep after'.  Now no matter how my PC wakes, it will only sleep after 20 minutes of inactivity.

More Information:

• Using the Windows Event Viewer and my customized Power Events view, I was able to determine that Windows and NextPVR have been in a battle over sleeping the PC in the early hours of the morning since I installed V5 on December 28.  Early in the morning of December 29 the battle first appeared.  I am not saying that there is anything wrong with NextPVR, just that V5 surfaced a dependency on 'System unattended sleep timeout' that was not there in V4, at least in my experience (it may have been exposed for other users prior to V5).
  
• Between 2020-12-12 and 2021-01-14 no Windows updates were made to this PC (per View Update History)
  

• I had no knowledge of 'System unattended sleep timeout'.  I suspect many other users don't either based on searching the NextPVR forum.  Perhaps this should be documented in the NextPVR Windows material - it would have saved may people a lot of time and effort.
  
• There appear to be 3 scenarios where the default value for 'System unattended sleep timeout' of 2 minutes has impacted users.  1) windows is not sleeping because NextPVR keeps waking it up (my scenario)  2)  Windows is sleeping when NextPVR has woken it to do a recording: 'Recording stopped less than 2 minutes in'   https://forums.nextpvr.com/showthread.ph...dows+sleep  3) During playback - another scenario that we hit where Windows slept when we paused a playback for more than 2 minutes, and another where it was playing and suddenly stopped (we use the Kodi NextPVR client) and after upgrading from Kodi 18 to 19 the sleep during playback problems started - in both of these cases Windows slept the PC because it was idle per the Event Viewer.  
  

Last comments:


Graham.  I am going to disagree with you.  I think Windows is accurately recording the reasons PCs are waking.  

NextPVR was waking my system since I moved up to V5.  I could speculate that in an effort to fix weird problems on the Windows implementation of NextPVR that somewhere code was added to get NextPVR to wake the PC when NextPVR really has something to do - something like, get notified that Windows is about to sleep, create a wike timer for 1 minute from now, Windows sleeps and the wake timer wakes the PC, and NextPVR can process until Windows sleeps the system again after 2 minutes of what Windows thinks is no activity (an idle system), and the cycle repeats.

In my case V5 surfaced a dependency on 'System unattended sleep timeout'.  Is this happening elsewhere?  If possible perhaps the first advice to users seeing weird problems around sleep is to adjust 'System unattended sleep timeout' to equal their value for 'Sleep after' and see if this helps to solve the problem.  Here is a link to the webpage that I used to make 'System unattended sleep timeout' visible and then set it   https://appuals.com/windows-10-sleeps-af...nactivity/

Thanks you to everyone for their patience and help.