Article 023

How does a notebook handle missed detection cycles?

Here's what happens on a notebook that is frequently turned on and off, or hibernates regularly -- in my case, this machine probably is powered down, or hibernates three or four times a day, maybe more on some days, but at least twice a day.

I have omitted log entries that have no direct bearing on this demonstration of how notebooks deal with missed detection/reporting cycles.

I have a 12 hour detection frequency on my desktop systems. (I only have four desktop systems on this WSUS server, so the impact is insignificant.)

In consideration of the triggering of the detection at power up and wakeup, I am considering placing this system back into its own OU with the default 22 hour detection cycle. The example shows that I missed most of the 'scheduled' cycles, but because of powerup and wakeup automatic detections, I still get, on average, two detection cycles performed per day.

Incidentally... for desktop systems that are routinely powered down at the end of the day -- this also has relevance... because /all/ of those desktop systems will be performing detections at powerup the next morning. This could be placing one heck of a demand on your WSUS server if everybody powers up at approximately the same time each morning. (Not to mention what it's doing to your AD/GAC/DHCP/DNS servers.)

Looking at the logs for the first four days of August 2005, which is sufficient to demonstrate the behavior with both powered down systems, hibernating systems, and what happens when the system is powered up or wakes up. As of midnight on 8/1, the next detection is scheduled for 8/1 4:30am:

    2005-08-01 00:15:15 828 d0 AU AU received hibernate event

*** 04:30:20 -- scheduled detection not possible due to hibernation

    2005-08-01 08:30:40 828 d0 AU AU received wakeup event

When the system wakes up, it triggers detection and reporting activities and reschedules the next detection for 6:20pm

    2005-08-01 08:30:49 828 d0 AU #############
    2005-08-01 08:30:49 828 d0 AU ## START ## AU: Search for updates
    2005-08-01 08:30:49 828 d0 AU #########

    2005-08-01 08:33:09 828 4f8 Agent   * Found 0 updates and 9 categories in search
    2005-08-01 08:33:10 828 3e8 AU #########
    2005-08-01 08:33:10 828 3e8 AU ## END ## AU: Search for updates
    2005-08-01 08:33:10 828 3e8 AU #############
    2005-08-01 08:33:10 828 3e8 AU AU setting next detection timeout to
2005-08-01 23:20:59

    2005-08-01 08:37:37 828 3e8 Report Reporter successfully uploaded 2 events.

But then I powered the system down at 12:47pm

    2005-08-01 12:47:42 808 5cc Service *********
    2005-08-01 12:47:42 808 5cc Service ** END ** Service: Service exit
[Exit code = 0x240001]
    2005-08-01 12:47:42 808 5cc Service *************

*** 18:20:59 -- scheduled detection not possible due to power down status

The system was powered back up at 7:23pm

    2005-08-01 19:23:35 836 d8 Service *************
    2005-08-01 19:23:35 836 d8 Service ** START ** Service: Service startup
    2005-08-01 19:23:35 836 d8 Service *********

and it again triggered detection and reporting activities, and rescheduled the next detection for 5:40am

    2005-08-01 19:25:11 836 d8 AU #############
    2005-08-01 19:25:11 836 d8 AU ## START ## AU: Search for updates
    2005-08-01 19:25:11 836 d8 AU #########
    2005-08-01 19:25:11 836 d8 AU AU setting next detection timeout to
2005-08-02 00:25:11

    2005-08-01 19:25:47 836 3e4 Report Reporter successfully uploaded 9 events.

    2005-08-01 19:27:01 836 3e4 Agent   * Found 0 updates and 9 categories in search
    2005-08-01 19:27:02 836 3e4 AU #########
    2005-08-01 19:27:02 836 3e4 AU ## END ## AU: Search for updates
    2005-08-01 19:27:02 836 3e4 AU #############
    2005-08-01 19:27:02 836 3e4 AU AU setting next detection timeout to
2005-08-02 10:40:15

    2005-08-01 19:33:50 836 760 Report Reporter successfully uploaded 2 events.

The machine went into hibernation at 1:43am

    2005-08-02 01:43:11 836 d8 AU AU received hibernate event

*** 05:40:15 -- scheduled detection not possible due to hibernation

and upon receiving a wakeup event,

    2005-08-02 10:22:29 836 d8 AU AU received wakeup event

triggered a detection and reporting activity, and rescheduled the next detection for 3:22pm

    2005-08-02 10:22:35 836 d8 AU #############
    2005-08-02 10:22:35 836 d8 AU ## START ## AU: Search for updates
    2005-08-02 10:22:35 836 d8 AU #########

    2005-08-02 10:22:49 836 b30 AU #########
    2005-08-02 10:22:49 836 b30 AU ## END ## AU: Search for updates
    2005-08-02 10:22:49 836 b30 AU #############
    2005-08-02 10:22:49 836 b30 AU AU setting next detection timeout to
2005-08-02 20:22:49

This detection actually got to run as scheduled and the next detection was scheduled for 3:14am

    2005-08-02 15:22:49 836 d8 AU #############
    2005-08-02 15:22:49 836 d8 AU ## START ## AU: Search for updates
    2005-08-02 15:22:49 836 d8 AU #########

    2005-08-02 15:24:36 836 528 Agent   * Found 0 updates and 9 categories in search
    2005-08-02 15:24:36 836 528 AU #######
    2005-08-02 15:24:36 836 528 AU ## END ## AU: Search for updates
    2005-08-02 15:24:36 836 528 AU #############
    2005-08-02 15:24:36 836 528 AU AU setting next detection timeout to
2005-08-03 08:14:34

    2005-08-02 15:31:25 836 760 Report Reporter successfully uploaded 2 events.

But, again, the system hibernates...

    2005-08-03 02:22:27 836 d8 AU AU received hibernate event

Except this time.. and only one of two times it occurred in August, the system is able to...... do what??? Wake itself up to log the fact that it's deferring the detection?

This one I'm not yet understanding, and I've never seen this entry in any previous notebook log I've reviewed. And why did it only occur this time, and not the other half dozen times during these four days?

It may be a function of how the system is "hibernating"..... and whether it's a true hibernation (with RAM written to hard disk and the system powered down) or whether it's just an APCI power-management event, where the CPU is still awake, but the display and disk are powered down.

    2005-08-03 03:22:38 836 d8 AU AU deferring detection until wake-up from hibernation
    2005-08-03 03:22:38 836 d8 AU AU received wakeup event
    2005-08-03 03:22:38 836 d8 AU AU received wakeup event
    2005-08-03 03:22:38 836 d8 AU AU received hibernate event

The system returned from hibernation at 8:29am,

    2005-08-03 08:29:18 836 d8 AU AU received wakeup event

and triggered another detection and reporting activity, and rescheduled the next detection for 7:16pm

    2005-08-03 08:29:20 836 d8 AU #############
    2005-08-03 08:29:20 836 d8 AU ## START ## AU: Search for updates
    2005-08-03 08:29:20 836 d8 AU #########

    2005-08-03 08:31:04 836 c84 Agent   * Found 0 updates and 9 categories in search
    2005-08-03 08:31:04 836 c84 AU #########
    2005-08-03 08:31:04 836 c84 AU ## END ## AU: Search for updates
    2005-08-03 08:31:04 836 c84 AU #############
    2005-08-03 08:31:04 836 c84 AU AU setting next detection timeout to
2005-08-04 00:16:32

    2005-08-03 08:37:53 836 ea4 Report Reporter successfully uploaded 2 events.

The 7:16pm scheduled detection ran as scheduled, and the next detection was scheduled for 6:24am

    2005-08-03 19:16:32 828 d0 AU #############
    2005-08-03 19:16:32 828 d0 AU ## START ## AU: Search for updates
    2005-08-03 19:16:32 828 d0 AU #########

    2005-08-03 19:18:13 828 774 Agent   * Found 0 updates and 9 categories in search
    2005-08-03 19:18:13 828 774 AU #########
    2005-08-03 19:18:13 828 774 AU ## END ## AU: Search for updates
    2005-08-03 19:18:13 828 774 AU #############
    2005-08-03 19:18:13 828 774 AU AU setting next detection timeout to
2005-08-04 11:24:58

    2005-08-03 19:25:13 828 4f4 Report Reporter successfully uploaded 2 events.

It's of interest to note that my 3am scheduled installs are also pretty useless, since this was the only day of the four demonstrated where the system was actually powered up and awake at 3am!

    2005-08-04 03:00:09 828 d0 AU Forced install timer expired for scheduled install

So, the scheduled 6:24am detection ran and scheduled the next detection for 4:55pm

    2005-08-04 06:25:11 828 d0 AU #############
    2005-08-04 06:25:11 828 d0 AU ## START ## AU: Search for updates
    2005-08-04 06:25:11 828 d0 AU #########

    2005-08-04 06:27:35 828 774 Agent   * Found 0 updates and 9 categories in search
    2005-08-04 06:27:35 828 774 AU #########
    2005-08-04 06:27:35 828 774 AU ## END ## AU: Search for updates
    2005-08-04 06:27:35 828 774 AU #############
    2005-08-04 06:27:35 828 774 AU AU setting next detection timeout to
2005-08-04 21:55:52

    2005-08-04 06:34:36 828 4f4 Report Reporter successfully uploaded 2 events.

But I powered down the system at 4:34pm

    2005-08-04 16:34:18 804 5cc Service *********
    2005-08-04 16:34:18 804 5cc Service ** END ** Service: Service exit [Exit code = 0x240001]
    2005-08-04 16:34:18 804 5cc Service *************

** 16:55:52 -- scheduled detection not possible due to power down state

And, when the system powered back up at 5:14pm a detection and reporting activity occurred and the next detection was scheduled for 3:28am

    2005-08-04 17:14:44 792 5c8 Service *************
    2005-08-04 17:14:44 792 5c8 Service ** START ** Service: Service startup
    2005-08-04 17:14:44 792 5c8 Service *********

    2005-08-04 17:15:31 792 5c8 AU AU setting next detection timeout to
2005-08-04 22:15:31

    2005-08-04 17:19:38 792 5c8 AU #############
    2005-08-04 17:19:38 792 5c8 AU ## START ## AU: Search for updates
    2005-08-04 17:19:38 792 5c8 AU #########

    2005-08-04 17:20:35 792 b60 Agent   * Found 0 updates and 9 categories in search
    2005-08-04 17:20:35 792 b60 AU #########
    2005-08-04 17:20:35 792 b60 AU ## END ## AU: Search for updates
    2005-08-04 17:20:35 792 b60 AU #############
    2005-08-04 17:20:35 792 b60 AU AU setting next detection timeout to
2005-08-05 08:28:53

    2005-08-04 17:28:22 792 bb0 Report Reporter successfully uploaded 2 events.