Forum Discussion

John_Zammit_459

Nimbostratus

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

hoolio
Cirrostratus
Mar 14, 2011
Hi John,

What's the error you're seeing?

Aaron

Michael_Yates

Nimbostratus

Mar 14, 2011

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.

hoolio
Cirrostratus
Mar 14, 2011
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
Michael_Yates
Nimbostratus
Mar 14, 2011
Hadn't thought about that.

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

Thanks Aaron!
Michael_Yates
Nimbostratus
Mar 14, 2011
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.

Michael_Yates

Nimbostratus

Mar 14, 2011

 
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

Nimbostratus

Jan 26, 2017

Hi, just fix line 7

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

}

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

}

Cheers, Nicola

Michael_Yates_6

Cirrus

Mar 14, 2011

 
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

Nimbostratus

Jan 26, 2017

Hi, just fix line 7

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

}

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

}

Cheers, Nicola

hoolio
Cirrostratus
Mar 14, 2011
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

Michael_Yates

Nimbostratus

Mar 14, 2011

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)

John_Zammit_459
Nimbostratus
Mar 15, 2011
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