Active Directory – Parsing LDAP search logging information

Sometimes you are interested in what searches hit your domain controllers. Maybe you want to demote it and find applications which use specific DC’s; Maybe you want to see expensive searches using non indexed attributes or maybe you are simply curious.
There is a good blog entry about some details on how to configure LDAP search logging and some knowledge base articles around this topic which you can find at the end of this blog entry. So I don’t want to go in details about how to configure it.

I’d like to focus on how you can use a little PowerShell script to view / enable / disable the logging and with some regex magic how to create a csv out of the potential several thousand of event log entries.
One note of caution: Depending on your environment you may slow down your DC(s) and rapidly fill your Directory Services Log. Make sure your logfile is big enough.
AND:
PowerShell 3.0 seems to have a bug; Get-WinEvent does return an empty message field. So you need to run PowerShell.exe -version 2

The script is intended to be dot sources. So you will need to “load” the functions by running the following command:

. .LDAPLogging.ps1

Notice the first dot which tells PowerShell to make the function global so you can use them after running the script containing them.
The script contains two functions:

Configure-Logging
Get-LDAPEventLog

The first one is used the view / enable / disable logging. The second one to parse the generated event-log entries.

Configure-Logging

Configure-Logging has three aliases defined:

Get-LDAPLogging / Enable-LDAPLogging / Disable-LDAPLogging

Depending which one is called the Configure-Logging function will react differently.
Side note: have you ever recognized that there is a slight difference calling PowerShell help using the function get-help vs. using its alias help. Try it!
Back to my script. You can use $MyInvocation.InvocationName to find out what was calling the command. The switch statement evaluates what called the function and sets the variables used later accordingly.
Then we check if the server is online

Test-Connection $HostName -Quiet -Count 1

And if it is a DC:

Get-WmiObject -query “select producttype from Win32_OperatingSystem where producttype=’2′” `
-ComputerName $HostName -ErrorAction SilentlyContinue

Then I define registry paths. The trick to log all directory searches is to set Expensive and the Inefficient Search Result Threshold to 1 and set the 15 Field Engineering loglevel to 5.

$NTDSParams = “SYSTEMCurrentControlSetServicesNTDSParameters”
$ExpThre = “Expensive Search Results Threshold”
$IneThre = “Inefficient Search Results Threshold”

$NTDSDiag = “SYSTEMCurrentControlSetServicesNTDSDiagnostics”
$FieldEng = “15 Field Engineering”

Then open the remote registry

$baseKey = [Microsoft.Win32.RegistryKey]::OpenRemoteBaseKey( “LocalMachine”, $HostName )

First we read / set or delete the NTDS Parameters, depending of the alias used to call the function.
Open the subkey:

$key = $baseKey.OpenSubKey($NTDSParams,$ReadWrite)

Set the keys if we enable logging

$key.SetValue( $ExpThre, 1, [Microsoft.Win32.RegistryValueKind]::DWord )
$key.SetValue( $IneThre, 1, [Microsoft.Win32.RegistryValueKind]::DWord )

Delete them (default they don’t exists) when we will disable logging

$key.DeleteValue( $ExpThre )
$key.DeleteValue( $IneThre )

And read them again to display current setting and close the registry key:

$ExpThreValue = $key.GetValue($ExpThre)
$IneThreValue = $key.GetValue($IneThre)
$key.Close()

Unlike the NTDS Parameter setting I assume this key already exists. So we simply set it to 0 or 5.
Again open the key:

$key = $baseKey.OpenSubKey($NTDSDiag,$ReadWrite)

Setting the Value

$key.SetValue( $FieldEng, $FieldEngDef )

Reading it again and closing the registry key.

$FieldEngValue = $key.GetValue($FieldEng)
$key.Close()

You may noticed, before I checked if $EnableLogging is either $true or $false. But now I ceck if it is not $null.
When checking what alias was used to call the function, I use the following terminology to set the value of $EnableLogging:

[System.Nullable“1[[System.Int32]]]$EnableLogging

This way the Boolean variable has three instead of two state: $true, $false and $null.

Get-LDAPEventLog

The second function uses a multiline regular expression to parse eventlog entry. I only tested this on Windows Server 2008 and 2008 R2 DCs and assume the entries look similar in older versions.
The function defaults to list the last 60 minutes of the eventlog to keep the results relatively small. Depending on your environment you may increase or decrease this.
Custom PowerShell objects created using New-Object PSObject have two disadvantages: 1. They are slow compared to .Net Object and 2. You cannot determine the order of properties.
To always have the same output order (which makes it much easier to work with the results in Excel and create Pivots) I create a custom dotnet object:

Add-Type @’
using System;
public class LDAPLookups {
public string DNSHostName;
public string ClientIP;
public string ClientName;
public string StartNode;
public string Filter;
public string SearchScope;
public string Attributes;
public string ServerControls;
public System.Nullable<int> VisitedEntries;
public System.Nullable<int> ReturnedEntries;
}
‘@

I use again System.Nullable. This time to allow a null integer.
Then prepare the reqular expression. The option x allows comments and spaces to allow simpler reading. Otherwise all would need to go to one line.

$RegEx = @”
(?msx)
# Option m = multi-line e.g. ^=start of line and $=end of line
# Option s = single-line e.g. . includes end-of-line
# Option x = spaces and comments are allowed in the pattern
Client:rn
(?<Client>.*):(?<Port>.*)rn?

Startingsnode:rn
(?<StartNode>.*?)rn

Filter:rn
(?<Filter>.*?)rn

Searchsscope:rn
(?<SearchScope>.*?)rn

Attributesselection:rn
(?<Attributes>.*?)rn

Serverscontrols:rn
(?<ServerControls>.*?)rn

Visitedsentries:rn
(?<VisitedEntries>.*?)rn

Returnedsentries:rn
(?<ReturnedEntries>.*)
“@

To read the eventlog use either Get-Eventlog or Get-WinEvent which as it turns out is much faster than first one. Specifically against remote machines.

Get-WinEvent -ComputerName $DNSHostName -FilterHashtable @{
“LogName”=”Directory Service” ; “ID”=1644; StartTime= [datetime]::Now.AddMinutes( -$LookupMinutes ) }

The event we are looking for has the eventID 1644 and is stored in the “Directory Service” log.
The containing message looks like this:
Internal event: A client issued a search operation with the following options.

Client:
169.254.218.82:65387
Starting node:
CN=Partitions,CN=Configuration,DC=adds,DC=int
Filter:
( & (objectCategory=CN=Cross-Ref,CN=Schema,CN=Configuration,DC=adds,DC=int) (systemFlags&2) ( | (dnsRoot=adds.int) (nCName=adds.int) (nETBIOSName=adds.int) ) )
Search scope:
onelevel
Attribute selection:
nETBIOSName,distinguishedName
Server controls:

Visited entries:
5
Returned entries:
1

#

Within the Foreach-Object loop we create new LDAPLookups object type as defined above. As the New-Object commandlet does not go into variable, the object returned goes again to the pipeline. Or in other words, the pipeline will contain custom LDAPLookups objects.

Foreach-Object {
if ( $_.Message -match $RegEx ) {
New-Object LDAPLookups -Property @{
[…] Property List […]
}
}
}

Most of the properties are filled straight away. For example:

“ClientPort” = ($Matches.Port).Trim()
“StartNode” = ($Matches.StartNode).Trim()

To make it easier to find out what client did actually do the lookup I use the following command to resolve the IP Address to the hostname:

[System.Net.Dns]::GetHostByAddress( $ClientIP ).HostName

And to avoid multiple lookups for the same address, I maintain a cache which was initialized at the beginning of the script.

if( -not $AlreadyLookedUp.contains( $ClientIP ) ){
$AlreadyLookedUp.$ClientIP = ( [System.Net.Dns]::GetHostByAddress( $ClientIP ).HostName )
}

And use this cache to return the name (or the IP if reverse lookup failed)

$AlreadyLookedUp.$ClientIP

After all objects were pushed thru the pipeline I clear the cache again
Remove-Variable -Scope Script -Name AlreadyLookedUp

Below you can find the complete script as well as in PoShCode.org
References:
Logging LDAP searches: AD and ADAM
http://www.activedir.org/Articles/tabid/54/articleType/ArticleView/articleId/41/Default.aspx
Creating More Efficient Microsoft Active Directory-Enabled Applications
http://msdn.microsoft.com/en-us/library/ms808539.aspx
How to configure Active Directory diagnostic event logging in Windows Server 2003 and in Windows 2000 Server
http://support.microsoft.com/kb/314980/en-us
Store the following content as LDAPLogging.ps1
You may download the code from
http://poshcode.org/3674

Code:

function Private:Configure-Logging {
<#
.SYNOPSIS
Enables, disables or view current LDAP Logging settings on a domain controller.

.DESCRIPTION
Enables, disables or view current LDAP Logging settings on a domain controller.

Use one of the following aliases:

Get-LDAPLogging
View current LDAP logging settings

Enable-LDAPLogging
Enables LDAP logging. Logging is set to log every single LDAP query and stores it in directory services log.

Disable-LDAPLogging
Disables LDAP logging. Logging is set to its default values.

.EXAMPLE
PS C:> Get-LDAPLogging

.EXAMPLE
PS C:> Enable-LDAPLogging DC1

.INPUTS
N/A

.OUTPUTS
N/A

.NOTES
Author: Patrick Sczepanski

.LINK
Get-LDAPLogging
Enable-LDAPLogging
Disable-LDAPLogging

#>

Param (
[string]
$HostName = $env:COMPUTERNAME
)

[System.Nullable“1[[System.Int32]]]$EnableLogging = $null
switch ( $MyInvocation.InvocationName ) {
“Enable-LDAPLogging” {
[System.Nullable“1[[System.Int32]]]$EnableLogging = $true
[bool]$ReadWrite = $true
[int]$Threshold = 1
[int]$FieldEngDef = 5
break
}
“Disable-LDAPLogging” {
[System.Nullable“1[[System.Int32]]]$EnableLogging = $false
[bool]$ReadWrite = $true
[int]$Threshold = 0
[int]$FieldEngDef = 0
break
}
Default {
[System.Nullable“1[[System.Int32]]]$EnableLogging = $null
[bool]$ReadWrite = $false
}
}

if ( -not (Test-Connection $HostName -Quiet -Count 1) ) {
Write-Warning “Cannot Ping $HostName”
continue
}
if ( -not (
Get-WmiObject -query “select producttype from Win32_OperatingSystem where producttype=’2′” `
-ComputerName $HostName -ErrorAction SilentlyContinue) ) {
Write-Warning “$HostName is not a domain controller or you do not have access.”
continue
}

$NTDSParams = “SYSTEMCurrentControlSetServicesNTDSParameters”
$ExpThre = “Expensive Search Results Threshold”
$IneThre = “Inefficient Search Results Threshold”

$NTDSDiag = “SYSTEMCurrentControlSetServicesNTDSDiagnostics”
$FieldEng = “15 Field Engineering”

$baseKey = [Microsoft.Win32.RegistryKey]::OpenRemoteBaseKey( “LocalMachine”, $HostName )

try {
$key = $baseKey.OpenSubKey($NTDSParams,$ReadWrite)
if ( $EnableLogging -eq $true ) {
$key.SetValue( $ExpThre, 1, [Microsoft.Win32.RegistryValueKind]::DWord )
$key.SetValue( $IneThre, 1, [Microsoft.Win32.RegistryValueKind]::DWord )
} elseif ( $EnableLogging -eq $false ) {
$key.DeleteValue( $ExpThre )
$key.DeleteValue( $IneThre )
}
$ExpThreValue = $key.GetValue($ExpThre)
$IneThreValue = $key.GetValue($IneThre)
$key.Close()
}
catch {
Write-Warning “Failed to read or change $NTDSParams.`r`n$_”
}
try {
$key = $baseKey.OpenSubKey($NTDSDiag,$ReadWrite)
if ( $EnableLogging -ne $null ) {
$key.SetValue( $FieldEng, $FieldEngDef )
}
$FieldEngValue = $key.GetValue($FieldEng)
$key.Close()
}
catch {
Write-Warning “Failed to read or change $NTDSDiag.`r`n$_”
}
$baseKey.Close()
New-Object PSObject -Property @{
“FieldEngineering” = $FieldEngValue
“ExpensiveThreshold” = $ExpThreValue
“InefficientThreshold” = $IneThreValue
}
}
New-Alias Get-LDAPLogging Configure-Logging -Force
New-Alias Enable-LDAPLogging Configure-Logging -Force
New-Alias Disable-LDAPLogging Configure-Logging -Force

Function Global:Get-LDAPEventLog {
Param (
[Parameter(ValueFromPipeline=$true,ValueFromPipelineByPropertyName=$true,Position=0)]
[string]
$DNSHostName = $env:COMPUTERNAME,

[int]
$LookupMinutes = 60

)
Begin {
$Script:AlreadyLookedUp = @{}
Add-Type @’
using System;
public class LDAPLookups {
public string DNSHostName;
public string ClientIP;
public System.Nullable<int> ClientPort;
public string ClientName;
public string StartNode;
public string Filter;
public string SearchScope;
public string Attributes;
public string ServerControls;
public System.Nullable<int> VisitedEntries;
public System.Nullable<int> ReturnedEntries;
public string Date;
public string Time;
}
‘@

$RegEx = @”
(?msx)
# Option m = multi-line e.g. ^=start of line and $=end of line
# Option s = single-line e.g. . includes end-of-line
# Option x = spaces and comments are allowed in the pattern
Client:rn
(?<Client>.*):(?<Port>.*)rn?

Startingsnode:rn
(?<StartNode>.*?)rn

Filter:rn
(?<Filter>.*?)rn

Searchsscope:rn
(?<SearchScope>.*?)rn

Attributesselection:rn
(?<Attributes>.*?)rn

Serverscontrols:rn
(?<ServerControls>.*?)rn

Visitedsentries:rn
(?<VisitedEntries>.*?)rn

Returnedsentries:rn
(?<ReturnedEntries>.*)
“@
}
Process {
Write-Host “… $DNSHostName …”
Get-WinEvent -ComputerName $DNSHostName -FilterHashtable @{ “LogName”=”Directory Service” ; “ID”=1644; StartTime= [datetime]::Now.AddMinutes( -$LookupMinutes ) } |
Foreach-Object {
if ( $_.Message -match $RegEx ) {
New-Object LDAPLookups -Property @{
“DNSHostName” = $DNSHostName
“ClientIP” = $Matches.Client
“ClientPort” = ($Matches.Port).Trim()
“ClientName” = $( $ClientIP = $Matches.Client
try {
if( -not $AlreadyLookedUp.contains( $ClientIP ) ){
$AlreadyLookedUp.$ClientIP = ( [System.Net.Dns]::GetHostByAddress( $ClientIP ).HostName )
}
}
catch {
$AlreadyLookedUp.$ClientIP = $ClientIP
}
$AlreadyLookedUp.$ClientIP
)
“StartNode” = ($Matches.StartNode).Trim()
“Filter” = ($Matches.Filter).trim()
“SearchScope” = ($Matches.SearchScope).trim()
“Attributes” = ($Matches.Attributes).trim()
“ServerControls” = ($Matches.ServerControls).trim()
“VisitedEntries” = ($Matches.VisitedEntries).trim()
“ReturnedEntries” = ($Matches.ReturnedEntries).trim()
“Date” = $_.TimeCreated.ToString( “yyyy.MM.dd” )
“Time” = $_.TimeCreated.ToString( “HH:mm:ss” )
}
}
}
}
End {
Remove-Variable -Scope Script -Name AlreadyLookedUp
}
}
Write-Host “LDAPLogging functions loaded into Global.”