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 }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
iRule Execution Tracing and Performance Profiling, Part 2
In the last article we discussed some intriguing questions around iRules tracing and profiling. There are a lot we can do to facilitate iRules debugging and performance tuning, and we took the first step in BIG-IP v13.1. We are pleased to announce that iRules tracing and profiling feature is added to TMOS tool chain in this release. This feature enables both users and iRules infrastructure development team to broaden iRules functionality and application prospects. In this article we will describe the focal use cases and design principles of the feature; we will use examples to demonstrate how to use the feature. Use case and consideration Following are the major use model we target and the design principles we employ for the feature in this release: This feature is mostly used in debug environment. Execution tracing and performance tuning are part of development process. We envision that the most typical use case is users take to the tracing functionality when scripts are still in development. It is possible that the iRules are running on production systems, yet when users like to inspect performance issues, they take the scripts to lab environment to collect performance data, analyze bottleneck and experiment algorithm tuning. The solution needs to be non-intrusive. Tcl language has tracing constructs in its core infrastructure, for example trace command is a Tcl core command. Historically trace command is not supported by iRules. Although it is a viable option to reuse Tcl's trace command as the basic facility for the tracing feature, we make the choice that the feature does not require users to modify the script; instead, it is a passive observation solution: users configure the conditions and leave the script intact. This provides a smooth debugging experience: users can enable the feature, observe the result and adjust the feature configuration continuously. Graphical interface is not critical in the first release. Ideally the feature is presented in a GUI environment. We believe a command line interaction in the first release properly addresses the most critical use cases. Separate data collecting and data scoping. Tracing comes with high volume data, the deeper and wider the tracing goes, the more data are generated. In this release we focus on picking the right data (the "occurrences" presented in the last article) and delivering the data timely and securely. Providing tool chain to help users to mine the data is a logical next step. The Feature OK, now we are ready to present the feature. The audience of this article are familiar with BIG-IP and iRules, so let's have fun and jump to some examples. Example Here is a simple iRules script: ltm rule dc_1 { when CLIENT_ACCEPTED { if {[IP::remote_addr] eq "10.10.10.2"} { set the_one true } else { set the_one false } } when HTTP_REQUEST { if {$the_one} { HTTP::uri [string map {myPortal UserPortal} [HTTP::uri]] } } } Now issue the following TMSH commands to insert the tracer: tmsh create ltm rule-profiler dc_1_tracer event-filter add { CLIENT_ACCEPTED HTTP_REQUEST } vs-filter add { /Common/vs1 } publisher tracer_pub1 tmsh modify ltm rule-profiler dc_1_tracer occ-mask { cmd cmd-vm event rule rule-vm var-mod } tmsh modify ltm rule-profiler dc_1_tracer state enabled The feature introduces a new TMSH configuration object, rule-profiler. There can be multiple rule-profiler objects, this facilitates difference tracing scenarios. Following attributes of rule-profiler are configured in the above TMSH commands: event-filter, the iRule events to trace; if not defined, all events are traced. vs-filter, the virtual servers to trace; if not defined, all virtual servers are traced. occ-mask, the occurrences to trace. The viable values are as explained in the last article. publisher, the syslog publisher to receive the tracing log. The user needs to enable the rule-profiler object after the configuration. Now the tracing facility is ready. We start the tracing on a running traffic by the following command: tmsh start ltm rule-profiler dc_1_tracer The lab setup for this example has publisher point to the local syslog and here is a partial capture of the output in /var/log/ltm (the color coding is for this article to describe the data): 1511494952932589,RP_EVENT_ENTRY,/Common/vs1,CLIENT_ACCEPTED,18291,0x94558076344064,10.10.10.2,46052,0,10.10.10.160,80, 01511494952932622,RP_RULE_ENTRY,/Common/vs1,/Common/dc_1,18291,0x94558076344064,10.10.10.2,46052,0,10.10.10.160,80,0 1511494952932625,RP_RULE_VM_ENTRY,/Common/vs1,/Common/dc_1,18291,0x94558076344064,10.10.10.2,46052,0,10.10.10.160,80,0 1511494952932628,RP_CMD_VM_ENTRY,/Common/vs1,IP::remote_addr,18291,0x94558076344064,10.10.10.2,46052,0,10.10.10.160,80,0 1511494952932630,RP_CMD_ENTRY,/Common/vs1,IP::remote_addr,18291,0x94558076344064,10.10.10.2,46052,0,10.10.10.160,80,0 1511494952932633,RP_CMD_EXIT,/Common/vs1,IP::remote_addr,18291,0x94558076344064,10.10.10.2,46052,0,10.10.10.160,80,0 1511494952932636,RP_CMD_VM_EXIT,/Common/vs1,IP::remote_addr,18291,0x94558076344064,10.10.10.2,46052,0,10.10.10.160,80, 01511494952932638,RP_VAR_MOD,/Common/vs1,the_one=true,18291,0x94558076344064,10.10.10.2,46052,0,10.10.10.160,80 Now let us take a close look at the logs. Occurrence fields Each tracing occurrence, as defined by "occ-mask" attribute, dumps one line to the log file; there are 7 fields within each line: Timestamp - This is the TMM time stamp at the occurrence. The unit is micro second. Occurrence type - This is the type of the occurrence. It is corresponding to "occ-mask" attribute definition. The meaning of each occurrence is defined in the last article. "RP" stands for "Rule Profiler". Virtual server - This is the name of the virtual server on which the iRules are running. Occurrence value - This is the value of the corresponding occurrence. For example, the first log in the above snippet is at the entry occurrence of iRule event CLIENT_ACCEPTED. Process ID - This is the TMM process ID. Flow ID - This is the flow ID. Remote tuple - There are 3 fields, IP address, port and routing domain. Local tuple - There are 3 fields, IP address, port and routing domain. Stop Tracing User can stop the tracing by issuing this TMSH command: tmsh stop ltm rule-profiler <rule-profiler name> Tracer has a built-in timer, it stops tracing after 10 milliseconds. User can adjust it through the following command: tmsh modify ltm rule-profiler dc_1_tracer period <new value in ms> Bytecode As mentioned in the first article, the tracing feature supports bytecode tracing. Using the example above, add "bytecode" to "occ-mask": tmsh modify ltm rule-profiler dc_1_tracer occ-mask { bytecode cmd cmd-vm event rule rule-vm var-mod } With this addition, you will see the bytecode execution. But keep one thing in mind, you will see a lot more logging. 1511673715911247,RP_EVENT_ENTRY,/Common/vs1,CLIENT_ACCEPTED,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0, 1511673715911273,RP_RULE_ENTRY,/Common/vs1,/Common/dc_1,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0,2 1511673715911277,RP_RULE_VM_ENTRY,/Common/vs1,/Common/dc_1,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0,2 1511673715911280,RP_CMD_BYTECODE,/Common/vs1,push1,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0,2 1511673715911282,RP_CMD_BYTECODE,/Common/vs1,invokeStk1,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0,2 1511673715911284,RP_CMD_VM_ENTRY,/Common/vs1,IP::remote_addr,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0,2 1511673715911286,RP_CMD_ENTRY,/Common/vs1,IP::remote_addr,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0,2 1511673715911288,RP_CMD_EXIT,/Common/vs1,IP::remote_addr,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0,0 1511673715911291,RP_CMD_VM_EXIT,/Common/vs1,IP::remote_addr,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0,0 1511673715911293,RP_CMD_BYTECODE,/Common/vs1,push1,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0,2 1511673715911295,RP_CMD_BYTECODE,/Common/vs1,streq,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0,2 1511673715911296,RP_CMD_BYTECODE,/Common/vs1,push1,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0,2 1511673715911298,RP_CMD_BYTECODE,/Common/vs1,push1,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0,2 1511673715911300,RP_CMD_BYTECODE,/Common/vs1,storeScalarStk,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0,2 1511673715911302,RP_VAR_MOD,/Common/vs1,the_one=true,18291,0x94558076344064,10.10.10.2,41772,0,10.10.10.160,80,0 What's to come This article describes the TMSH commands to configure rule-profiler and how to interpret the tracing logs. Next article will talk about tips and tricks of using the tracing feature. Authors:Jibin Han, Bonny Rais
