First published on TechNet on May 06, 2012
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. đ
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.
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.
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
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.
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
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 by searching for the following names:
Microsoft
