Learn F5 Technologies, Get Answers & Share Community Solutions Join DevCentral

Filter by:
  • Solution
  • Technology
code share

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_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_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>: uid: 382951fe9 - pool member IP: 192.168.3.6:80
<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: 192.168.3.6:80
<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 -----------
Tested on Version:
13.0
Comments on this Snippet
Comment made 6 days ago by nico73 77

Well done Youssef !

0
Comment made 6 days ago by Philippe Logean 1

Excellent! Thanks Youssef!

0
Comment made 5 days ago by JTI 2357

Amazing !

0
Comment made 3 days ago by Niels van Sluis 2591

Nice! Thanks for sharing Youssef.

0
Comment made 3 days ago by michael molho 80

Well done man !

0
Comment made 2 days ago by Lucern 0

It works great, except when I added it to one of my VIPs I was no longer able to access that VIP :(

Fortunately it was a test VIP of sorts.

Here's something that popped in the log which might be related:

err tmm3[31788]: 01220001:3: TCL error: /Common/irule_debug_logging - command serverside error:server side connection does not exist. (line 56) invoked from within "serverside { log local0. "uid: $uid - pool member IP:2 [IP::remote_addr]:[TCP::remote_port]" }"

Do you think there's something that could be tweaked so that doesn't happen, or is that just how it works? Still useful though, just got to be careful when/where you enable it!

Oh, I'm running 12.x

Thanks!

0
Comment made 2 days ago by youssef 3499

Hi Lucern,

In fact Some person notify me that in some case / version (sometimes when we don't set a backend) we can have this kind of problem. I advise you for the moment to disable the following lines

#serverside {
#   log local0. "uid: $uid - pool member IP: [IP::remote_addr]:[TCP::remote_port]"
#}

In 2 event:

when HTTP_RESPONSE

and

when HTTP_RESPONSE_RELEASE

I will fix the problem tomorrow and keep you in touch (and add caught function in order to avoir TCL error).

I think it was due to serverside command, because of server side connection does not exist... and I reassure you it's not normal behavior. When it will be corrected you will be able to use it without problem.

regards,

1