Forum Discussion
John_Zammit_459
Nimbostratus
NimbostratusiRule 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
hooleylistCirrostratus
Hi John,
What's the error you're seeing?
Aaron
Michael_YatesI'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.- hooleylistThanks 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_YatesHadn't thought about that.
The more efficient the better, especially in an iRule designed to measure session and request response time.
Thanks Aaron! - Michael_YatesI 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
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_DTHi, 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
Michael_Yates_6Cirrus
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
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
- hooleylistThat 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_YatesThese 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_459Thanks 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