Why is NextPVR waking my Windows 10 system from sleep?

[PapaJay]

Hi

NextPVR V5 is waking my Windows 10 system from sleep.  It is not doing it because a recording needs to be made or the EPG needs to be updated.  These wakes are happening in the middle of the night when no recordings are scheduled and there is no EPG update to be performed.  It appears that it is waking to be ready to receive requested from the NextPVR add-on running on Kodi for maintenance of EPG data, the schedule of recordings, etc - I am not really sure which of these is happening based on reviewing the NextPVR nrecord logs, as I don't know what the methods being logged do.

I have run a powercfg -sleepstudy command on Windows to generate a sleep study report and it clearly shows the sleep Exit Reason to be 'Timer - NextPVRServer.exe'. For example per the sleep study report (see attached) on 2021-03-02 at 06:12:31 the system entered Hybrid Sleep only to be woken 1 minute and 2 seconds later by 'Timer - NextPVRServer.exe'.  When I checked the nrecord logs for 06:12:31 plus 1:02 or around 06:13:33 I can see that the following:

2021-03-02 06:13:34.101 [DEBUG][42] [Resume]
2021-03-02 06:13:34.144 [DEBUG][42] OnResume...
2021-03-02 06:13:38.791 [DEBUG][234] Got request [192.168.2.102]: /service (recording.lastupdated)
2021-03-02 06:13:38.792 [DEBUG][234] method=recording.lastupdated
2021-03-02 06:13:38.792 [DEBUG][234] parameters:
2021-03-02 06:13:38.792 [DEBUG][234]   method: recording.lastupdated
2021-03-02 06:13:38.792 [DEBUG][234]   sid: 412f64654cf04f5494979edd7a357e7c
2021-03-02 06:13:38.792 [DEBUG][234]   client_ip: 192.168.2.102
2021-03-02 06:13:38.792 [DEBUG][234]   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-02 06:13:38.792 [DEBUG][234]   host_callback: 192.168.2.101:8866
2021-03-02 06:13:38.793 [DEBUG][234] LastUpdated
2021-03-02 06:13:38.793 [DEBUG][234] <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
  <last_update>1614661561</last_update>
</rsp>

Based on this it looks like NextPVR service reported that the system resumed at 06:13:34:101 and then at 06:13:38:791 it got a request from 192:168:2:102 which happens to be my Nvidia Shield (it has a fixed IP address to make debugging easier) for the method=recording.lastupdated.  I am not sure exactly what this does, but if you look through the nrecord logs this an may other events including methiod:channel.groups, method:channel.list and method:recording list (these are around 07:31:28 in the nrecord log) - I think these later are normal to update the channels and scheduled recordings from the Windows server, but I am not sure.

More background.  On Feb 24 overnight, Kodi on the Shield was updated to Kodi 19 automatically and on the night of Feb 25 my sleep problems started.  To be honest there is also another event waking the Windows server - an interrupt, probably a magic packet (wake on LAN) being received by the network ethernet interface card ( Device -Realtek PCIe GbE Family Controller ) which I am also investigating.  But there are clearly events in the sleep study report that show that NextPVR is waking the server too.

My EPG update interval is set to 120 minutes on Kodi if that has a bearing on what is happening.  My EPG data is updated daily from Schedules Direct at 19:05:00 (7:05 PM) and historically we have seen that NextPVRService wakes the Windows system just prior to 7:05 to do this update if Windows is sleeping.

When we upgraded to NextPVR 5 back in the late fall of 2020, the Windows systems continued as it had before, sleeping when there was nothing to do and being woken when NextPVR had something to do - update EPG or make a recording.  The upgrade of Kodi on the Shield from 18 to 19 seems to have triggered these new behaviors.  We want the Windows 10 PC to sleep when NextPVR is not updating the EPG or making recordings OR we are watching recorded shows. My sleep interval on Windows was set to 1 hour so I could gather debug data easier, but has now been set back to 20 minutes that we desire (at 20 minutes there were to many sleep / wake vents on the Sleep Study Report to look through). 

Perhaps there are some new configuration parameters that I need to learn about to get the behavior back to where it was before the upgrade to Kodi 19.  We checked last night a we can no see new configuration parms - perhaps the behaviour of some have changed.

Attachments

• Nrecord logs (created from settings)
  
• Sleep Study report ( I do not seem to be able to attach two files, so I will try to post it in a reply to this post)
  

Thank you for your help.

[mvallevand]

First check Kodi to make sure that you have WOL disabled if you don't want it to wake your server.

If WOL is off it sounds like you enabled a sleep setting that wakes on network activity.

Martin

[PapaJay]

Martin

In the screen SETTINGS - NEXT PVR CLIENT -->  CONNECTION  the configuration parm ENABLE WAKE ON LAN is OFF.  I saw a post from 2016 last night when I was searching for a solution where it stated that if this was enabled the Windows system would never sleep, so I check it and it was off.

When Kodi was updated to Kodi 19 automatically, I checked all the Kodi configuration parameters to make sure nothing had changed, including the NextPVR client, using digital photos I had taken after getting Kodi 18 running smoothly on the new Shield back in November of 2020.

I am going to try to attach the Sleep Study Report and a PDF of one page of a spreadsheet where I summarized the sleep / wake events.  I tried once already but I must have messed something up.

Jay.

[mvallevand]

Did you also check your Windows sleep setting to make sure sleep on network activity is disabled.

Martin

[PapaJay]

Martin

I was not 100% sure what you meant by 'sleep on network activity is disabled'.  I could not find any references to this when searching on the internet.

So I decided to spend time trying to figure out the other problem that is causing my HTPC to be woken from sleep, the fact that a request is being made across the network to the HTPC since the Sleep Study report said the the Realtek GbE adapter was the source of the wake event.  Since this was not happening back in the fall and the HTPC was sleeping as expected, what has changed - I keep a log book of any changes I make and any automatic software updates that occur.

Working back through the changes one at a time and undoing them, I discovered that when the Shield was off the network (ethernet cable unplugged), the HTPC would remain asleep. I did some research and discovered that there is a game component on the Shield that sends out messages on the network trying to find the 'game server' - it is unclear if these are targeted messages or general broadcasts.  The only computer on the house network that is setup to 'listen' when it is asleep is the HTPC.  I did some more digging and discovered that you can restrict new adapters to only listen for 'magic packets' to wake the computer.  I checked and the Realtek GbE adapter had 'Allow this device to wake the computer' enabled, and the 'Only allow a magic packet to wake the computer' was disabled.  So I enabled this last option.

After putting the Shield back on the network (plugging in the ethernet cable), I put the HTPC to sleep.  I was still asleep 20 minutes later.  What I now believe is that Shield was causing the HTPC to wake by sending network messages - whether they were directed at the HTPC or just broadcast messages I do not know.  Restricting the network adapter ability to wake the HTPC to just magic packets has solved that one problem.

So how long has this been the reason why the HTPC was always awake.  I can tell you that a Sleep Study report run for 28 days (max days) only has the Realtek adapter walking the HTPC since March 1, 2021 at 18:16:48. 

Every wake event prior to that was either unknown (meaning I woke it up to do something) or it was awoken by 'Timer - NextPVRService.exe'.   There are 856 times in 28 days that NextPVRServer.exe woke up the HTPC by a timer.  On Feb 7 there are about 60 events between 03:15:36 and 07:00:00 where NextPVRService.exe wakes up HTPC - NextPVRService.exe wakes it, it is awake for about 2.5 minutes, then sleeps for just over a minute and the the cycle repeats.  Same pattern on Feb. 9, 10, 13, 16, 17, etc.  This pattern is present on most days up until the early morning hours of March 1 when the Realtek adapter started waking up HTPC, and then it is a mix of Realtek and NextPVRServer.exe doing the waking.

Hopefully preventing the Shield from waking up HTPC with anything other than a magic packet will solve even the NextPVRService.exe from waking the HTPC.  It still is not clear why NextPVRService.exe is using a timer to wake up the HTPC in the middle of the night when there are no recordings to be done and the EPG update is at 7:05 PM.  NextPVRServer.exe has not woken up the HTPC since Mar. 3rd (most likely since it has been awake 99% of the time (due to Realtek).

I will start to monitor the wake events daily and will report any discoveries to this post.  If nothing happens in a few weeks, then we will leave the reason why NextPVRService.exe was waking HTPC unresolved.

Thanks for your help.  Jay in Richmond Hill, ON.

[mvallevand]

That was the kind of network setting I was expecting would cause it. There is a change in the Kodi V19 addon that I added and Kodi will try and reconnect to the server if it is offline. Before it might end up disabling the addon.

As part of this change if Kodi is running and the backend comes "alive" and does an EPG update, that should trigger an EPG update in the Shield.

Martin

[PapaJay]

Martin

That would suggest that Kodi 19 is somehow 'polling' the NextPVR server at some interval to see if it is awake - polling could be as easy as sending the NextPVR server a request and seeing if it responds - if it does not then wait a predefined period and try again.  I am betting that period is controlled by 'Update interval'

That is not what I have observed.  The Sleep Study Report clearly shows that 'Timer - NextPVRServer.exe' woke up HTPC.  And the HTPC seems to be in a cycle of sleep, wake, sleep, wake.  Assuming the Kodi 19 NextPVR add-on finds the NextPVR server awake and starts to request an update for the EPG, I doubt this creates a lot of activity on the PC, and Windows is notorious for putting a PC to sleep (back to sleep) when it thinks just the standard background work is being done (I think over time Windows builds a profile of what it thinks is effectively no real workload).  How would NextPVR prevent the EPG on the Shield (in my case) from being updated completely?  As I recall (it has been many years since I worked in this area) when Windows is about to put a PC to sleep, it sends out a warning; there is no way for an app to say not now, and all it can do is save its state  AND  schedule a timer event to wake the PC backup in say a minute to continue processing.  Could the NextPVR server be doing this?  Evidence in the Sleep Study Report and NextPVR nrecord logs would suggest this.

What do [Sleep],  [Resume], etc. log records in nrecord mean?  I see them in the logs around the time Windows is going to sleep and NextPVRServer.exe is waking it back up.  Knowing the meaning of these could help explain what is going on.

Ok, next question.  I have the config parm 'Prevent updates during playback' disabled in my Settings -->  PVR & Live TV --> Guide screen.  This was done years ago when my son and I first started using Kodi on the original Raspberry PI and updating the EPG would cause the playback to studder due to lack of processing power on the original PI.  Today we usually watch TV for about 2 hours each night and there is lots of horse power in the Shield, so I am considering changing it so that the EPG update can happen while we are watching TV.  Only problem I see with this strategy is the frequency of the EPG update that is controlled by 'Update interval' on the same screen as above.  I am assuming that with my value set at the default of 120 minutes, every 2 hours the addon will check with the server.

So this brings up the next question.  Do the NextPVR addon and the NextPVR server do a check to see if there is anything new (e.g. new/updated EPG data) and only do an update if there is?  If they only do an update if there is something new, then I could lower this interval to 30 to 60 minutes and that change along with allowing EPG updates during playback might push the EPG update into the evening hours when we are watching TV and the server is awake.  This could get rid of what appears to be an EPG update and a fight between Windows and NextPVR server that starts at 3 AM in the morning and continues for hours on some nights.  What I want to avoid is a complete replacement of the EPG data every 30 to 60 minutes if I lower the value.

Thanks for your continued help on this.  If I get this sorted out I am hoping it will help others.

Jay

PS.  We post process all recorded TV to remove commercials and change format to mp4 to save space.  Some nights after 3 or 4 one hour TV shows are recorded it can take up to 6 hours starting at 11:30 PM to do this work.  On other nights it is often done in by 2 AM.  This could explain why some nights I don't see the fight between Windows and NextPVR server - the system is awake an the EPG update completes without incident. Other nights it is underway and Windows decides to sleep in the middle of it.

[mvallevand]

I didn't try and read or reply to everything, but here is what the addon does.

The addon doesn't poll to see if it is awake, Kodi assumes the backend is online and if it is offline the addon tries to connect again in a few minutes.

There are client checks every mintute to see if there are recording update or EPG updates (via lastupdated).

If there is a change there is a second lastupdated check and and EPG update check. It would have been nicer if sub combined this all in one call but it works. Recordings and the EPG will be updated if necessary

Kodi core has additional polls based on advancedsettings.xml on how often to refresh the EPG data. With SD it isn't too much of an issue, prefer longer time between checks with the risk of some stale data is it if too long.

Martin

[sub]

What do [Sleep],  [Resume], etc. log records in nrecord mean?  I see them in the logs around the time Windows is going to sleep and NextPVRServer.exe is waking it back up.  Knowing the meaning of these could help explain what is going on.

When Windows notifies applications that it is going to sleep, NextPVR logs a [Suspend] message. When Windows notifies applications that has woken, NextPVR logs a [Resume] message. ie, these messages are not indication that NextPVR is doing anything, or has requested something to happen. It's just meant to be a useful log message to note what time a machine might have gone to sleep or woken up.

[mvallevand]

As a asterisk on sub's comment those messages only seem to be logged when running as a service perhaps it's a user permission issue.

Martin