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

Was this article helpful?

No CommentsBe the first to comment