SCCM: Zoinks... Mystery Maintenance Windows

What am I trying to do?

We have a few SCCM clients, mostly publicly facing websites running on Windows Server 2008 R2's IIS 7.5, that are monitored by a system called XYmon. We have recently noticed these servers are rebooting after installing their monthly Windows Updates about an hour early. There is a certain amount of delay inherent in the SCCM Client Actions and the monitoring system but XYmon loses connection with these machines right around 19:20-19:30ish whereas the rest of the monitored machines seem to reboot about an hour later around 20:20-20:30.

The Maintenance Window that I expect to be applied starts at 20:00 and ends at 22:00 and reoccurs every Thursday.

I am trying to figure out why these machines are installing their updates an hour early. I know that multiple Maintenance Windows are "union-ed" or merged so I suspect there is another Maintenance Window that is also applying to these clients.

These machines are also in a non-domain joined DMZ so I'm not going to rule out any timezone / clock skew issues either.

What did I try in order to make it happen?

I figured the timezone / clock skew issue was the most likely but both machines were in the correct timezone, had synchronized time and managed to handle the Daylight Savings change that happened on March 8th appropriately.

My next hypothesis is that we had an errant or old Maintenance Window that was applying to a Collection these machines were in. This seems a little unlikely to me since there is another machine that should be all the same Collections which reboots at the correct time of 20:00-ish.

Let's make sure the client is actually rebooting when the monitoring system says it is!

If I check a client, systeminfo shows the boot time at 19:22. The Event Log seems to collaborate this:

Log Name:      System
Source:        USER32
Date:          3/12/2015 7:21:02 PM
Event ID:      1074
Task Category: None
Level:         Information
Keywords:      Classic
User:          SYSTEM
Computer:      HOST09
Description:
The process C:\Windows\CCM\CcmExec.exe (HOST09) has initiated the restart of computer HOST09 on behalf of user NT AUTHORITY\SYSTEM for the following reason: No title for this reason could be found
 Reason Code: 0x80020001
 Shutdown Type: restart
 Comment: Your computer will restart at 03/12/2015 07:21:02 PM to complete the installation of applications and software updates.

Did it reboot because of SCCM's Windows Updates?

If I dig into the UpdatesHandler.log the answer is a big old "yes":

Initiating updates scan for checking applicability. UpdatesHandler  3/12/2015 7:00:00 PM    6472 (0x1948)
Successfully initiated scan.    UpdatesHandler  3/12/2015 7:00:00 PM    6472 (0x1948)
Updates scan completion received, result = 0x0. UpdatesHandler  3/12/2015 7:00:00 PM    8396 (0x20CC)
Initiating updates scan for checking applicability. UpdatesHandler  3/12/2015 7:00:02 PM    10160 (0x27B0)
Method (Apply) called from SDM. UpdatesHandler  3/12/2015 7:00:02 PM    8888 (0x22B8)
Starting job with id = {7DD179F1-1B94-4ADB-A5F1-08E9A000709F}   UpdatesHandler  3/12/2015 7:00:02 PM    8888 (0x22B8)
Successfully initiated scan.    UpdatesHandler  3/12/2015 7:00:02 PM    10160 (0x27B0)
Updates scan completion received, result = 0x0. UpdatesHandler  3/12/2015 7:00:02 PM    8396 (0x20CC)
Initiating Scan. Forced = (0)   UpdatesHandler  3/12/2015 7:00:02 PM    8888 (0x22B8)
Successfully initiated scan for job ({7DD179F1-1B94-4ADB-A5F1-08E9A000709F}).   UpdatesHandler  3/12/2015 7:00:02 PM    8888 (0x22B8)
Scan completion received for job ({7DD179F1-1B94-4ADB-A5F1-08E9A000709F}).  UpdatesHandler  3/12/2015 7:00:02 PM    8396 (0x20CC)
Evaluating status of the updates for the job ({7DD179F1-1B94-4ADB-A5F1-08E9A000709F}).  UpdatesHandler  3/12/2015 7:00:02 PM    8396 (0x20CC)
Initiating download for the job ({7DD179F1-1B94-4ADB-A5F1-08E9A000709F}).   UpdatesHandler  3/12/2015 7:00:02 PM    8396 (0x20CC)
Bundle update (038c4fc9-664f-45e5-b838-f7263ffc4512) is requesting download from child updates for action (INSTALL) UpdatesHandler  3/12/2015 7:00:02 PM    8396 (0x20CC)

The 'ServiceWindowManager.log` shows that that Maintenance Window was applied at 19:00:

Active Service Windows List has 1 windows   ServiceWindowManager    3/12/2015 7:28:13 PM    2404 (0x0964)
    Service Window with ID = {F51051BF-90E8-4ED7-BA06-F74F9E74A098} having Starttime=03/12/15 19:00:00  ServiceWindowManager    3/12/2015 7:28:13 PM    2404 (0x0964)
        Duration is 0 days, 08 hours, 00 mins, 00 secs  ServiceWindowManager    3/12/2015 7:28:13 PM    2404 (0x0964)

OK... Where did that Maintenance Window come from?

A little bit of SQL should show me all the Maintenance Windows applied to a particular SCCM client:

select
v_FullCollectionMembership.Name as Computername ,v_Collection.Name as CollectionName,
v_ServiceWindow.Description as "Next Maintanance Window"
from v_ServiceWindow 
inner join v_FullCollectionMembership on (v_FullCollectionMembership.CollectionID = v_ServiceWindow.CollectionID)
inner join v_Collection on (v_Collection.CollectionID = v_FullCollectionMembership.CollectionID)
order by Computername

and I get the following results:

Computername    CollectionName  Next Maintanance Window
HOST09  Default Maintenance Window  Occurs on 9/15/2013 1:00 AM
HOST09  Weekly Maintenance Window - Thursday    Occurs every 1 weeks on Thursday effective 11/1/2013 8:00 PM

A bit of explanation is in order: All our SCCM clients belong to a Collection that gets assigned a Default Maintenance Window that only occurs once and is in the past. This prevents Collection membership changes and untimely client policy requests from causing clients that have held off actions from immediately performing them. However, since the Maintenance Windows are "union-ed" the Weekly Maintenance Window should apply... at 20:00.

On a hunch I dumped all the Collections this client was in and then went and checked to see if they have Maintenance Windows assigned to them:

SELECT dbo.v_Collection.Name 
FROM dbo.v_FullCollectionMembership INNER JOIN dbo.v_Collection ON dbo.v_FullCollectionMembership.CollectionID = dbo.v_Collection.CollectionID 
WHERE (LOWER(dbo.v_FullCollectionMembership.Name) = LOWER('HOST09'))

Long story short. They don't.

What results did you expect?

I really expected to see a Collection that had a Maintenance Window applied to it that started at 19:00 and unless my SQL is bad and I missed it I guess that is not what's going on here.

The fact that it is one hour early really also inclines me to think it could be an issue with timezones or clock skew but that looks to be expected as well.

I still think both my hypotheses are decent and have not been refuted but I do not know how to gather more information to make a determination about them. Any ideas on how I should proceed with troubleshooting?

Is there something else I should consider? What other things could cause this?

EDIT:

I checked the Software Update Group for this month's Software Updates and there is a deadline set for 03/10/15 at 20:53 but the deadline behavior for activities to be performed outside the maintenance window is disabled for both Software updates installation and System restart.

As for the current time on the box, like it really does look OK but I'm just checking Date and Time in the Control Panel:

Like most things Systems Center Configuration Manager, I'm sure there is a perfectly logical reasons for why things are the way they are but as a lowly technician I am also sure I'll never understand why.

I checked using the Policy Spy from System Center 2012 R2 Configuration Manager Toolkit and again verified that, yes I am getting the two Maintenance Windows that I expected to find except that F51051BF starts one hour earlier than it should:

If I correlate that list with all of the available Maintenance Windows I find the ServiceWindowIDs of the exact Maintenance Windows I expect to see and while the it's clipped off in the screenshot F51051BF does indeed begin at 20:00:

SELECT * FROM v_ServiceWindow
ORDER BY ServiceWindowID

What about a machine that has the same Maintenance Windows that is working as expected (i.e., the Maintenance Window is starting at 20:00):

Biggest Active Service Window has ID = {F51051BF-90E8-4ED7-BA06-F74F9E74A098} having Starttime=3/5/2015 7:00:00 PM  ServiceWindowManager    3/5/2015 10:00:00 PM    68400 (0x10B30)

Wait WUT? That line was from another client's ServiceWindowManager.log and it certainly believed that 19:00 was the appropriate time to start. I checked a few others. Guess what. Not a single mention of F51051BF-90E8-4ED7-BA06-F74F9E74A098 starting at 20:00... but if I look at the what is listed in the database AND in the Configuration Manager Console the Thurs. Night Maintenance Window is listed as starting at 20:00.

Zoinks! It's not a mystery maintenance window! It's a masked maintenance window!

It looks like that for whatever reason F51051BF is configured to start at 20:00. The Configuration Manager Console reports that and so does the database but if I look at a handful of clients some go 19:00 and others at 20:00.

Two WAG (Wild Ass Guesses): 1) We have old Machine Policies hanging around from a previously implemented ConfigMgr 2007 Site. or 2) the Maintenance Window policy got changed from 19:00 to 20:00 at some point and the not every machine got the news. Whatever. I have no idea what I'm doing here.

Resolution

I created a new Maintenance Window to replace F51051BF and assigned it to the appropriate Collection. I waited an hour or two for the clients to do their policy pulls and guess what:

Service Window with ID = {D047CD9F-25E4-4EDC-95E3-44E971E234FA} having Starttime=3/19/2015 8:00:00 PM   ServiceWindowManager    3/16/2015 12:13:41 PM   15500 (0x3C8C)

Mystery solved? Not really. Problem solved? More or less...spooky huh?