Hello, Ray Zabilla and Rick Bergman again. As promised in our previous post on this topic we will go into the details of how we created the script, the challenges we had during testing and what final code looks like. We are even so generous that we are going to share the scripts with you too. :)

How to Track the Who, What, When and Where of Active Directory Attribute Changes – Part I (The Case of the Mysteriously Modified UPN)

 

Quick Review – The story you’re about to hear is true and the names have been changed to protect the innocent…

Some unknown process, running on some unknown computer, at some unknown time was changing the UPN on the Active Directory user accounts.

Since Contoso is running Windows Server 2003 R2 X64 Domain Controllers, we recommended they search the Security event log for Event ID 642 which indicates a successful “User Account Change”. The Event ID includes information that identifies the attribute which was changed and the “calling account” initiating the change. This means that each domain controller will have to be scanned for the Event ID 642, because you never know on which writable DC the change is going to be made.

Contoso uses an enterprise auditing and collection system so the logical thing to do was to use the tool to search for the 642 Event ID versus searching each DC independently. Contoso IT made an inquiry to their security auditing team to give us all event ID 642 from all DC’s in the environment from their enterprise collection system and we would search through them. This effort turned out to be unsuccessful since for some reason the archived logs did not contain all the data and they were only able to provide part of the data needed, which of course did not contain any of the specific UPN change events we were hoping to find.  We discussed Microsoft’s SCOM ACS tool, System Center Operations Manager Audit Collection Systems as a solution, but the customer declined because that was not a strategic direction for them.

The Solution – Version 1

It was stated in the previous post that the domain controllers had a security event log size of 180 MB, this means that it took less than 15 minutes for the event log to wrap. The security event log needed to be increased on each DC in order to buy additional time to see if it would be possible to capture the Event ID 642. It was good that Contoso was running Windows Server2003 x64, because the 64-bit OS would be able to handle larger event log sizes.

Change the Security Event File Size

The first thing the Contoso IT team did was increase the Security Event log size to 2GB. We had researched and found there had been a few incidents reported on Server 2003 x64 domain controllers when the security log files were set to the maximum 4GB. We recommend Contoso set the log file size at 2GB which should give us enough data to capture the 642 event but be well below the max size. After increasing the log file size some quick analysis found they now had 3 – 3.5 hours before the security event log wrapped. Our thoughts were this should give us enough time to find Event ID 642.

There is one odd situation that occurred on only one of the Domain Controllers that had its Security Event Log size changed by the GPO. The properties showed that it was properly set at 2GB and the size of the on the disk was at 2 GB, but there were not as many entries in the event log as the others. When changing the size of the Event Viewer Logs, best practice is to use the “clear log” button to allow the event log to properly resize.

Get Event ID 642 from the Domain Controllers

The information provided by the REPADMIN /showobjmeta meant we should only have to search the Security log on the domain controller where the user objects UPN was changed to find the Event ID 642. REPADMIN /showobjmeta gives the precise time when the changed occurred and on which domain controller, allowing our search to specific and limited. Once the Event ID 642 was found in the appropriate security event log we would know the AD account that made the change and could identify 4 of the 5 key variables (who, where, when, what), which would hopefully provide enough information to lead us to the process making the change.

image

Figure 1 – REPADMIN /showobjmeta output

In the example shown above, Figure 1 - REPADMIN /showobjmeta output, you can see the change that was made to test5455 on DC02NA which we got from the metadata. It also shows the other key piece of information, the AD account initiating the change, which in this case is Administrator.

Armed with this knowledge, we started down the path of creating PowerShell scripts to identify user accounts where the UPN that had been set to an incorrect value and create a “Bad UPN” report/log file with the associated replication metadata. We quickly realized it is going to take an enormous amount of time to do this for all users, we needed subset of users to focus on and that would be quicker.

Contoso IT team came up with 1600 users that they would watch for changes to the UPN and we would use that for the input file for the script. Great, how do we script this in powershell? We looked at the output from REPADMIN /showobjmeta, and quickly surmised that it would take a lot of work to parse the output. How can we do all this in powershell?

We decided to use the PowerShell equivalent of the REPADMIN /showobjmeta, the GetReplicationMetadata method of the System.DirectoryServices.ActiveDirectory.DirectoryContext object for the ease of handling the data. We opened up our favorite search engine, www.bing.com, to start looking for examples and we found one really good example.

AD Replication Metadata (when did that change?)

http://bsonposh.com/archives/253

We used the sample from above website along with some minor changes to retrieve the AD Users object meta data and get the OriginatingServer and LastOrginatingServer values. See figure 2.

image

Figure 2 – PowerShell REPADMIN /ShowObjMeta example

These values along with the UPN would be written out to a log file, “BadUPN”, so we could use them for searching for Event ID 642. From the “Bad UPN” list, we got the list of domain controllers we needed to get the security event log from.

The Solution – Version 2

Reality set in at this point, it made no sense to repeatedly query the same DCs for the Event ID 642, when we only needed to get the data once. We changed the script so only a filtered list of the DCs would be queried versus all DCs.

Filtered Server List approach

We already had the script looping through the each user identifying their metadata. Part of the information being collected was the name of the server. Using PowerShell, when looking at the server data, if the servers had been removed from the domain, for any reason, the server name returned a Null value. Remember that the server names in AD are actually GUIDs and not the FQDN name. This meant we needed to handle the Null value to ensure it wasn’t included in the array and ensure there weren’t any duplicates server names in the array. FYI, handling the Null value in the array was not obvious to us right way and took a while to figure out why things weren’t working as expected in the script. In Table 1 below, you can see what the Repadmin /showobjmeta output looks like when the DC is missing. The server name looks like “cd5d12e9-ad2e-4e44-a785-f6757f209d4e” when it is missing. When it is there it looks like “Default-First-Site\DC01”.

We checked if the returned Server Name was a Null, and if it was then it was skipped and not put in the Array. If the Server name was a not a Null, then check to see if the array contained this server name. If the array did not contain the Server Name, then add it to the array; otherwise continue on without adding the server name to the array. See Figure 4 for the example code.

 

Loc.USN Originating DSA Org.USN Org.Time/Date Ver Attribute

======= =============== ========= ============= === =========

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 objectClass

1133651 Default-First-Site\DC01 1133651 2011-08-11 12:04:10 1 cn

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 sn

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 st

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 title

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 postalCode

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 physicalDeliveryOfficeName

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 givenName

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 instanceType

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 whenCreated

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 displayName

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 department

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 company

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 391356011 2011-06-30 10:54:29 3 homeMTA

118496097 Default-First-Site\DC02 65408863 2011-10-26 20:41:02 3 proxyAddresses

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 streetAddress

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 nTSecurityDescriptor

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 mDBUseDefault-First-Sites

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 extensionAttribute9

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 mailNickname

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 employeeType

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 name

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255842 2010-05-11 02:07:58 3 userAccountControl

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255839 2010-05-11 02:07:58 1 codePage

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255839 2010-05-11 02:07:58 1 countryCode

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 employeeID

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255840 2010-05-11 02:07:58 2 unicodePwd

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255840 2010-05-11 02:07:58 2 ntPwdHistory

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255843 2010-05-11 02:07:58 3 pwdLastSet

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255839 2010-05-11 02:07:58 1 primaryGroupID

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255841 2010-05-11 02:07:58 1 supplementalCredentials

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 objectSid

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255839 2010-05-11 02:07:58 1 accountExpires

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255840 2010-05-11 02:07:58 2 lmPwdHistory

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 sAMAccountName

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 division

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 sAMAccountType

1133651 5c66f360-c067-4e66-959a-d11bba47e42c 385295851 2010-05-11 02:08:51 1 legacyExchangeDN

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 userPrincipalName

392184935 Default-First-Site\DC01 392184935 2012-01-23 09:13:47 1 lockoutTime

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 objectCategory

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 msNPAllowDialin

1133651 5c66f360-c067-4e66-959a-d11bba47e42c 385295851 2010-05-11 02:08:51 1 textEncodedORAddress

1133651 5c66f360-c067-4e66-959a-d11bba47e42c 385295851 2010-05-11 02:08:51 1 mail

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 departmentNumber

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 middleName

41048248 Default-First-Site\DC01 41048248 2011-09-07 10:18:35 4 msExchPoliciesIncluded

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 391356011 2011-06-30 10:54:29 3 msExchHomeServerName

1133651 5c66f360-c067-4e66-959a-d11bba47e42c 385296006 2010-05-11 02:09:51 2 msExchALObjectVersion

1133651 cd5d12e9-ad2e-4e44-a785-f6757f209d4e 127255838 2010-05-11 02:07:58 1 msExchHideFromAddressLists

1133651 5c66f360-c067-4e66-959a-d11bba47e42c 385295851 2010-05-11 02:08:51 1 msExchMailboxSecurityDescriptor

1133651 5c66f360-c067-4e66-959a-d11bba47e42c 385295851 2010-05-11 02:08:51 1 msExchUserAccountControl

1133651 5c66f360-c067-4e66-959a-d11bba47e42c 385295851 2010-05-11 02:08:51 1 msExchMailboxGuid

1133651 5c66f360-c067-4e66-959a-d11bba47e42c 610906234 2011-03-02 07:42:52 1 msRTCSIP-InternetAccessEnabled

1133651 5c66f360-c067-4e66-959a-d11bba47e42c 610906237 2011-03-02 07:42:52 1 msRTCSIP-PrimaryUserAddress

1133651 5c66f360-c067-4e66-959a-d11bba47e42c 610906233 2011-03-02 07:42:52 1 msRTCSIP-UserEnabled

1133651 5c66f360-c067-4e66-959a-d11bba47e42c 610906238 2011-03-02 07:42:52 1 msRTCSIP-PrimaryHomeServer

1133651 5c66f360-c067-4e66-959a-d11bba47e42c 610906236 2011-03-02 07:42:52 1 msRTCSIP-OptionFlags

1133651 5c66f360-c067-4e66-959a-d11bba47e42c 610906235 2011-03-02 07:42:52 1 msRTCSIP-FederationEnabled

Table 1 - REPADMIN /showobjmeta output Missing DC

 

image

Figure 4 – Filtering DC for the Array

Let’s Test the Script

We were pretty confident that the script would work quite well and it would be something that could be run frequently, like once an hour or two. After the first test taking over 3 hours to complete on just one DC, we were back to rethinking how to improve the performance of collecting Event ID 642 from the list of DCs.

The Solution – Version 3.0

After seeing how long it took to return results we did some more thinking, research and testing on how to improve the performance of collecting the event log entries. While discussing the scenario, it sure made sense to use a multithreaded approach, so we could collect from each DC at the same time. Let’s rephrase the previous sentence into tech speak, “It would be really cool if we could do multithreading with PowerShell.”

Researching PowerShell and Multi-Threading

We fired our favorite search engine, www.bing.com, and starting looking ways to collect from all the DC in the array list the script created. The following sites were extremely helpful in getting us started using PowerShell V2 Start-Job command let.

Ryan's PowerShell Blog

Multi-Threading in PowerShell V2

http://ryan.witschger.net/?p=22

TechNet Library

Start-Job

http://technet.microsoft.com/en-us/library/dd347692.aspx

PowerShell Multi-Threading using Start-Jobs

PowerShell 2.0 has the ability to a form of multithreading and it is called “Jobs.” This would give us the ability to use a parallel versus a serial approach for gathering the events from the event logs. Great, let’s try using “Jobs” to see if it will speed up the security event log collections for the list of DCs. It took a while to figure out what was the proper syntax to use when collecting the security event log from multiple domain controllers. While working through the syntax, we learned that we needed to use the “-ScriptBlock” parameter to get what we wanted to do working correctly. One of the syntax tricks to the Start-Job cmdlet is where the “{“ is placed. Normally for readability of code, the “{“ is place on the next line, but that doesn’t work correctly with Start-Job. The curly bracket needed to go on the same line and after your last parameter for everything to work correctly. The last interesting tidbit of information was figuring out how to use variables in the Job. After reviewing samples and reading forums, we determined that global variables do not work and we needed to pass them. The way to do that is with “-ArgumentList” parameter.

In figure 4 – Start-Job Section, we are showing the working code we came up with to collect the security events logs from multiple Domain Controllers. There is a more to this part of the script than what we have talked about to this point.

image

Figure 4 – Start-Job Code Section

We tested the script and collected data to prove less time was spent collecting the events from the event logs. The data was collected with start and stop time for each DC we collected event logs from by writing to a log file. It discovered when reviewing the log files that some DC were taking longer than others. When we tested we quickly found out that a couple of the DCs were the bottleneck when it came to collecting the security event logs. The only reason we came up with to explain this was that those slower DCs were averaging more security events/second that the rest.

Event Filtering Performance

We checked to make sure we were using the fastest methods possible for collecting events from the security log. We ended up testing WMI and Get-Eventlog from PowerShell. We found that if we did anymore than just filtering for a single Event ID using “Where” clauses, it took longer to get the data. The reason it takes longer is that it reads the entire event log first and then filters it before out dumping the information to file.

Through multiple tests we determined that using the simple filter for retrieving Event ID 642 only and placing that data in a log file worked the fastest. One other interesting observation we need to share, is the amount of audit data being logged into the Event Logs and how that affects the performance of retrieving the event logs. Especially on Windows Server 2003, the more entries being written the longer it took to retrieve the events from the security log.

Testing & Performance Thoughts

We ran this version through some testing and determined that it did work and actually helped us catch one account that was making the change to the UPN’s. The testing also showed us that we could not run the full version of the script every hour or two like we were thinking. The reality was it needed to be run in the full version right after we knew when the changes were being made to the UPN’s.

We also changed the script to allow it to gather the UPN changes only, but not go out and pull from the DC’s security event logs. The script can be started in in either mode, by using a command line parameter when launching the script. If the script launches without any command line parameters, then it only collects the changed UPN values in a log file. If the ‘Full’ command line parameter is used then the security event log scan is done too.

Command Line Parameters Examples

O365UPNCheckV4.ps1 – will log only UPN update information and NOT gather the Security event logs

O365UPNCheckV4.ps1 ‘Full’ – will log UPN update information and gather the Security event log

Analysis of the Event logs

A Log file is generated from each DC containing the Event ID 642 that has been collected. The log could be quite large and would take a long time to manually review them. To speed that process up, Ray developed another script that will do the analysis of the each of the log files looking for the Event ID 642’s that had the UPN values changed. If a 642 that had its UPN changed, it outputs to a .csv file listing the originating domain controller, date/time, and the new value of the of the UPN attribute. This gives us one place to look for the “who, when and where” the UPN’s changed.

Parallel Tasks

The Contoso IT team was working in parallel to find out what they could about what could be making changes to AD. From the work they had already completed, once they knew the AD account making the change, they were able to identify the offending process in about 15 minutes and get the migration back on track.

PostScript

We hope you found the additional detail we included of how we approached solving the problem, the challenges we went through and the script development process we used. The scripts are attached the blog post and we hope you find those helpful too.

We hoped you enjoyed this post.

Ray and Rick

Attached Sample Scripts

To centralize the storage of all AskPFEPlat scripts, we are now storing them on the TechNet Script Center Repository.  This specific script can be found at the following location:

O365UPNMetaDataCheck

ScanforEventID