View Categories

iRule to Log Activity

8 min read

This iRule helps log activity on your Virtual Server

TCL
when HTTP_REQUEST {
set client [IP::client_addr]:[TCP::client_port]
set url [HTTP::header Host][HTTP::uri]
}

when HTTP_RESPONSE
{
set node [IP::server_addr]:[TCP::server_port]
set nodeResp [HTTP::status]

# log connection info
log local0.info "Client: $client request URL is $url and accessed Virtual Server Name [virtual]. Selected pool server is [LB::server]. Node $node responded with $nodeResp"
}

Output looks like this

Feb 26 10:09:08 usfnt2slbtst01.mwg.corp info tmm1[19474]: Rule /Common/irule.logging <HTTP_RESPONSE>: Client: 10.29.39.49:51631 request URL is apptst73.mwg.corp/ and accessed Virtual Server Name /Common/apptst73.mwg.corp. Selected pool server is /Common/pool.apptst.mwg.corp 10.11.18.92 80. Node 10.11.18.92:80 responded with 200

Here is another version of the above

TCL
when HTTP_REQUEST {
set uri [HTTP::uri]
log local0. "Requested hostname: [HTTP::host] & URI : $uri"
}
when SERVER_CONNECTED {
log local0. "client: [IP::client_addr]:[TCP::client_port] -> VIP: [clientside {IP::local_addr}]:[clientside {TCP::local_port}] -> Node: [IP::server_addr]:[TCP::server_port]"
#log local0. "Apache Server connected [IP::server_addr]:[TCP::server_port]"
}
when HTTP_RESPONSE {
log local0. "Response code [HTTP::status] for URI: $uri"
}

So when you query a Virtual Server you will see in /var/log/ltm

Feb 26 09:56:36 usfnt2slbtst01.mwg.corp info tmm[19474]: Rule /Common/irule.tshoot.logging <HTTP_REQUEST>: Requested hostname: apptst73.mwg.corp & URI : /
Feb 26 09:56:36 usfnt2slbtst01.mwg.corp info tmm[19474]: Rule /Common/irule.tshoot.logging <SERVER_CONNECTED>: client: 10.29.39.49:65462 -> VIP: 10.11.33.73:80 -> Node: 10.11.18.93:80
Feb 26 09:56:36 usfnt2slbtst01.mwg.corp info tmm[19474]: Rule /Common/irule.tshoot.logging <HTTP_RESPONSE>: Response code 200 for URI: /

Now you can go for more serious logging applying the following iRule to your Virtual Server

TCL
when CLIENT_ACCEPTED {

# set a unique id for transaction
set uid [string range [AES::key 256] 15 23]

# set what's you want to retrieve 0 or 1
array set app_arrway_referer {
client_dest_ip_port  1
client_cert  1
http_request 1
http_request_release 1
http_request_payload 1
http_lb_selected 1
http_response 1
http_response_release 1
http_response_payload 1
http_time_process 1
}

if {$app_arrway_referer(client_dest_ip_port)} {
log local0. " ----------- client_dest_ip_port ----------- "
clientside {
    log local0. "uid: $uid - Client IP Src: [IP::client_addr]:[TCP::client_port]"
}
log local0. "uid: $uid - Client IP Dest:[IP::local_addr]:[TCP::local_port]"
log local0. " ----------- client_dest_ip_port ----------- "
log local0. "  "
}
}

when HTTP_REQUEST {

set http_request_time [clock clicks -milliseconds]

# Triggered when the system receives a certificate message from the client. The message may contain zero or more certificates.
if {$app_arrway_referer(client_cert)} {
log local0. " ----------- client_cert ----------- "
# SSL::cert count - Returns the total number of certificates that the peer has offered.
if {[SSL::cert count] > 0}{
# Check if there was no error in validating the client cert against LTM's server cert
if { [SSL::verify_result] == 0 }{
for {set i 0} {$i < [SSL::cert count]} {incr i}{
           log local0. "uid: $uid - cert number: $i"
           log local0. "uid: $uid - subject: [X509::subject [SSL::cert $i]]"
           log local0. "uid: $uid - Issuer Info: [X509::issuer [SSL::cert $i]]"
           log local0. "uid: $uid - cert serial: [X509::serial_number [SSL::cert $i]]"
}
} else {
# https://devcentral.f5.com/s/wiki/iRules.SSL__verify_result.ashx (OpenSSL verify result codes)
log local0. "uid: $uid - Cert Info: [X509::verify_cert_error_string [SSL::verify_result]]"
}
} else {
log local0. "uid: $uid - No client certificate provided"
}
log local0. " ----------- client_cert ----------- "
log local0. "  "
}

if {$app_arrway_referer(http_request)} {
log local0. " ----------- http_request ----------- "
if { [PROFILE::exists clientssl] == 1 } {
log local0. "uid: $uid - protocol: https"
log local0. "uid: $uid - cipher name: [SSL::cipher name]"
log local0. "uid: $uid - cipher version: [SSL::cipher version]"
}

log local0. "uid: $uid - VS Name: [virtual]"
log local0. "uid: $uid - Request: [HTTP::method] [HTTP::host][HTTP::uri]"

foreach aHeader [HTTP::header names] {
log local0. "uid: $uid - $aHeader: [HTTP::header value $aHeader]"
}
log local0. " ----------- http_request ----------- "
log local0. "  "
}

set collect_length_request [HTTP::header value "Content-Length"]
set contentlength 1

if {$app_arrway_referer(http_request_payload)} {
if { [catch {
if { $collect_length_request > 0 && $collect_length_request < 1048577 } {
set collect_length $collect_length_request
} else {
set collect_length 1048576
} 
if { $collect_length > 0 } {
HTTP::collect $collect_length_request
set contentlength 1
}
}] } {

# no DATA in POST Request
log local0. " ----------- http_request_payload ----------- "
log local0. "uid: $uid - Content-Length header null in request"
log local0. " ----------- http_request_payload ----------- "
log local0. " "
set contentlength 0
}
}
}

when HTTP_REQUEST_DATA {

if {$app_arrway_referer(http_request_payload)} {
log local0. " ----------- http_request_payload ----------- "
if {$contentlength} {
set postpayload [HTTP::payload]
log local0. "uid: $uid - post payload: $postpayload"
#HTTP::release
}
log local0. "  ----------- http_request_payload ----------- "
log local0. " "
}
}

when HTTP_REQUEST_RELEASE {

if {$app_arrway_referer(http_request_release)} {
log local0. "  ----------- http_request_release ----------- "
if { [PROFILE::exists clientssl] == 1 } {
log local0. "uid: $uid - cipher protocol: https"
log local0. "uid: $uid - cipher name: [SSL::cipher name]"
log local0. "uid: $uid - cipher version: [SSL::cipher version]"
}

log local0. "uid: $uid - VS Name: [virtual]"
log local0. "uid: $uid - Request: [HTTP::method] [HTTP::host][HTTP::uri]"

foreach aHeader [HTTP::header names] {
log local0. "uid: $uid - $aHeader: [HTTP::header value $aHeader]"
}

log local0. "  ----------- http_request_release ----------- "
log local0. " "
}
set http_request_time_release [clock clicks -milliseconds]
}

when LB_SELECTED {
if {$app_arrway_referer(http_lb_selected)} {
log local0. "  ----------- http_lb_selected ----------- "
log local0. "uid: $uid - pool member IP: [LB::server]"
log local0. "  ----------- http_lb_selected ----------- "
log local0. " "
}
}

when HTTP_RESPONSE {

set http_response_time [clock clicks -milliseconds]
set content_length [HTTP::header "Content-Length"]

if {$app_arrway_referer(http_response)} {
log local0. "  ----------- http_response ----------- "
log local0. "uid: $uid - status: [HTTP::status]"
log local0. "uid: $uid - pool member IP: [LB::server]"
foreach aHeader [HTTP::header names] {
log local0. "uid: $uid - $aHeader: [HTTP::header value $aHeader]"
}

log local0. "  ----------- http_response ----------- "
log local0. " "
}

if {$app_arrway_referer(http_response_payload)} {
if { $content_length > 0 && $content_length < 1048577 } {
set collect_length $content_length
} else {
set collect_length 1048576
} 

if { $collect_length > 0 } {
HTTP::collect $collect_length
}
}
}

when HTTP_RESPONSE_DATA {

if {$app_arrway_referer(http_response_payload)} {
log local0. "  ----------- http_response_payload ----------- "
set payload [HTTP::payload]  
log local0. "uid: $uid - Response (Body) payload: $payload"
log local0. "  ----------- http_response_payload ----------- "
log local0. " "
}
}

when HTTP_RESPONSE_RELEASE {

set http_response_time_release [clock clicks -milliseconds]

if {$app_arrway_referer(http_response_release)} {
log local0. "  ----------- http_response_release ----------- "
log local0. "uid: $uid - status: [HTTP::status]"
log local0. "uid: $uid - pool member IP: [LB::server]"
foreach aHeader [HTTP::header names] {
log local0. "uid: $uid - $aHeader: [HTTP::header value $aHeader]"
}
log local0. "  ----------- http_response_release ----------- "
log local0. " "
}

if {$app_arrway_referer(http_time_process)} {
log local0. "  ----------- http_time_process ----------- "
log local0.info "uid: $uid - Time to request  (F5 request time) = [expr $http_request_time - $http_request_time_release] (ms)"
log local0.info "uid: $uid - Time to response (F5 response time) = [expr $http_response_time - $http_response_time_release] (ms)"
log local0.info "uid: $uid - Time to server (server backend process time) = [expr $http_request_time_release - $http_response_time] (ms)"
log local0. "  ----------- http_time_process ----------- "
log local0. " "
}
}

Same output using the above iRule

Feb 26 10:16:46 usfnt2slbtst01.mwg.corp info tmm1[19474]: Rule /Common/irule.ultimate.logging <CLIENT_ACCEPTED>:  ----------- client_dest_ip_port -----------
Feb 26 10:16:46 usfnt2slbtst01.mwg.corp info tmm1[19474]: Rule /Common/irule.ultimate.logging <CLIENT_ACCEPTED>: uid: 48b2e6810 - Client IP Src: 10.29.39.49:53077
Feb 26 10:16:46 usfnt2slbtst01.mwg.corp info tmm1[19474]: Rule /Common/irule.ultimate.logging <CLIENT_ACCEPTED>: uid: 48b2e6810 - Client IP Dest:10.11.33.73:80
Feb 26 10:16:46 usfnt2slbtst01.mwg.corp info tmm1[19474]: Rule /Common/irule.ultimate.logging <CLIENT_ACCEPTED>:  ----------- client_dest_ip_port -----------
Feb 26 10:16:46 usfnt2slbtst01.mwg.corp info tmm1[19474]: Rule /Common/irule.ultimate.logging <CLIENT_ACCEPTED>:
Feb 26 10:16:46 usfnt2slbtst01.mwg.corp info tmm1[19474]: Rule /Common/irule.ultimate.logging <HTTP_REQUEST>:  ----------- client_cert -----------
Feb 26 10:16:46 usfnt2slbtst01.mwg.corp err tmm1[19474]: 01220001:3: TCL error: /Common/irule.ultimate.logging <HTTP_REQUEST> - SSL hudfilter not reached or not in chain (line 1)     invoked from within "SSL::cert count"

In case you are trying to capture a tcp app instead of http the following iRule may be fit your needs more

TCL
when CLIENT_ACCEPTED {
      set client [IP::remote_addr]:[TCP::remote_port]
      set vip [IP::local_addr]:[TCP::local_port]
   }
when SERVER_CONNECTED {
      #set hsl [HSL::open -proto TCP -pool pool.HSLogging.splunk]
      set ldap [IP::remote_addr]:[TCP::remote_port]
      set snat [IP::local_addr]:[TCP::local_port]
	  log local0. "Client-side connection, $client -> $vip, Server-side connection, $snat -> $ldap"
	  #HSL::send $hsl "<190>Client-side connection, $client -> $vip, Server-side connection, $snat -> $ldap\r\n"
   }

A sample output

Feb 26 10:14:41 usfnt2slbtst01.mwg.corp info tmm1[19474]: Rule /Common/irule.tcp.logging <SERVER_CONNECTED>: Client-side connection, 10.29.39.49:52667 -> 10.11.33.73:80, Server-side connection, 10.11.33.4:52667 -> 10.11.18.91:80
Protected By
Shield Security