Ultimate irule debug - Capture and investigate

Problem this snippet solves:

I decided to share this Irule for different reasons. When I help our community on devcentral, I regularly see people making recurring requests:

• How do I do to capture the queries header.
• How do I do to capture the response header.
• How do I check the information in the POST Request.
• How do I check response data (body).
• What cypher/protocol I use (SSL/TLS).
• I set up client certificate authentication but I do not know if it works and if I pass my certificate auth.
• I want to retrieve information from my authentication certificate (subject, issuer, …).
• My authenticating by certificate does not work and I get an error of what I have to do.
• I have latencies when dealing with my request. where does the latency come from (F5, server,..).
• I set up sso (kerberos delegation, json post, Form sso). I do not feel that my request is sent to the backend (or the kerberos token).
• Does F5 add information or modify the request/response.
• Which pool member has been selected
• My VS don’t answer (where does the problem come from)
• …

instead of having an Irule for each request why not consolidate everything and provide a compact Irule. this Irule can help you greatly during your investigations and allows you to capture these different items:

How to use this snippet:

you have a function that allows you to activate the desired logs (1 to activate and 0 to disable) as describe below:

array set app_arrway_referer {
    client_dest_ip_port 1
    client_cert  1
    http_request 1
    http_request_release 1
    http_request_payload 0
    http_lb_selected 1
    http_response 0
    http_response_release 0
    http_response_payload 0
    http_time_process 0
}

the posted logs will be preceded by a UID which will allow you to follow from the beginning to the end of the process of your request / answer. you can for example make a grep on the log to follow the complete process (request / answer).

the UID is generated in the following way: `set uid [string range [AES::key 256] 15 23]

client_dest_ip_port:

this section will allow you to see source IP/Port and destination IP/Port.

<CLIENT_ACCEPTED>:  ----------- client_dest_ip_port -----------
<CLIENT_ACCEPTED>: uid: 382951fe9 - Client IP Src: 10.20.30.4:60419
<CLIENT_ACCEPTED>: uid: 382951fe9 - Client IP Dest:192.168.30.45:443
<CLIENT_ACCEPTED>:  ----------- client_dest_ip_port -----------

client_cert:

this section will allow you to check the result code for peer certificate verification ( and also if you have provide a certificate auth). moreover you will be able to recover the information of your authentication certficat (issuer, subject, …).

if your authentication certificate that you provid is not valid an error message will be returned (ex: certificate chain too long, invalid CA certificate, …). all errors are listed in the link below:

https://devcentral.f5.com/wiki/iRules.SSL__verify_result.ashx

<HTTP_REQUEST>:  ----------- client_cert -----------
<HTTP_REQUEST>: uid: 382951fe9 - cert number: 0
<HTTP_REQUEST>: uid: 382951fe9 - subject: OU=myOu, CN=youssef
<HTTP_REQUEST>: uid: 382951fe9 - Issuer Info: DC=com, DC=domain, CN=MobIssuer
<HTTP_REQUEST>: uid: 382951fe9 - cert serial: 22:00:30:5c:de:dd:ec:23:6e:b5:e6:77:bj:01:00:00:22:3c:dc
<HTTP_REQUEST>:  ----------- client_cert -----------

OR

<HTTP_REQUEST>:  ----------- client_cert -----------
<HTTP_REQUEST>: uid: 382951fe9 - No client certificate provided
<HTTP_REQUEST>:  ----------- client_cert -----------

http_request:

This section allow you to retrieve the complete client HTTP request headers (that is, the method, URI, version, and all headers). I also added the protocol, the ciphers and the name of the vs used.

<HTTP_REQUEST>:  ----------- http_request -----------
<HTTP_REQUEST>: uid: 382951fe9 - protocol: https
<HTTP_REQUEST>: uid: 382951fe9 - cipher name: ECDHE-RSA-AES128-GCM-SHA256
<HTTP_REQUEST>: uid: 382951fe9 - cipher version: TLSv1.2
<HTTP_REQUEST>: uid: 382951fe9 - VS Name: /Common/vs-myapp-443
<HTTP_REQUEST>: uid: 382951fe9 - Request: POST myapp.mydomain.com/browser-management/users/552462/playlist/play/api
<HTTP_REQUEST>: uid: 382951fe9 - Host: myapp.mydomain.com
<HTTP_REQUEST>: uid: 382951fe9 - Connection: keep-alive
<HTTP_REQUEST>: uid: 382951fe9 - Content-Length: 290
<HTTP_REQUEST>: uid: 382951fe9 - Accept: application/json, text/javascript, */*; q=0.01
<HTTP_REQUEST>: uid: 382951fe9 - X-Requested-With: XMLHttpRequest
<HTTP_REQUEST>: uid: 382951fe9 - User-Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.106 Safari/537.36
<HTTP_REQUEST>: uid: 382951fe9 - Referer: https://myapp.mydomain.com/
<HTTP_REQUEST>: uid: 382951fe9 - Accept-Encoding: gzip, deflate, sdch, br
<HTTP_REQUEST>: uid: 382951fe9 - Accept-Language: en-US,en;q=0.8
<HTTP_REQUEST>: uid: 382951fe9 - Cookie: RLT=SKjpfdkFDKjkufd976HJhldds=; secureauth=true; STT="LKJSDKJpjslkdjslkjKJSHjfdskjhoLHkjh78dshjhd980szKJH"; ASP.SessionId=dsliulpoiukj908798dsjkh
<HTTP_REQUEST>: uid: 382951fe9 - X-Forwarded-For: 10.10.10.22
<HTTP_REQUEST>:  ----------- http_request -----------

http_request_release:

This section triggered when the system is about to release HTTP data on the serverside of the connection. This event is triggered after modules process the HTTP request. So it will allow you to check request after F5 process. suppose that you have put APM with SSO kerberos, you will be able to see the kerberos token insert by F5. Or XFF insert by HTTP profile…

<HTTP_REQUEST_RELEASE>:   ----------- http_request_release -----------
<HTTP_REQUEST_RELEASE>: uid: 382951fe9 - VS Name: /Common/vs-myapp-443
<HTTP_REQUEST_RELEASE>: uid: 382951fe9 - Request: GET myapp.mydomain.com/browser-management/users/552462/playlist/play/api
<HTTP_REQUEST_RELEASE>: uid: 382951fe9 - Host: myapp.mydomain.com
<HTTP_REQUEST_RELEASE>: uid: 382951fe9 - Connection: keep-alive
<HTTP_REQUEST_RELEASE>: uid: 382951fe9 - Accept: application/json, text/javascript, */*; q=0.01
<HTTP_REQUEST_RELEASE>: uid: 382951fe9 - X-Requested-With: XMLHttpRequest
<HTTP_REQUEST_RELEASE>: uid: 382951fe9 - User-Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.106 Safari/537.36
<HTTP_REQUEST_RELEASE>: uid: 382951fe9 - Referer: https://myapp.mydomain.com/
<HTTP_REQUEST_RELEASE>: uid: 382951fe9 - Accept-Encoding: gzip, deflate, sdch, br
<HTTP_REQUEST_RELEASE>: uid: 382951fe9 - Accept-Language: en-US,en;q=0.8
<HTTP_REQUEST_RELEASE>: uid: 382951fe9 - Cookie: RLT=SKjpfdkFDKjkufd976HJhldds=; secureauth=true; STT="LKJSDKJpjslkdjslkjKJSHjfdskjhoLHkjh78dshjhd980szKJH"; ASP.SessionId=dsliulpoiukj908798dsjkh
<HTTP_REQUEST_RELEASE>: uid: 382951fe9 - X-Forwarded-For: 10.10.10.22
<HTTP_REQUEST_RELEASE>:   ----------- http_request_release -----------

http_request_payload:

This section will allow you to retrieve the HTTP request body.

<HTTP_REQUEST>:  ----------- http_request_payload -----------
<HTTP_REQUEST>: uid: 382951fe9 - Content-Length header null in request If GET or POST withtout content)
<HTTP_REQUEST>:  ----------- http_request_payload -----------

or

<HTTP_REQUEST>:  ----------- http_request_payload -----------
<HTTP_REQUEST>: uid: 382951fe9 - post payload: {  id: 24,  retrive: 'identity',  service: 'IT'}
<HTTP_REQUEST>:  ----------- http_request_payload -----------

http_lb_selected

This section will allow you to you to see which pool member has been selected. Once the pool memeber has been selected, you will not see this logs again until another load balancing decision will be made.

If you want to see the selected pool memeber for each request you can see this information in "http_response".

<HTTP_REQUEST>:  ----------- http_lb_selected -----------
<LB_SELECTED>: uid: 382951fe9 - pool member IP: /Common/pool-name 10.22.33.54 443
<HTTP_REQUEST>:  ----------- http_lb_selected -----------

http_response:

This section will allow you to retrieve the response status and header lines from the server response.

You can also see which pool member has been selected.

<HTTP_RESPONSE>:   ----------- http_response -----------
<HTTP_RESPONSE>: uid: 382951fe9 - status: 200
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - pool member IP: /Common/pool-name 10.22.33.54 443
<HTTP_RESPONSE>: uid: 382951fe9 - Cache-Control: no-cache
<HTTP_RESPONSE>: uid: 382951fe9 - Pragma: no-cache
<HTTP_RESPONSE>: uid: 382951fe9 - Content-Type: application/json; charset=utf-8
<HTTP_RESPONSE>: uid: 382951fe9 - Expires: -1
<HTTP_RESPONSE>: uid: 382951fe9 - Server: Microsoft-IIS/8.5
<HTTP_RESPONSE>: uid: 382951fe9 - X-Powered-By: ASP.NET
<HTTP_RESPONSE>: uid: 382951fe9 - Date: Fri, 28 Oct 2018 06:46:59 GMT
<HTTP_RESPONSE>: uid: 382951fe9 - Content-Length: 302
<HTTP_RESPONSE>:   ----------- http_response -----------

http_response_release:

This section triggered when the system is about to release HTTP data on the clientside of the connection. This event is triggered after modules process the HTTP response. you can make sure that the answer has not been altering after the f5 process.

You can also see which pool member has been selected.

<HTTP_RESPONSE_RELEASE>:   ----------- http_response_release -----------
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - status: 200
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - pool member IP: /Common/pool-name 10.22.33.54 443
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - Cache-Control: no-cache
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - Pragma: no-cache
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - Content-Type: application/json; charset=utf-8
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - Expires: -1
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - Server: Microsoft-IIS/8.5
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - X-Powered-By: ASP.NET
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - Date: Fri, 28 Oct 2018 06:46:59 GMT
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - Content-Length: 302
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - Strict-Transport-Security: max-age=16070400; includeSubDomains
<HTTP_RESPONSE_RELEASE>:   ----------- http_response_release -----------

http_response_payload:

This section will allow you to Collects an amount of HTTP body data that you specify.

<HTTP_RESPONSE_DATA>:   ----------- http_response_payload -----------
<HTTP_RESPONSE_DATA>: uid: 382951fe9 - Response (Body) payload: {   "username" : "youssef",   "genre" : "unknown",   "validation-factors" : {      "validationFactors" : [         {    "name" : "remote_address",  "value" : "127.0.0.1"         }      ]   }}
<HTTP_RESPONSE_DATA>:   ----------- http_response_payload -----------

http_time_process:

this part will allow you to put back information which can be useful to you to target the latency problematic. it is clear that it is not precise and that f5 offers other tools for that. but you will be able to quickly see which elements take the most time to be processed. you will be able to see how long f5 takes to process the request, the response and how long the backend server takes time to respond.

<HTTP_RESPONSE_RELEASE>:   ----------- http_time_process -----------
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - Time to request (F5 request time) = 5 (ms)
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - Time to response (F5 response time) = 0 (ms)
<HTTP_RESPONSE_RELEASE>: uid: 382951fe9 - Time to server (server backend process time) = 4 (ms)
<HTTP_RESPONSE_RELEASE>:   ----------- http_time_process -----------

Code :

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. " "
}
}

Tested this on version:

13.0