Procedure based HTML Debug-Page with elapsed time performance data
Problem this snippet solves: The outlined iRule contains a debugging procedure that can become an useful tool while developing HTTP related iRules. The debug [proc] can be plugged into existing iRules on a position of your choice, to break the iRule execution, collect various informations and display them in a easy to use HTML page. The debug [proc] is also able to meassure the elapsed time between independent code positions to get a first impression which coding technique performs better than the other. The debug [proc] will store the collected performance data of every single execution in a scaling window session [table] for statistical calculation. It would output statistical information in a raw format and a #% cuttoff style to filter outliers. Cheers, Kai How to use this snippet: Procedure functionality To store debugging information use.. set debug(ORIG_HOST) "somedata [HTTP::host] [HTTP::uri]" To meassure elapsed time between a given starting/ending point... set time(YOUR_TIMER_NAME1) [clock clicks] ... your code... lappend time(YOUR_TIMER_NAME1) [clock clicks] set time(YOUR_TIMER_NAME2) [clock clicks] ... your code... lappend time(YOUR_TIMER_NAME2) [clock clicks] To break the iRule execution and display the page... eval [call YOUR_DEBUG_IRULE_NAME::DEBUGPAGE] Sample iRule integration... when HTTP_REQUEST { # # THIS IS JUST AN EXAMPLE CODE TO SHOW HOW THE DEBUG PAGE WORKS # YOU MAY USE YOUR OWN SNIPPETS TO TEST THE FUNCTIONALITY # # # Collect Debug information # # Note: Each debug(name) variable will be listed # in the response HTML page # set debug(ORIG_HOST) [HTTP::host] set debug(ORIG_URI) [HTTP::uri] # # Collect Timestamp information # # Note: Each time(name) variable will be a dedicated perf # counter and included in the HTML response page # # To start a timestamp: # # set time(timestamp_name) [clock clicks] # # To finish a timestamp: # # lappend time(timestamp_name) [clock clicks] # set time(Total) [clock clicks] if { [HTTP::uri] starts_with "/test1" } then { # Test 1: Meassure the time taken to generate a AES key set time(AES_Keygen) [clock clicks] set debug(aes_key) [AES::key 256] lappend time(AES_Keygen) [clock clicks] } elseif { [HTTP::uri] starts_with "/test2" } then { # Test 2: Meassure the time taken to rewrite HOST and URI set time(HOST_URI_rewrite) [clock clicks] HTTP::header replace Host "www.domain.de" HTTP::uri "/somefolder[HTTP::uri]" lappend time(HOST_URI_rewrite) [clock clicks] set debug(NEW_HOST) [HTTP::host] set debug(NEW_URI) [HTTP::uri] } lappend time(Total) [clock clicks] # # EVAL the TCL script fetched from the Debug Page procedure # # Note: The iRule used to store the Debug-Procedure is # "YOUR_DEBUG_IRULE_NAME" with "DEBUGPAGE" proc name. # eval [call YOUR_DEBUG_IRULE_NAME::DEBUGPAGE] } Code : when RULE_INIT { # # Proc based Debug-Page with statistical performance counters # # Configure the sample window size set static::sample_frame 60 ;# seconds # Configure the statistical cutoff value to supress outliers set static::sample_cutoff 10;# percent # Stop further iRule processing and TCP::close the connection set static::stop_futher_processing 1;# bolean } proc DEBUGPAGE { return { # # The proc will return a TCL script containing the debug page code. # # Rendering HTML response head/body set temp(http_response) " Debug Page Debug Information " # Rendering HTML response debug table if { [array exist debug] } then { foreach temp(var) "[lsort -dictionary [array names debug]]" { append temp(http_response) " $temp(var) $debug($temp(var)) " } append temp(http_response) " " } else { append temp(http_response) " --NA----NA-- " } # Enumarating active time frames and calculating statistical information foreach temp(timeframe_name) [array names time] { # Checking validity of current time frame if { [llength $time($temp(timeframe_name))] == 2 } then { # Calculating the total time of current time frame set temp(timeframe_last_sum) [expr {[lindex $time($temp(timeframe_name)) 1] - [lindex $time($temp(timeframe_name)) 0] - 2 }] # Preparing HTML table for the current time frame append temp(http_response_table_last) " $temp(timeframe_name)$temp(timeframe_last_sum) " # Storing the total time of the current time frame into session table table set -subtable $temp(timeframe_name) [lindex $time($temp(timeframe_name)) 0] $temp(timeframe_last_sum) indef $static::sample_frame # Init statistics calculation set temp(timeframe_table_keys_values) "" # Enumarating the stored time frame values for current time frame foreach temp(timeframe_table_key) [table keys -subtable $temp(timeframe_name)] { # Fetching next stored time frame for current time frame set temp(timeframe_table_key_value) [table lookup -subtable $temp(timeframe_name) $temp(timeframe_table_key)] # Checking if next stored time frame still exist (race conditions) if { $temp(timeframe_table_key_value) ne "" } then { lappend temp(timeframe_table_keys_values) $temp(timeframe_table_key_value) } } if { $temp(timeframe_table_keys_values) ne "" } then { # Calculating raw statistics for current time frame set temp(timeframe_table_keys_values_sorted) [lsort -integer $temp(timeframe_table_keys_values) ] set temp(timeframe_table_keys_count) [llength $temp(timeframe_table_keys_values_sorted)] set temp(timeframe_table_keys_min) [lindex $temp(timeframe_table_keys_values_sorted) 0] set temp(timeframe_table_keys_max) [lindex $temp(timeframe_table_keys_values_sorted) end] set temp(timeframe_table_keys_sum) [expr "[join $temp(timeframe_table_keys_values_sorted) " + " ]"] set temp(timeframe_table_keys_avg) [expr { $temp(timeframe_table_keys_sum) / $temp(timeframe_table_keys_count) }] # Preparing HTML table for raw statistics of current time frame append temp(http_response_table_avg) " $temp(timeframe_name)$temp(timeframe_table_keys_min)$temp(timeframe_table_keys_max)$temp(timeframe_table_keys_avg)$temp(timeframe_table_keys_count) " # Calculating cutoff statistics for current time frame set temp(timeframe_table_keys_count_cutoff_mask) [expr { int($temp(timeframe_table_keys_count) * "0.$static::sample_cutoff" )}] set temp(timeframe_table_keys_values_cutoff) [lrange $temp(timeframe_table_keys_values_sorted) [expr { 0 + $temp(timeframe_table_keys_count_cutoff_mask) }] [expr { $temp(timeframe_table_keys_count) - 1 - $temp(timeframe_table_keys_count_cutoff_mask) }]] set temp(timeframe_table_keys_count_cutoff) [llength $temp(timeframe_table_keys_values_cutoff)] set temp(timeframe_table_keys_min_cutoff) [lindex $temp(timeframe_table_keys_values_cutoff) 0] set temp(timeframe_table_keys_max_cutoff) [lindex $temp(timeframe_table_keys_values_cutoff) end] set temp(timeframe_table_keys_sum_cutoff) [expr "[join $temp(timeframe_table_keys_values_cutoff) " + " ]"] set temp(timeframe_table_keys_avg_cutoff) [expr { $temp(timeframe_table_keys_sum_cutoff) / $temp(timeframe_table_keys_count_cutoff) }] # Preparing HTML table for cutoff statistics of current time frame append temp(http_response_table_avg_cutoff) " $temp(timeframe_name)$temp(timeframe_table_keys_min_cutoff)$temp(timeframe_table_keys_max_cutoff)$temp(timeframe_table_keys_avg_cutoff)$temp(timeframe_table_keys_count_cutoff)2 * $temp(timeframe_table_keys_count_cutoff_mask) " } } } # Rendering HTML response Last CPU clicks table if { [info exists temp(http_response_table_last)] } then { append temp(http_response) " Last CPU clicks Counter Name Last CPU Clicks $temp(http_response_table_last) " } # Rendering HTML response Avg CPU clicks (raw) table if { [info exists temp(http_response_table_avg)] } then { append temp(http_response) " Avg CPU clicks (raw) Counter Name Min CPU Clicks Max CPU Clicks Avg CPU Clicks # Samples $temp(http_response_table_avg) " } # Rendering HTML response Avg CPU clicks (-% cutoff) table if { [info exists temp(http_response_table_avg)] } then { append temp(http_response) " Avg CPU clicks (-$static::sample_cutoff % cutoff) Counter Name Min CPU Clicks Max CPU Clicks Avg CPU Clicks # Samples # Cutoff $temp(http_response_table_avg_cutoff) " } # Rendering HTML response head/body append temp(http_response) " " HTTP::respond 200 content $temp(http_response) noserver "Content-Type" "text/html" # Stopping further iRule processing if { $static::stop_futher_processing } then { event disable all TCP::close return } else { unset -nocomplain temp unset -nocomplain time } }} Tested this on version: 12.0
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.0Performance Logging iRule (Rule_http_log)
Problem this snippet solves: Here's a logging iRule. You'll need a HSL syslog pool to log too. Various bits gathered from other posts on DevCentral. Sharing in case there is interest. Make sure your rsyslogd is setup to use the newer syslog format like RFC-5424 including milliseconds and timezone info.Includes Country (co) and logs individual request times for each request on a HTTP/1.1 connection. To configure F5 logging to use milliseconds and timezone, disable logging in the gui and use tmsh edit sys syslog and something like: include " # short hostnames options { use_fqdn(no); }; # Remote syslog in RFC5424 - Tim Riker <Tim@Rikers.org> destination remotesyslog { syslog(\"10.1.2.3\" transport(\"udp\") port(51443) ts_format(iso)); }; log { source(s_syslog_pipe); destination(remotesyslog); }; " Uses upvar and proc. Tested on 11.6 - 15.1 This tracks connection info in a table and then copies that down to the per-request log() to handle reporting on http2. This version works around a BIG-IP bug where HTTP::version does not report 2 or higher for http2 and later requests. With http2 profiles, subsequent requests using the same connection can generate this error in the logs if HTTP::respond HTTP::redirect or HTTP::retry is called from and earlier iRule. Reorder your iRules to avoid this. <HTTP_REQUEST> - No HTTP header is cached - ERR_NOT_SUPPORTED (line 1)invoked from within "HTTP::method" How to use this snippet: Add this iRule to whatever virtual hosts you desire. I always add it as the first rule. If you have a rule that sets headers you want to track, you may want this after the rule that sets headers. Interesting Splunk queries can be created like: index=* perflog | timechart avg(cpu_5sec) by host limit=10 to show load across multiple F5s. index=* perflog | timechart max(upstream_time) by http_host limit=10 to show long request times by http_host Any other iRule may add things to the log() array and those will get added to the single hsl output. If you create a dg_http_log datagroup, that will be used to filter what gets logged. Tested on version: 13.0 - 15.1 # Rule_http_log # http logging - Tim Riker <Tim@Rikers.org> # bits taken from this post: # https://devcentral.f5.com/questions/irule-for-getting-total-response-time-server-response-time-and-server-connection-time # iRule performance tracking # https://devcentral.f5.com/questions/Timing-iRules timing on # timing is on by default in 11.5.0+ to see stats: # tmsh show ltm rule Rule_http_log # # if the dg_http_log datagroup exists then vips or hosts/paths in dg_http_log that start with # "NONE" no logging (really anything other than empty) # "INFO" normal logging # "FINE" full request and response headers and CLIENT_CLOSED # # upstream_time := 15000 in the datagroup to log all requests over 15 seconds # # example: # "/Common/vs_www.example.com_HTTPS" := "FINE" - logged including CLIENT_CLOSED # "www.example.com/" := "INFO" - logged # "www.example.com/somepath" := "FINE" - full headers # "www.example.com/otherpath" := "NONE" - not logged when RULE_INIT { # hostname up to first dot set static::hostname [getfield [info hostname] "." 1] } # not calling /Common/proc:hsllog as this logs when the request occurred # instead of the time it calls hsllog at the end of the request proc hsllog {time mylog} { upvar 1 $mylog log # https://tools.ietf.org/html/rfc5424 <local0.info>version rfc-3339time host procid msgid structured_data log # should be able to use a "Z" here instead of "+00:00" but our splunk logs don't handle that # 134 = local0.info set output "<134>1 [clock format [string range $time 0 end-3] -gmt 1 -format %Y-%m-%dT%H:%M:%S.[string range $time end-2 end]+00:00] ${static::hostname} httplog [TMM::cmp_group].[TMM::cmp_unit] - -" foreach key [lsort [array names log]] { if { ($log($key) matches_regex {[\" ;,:]}) } { append output " $key=\"[string map {\" "|"} $log($key)]\"" } else { append output " $key=$log($key)" } } # avoid marking virtual server up when hsl pool is up # https://support.f5.com/csp/article/K14505 set hsl pool_syslog HSL::send [HSL::open -proto UDP -pool $hsl] $output } when CLIENT_ACCEPTED { # calculate and track milliseconds # is this / 1000 guaranteed to be clock seconds? TCL docs say no, but it looks like on f5 it is. set tcp_start_time [clock clicks -milliseconds] set log(loglevel) 0 if { [class exists dg_http_log] } { # virtual name entries need to be full path, ie: /Common/vs_www.example.com_HTTP switch -- [string range [class match -value -- [virtual name] equals dg_http_log] 0 3] { "FINE" { set log(loglevel) 2 } "INFO" { set log(loglevel) 1 } default { set log(loglevel) 0 } } } table set -subtable [IP::client_addr]:[TCP::client_port] loglevel $log(loglevel) table set -subtable [IP::client_addr]:[TCP::client_port] tmm "[TMM::cmp_group].[TMM::cmp_unit]" table set -subtable [IP::client_addr]:[TCP::client_port] client_addr [IP::client_addr] table set -subtable [IP::client_addr]:[TCP::client_port] client_port [TCP::client_port] table set -subtable [IP::client_addr]:[TCP::client_port] cpu_5sec [cpu usage 5secs] table set -subtable [IP::client_addr]:[TCP::client_port] virtual_name [virtual name] set co [whereis [IP::client_addr] country] if { $co eq "" } { set co unknown } table set -subtable [IP::client_addr]:[TCP::client_port] co $co } when HTTP_REQUEST { set http_request_time [clock clicks -milliseconds] set keys [table keys -subtable [IP::client_addr]:[TCP::client_port]] foreach key $keys { set log($key) "[table lookup -subtable "[IP::client_addr]:[TCP::client_port]" "$key"]" } if {[HTTP::has_responded]} { # The rule should come BEFORE any rules that do things like redirects set log(http_has_responded) [HTTP::has_responded] set log(loglevel) 1 set log(event) HTTP_REQUEST call hsllog $http_request_time log return } if { [class exists dg_http_log] } { set logsetting [class match -value -- [HTTP::host][HTTP::uri] starts_with dg_http_log] if { $logsetting ne "" } { # override log(loglevel) if we found something switch -- [string range $logsetting 0 3] { "FINE" { set log(loglevel) 2 } "INFO" { set log(loglevel) 1 } default { set log(loglevel) 0 } } } } set log(http_host) [HTTP::host] set log(http_uri) [HTTP::uri] set log(http_method) [HTTP::method] # request_num might not be accurate for HTTP2 set log(request_num) [HTTP::request_num] set log(request_size) [string length [HTTP::request]] # BUG http2 reported as http1 in pre 16.x # https://cdn.f5.com/product/bugtracker/ID842053.html set log(http_version) [HTTP::version] if { [catch \[HTTP2::version\] result] == 1 } { if { $result contains "Operation not supported" } { #log local0. "HTTP version is: [HTTP::version]" } else { set h2ver [eval "\HTTP2::version"] # we might have http2 support, but not be http2 if { $h2ver != 0 } { set log(http_version) $h2ver } } } #log local0. "http_version = $log(http_version)" if { $log(loglevel) > 1 } { foreach {header} [HTTP::header names] { set log(req-$header) [HTTP::header $header] } } else { foreach {header} {"connection" "content-length" "keep-alive" "last-modified" "policy-cn" "referer" "transfer-encoding" "user-agent" "x-forwarded-for" "x-forwarded-proto" "x-forwarded-scheme"} { if { [HTTP::header exists $header] } { set log(req-$header) [HTTP::header $header] } } } } when LB_SELECTED { set lb_selected_time [clock clicks -milliseconds] set log(server_addr) [LB::server addr] set log(server_port) [LB::server port] set log(pool) [LB::server pool] } when SERVER_CONNECTED { set log(connection_time) [expr {[clock clicks -milliseconds] - $lb_selected_time}] set log(snat_addr) [IP::local_addr] set log(snat_port) [TCP::local_port] } when LB_FAILED { set log(event_info) [event info] } when HTTP_REJECT { set log(http_reject) [HTTP::reject_reason] } when HTTP_REQUEST_SEND { set http_request_send_time [clock clicks -milliseconds] } when HTTP_RESPONSE { set log(upstream_time) [expr {[clock clicks -milliseconds] - $http_request_send_time}] set log(http_status) [HTTP::status] if { $log(loglevel) > 1 } { foreach {header} [HTTP::header names] { set log(res-$header) [HTTP::header $header] } } else { foreach {header} {"cache-control" "connection" "content-encoding" "content-length" "content-type" "content-security-policy" "keep-alive" "last-modified" "location" "server" "www-authenticate"} { if { [HTTP::header exists $header] } { set log(res-$header) [HTTP::header $header] } } } # if logging is off, but upstream_time is over threshold in datagroup, log anyway if { ($log(loglevel) < 1) && [class exists dg_http_log] } { set log_upstream_time [class match -value -- upstream_time equals dg_http_log] if {$log_upstream_time ne "" && $log(upstream_time) >= $log_upstream_time} { set log(over_upstream_time) $log_upstream_time set log(loglevel) 1 } } } when HTTP_RESPONSE_RELEASE { if { [info exists http_request_time] } { set log(http_time) "[expr {[clock clicks -milliseconds] - $http_request_time}]" # push http_time into table so CLIENT_CLOSED can see it in HTTP/2 table set -subtable [IP::client_addr]:[TCP::client_port] http_time $log(http_time) } else { set http_request_time [clock clicks -milliseconds] } set log(event) HTTP_RESPONSE_RELEASE if { $log(loglevel) > 0 } { call hsllog $http_request_time log } } when HTTP_DISABLED { set log(http_passthrough_reason) [HTTP::passthrough_reason] } when CLIENT_CLOSED { # grab log() values from table set keys [table keys -subtable [IP::client_addr]:[TCP::client_port]] foreach key $keys { set log($key) "[table lookup -subtable "[IP::client_addr]:[TCP::client_port]" "$key"]" } set log(tcp_time) "[expr {[clock clicks -milliseconds] - $tcp_start_time}]" set log(event) CLIENT_CLOSED # http_time didn't get set, log here (HTTP_RESPONSE_RELEASE never called, catch redirects, aborted connections) if { not ([info exists log(http_time)]) } { if { [info exists http_request_time] } { # called HTTP_REQUEST but not HTTP_RESPONSE_RELEASE using HTTP 1.0 or 1.1 set log(http_time) "[expr {[clock clicks -milliseconds] - $http_request_time}]" } call hsllog $tcp_start_time log } elseif { $log(loglevel) > 1 } { call hsllog $tcp_start_time log } # clean out table when client disconnects table delete -subtable [IP::client_addr]:[TCP::client_port] -all }
