Recipe 15.11 Using Perfmon Trace Logs to Monitor AD

15.11.1 Problem

You want to enable Perfmon Trace Logs to view system level calls related to Active Directory.

15.11.2 Solution

Open the Performance Monitor.
In the left pane, expand Performance Logs and Alerts.
Right-click on Trace Logs and select New Log Settings.
Enter a name for the log and click OK.
Click the Add button.
Highlight one or more of the Active Directory providers and click OK.
Use the tabs to configure additional settings about the log.
When you are done, click OK.
Unless you've scheduled it to run at a different time, the trace log you created should show up in the right pane next to a green icon, which indicates it is running.
To stop the Trace Log, right-click on it in the right pane and select Stop.
Now open up a command shell (cmd.exe).
Use cd to change into the directory where the trace log files are stored (c:\perflogs by default).
Run the following command:
```
> tracerpt <LogFileName>
```

This command is available by default with Windows Server 2003. On Windows 2000, you'll need to use the Resource Kit utility called tracedmp.exe.

The tracerpt command generates a summary.txt file that summarizes all of the events by total. A second file called dumpfile.csv is created that can be imported into Excel or viewed with a text viewer to show the details of each event.

15.11.3 Discussion

Trace Logs capture detailed system and application level events. Applications support Trace Log capability by developing a Trace Log Provider. Active Directory supports several providers that log low-level system calls related to Kerberos, LDAP, and DNS, to name a few. This can be an extremely valuable tool for debugging and even figuring out the inner-workings of Active Directory. Trace Logs can be resource intensive, so you should enable them with care.

Here is an example of what the summary.txt file looks like on a domain controller that had all of the Active Directory-related Trace Log Providers enabled:

Files Processed:
        AD_000001.etl
Total Buffers Processed 5
Total Events  Processed 193
Total Events  Lost      0
Start Time              Friday, May 23, 2003
End Time                Friday, May 23, 2003
Elapsed Time            24 sec
+-----------------------------------------------------------------------------+
|Event Count Event Name           Event Type  Guid                                  |
+-----------------------------------------------------------------------------------+
|  1         EventTrace           Header      {68fdd900-4a3e-11d1-84f4-0000f80464e3}|
| 69         SamNameById          Start       {25059476-899f-11d2-819e-0000f875a064}|
| 69         SamNameById          End         {25059476-899f-11d2-819e-0000f875a064}|
|  2         KerbInitSecurityContext End      {52e82f1a-7cd4-47ed-b5e5-fde7bf64cea6}|
|  2         KerbInitSecurityContext Start    {52e82f1a-7cd4-47ed-b5e5-fde7bf64cea6}|
|  1         KerbAcceptSecurityContext Start  {94acefe3-9e56-49e3-9895-7240a231c371}|
|  1         KerbAcceptSecurityContext End    {94acefe3-9e56-49e3-9895-7240a231c371}|
|  1         SamGetAliasMem       Start       {1cf5fd19-1ac1-4324-84f7-970a634a91ee}|
|  1         SamGetAliasMem       End         {1cf5fd19-1ac1-4324-84f7-970a634a91ee}|
| 14         LdapRequest          End         {b9d4702a-6a98-11d2-b710-00c04fb998a2}|
| 14         LdapRequest          Start       {b9d4702a-6a98-11d2-b710-00c04fb998a2}|
|  1         DsLdapBind           Start       {05acd009-daeb-11d1-be80-00c04fadfff5}|
|  1         DsLdapBind           End         {05acd009-daeb-11d1-be80-00c04fadfff5}|
|  8         DsDirSearch          End         {05acd000-daeb-11d1-be80-00c04fadfff5}|
|  8         DsDirSearch          Start       {05acd000-daeb-11d1-be80-00c04fadfff5}|
+-----------------------------------------------------------------------------------+

Here you can see that over a 24-second period there was 1 LDAP bind request (DsLdapBind), 8 directory searches (DsDirSearch), and 14 total LDAP requests (LdapRequest).

The dumpfile.csv contains entries for every event that was generated during the time period. Here is an example of an entry for one of the DsDirSearch requests (note that the lines will wrap due to their length so I've added a blank line in between for separation):

DsDirSearch, Start, 0x000003F4, 126982224636242128, 61350, 440530, "DS", 3, 3, 
1141178432, 2694848000, "192.168.5.26", "deep", "OU=Sales,DC=rallencorp,DC=com", "0, 
0

DsDirSearch, End, 0x000003F4, 126982224636342271, 61350, 440540, "DS", 3, 5, 
1157955648, 2694848000, "0", " 
(&(objectCategory=CN=Person,CN=Schema,CN=Configuration,DC=rallencorp,DC=com)  
(objectClass=user)) 0, 0

Based on just those two lines (disregarding most of the numeric values), we can deduce that a user on the host with IP address 192.168.5.26 performed an LDAP query for user objects in the Sales OU. Pretty neat, huh?