LDAP_ Stats_ Measuring
Problem this snippet solves:
This iRule decodes the LDAP messages and counts statistics for LDAP connections and searches. It utilises an HSL connection to send the statistics to a remote listener for further processing.
The iRule will decode client and server messages and specifically calculate times for searches as well as keeping counts of connection, number of simultaneous searches for each user, and total for a VS.
In addition, the iRule is capable of over-riding the destination pool for specific users (Decoded from the LDAP BIND message).
This iRule is part of a system for dynamic intelligent load balancing, which I have been working on for a client in London and they have granted permission for it to be uploaded to devcentral.
Updated 07/04/2011 - Placed the up-2-date version in place
Code :
timing on
when RULE_INIT {
log local0. "Initialising..."
# verboseLogs == 0 - Only send 'status' log messages from 'after {}' thread (Except open & close)...
# verboseLogs == 1 - Send logs for SEARCH, BIND and SEARCHDONE as well...
set static::verboseLogs 0
set static::status_timer 10000
set static::tableTimeout 7200
set static::tableShortTimeout 60
set static::tableName "ldap_measure"
set static::msgtimeout 60
}
when CLIENT_ACCEPTED {
TCP::collect
# Variables to hold connection status, table names etc...
set conn_status "IDLE"
set conn_msg_count 0
set conn_search_elapsed 0
set conn_search_total 0
set connbytesin 0
set connbytesout 0
set bindbytesin 0
set bindbytesout 0
set searchbytesout 0
set searchbytesin 0
set logseq 0
set uid "anonymous"
set hsl [HSL::open -proto TCP -pool logging]
set logprefix ":[IP::client_addr]:[TCP::client_port]:[IP::local_addr]:[TCP::local_port]"
set tcptuple "[IP::client_addr]:[TCP::client_port]:[IP::local_addr]:[TCP::local_port]"
set logsuffix "\n"
set s_offset 1
set now [clock seconds]
# Add the connections into the connection tables (User and Total) so we can count them later...
table set -subtable "${static::tableName}.user.${uid}.connections" $tcptuple 0 ${static::tableShortTimeout}
table set -subtable "${static::tableName}.connections" $tcptuple 0 ${static::tableShortTimeout}
table set -subtable "${static::tableName}.activeUsers" ${uid} $now ${static::tableTimeout}
table incr -subtable "${static::tableName}.user.${uid}" "conncount"
table incr -subtable "${static::tableName}.total" "conncount"
#
#
set user_search_active [table keys -count -subtable "${static::tableName}.user.$uid.searchactive"]
set all_search_active [table keys -count -subtable "${static::tableName}.total.searchactive"]
set user_conn_active [table keys -count -subtable "${static::tableName}.user.${uid}.connections"]
set all_conn_active [table keys -count -subtable "${static::tableName}.connections"]
set user_search_total [table lookup -subtable "${static::tableName}.user.${uid}" "searchcount"]
set all_search_total [table lookup -subtable "${static::tableName}.total" "searchcount"]
set user_conn_total [table lookup -subtable "${static::tableName}.user.${uid}" "conncount"]
set all_conn_total [table lookup -subtable "${static::tableName}.total" "conncount"]
set user_msg_count [table lookup -subtable "${static::tableName}.user.${uid}" "msgcount"]
set all_msg_count [table lookup -subtable "${static::tableName}.total" "msgcount"]
set user_search_elapsed [table lookup -subtable "${static::tableName}.user.${uid}" "elapsed"]
set all_search_elapsed [table lookup -subtable "${static::tableName}.total" "elapsed"]
set secs [clock seconds]
set msec [clock clicks -milliseconds]
set base [expr { $secs * 1000 } ]
set fract [expr { $msec - $base }]
if { $fract >= 1000 } {
set diff [expr { $fract / 1000 }]
incr secs $diff
incr fract [expr { -1000 * $diff }]
}
set timestamp "[expr {(($secs % 86400) * 1000) + $fract}]"
HSL::send $hsl "$logprefix:$logseq:$timestamp:open:${uid}:${conn_status}:${user_search_active}: \
${all_search_active}:${user_conn_active}:${all_conn_active}:${user_conn_total}: \
${all_conn_total}:${user_search_total}:${conn_search_total}:${all_search_total}: \
${user_msg_count}:${conn_msg_count}:${all_msg_count}:${user_search_elapsed}: \
${conn_search_elapsed}:${all_search_elapsed}:$logsuffix"
incr logseq 1
set last_message [clock seconds]
#
#
# The X second Status messages...
after ${static::status_timer} -periodic {
set now [clock seconds]
set diff [expr {(${now} - ${last_message}) * 1000 }]
# Tickle the tables to keep the entries alive while the connection is alive
table set -subtable "${static::tableName}.activeUsers" ${uid} $now ${static::tableTimeout}
table set -subtable "${static::tableName}.user.${uid}.connections" $tcptuple 0 ${static::tableShortTimeout}
set user_search_active [table keys -count -subtable "${static::tableName}.user.$uid.searchactive"]
set all_search_active [table keys -count -subtable "${static::tableName}.total.searchactive"]
set user_conn_active [table keys -count -subtable "${static::tableName}.user.${uid}.connections"]
set all_conn_active [table keys -count -subtable "${static::tableName}.connections"]
set user_search_total [table lookup -subtable "${static::tableName}.user.${uid}" "searchcount"]
set all_search_total [table lookup -subtable "${static::tableName}.total" "searchcount"]
set user_conn_total [table lookup -subtable "${static::tableName}.user.${uid}" "conncount"]
set all_conn_total [table lookup -subtable "${static::tableName}.total" "conncount"]
set user_msg_count [table lookup -subtable "${static::tableName}.user.${uid}" "msgcount"]
set all_msg_count [table lookup -subtable "${static::tableName}.total" "msgcount"]
set user_search_elapsed [table lookup -subtable "${static::tableName}.user.${uid}" "elapsed"]
set all_search_elapsed [table lookup -subtable "${static::tableName}.total" "elapsed"]
set secs [clock seconds]
set msec [clock clicks -milliseconds]
set base [expr { $secs * 1000 } ]
set fract [expr { $msec - $base }]
if { $fract >= 1000 } {
set diff [expr { $fract / 1000 }]
incr secs $diff
incr fract [expr { -1000 * $diff }]
}
set timestamp "[expr {(($secs % 86400) * 1000) + $fract}]"
HSL::send $hsl "$logprefix:$logseq:$timestamp:status:${uid}:${conn_status}:${user_search_active}: \
${all_search_active}:${user_conn_active}:${all_conn_active}:${user_conn_total}: \
${all_conn_total}:${user_search_total}:${conn_search_total}:${all_search_total}: \
${user_msg_count}:${conn_msg_count}:${all_msg_count}:${user_search_elapsed}: \
${conn_search_elapsed}:${all_search_elapsed}:$logsuffix"
incr logseq 1
set last_message [clock seconds]
}
}
when CLIENT_DATA {
incr connbytesin [TCP::offset]
# Assumes msgid is 1 Byte in length. Which it may not be... Should decode properly...
binary scan [TCP::payload] x3c jump
binary scan [TCP::payload] x4c${jump} msgid
binary scan [TCP::payload] x4x${jump}H2 opcode
incr conn_msg_count 1
table incr -subtable "${static::tableName}.user.${uid}" "msgcount"
table incr -subtable "${static::tableName}.total" "msgcount"
table set -subtable "${static::tableName}.activeUsers" ${uid} $timestamp ${static::tableTimeout}
switch $opcode {
60 {
binary scan [TCP::payload] x4x${jump}x6c jump2
binary scan [TCP::payload] x4x${jump}x7a${jump2} uidstr
set binduid [findstr $uidstr "uid=" 4 ","]
if { $binduid eq "" } { set binduid "anonymous" }
set conn_status "BINDING ${uid}->${binduid}"
catch { pool [class match -value $binduid eq ldapuid_to_pool] }
unset uidstr
unset jump2
}
63 {
set searchbytesin [TCP::offset]
set searchbytesout $connbytesout
set conn_status "SEARCHING 0"
set secs [clock seconds]
set msec [clock clicks -milliseconds]
set base [expr { $secs * 1000 } ]
set fract [expr { $msec - $base }]
if { $fract >= 1000 } {
set diff [expr { $fract / 1000 }]
incr secs $diff
incr fract [expr { -1000 * $diff }]
}
set timestamp "[expr {(($secs % 86400) * 1000) + $fract}]"
table set -subtable "${static::tableName}.user.$uid.$msgid" "start" $timestamp ${static::msgtimeout}
table set -subtable "${static::tableName}.user.$uid.searchactive" "$msgid" "$timestamp" ${static::tableShortTimeout}
table set -subtable "${static::tableName}.total.searchactive" "${tcptuple}.${msgid}" "$timestamp" ${static::tableShortTimeout}
if { ${static::verboseLogs} eq 1 } {
set user_search_active [table keys -count -subtable "${static::tableName}.user.${uid}.searchactive"]
set total_search_active [table keys -count -subtable "${static::tableName}.total.searchactive"]
HSL::send $hsl "$logprefix:$logseq:$timestamp:search:$msgid:$uid:$user_search_active:$total_search_active:$logsuffix"
incr logseq 1
set last_message [clock seconds]
}
set firstMessage 1
set firstMsgTime 0
}
}
TCP::release
TCP::collect
}
when CLIENT_CLOSED {
table delete -subtable "${static::tableName}.user.${uid}.connections" $tcptuple
table delete -subtable "${static::tableName}.connections" $tcptuple
set user_search_active [table keys -count -subtable "${static::tableName}.user.$uid.searchactive"]
set all_search_active [table keys -count -subtable "${static::tableName}.total.searchactive"]
set user_conn_active [table keys -count -subtable "${static::tableName}.user.${uid}.connections"]
set all_conn_active [table keys -count -subtable "${static::tableName}.connections"]
set user_search_total [table lookup -subtable "${static::tableName}.user.${uid}" "searchcount"]
set all_search_total [table lookup -subtable "${static::tableName}.total" "searchcount"]
set user_conn_total [table lookup -subtable "${static::tableName}.user.${uid}" "conncount"]
set all_conn_total [table lookup -subtable "${static::tableName}.total" "conncount"]
set user_msg_count [table lookup -subtable "${static::tableName}.user.${uid}" "msgcount"]
set all_msg_count [table lookup -subtable "${static::tableName}.total" "msgcount"]
set user_search_elapsed [table lookup -subtable "${static::tableName}.user.${uid}" "elapsed"]
set all_search_elapsed [table lookup -subtable "${static::tableName}.total" "elapsed"]
set secs [clock seconds]
set msec [clock clicks -milliseconds]
set base [expr { $secs * 1000 } ]
set fract [expr { $msec - $base }]
if { $fract >= 1000 } {
set diff [expr { $fract / 1000 }]
incr secs $diff
incr fract [expr { -1000 * $diff }]
}
set timestamp "[expr {(($secs % 86400) * 1000) + $fract}]"
HSL::send $hsl "$logprefix:$logseq:$timestamp:close:${uid}:${conn_status}:${user_search_active}:${all_search_active}:${user_conn_active}:${all_conn_active}:${user_conn_total}:${all_conn_total}:${user_search_total}:${conn_search_total}:${all_search_total}:${user_msg_count}:${conn_msg_count}:${all_msg_count}:${user_search_elapsed}:${conn_search_elapsed}:${all_search_elapsed}:$logsuffix"
incr logseq 1
set last_message [clock seconds]
}
when SERVER_CONNECTED {
if { $s_offset != 1 } {
log local0. "$logprefix:$logseq:ERROR: s_offset was $s_offset"
set s_offset 1
}
TCP::collect
}
when SERVER_DATA {
incr connbytesout [TCP::offset]
while { [binary scan [TCP::payload] x${s_offset}B1 long_encoding] } {
if { $long_encoding } {
binary scan [TCP::payload] x${s_offset}xS s_next_response
# Assumes msgid is 1 Byte in length. Which it may not be... Should decode properly...
binary scan [TCP::payload] x[expr {$s_offset +4}]c jump
binary scan [TCP::payload] x[expr {$s_offset +5}]c${jump} msgid
binary scan [TCP::payload] x[expr {$s_offset +5 + $jump}]H2 opcode
incr s_offset $s_next_response
incr s_offset 4
} else {
binary scan [TCP::payload] x${s_offset}c s_next_response
set s_next_response [expr {$s_next_response & 0xff}]
binary scan [TCP::payload] x[expr {$s_offset +2}]c jump
binary scan [TCP::payload] x[expr {$s_offset +3}]c${jump} msgid
binary scan [TCP::payload] x[expr {$s_offset +3 + $jump}]H2 opcode
incr s_offset $s_next_response
incr s_offset 2
}
# 61: ProtocolOp = BindResponse
# 64: ProtocolOp = SearchResult
# 65: ProtocolOp = SearchResult Done
switch $opcode {
61 {
# How to detect success/failure...
# Oohhh... Ugly hack... Check the opcode offset + 4..
set bindResult 0
binary scan [TCP::payload] x[expr {$s_offset + 3 + $jump + 4}]H2 bindResult
if { $bindResult eq 0 } {
# success...
set olduid ${uid}
set uid $binduid
if { !(${olduid} equals ${uid}) } {
# Decrement the counts for the old user. And increment the counts for the new user...
table delete -subtable "${static::tableName}.user.${olduid}.connections" $tcptuple
table set -subtable "${static::tableName}.user.${uid}.connections" $tcptuple ${uid} ${static::tableShortTimeout}
table set -subtable "${static::tableName}.activeUsers" ${uid} ${uid} ${static::tableTimeout}
table incr -subtable "${static::tableName}.user.${uid}" "conncount"
# Need to send a status message from the OLD userid... Otherwise we get a hanging connection in the destination...
set user_search_active [table keys -count -subtable "${static::tableName}.user.$olduid.searchactive"]
set all_search_active [table keys -count -subtable "${static::tableName}.total.searchactive"]
set user_conn_active [table keys -count -subtable "${static::tableName}.user.${olduid}.connections"]
set all_conn_active [table keys -count -subtable "${static::tableName}.connections"]
set user_search_total [table lookup -subtable "${static::tableName}.user.${olduid}" "searchcount"]
set all_search_total [table lookup -subtable "${static::tableName}.total" "searchcount"]
set user_conn_total [table lookup -subtable "${static::tableName}.user.${olduid}" "conncount"]
set all_conn_total [table lookup -subtable "${static::tableName}.total" "conncount"]
set user_msg_count [table lookup -subtable "${static::tableName}.user.${olduid}" "msgcount"]
set all_msg_count [table lookup -subtable "${static::tableName}.total" "msgcount"]
set user_search_elapsed [table lookup -subtable "${static::tableName}.user.${olduid}" "elapsed"]
set all_search_elapsed [table lookup -subtable "${static::tableName}.total" "elapsed"]
set secs [clock seconds]
set msec [clock clicks -milliseconds]
set base [expr { $secs * 1000 } ]
set fract [expr { $msec - $base }]
if { $fract >= 1000 } {
set diff [expr { $fract / 1000 }]
incr secs $diff
incr fract [expr { -1000 * $diff }]
}
set timestamp "[expr {(($secs % 86400) * 1000) + $fract}]"
HSL::send $hsl "$logprefix:$logseq:$timestamp:status:${olduid}:${conn_status}:${user_search_active}:${all_search_active}:${user_conn_active}:${all_conn_active}:${user_conn_total}:${all_conn_total}:${user_search_total}:${conn_search_total}:${all_search_total}:${user_msg_count}:${conn_msg_count}:${all_msg_count}:${user_search_elapsed}:${conn_search_elapsed}:${all_search_elapsed}:$logsuffix"
incr logseq 1
}
} else {
set olduid ${uid}
LB::detach
# Catch any errors
catch { pool [class match -value $uid eq ldapuid_to_pool] }
}
if { ${static::verboseLogs} eq 1 } {
set secs [clock seconds]
set msec [clock clicks -milliseconds]
set base [expr { $secs * 1000 } ]
set fract [expr { $msec - $base }]
if { $fract >= 1000 } {
set diff [expr { $fract / 1000 }]
incr fract [expr { -1000 * $diff }]
}
set timestamp "[expr {(($secs % 86400) * 1000) + $fract}]"
set user_conn_active [table keys -count -subtable "${static::tableName}.user.${uid}.connections"]
set total_conn_count [table keys -count -subtable "${static::tableName}.connections"]
HSL::send $hsl "$logprefix:$logseq:$timestamp:bind:$bindResult:$msgid:$olduid:$uid:$user_conn_active:$total_conn_active:$logsuffix"
incr logseq 1
set last_message [clock seconds]
set conn_status "IDLE"
}
}
64 {
if { $firstMessage eq 1 } {
set secs [clock seconds]
set msec [clock clicks -milliseconds]
set base [expr { $secs * 1000 } ]
set fract [expr { $msec - $base }]
if { $fract >= 1000 } {
set diff [expr { $fract / 1000 }]
incr secs $diff
incr fract [expr { -1000 * $diff }]
}
set timestamp "[expr {(($secs % 86400) * 1000) + $fract}]"
set firstMsgTime [expr {$timestamp - [table lookup -subtable "${static::tableName}.user.$uid.$msgid" "start"]}]
set firstMessage 0
}
set conn_status "SEARCHRESP"
}
65 {
set conn_status "IDLE"
set secs [clock seconds]
set msec [clock clicks -milliseconds]
set base [expr { $secs * 1000 } ]
set fract [expr { $msec - $base }]
if { $fract >= 1000 } {
set diff [expr { $fract / 1000 }]
incr secs $diff
incr fract [expr { -1000 * $diff }]
}
set timestamp "[expr {(($secs % 86400) * 1000) + $fract}]"
table delete -subtable "${static::tableName}.user.$uid.searchactive" "$msgid"
table delete -subtable "${static::tableName}.total.searchactive" "${tcptuple}.${msgid}"
table incr -subtable "${static::tableName}.user.${uid}" "searchcount"
table incr -subtable "${static::tableName}.total" "searchcount"
set searchbytesout [expr {$connbytesout - $searchbytesout}]
set elapsedTime [expr {$timestamp - [table lookup -subtable "${static::tableName}.user.$uid.$msgid" "start"]}]
table incr -subtable "${static::tableName}.user.${uid}" "elapsed" $elapsedTime
table incr -subtable "${static::tableName}.total" "elapsed" $elapsedTime
incr conn_search_elapsed $elapsedTime
incr conn_search_total
if { ${static::verboseLogs} eq 1 } {
set user_search_active [table keys -count -subtable "${static::tableName}.user.$uid.searchactive"]
set total_search_active [table keys -count -subtable "${static::tableName}.total.searchactive"]
HSL::send $hsl "$logprefix:$logseq:$timestamp:searchdone:$msgid:$uid:$searchbytesin:$searchbytesout:$user_search_active:$total_search_active:$user_msg_count:$firstMsgTime:$elapsedTime:$logsuffix"
incr logseq 1
set last_message [clock seconds]
}
}
}
}
set s_offset [expr {$s_offset - [TCP::offset]}]
TCP::release
TCP::collect
}Published Mar 18, 2015
Version 1.0
Hamish
Cirrocumulus
CirrocumulusHamishCirrocumulus
CirrocumulusNo CommentsBe the first to comment