Forum Discussion

John_Zammit_459's avatar
John_Zammit_459
Icon for Nimbostratus rankNimbostratus
Mar 14, 2011

iRule logging HTTP/SSL session times

I'm trying to get a script working to log HTTP session times

 

 

script I'm running is as follows

 

 

 

 

 

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

 

 

 

when CLIENT_ACCEPTED {

 

Get time for start of TCP connection in milleseconds

 

set tcp_start_time [clock clicks -milliseconds]

 

}

 

when HTTP_REQUEST {

 

Get time for start of HTTP request

 

if {[HTTP::uri] ends_with ".html"} {

 

set url [HTTP::host][HTTP::uri]

 

set content_type [HTTP::header Content-Type]

 

set http_request_time [clock clicks -milliseconds]

 

} elseif {[HTTP::uri] ends_with ".htm"} {

 

set url [HTTP::host][HTTP::uri]

 

set content_type [HTTP::header Content-Type]

 

set http_request_time [clock clicks -milliseconds]

 

} elseif {[HTTP::uri] ends_with ".cgi"} {

 

set url [HTTP::host][HTTP::uri]

 

set content_type [HTTP::header Content-Type]

 

set http_request_time [clock clicks -milliseconds]

 

}

 

log "URL:$url "

 

}

 

when HTTP_RESPONSE {

 

Get time for end of HTTP request

 

set http_response_time [clock clicks -milliseconds]

 

set node [IP::server_addr]:[TCP::server_port]

 

}

 

 

 

when CLIENT_CLOSED {

 

set close_time [clock clicks -milliseconds]

 

set http_time [expr $close_time - $http_response_time]

 

set tcp_time [expr $close_time - $tcp_start_time]

 

 

 

Log the end time of the TCP connection

 

if {![info exists $url]} {

 

log "Content:$content_type URL:$url Client:[IP::client_addr] VIP:[IP::local_addr]:[TCP::local_port] Node:$node (HTTP response time $http_time ms) (TCP open for: $tcp_time ms) "

 

}

 

}

 

 

 

 

 

 

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

 

 

 

My issue is that the script keeps spitting out errors in the log

 

 

 

Any help is appreciated

 

 

 

regards

 

 

 

John Zammit

 

12 Replies

  • I've had to create a similar iRule to measure the entire Client Connection as well as the individual HTTP Requests made by that client in their connection.

    This will log it all to the LTM Log and is based on the Client IP Address (There are several options that are disabled, so you enable/disable options to get what you want):

     
    when CLIENT_ACCEPTED {
    Get time for start of TCP Connection in milliseconds
    set tcp_start_time [clock clicks -milliseconds]
    
    Log the start of a new HTTP Request
    set local0. "(TCP Connection - Start) [IP::client_addr]:[TCP::client_port] to [IP::local_addr]:[TCP::local_port]"
    }
    when HTTP_REQUEST {
    Get time for start of HTTP Request in milliseconds
    set http_request_time [clock clicks -milliseconds]
    
    Log the start of new HTTP Request with URI
    set LogString "Client [IP::client_addr]:[TCP::client_port] -> [HTTP::uri]"
    
    Log the start of new HTTP Request without URI
    set LogString "Client [IP::client_addr]:[TCP::client_port]"
    
    log local0. "(HTTP - Request) $LogString"
    }
    when HTTP_RESPONSE {
    Recieved the response headers from the server.  Log the pool name, IP and port, status and time delta
    Detailed Log Output - Client Communication - Pool Information - Status Messages - and Communication Delta
    log local0. "(Response) $LogString - pool info: [LB::server] - status: [HTTP::status] (Request / Response Delta:  [expr [clock clicks -milliseconds] - $http_request_time]ms)"
    
    Response and Communication Delta
    log local0. "(HTTP - Response) $LogString - (Request / Response Delta:  [expr [clock clicks -milliseconds] - $http_request_time]ms)"
    }
    when CLIENT_CLOSED {
    Log the end time of the TCP Connection
    Detailed Connection Closed - Transaction can be located by using the Client IP Address and Port to Load Balancer IP Address and Port for additional matching parameters.
    log local0. "(TCP Connection - Close) $LogString [IP::client_addr]:[TCP::client_port] to [IP::local_addr]:[TCP::local_port] (Connection Open for:  [expr [clock clicks -milliseconds] - $tcp_start_time]ms)"
    }
    

    Hope this helps.
  • Thanks for that Michael. Note that you can save some CPU cycles by wrapping expr operands in curly braces (which prevents double substitution of the variables):

     

     

    [expr [clock clicks -milliseconds] - $http_request_time]

     

    ->

     

    [expr {[clock clicks -milliseconds] - $http_request_time}]

     

     

    [expr [clock clicks -milliseconds] - $tcp_start_time]]

     

    ->

     

    [expr {[clock clicks -milliseconds] - $tcp_start_time}]]

     

     

    Aaron
  • Hadn't thought about that.

     

     

    The more efficient the better, especially in an iRule designed to measure session and request response time.

     

     

    Thanks Aaron!
  • I made Aaron's suggested modifications and retested the functionaltiy. There was an error in the original. This works fine.

     

     

    Thanks again for the suggestion Aaron.

     

     

    Code below. Additional errors corrected.
  •  
    when CLIENT_ACCEPTED {
    Get time for start of TCP Connection in milliseconds
    set tcp_start_time [clock clicks -milliseconds]
    
    Log the start of a new HTTP Request
    set local0. "(TCP Connection - Start) [IP::client_addr]:[TCP::client_port] to [IP::local_addr]:[TCP::local_port]"
    }
    when HTTP_REQUEST {
    Get time for start of HTTP Request in milliseconds
    set http_request_time [clock clicks -milliseconds]
    
    Log the start of new HTTP Request with URI
    set LogString "Client [IP::client_addr]:[TCP::client_port] -> [HTTP::uri]"
    
    Log the start of new HTTP Request without URI
    set LogString "Client [IP::client_addr]:[TCP::client_port]"
    
    log local0. "(HTTP - Request) $LogString"
    }
    when HTTP_RESPONSE {
    Recieved the response headers from the server.  Log the pool name, IP and port, status and time delta
    Detailed Log Output - Client Communication - Pool Information - Status Messages - and Communication Delta
    log local0. "(Response) $LogString - pool info: [LB::server] - status: [HTTP::status] (Request / Response Delta:  [expr {[clock clicks -milliseconds] - $http_request_time}]ms)"
    
    Response and Communication Delta
    log local0. "(HTTP - Response) $LogString - (Request / Response Delta:  [expr {[clock clicks -milliseconds] - $http_request_time}]ms)"
    }
    when CLIENT_CLOSED {
    Log the end time of the TCP Connection
    Detailed Connection Closed - Transaction can be located by using the Client IP Address and Port to Load Balancer IP Address and Port for additional matching parameters.
    log local0. "(TCP Connection - Close) Client [IP::client_addr]:[TCP::client_port] to [IP::local_addr]:[TCP::local_port] (Connection Open for:  [expr {[clock clicks -milliseconds] - $tcp_start_time}]ms)"
    }
    
    • Nicola_DT's avatar
      Nicola_DT
      Icon for Nimbostratus rankNimbostratus

      Hi, just fix line 7

      set local0. "(TCP Connection - Start) [IP::client_addr]:[TCP::client_port] to [IP::local_addr]:[TCP::local_port]"
      

      }

      to

      log local0. "(TCP Connection - Start) [IP::client_addr]:[TCP::client_port] to [IP::local_addr]:[TCP::local_port]"
      

      }

      Cheers, Nicola

  •  
    when CLIENT_ACCEPTED {
    Get time for start of TCP Connection in milliseconds
    set tcp_start_time [clock clicks -milliseconds]
    
    Log the start of a new HTTP Request
    set local0. "(TCP Connection - Start) [IP::client_addr]:[TCP::client_port] to [IP::local_addr]:[TCP::local_port]"
    }
    when HTTP_REQUEST {
    Get time for start of HTTP Request in milliseconds
    set http_request_time [clock clicks -milliseconds]
    
    Log the start of new HTTP Request with URI
    set LogString "Client [IP::client_addr]:[TCP::client_port] -> [HTTP::uri]"
    
    Log the start of new HTTP Request without URI
    set LogString "Client [IP::client_addr]:[TCP::client_port]"
    
    log local0. "(HTTP - Request) $LogString"
    }
    when HTTP_RESPONSE {
    Recieved the response headers from the server.  Log the pool name, IP and port, status and time delta
    Detailed Log Output - Client Communication - Pool Information - Status Messages - and Communication Delta
    log local0. "(Response) $LogString - pool info: [LB::server] - status: [HTTP::status] (Request / Response Delta:  [expr {[clock clicks -milliseconds] - $http_request_time}]ms)"
    
    Response and Communication Delta
    log local0. "(HTTP - Response) $LogString - (Request / Response Delta:  [expr {[clock clicks -milliseconds] - $http_request_time}]ms)"
    }
    when CLIENT_CLOSED {
    Log the end time of the TCP Connection
    Detailed Connection Closed - Transaction can be located by using the Client IP Address and Port to Load Balancer IP Address and Port for additional matching parameters.
    log local0. "(TCP Connection - Close) Client [IP::client_addr]:[TCP::client_port] to [IP::local_addr]:[TCP::local_port] (Connection Open for:  [expr {[clock clicks -milliseconds] - $tcp_start_time}]ms)"
    }
    
    • Nicola_DT's avatar
      Nicola_DT
      Icon for Nimbostratus rankNimbostratus

      Hi, just fix line 7

      set local0. "(TCP Connection - Start) [IP::client_addr]:[TCP::client_port] to [IP::local_addr]:[TCP::local_port]"
      

      }

      to

      log local0. "(TCP Connection - Start) [IP::client_addr]:[TCP::client_port] to [IP::local_addr]:[TCP::local_port]"
      

      }

      Cheers, Nicola

  • That looks better :). Can you post sample log output so others can see what the logging looks like for a request/response and connection?

     

     

    Thanks, Aaron
  • These are a few lines of the log output. They have been sanitized, but it give a basic view of the type of information that the above iRule will provide by default.

    It can easily be made to capture more or less information as needed.

    Pay close attention to the client IP Address and Port. As you can see below, there are two requests from the same IP Address but on different ports (this is because the IP Address is behind a SNAT, so these are two different user requests on the same Virtual Server).

     
    Mar 14 15:54:27 local/tmm info tmm[4903]: Rule irule.name : (HTTP - Request) Client 192.168.1.100:15251 -> /website/common/scripts/confirmit.js
    Mar 14 15:54:27 local/tmm info tmm[4903]: Rule irule.name : (HTTP - Response) Client 192.168.1.100:15251 -> /website/common/scripts/confirmit.js - (Request / Response Delta:  7ms)
    Mar 14 15:54:27 local/tmm info tmm[4903]: Rule irule.name : (HTTP - Request) Client 192.168.1.100:15252 -> /website/Style/Scripts/mbox.js
    Mar 14 15:54:27 local/tmm info tmm[4903]: Rule irule.name : (HTTP - Response) Client 192.168.1.100:15252 -> /website/Style/Scripts/mbox.js - (Request / Response Delta:  4ms)
    Mar 14 15:54:27 local/tmm info tmm[4903]: Rule irule.name : (TCP Connection - Close) Client 192.168.1.100:54635 to 192.168.1.101:80 (Connection Open for:  2068ms)
    
  • Thanks for the replies so far am going to test out aarons script first thing in the morning

     

    The error I was receiving was a variable not found... could have been some typo in my script but really couldn't find anything wrong with it