Log Http Headers
Problem this snippet solves: This simple rule logs all HTTP headers in requests and responses to /var/log/ltm. This can be helpful in troubleshooting. Code : when HTTP_REQUEST { set LogString "Client [IP::client_addr]:[TCP::client_port] -> [HTTP::host][HTTP::uri]" log local0. "=============================================" log local0. "$LogString (request)" foreach aHeader [HTTP::header names] { log local0. "$aHeader: [HTTP::header value $aHeader]" } log local0. "=============================================" } when HTTP_RESPONSE { log local0. "=============================================" log local0. "$LogString (response) - status: [HTTP::status]" foreach aHeader [HTTP::header names] { log local0. "$aHeader: [HTTP::header value $aHeader]" } log local0. "=============================================" } # Sample output: Rule log_http_headers_rule : ============================================= Rule log_http_headers_rule : Client 192.168.99.32:2950 -> webmail.example.com/exchange/Aaron/Inbox/?Cmd=contents (request) Rule log_http_headers_rule : Host: webmail Rule log_http_headers_rule : User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.9) Rule log_http_headers_rule : Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,im Rule log_http_headers_rule : Accept-Language: en-us,en;q=0.5 Rule log_http_headers_rule : Accept-Encoding: gzip,deflate Rule log_http_headers_rule : Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7 Rule log_http_headers_rule : Keep-Alive: 300 Rule log_http_headers_rule : Connection: keep-alive Rule log_http_headers_rule : Referer: https://webmail.example.com/exchange/ Rule log_http_headers_rule : X-Forwarded-For: 192.168.99.32 Rule log_http_headers_rule : Front-End-Https: On Rule log_http_headers_rule : ============================================= Rule log_http_headers_rule : ============================================= Rule log_http_headers_rule : Client 192.168.99.32:2950 -> webmail.example.com/exchange/Aaron/Inbox/?Cmd=contents (response) - status: 200 Rule log_http_headers_rule : Date: Tue, 06 Nov 2007 16 Rule log_http_headers_rule : Server: Microsoft-IIS/6.0 Rule log_http_headers_rule : X-Powered-By: ASP.NET Rule log_http_headers_rule : Content-Type: text/html Rule log_http_headers_rule : Content-Length: 55446 Rule log_http_headers_rule : MS-WebStorage: 6.5.7638 Rule log_http_headers_rule : Cache-Control: no-cache Rule log_http_headers_rule : =============================================Performance 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 }
Log client to vip connections
Problem this snippet solves: This iRule generates an entry in a log file whenever somebody connects to a virtual server. I haven't tested it extensively to find the exact meaning of CLIENT_ACCEPTED. Since the iRule gets connected to a VIP, it is not as universal as I would like it to be. You have to connect it to multiple VIPs if you want to log all of the traffic through your LTM. The log messages show up in /var/log/ltm. You can pull them out of the log file easily by grepping for TCP_logging. Code : rule TCP_logging { when CLIENT_ACCEPTED { set remote [IP::remote_addr]:[TCP::remote_port] set vip [IP::local_addr]:[TCP::local_port] log "Rule TCP_logging fired, from $remote to vip $vip" } }Log Tcp And Http Request Response Info
Problem this snippet solves: This iRule logs a line for the following events: when a new TCP connection is established with a client when the HTTP headers of an HTTP request are received from the client when the HTTP headers of an HTTP response are received from the pool member when the TCP connection with a client is closed Code : # Here is a sample of the log output for a single TCP connection with three HTTP requests: : New TCP connection from 192.168.99.210:2675 to 192.168.101.41:80 : Client 192.168.99.210:2675 -> test_http_vip/test0.html?parameter=val (request) : Client 192.168.99.210:2675 -> test_http_vip/test0.html?parameter=val (response) - pool info http_pool 192.168.101.45 80 - status: 200 (request/response delta: 0ms) : Client 192.168.99.210:2675 -> test_http_vip/test1.html?parameter=val (request) : Client 192.168.99.210:2675 -> test_http_vip/test1.html?parameter=val (response) - pool info http_pool 192.168.101.45 80 - status: 200 (request/response delta: 0ms) : Client 192.168.99.210:2675 -> test_http_vip/test2.html?parameter=val (request) : Client 192.168.99.210:2675 -> test_http_vip/test2.html?parameter=val (response) - pool info http_pool 192.168.101.45 80 - status: 200 (request/response delta: 1ms) : Closed TCP connection from 192.168.99.210:2675 to 192.168.101.41:80 (open for: 1078ms) when CLIENT_ACCEPTED { # Get time for start of TCP connection in milleseconds set tcp_start_time [clock clicks -milliseconds] # Log the start of a new TCP connection log local0. "New TCP connection from [IP::client_addr]:[TCP::client_port] to [IP::local_addr]:[TCP::local_port]" } when HTTP_REQUEST { # Get time for start of HTTP request set http_request_time [clock clicks -milliseconds] # Log the start of a new HTTP request set LogString "Client [IP::client_addr]:[TCP::client_port] -> [HTTP::host][HTTP::uri]" log local0. "$LogString (request)" } when LB_SELECTED { log local0. "Client [IP::client_addr]:[TCP::client_port]: Selected [LB::server]" } when LB_FAILED { log local0. "Client [IP::client_addr]:[TCP::client_port]: Failed to [LB::server]" } when SERVER_CONNECTED { log local0. "Client [IP::client_addr]:[TCP::client_port]: Connected to [IP::server_addr]:[TCP::server_port]" } when HTTP_RESPONSE { # Received the response headers from the server. Log the pool name, IP and port, status and time delta log local0. "$LogString (response) - pool info: [LB::server] - status: [HTTP::status] (request/response delta: [expr {[clock clicks -milliseconds] - $http_request_time}] ms)" } when CLIENT_CLOSED { # Log the end time of the TCP connection log local0. "Closed TCP connection from [IP::client_addr]:[TCP::client_port] to [IP::local_addr]:[TCP::local_port] (open for: [expr {[clock clicks -milliseconds] - $tcp_start_time}] ms)" }
FTP Session Logging
Problem this snippet solves: This iRule logs FTP connections and username information. By default connection mapping from client through BIG-IP to server is logged as well as the username entered by the client. Optionally you can log the entire FTP session by uncommenting the log message in CLIENT_DATA. Code : # This iRule logs FTP connections and username information. # By default connection mapping from client through BIG-IP to server is logged # as well as the username entered by the client. Optionally you can log the # entire FTP session by uncommenting the log message in CLIENT_DATA. when CLIENT_ACCEPTED { set vip [IP::local_addr]:[TCP::local_port] set user "unknown" } when CLIENT_DATA { # uncomment for full session logging #log local0. "[IP::client_addr]:[TCP::client_port]: collected payload ([TCP::payload length]): [TCP::payload]" # check if payload contains the string we want to replace if { [TCP::payload] contains "USER" } { # use a regular expression to save the user name ## regex modified by arkashik regexp "USER \(\[a-zA-Z0-9_-]+)" [TCP::payload] all user # log connection mapping from client through BIG-IP to server log local0. "FTP connection from $client. Mapped to $inside -> $node, user $user" TCP::release TCP::collect } else { TCP::release TCP::collect } } when SERVER_CONNECTED { set client "[IP::client_addr]:[TCP::client_port]" set node "[IP::server_addr]:[TCP::server_port]" set inside "[serverside {IP::local_addr}]:[serverside {TCP::local_port}]" TCP::collect } when SERVER_DATA { TCP::release clientside { TCP::collect } }Formatted Logging For W3c
Problem this snippet solves: Build a customized, compliant log message with this iRule that builds "properly" formatted log entries. The first example uses High Speed Logging to send the message remotely while the second example uses the log command to log to the local filesystem. Code : # iRule Source for remote logging using HSL # From: W3C Extended Log File Examples (IIS 6.0) # http://www.microsoft.com/technet/prodtechnol/WindowsServer2003/Library/IIS/ffdd7079-47be-4277-921f-7a3a6e610dcb.mspx?mfr=true #Fields: date time c-ip cs-username s-ip cs-method cs-uri-stem cs-uri-query sc-status sc-bytes cs-bytes time-taken cs-version cs(User-Agent) cs(Cookie) cs(Referrer) when CLIENT_ACCEPTED { # Open a new high speed logging connection to the syslog pool named syslog_server_pool set hsl [HSL::open -proto UDP -pool syslog_server_pool] } when HTTP_REQUEST priority 999 { # Save request variables that are not accessible in HTTP_RESPONSE, like the URI, request method, etc set req_start [clock clicks -milliseconds] set cs_username [HTTP::username] set cs_uri_stem [HTTP::path] set cs_uri_query [HTTP::query] set cs_bytes [HTTP::header Content-Length] set ua [HTTP::header User-Agent] set cookies [HTTP::header values Cookie] set referer [HTTP::header Referer] } when HTTP_RESPONSE { # Send the syslog message with a syslog facility of 134 (local0.info) # See the HSL wiki page for details on the facilties: # https://devcentral.f5.com/s/wiki/iRules.HSL__send.ashx # # Replace null values with a hyphen: #Use string map to replace a "tab space tab" with "tab hyphen tab" HSL::send $hsl "[string map [list "\t \t" "\t-\t"]\ "<134>\t\ [info hostname]\t\ [IP::local_addr]\t\ [clock format [clock seconds] -format "%d/%m/%Y %H:%M:%S %z"]\t\ [IP::client_addr]\t\ $cs_username\t\ [clientside {IP::local_addr}]\t\ $cs_uri_stem\t\ $cs_uri_query\t\ [HTTP::status]\t\ [HTTP::header Content-Length]\t\ [expr {[clock clicks -milliseconds] - $req_start}]\t\ [HTTP::version]\t\ \"$ua\"\t\ $cookies\t\ $referer\ "]\n" } # iRule Source for local logging when HTTP_REQUEST { # # Save Request Side Information # set http_request "\"[HTTP::method] [HTTP::uri] HTTP/[HTTP::version]\"" set http_request_time [clock clicks -milliseconds] set http_user_agent "\"[HTTP::header User-Agent]]\"" set http_host [HTTP::host] set http_username [HTTP::username] set client_ip [IP::remote_addr] set client_port [TCP::remote_port] set http_request_uri [HTTP::uri] set referer [HTTP::header value referer] } when HTTP_RESPONSE { set response_time [expr [clock clicks -milliseconds] - $http_request_time] set virtual [virtual] set content_length 0 if { [HTTP::header exists "Content-Length"] } { set content_length [HTTP::header "Content-Length"] } set lb_server "[LB::server addr]:[LB::server port]" if { [string compare "$lb_server" ""] == 0 } { set lb_server " " } set status_code [HTTP::status] set content_type [HTTP::header "Content-type"] set log_msg "" append log_msg "virtual=$virtual " append log_msg "client_ip=$client_ip " append log_msg "client_port=$client_port " append log_msg "lb_server=$lb_server " append log_msg "host=$http_host " append log_msg "username=$http_username " #append log_msg "$http_request_uri " append log_msg "request=$http_request " append log_msg "server_status=$status_code " #append log_msg "content_type=$content_type " append log_msg "content_length=$content_length " append log_msg "resp_time=$response_time " append log_msg "user_agent=$http_user_agent " append log_msg "referer=$referer" # log local0. $log_msg log local0. $log_msg }
iRule to decode WebSocket negotiation and frames
Problem this snippet solves: WebSocket establishes a socket via HTTP upgrade and once socket is established subsequent messages are non-HTTP, but WebSocket frame. There might be a situation where you want to dump WebSocket negotiation and frame into log for troubleshooting purpose. This iRule dumps negotiation and WebSocket frame header fields, and payload (only text data). WebSocket frame format looks as below. RFC 6455 - 5.2. Base Framing Protocol 0 1 2 3 0 1 2 3 4 5 6 7 8 9 0 1 2 3 4 5 6 7 8 9 0 1 2 3 4 5 6 7 8 9 0 1 +-+-+-+-+-------+-+-------------+-------------------------------+ |F|R|R|R| opcode|M| Payload len | Extended payload length | |I|S|S|S| (4) |A| (7) | (16/64) | |N|V|V|V| |S| | (if payload len==126/127) | | |1|2|3| |K| | | +-+-+-+-+-------+-+-------------+ - - - - - - - - - - - - - - - + | Extended payload length continued, if payload len == 127 | + - - - - - - - - - - - - - - - +-------------------------------+ | |Masking-key, if MASK set to 1 | +-------------------------------+-------------------------------+ | Masking-key (continued) | Payload Data | +-------------------------------- - - - - - - - - - - - - - - - + : Payload Data continued ... : + - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - + | Payload Data continued ... | +---------------------------------------------------------------+ WebSocket frame is quite simple. The first 2 bytes are necessary and always present. Extended payload length exists only when Payload length is set to 126 (in this case Ext len is 16 bits) or 127 (in this case Ext len is 64 bits). Masking-key exists only if MASK bit is set to 1. FIN : If the frame is the last frame, set to 1. If payload is fragmented, the last frame should have FIN = 1. Other fragmented ones should have FIN = 0. RSV : If extension is not used, it is set to 0 opcode : This tells you if it is data frame (can be text or binary) or control frame. %x0:continuation frame %x1:text frame %x2:binary frame %x3-7:reserved for further %x8:connection close %x9:ping %xA:pong %xB-F:reserved for further MASK : When browser sends a data, this bit MUST be set to 1, which means data is masked using the Masking-key. When server sends a data, this bit MUST NOT set to 1 Payload len : If 0 - 125, this field represents the payload length If it is 126, then the Extended payload length (16bit) are used to tell the actual payload length (maximum data size is 65535 bytes) If it is 127, then the Extended payload length (64bit : MSB must be 0) are used to tell the actual payload length (maximum data size is 9223372036854775807 bytes) Extended payload length Only when Payload len is set to 126 Extended payload length_continued Only when Payload len is set to 127 Masking-key Used to mask data. Masking is to avoid proxy poisoning. Non-compliant HTTP proxy caches WebSocket data. If MASK bit is 1, this field is present. If MASK bit is 0, this field is not present. Client sets this key and it must be unpredictable. Payload Payload from client to server is masked using Masking-key. How to use this snippet: Here I am sending text data "DEAD BEEF" in WebSocket frame via WebSocket_cURL.py (https://github.com/jussmen/WebSocket_cURL). HTTP request and response (negotiation) look like below. $ python WebSocket_cURL.py 10.10.148.101 80 -s "DEAD BEEF" GET /ws HTTP/1.1 Host: 10.10.148.101 Connection: Upgrade Upgrade: websocket Sec-WebSocket-Version: 13 Sec-WebSocket-Key: n5twxG/tNPf8h3po+pNrPA== User-Agent: IE HTTP/1.1 101 Switching Protocols Upgrade: websocket Connection: Upgrade Sec-WebSocket-Accept: y9WDs+d4zDl+qvQ7H17KpnP0EhI= This is how iRule dumps the negotiation and subsequent WebSocket frames in /var/log/ltm <ws_request>: ============================================= <ws_request>: Client 10.10.1.2:47427 -> 10.10.148.101/ws (request) <ws_request>: Host: 10.10.148.101 <ws_request>: Connection: Upgrade <ws_request>: Upgrade: websocket <ws_request>: Sec-WebSocket-Version: 13 <ws_request>: Sec-WebSocket-Key: n5twxG/tNPf8h3po+pNrPA== <ws_request>: User-Agent: IE <ws_request>: ============================================= <ws_response>: ============================================= <ws_response>: Client 10.10.1.2:47427 -> 10.10.148.101/ws (response) <ws_response>: Upgrade: websocket <ws_response>: Connection: Upgrade <ws_response>: Sec-WebSocket-Accept: y9WDs+d4zDl+qvQ7H17KpnP0EhI= <ws_response>: ============================================= <ws_server_frame>: ============================================= <ws_server_frame>: FIN bit : 1 <ws_server_frame>: MASK bit : 1 <ws_server_frame>: MASK : 0 <ws_server_frame>: Type : Text - 1 <ws_server_frame>: ============================================= <ws_server_data>: ============================================= <ws_server_data>: The server says: 'Hello'. Connection was accepted. <ws_server_data>: ============================================= <ws_client_frame>: ============================================= <ws_client_frame>: FIN bit : 1 <ws_client_frame>: MASK bit : 1 <ws_client_frame>: MASK : 1178944834 <ws_client_frame>: Type : Text - 1 <ws_client_frame>: ============================================= <ws_client_data>: ============================================= <ws_client_data>: DEAD BEEF <ws_client_data>: ============================================= <ws_server_frame>: ============================================= <ws_server_frame>: FIN bit : 1 <ws_server_frame>: MASK bit : 1 <ws_server_frame>: MASK : 0 <ws_server_frame>: Type : Text - 1 <ws_server_frame>: ============================================= <ws_server_data>: ============================================= <ws_server_data>: The server says: DEAD BEEF back at you <ws_server_data>: ============================================= <ws_client_frame>: ============================================= <ws_client_frame>: FIN bit : 1 <ws_client_frame>: MASK bit : 1 <ws_client_frame>: MASK : 1178944834 <ws_client_frame>: Type : Connection close - 8 <ws_client_frame>: ============================================= <ws_server_frame>: ============================================= <ws_server_frame>: FIN bit : 1 <ws_server_frame>: MASK bit : 1 <ws_server_frame>: MASK : 0 <ws_server_frame>: Type : Connection close - 8 <ws_server_frame>: ============================================= Code : when WS_REQUEST { # Copied from : https://devcentral.f5.com/s/articles/log-http-headers set LogString "Client [IP::client_addr]:[TCP::client_port] -> [HTTP::host][HTTP::uri]" log local0. "=============================================" log local0. "$LogString (request)" foreach aHeader [HTTP::header names] { log local0. "$aHeader: [HTTP::header value $aHeader]" } log local0. "=============================================" } when WS_RESPONSE { # Copied from : https://devcentral.f5.com/s/articles/log-http-headers log local0. "=============================================" log local0. "$LogString (response)" foreach aHeader [HTTP::header names] { log local0. "$aHeader: [HTTP::header value $aHeader]" } log local0. "=============================================" } when WS_CLIENT_FRAME { log local0. "=============================================" log local0. "FIN bit : [WS::frame eom]" log local0. "MASK bit : [WS::frame orig_masked]" if { [WS::frame orig_masked] eq 0 } { log local0. "Not masked. Client frame MUST be masked." } if { [WS::frame orig_masked] eq 1 } { log local0. "MASK : [WS::frame mask]" } switch -glob [WS::frame type] { "0" { log local0. "Type : Continuatoin frame - 0" } "1" { log local0. "Type : Text - 1" WS::collect frame } "2" { log local0. "Type : Binary - 2" } "3" - "4" - "5" - "6" - "7" { log local0. "Type : Reserved type (3-7) - [WS::frame type]" } "8" { log local0. "Type : Connection close - 8" } "9" { log local0. "Type : ping - 9" } "10" { log local0. "Type : pong - 10" } "11" - "12" - "13" - "14" - "15" { log local0. "Type : Reserved type (11-15) - [WS::frame type]" } } log local0. "=============================================" } when WS_SERVER_FRAME { log local0. "=============================================" log local0. "FIN bit : [WS::frame eom]" log local0. "MASK bit : [WS::frame orig_masked]" if { [WS::frame orig_masked] eq 1 } { log local0. "MASK : [WS::frame mask]" } switch -glob [WS::frame type] { "0" { log local0. "Type : Continuatoin frame - 0" } "1" { log local0. "Type : Text - 1" WS::collect frame } "2" { log local0. "Type : Binary - 2" } "3" - "4" - "5" - "6" - "7" { log local0. "Type : Reserved type (3-7) - [WS::frame type]" } "8" { log local0. "Type : Connection close - 8" } "9" { log local0. "Type : ping - 9" } "10" { log local0. "Type : pong - 10" } "11" - "12" - "13" - "14" - "15" { log local0. "Type : Reserved type (11-15) - [WS::frame type]" } } log local0. "=============================================" } #when WS_CLIENT_FRAME_DONE { #log local0. "WS_CLIENT_FRAME_DONE" #} #when WS_SERVER_FRAME_DONE { #log local0. "WS_SERVER_FRAME_DONE" #} when WS_CLIENT_DATA { log local0. "=============================================" log local0. "[WS::payload]" log local0. "=============================================" WS::release } when WS_SERVER_DATA { log local0. "=============================================" log local0. "[WS::payload]" log local0. "=============================================" WS::release } Tested this on version: 12.0Log binary HTTP payload in hex
Problem this snippet solves: This iRule demonstrates how to collect the HTTP request payload and log the output in hex How to use this snippet: # Convert $binary to $hex binary scan $binary H* hex # Convert $hex to $ascii set ascii [binary format H* $hex] Code : when HTTP_REQUEST { # Log debug? 1=yes, 0=no set debug 1 # Collect up to the first 1MB of POST data if {[HTTP::method] eq "POST"}{ set clength 0 # Check if there is a content-length header and the value is set to less than 1Mb if {[HTTP::header exists "Content-Length"] && [HTTP::header Content-Length] <= 1048576}{ set clength [HTTP::header Content-Length] } else { set clength 1048576 } if {[info exists clength] && $clength > 0} { if {$debug}{log local0. "[virtual name]: Collecting $clength bytes"} HTTP::collect $clength } } } when HTTP_REQUEST_DATA { # Log the payload converted to hex binary scan [HTTP::payload] H* payload_hex if {$debug}{log local0. "[virtual name]: $payload_hex: $payload_hex"} }
Small URL Generator
Problem this snippet solves: The Small URL Generator takes a long URL, examines its length, and assigns it a variable length key based on the original URL's length. The key is then stored in a subtable along with the original URL. When a user accesses the small URL (http:/// ), they are then redirected to the original long URL. This Small URL Generator also has the ability to create custom URL keys. Click here for the accompanying tech tip Code : when RULE_INIT { set static::small_url_timeout 86400 set static::small_url_lifetime 86400 set static::small_url_response_header " \ Small URL Generator Small URL Generator \ " set static::small_url_response_footer " " } when HTTP_REQUEST { if { ([HTTP::uri] starts_with "/create?") and ([HTTP::query] ne "") } { set url [URI::decode [string tolower [URI::query [HTTP::uri] url]]] set custom_url_key [string tolower [URI::query [HTTP::uri] custom_url_key]] if { $custom_url_key ne "" } { if { ([table lookup -subtable small_url $custom_url_key] ne "") } { HTTP::respond 200 content "$static::small_url_response_header \ Error: the custom Small URL \ http://[HTTP::host]/$custom_url_key has already been taken. Please try again. \ $static::small_url_response_footer" } else { set url_key $custom_url_key log local0. "Custom Small URL created for $url with custom key $url_key" } } else { switch -glob [string length $url] { {[1-9]} { set url_key_length 3 } {1[0-9]} { set url_key_length 3 } {2[0-9]} { set url_key_length 4 } {3[0-9]} { set url_key_length 5 } default { set url_key_length 6 } } set url_key [string tolower [scan [string map {/ "" + ""} [b64encode [md5 $url]]] "%${url_key_length}s"]] } if { ([table lookup -subtable small_url $url_key] eq "") } { table add -subtable small_url $url_key $url $static::small_url_timeout $static::small_url_lifetime log local0. "Small URL created for $url with key $url_key" } else { log local0. "Small URL for $url already exists with key $url_key" } HTTP::respond 200 content "$static::small_url_response_header The Small URL for \ $url is \ http://[HTTP::host]/$url_key $static::small_url_response_footer" } else { set url_key [string map {/ ""} [HTTP::path]] set url [table lookup -subtable small_url $url_key] if { [string length $url] != 0 } { log local0. "Found key $url_key, redirecting to $url" HTTP::redirect $url } else { HTTP::respond 200 content "$static::small_url_response_header \ Make it custom! \ (optional) http://[HTTP::host]/ \ $static::small_url_response_footer" } } }
Custom Apache-style logging for Java-based applications
Problem this snippet solves: I had a requirement to have the F5 BigIP produce logs which replicated our current custom Apache Logs. The Apache custom log format was: CustomLog /../apache/logs/ssl_request_log "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %T %{JSESSIONID}C %{SSL_PROTOCOL}x %{SSL_CIPHER}x %D" This was used for logging a Tomcat based web application. We have scripts which parse through the logs and create .csv baed documents to aid in the creation of reports (hence the use of commas as separators and quotations around values which could contain commas such as URLs and SessionIDs). Thanks to a lot of help from the contributors at the forums here I have had success. I hope you find this useful. Code : when HTTP_REQUEST { set http_request_time [clock clicks -milliseconds] set request_log_line "\ [HTTP::request_num],\ [IP::remote_addr],\ [HTTP::method],\ [HTTP::version],\ [HTTP::host],\ \"[HTTP::uri]\",\ \"[HTTP::header value Referer]\", \"[HTTP::header User-Agent]\",\ \"[HTTP::cookie value JSESSIONID]\",\ [SSL::cipher name],\ [SSL::cipher version],\ [SSL::cipher bits]" } when HTTP_RESPONSE { set http_response_time [ clock clicks -milliseconds ] log local0. "$request_log_line,\ [HTTP::status],\ [HTTP::payload length],\ [expr $http_response_time - $http_request_time]" }
