iRule Event Order
Problem this snippet solves: It's sometimes hard which event is triggered and in which order. This code provide visibility on the event order and time between each event in millisecond. Possible (but not limited to) use cases : Troubleshooting connection Identify event triggered for specific requests learn the order of irule events How to use this snippet: Installation irule You need to install the irule on the top of the list in your Virtual Server. Special considerations Irule Generator the displayed irule has been generated with a proprietary tool developed in golang. Zip file Content The downloadable zip file contains : a shell script that generate the irule code for the list of event specified in event_list.tcl file a file that contain a list of all irule event (excluded : CLIENT_ACCEPTED, CLIENT_CLOSED, RULE_INIT) an irule containing all possible events (generated by the script). Just for demo, can not be used in real life. Compatibility Supported in v12.1.0 ACCESS_PER_REQUEST_AGENT_EVENT BOTDEFENSE_ACTION BOTDEFENSE_REQUEST WS_CLIENT_DATA WS_CLIENT_FRAME WS_CLIENT_FRAME_DONE WS_REQUEST WS_RESPONSE WS_SERVER_DATA WS_SERVER_FRAME WS_SERVER_FRAME_DONE Irule Events The displayed irule currently support events from CLIENT_*, HTTP_*, LB_* and SSL_*. This irule should fit for most of the standard ltm use cases on http and https. Outputs syslog output : virtual=/Common/vs_test_irule_order_event, id=d5f693399, time=0, event_order=0, event_type=CLIENT_ACCEPTED virtual=/Common/vs_test_irule_order_event, id=d5f693399, time=0, event_order=1, event_type=CLIENTSSL_CLIENTHELLO virtual=/Common/vs_test_irule_order_event, id=d5f693399, time=6, event_order=2, event_type=CLIENTSSL_HANDSHAKE virtual=/Common/vs_test_irule_order_event, id=d5f693399, time=6, event_order=3, event_type=HTTP_REQUEST virtual=/Common/vs_test_irule_order_event, id=d5f693399, time=6, event_order=4, event_type=LB_FAILED virtual=/Common/vs_test_irule_order_event, id=d5f693399, time=6, event_order=5, event_type=CLIENT_CLOSED ` JSON output : { "d5f693399": [ { "virtual": "/Common/vs_test_irule_order_event", "id": "d5f693399", "time": "0", "event_order": "0", "event_type": "CLIENT_ACCEPTED" }, { "virtual": "/Common/vs_test_irule_order_event", "id": "d5f693399", "time": "0", "event_order": "1", "event_type": "CLIENTSSL_CLIENTHELLO" }, { "virtual": "/Common/vs_test_irule_order_event", "id": "d5f693399", "time": "6", "event_order": "2", "event_type": "CLIENTSSL_HANDSHAKE" }, { "virtual": "/Common/vs_test_irule_order_event", "id": "d5f693399", "time": "6", "event_order": "3", "event_type": "HTTP_REQUEST" }, { "virtual": "/Common/vs_test_irule_order_event", "id": "d5f693399", "time": "6", "event_order": "4", "event_type": "LB_FAILED" }, { "virtual": "/Common/vs_test_irule_order_event", "id": "d5f693399", "time": "6", "event_order": "5", "event_type": "CLIENT_CLOSED" } ] } Features Version 1.0 List Event order Generate a sessionid to track the Client connection until it close Display time elapsed since client has been accepted Logging in JSON format (to use with third party libraries like d3.js) Backlog add logging using csv format use HSL instead of local logging add extra comments for specific events like CLIENT_CERT and LB_FAILED add more events (security related events) release a script to generate an irule that use events related to the other irules present in a Virtual Server External links Github : https://github.com/e-XpertSolutions/f5 iRule Sample when RULE_INIT { set static::client_ip "192.168.10.1" set static::json 1 } when CLIENT_ACCEPTED { set counter 0 set event_type "CLIENT_ACCEPTED" set sessionid "[IP::client_addr][TCP::client_port][IP::local_addr][TCP::local_port][expr { int(100000000 * rand()) }]" binary scan [md5 $sessionid] H* md5_string trash set md5_string [string range $md5_string 12 20] set start_time [clock clicks -milliseconds] log local0. "virtual=[virtual], id=$md5_string, time=0, event_order=$counter, event_type=$event_type" if { $static::json } { set json_log "\{ \"$md5_string\": \[\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"0\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when CLIENT_CLOSED { set counter [expr { $counter+1 }] set event_type "CLIENT_CLOSED" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}\]\}" log local0. "$json_log" } } when HTTP_REQUEST { set counter [expr { $counter+1 }] set event_type "HTTP_REQUEST" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when HTTP_REQUEST_RELEASE { set counter [expr { $counter+1 }] set event_type "HTTP_REQUEST_RELEASE" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when HTTP_RESPONSE { set counter [expr { $counter+1 }] set event_type "HTTP_RESPONSE" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when HTTP_RESPONSE_RELEASE { set counter [expr { $counter+1 }] set event_type "HTTP_RESPONSE_RELEASE" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when HTTP_RESPONSE_CONTINUE { set counter [expr { $counter+1 }] set event_type "HTTP_RESPONSE_CONTINUE" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when HTTP_REQUEST_SEND { set counter [expr { $counter+1 }] set event_type "HTTP_REQUEST_SEND" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when HTTP_REQUEST_DATA { set counter [expr { $counter+1 }] set event_type "HTTP_REQUEST_DATA" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when CLIENT_DATA { set counter [expr { $counter+1 }] set event_type "CLIENT_DATA" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when HTTP_PROXY_REQUEST { set counter [expr { $counter+1 }] set event_type "HTTP_PROXY_REQUEST" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when HTTP_DISABLED { set counter [expr { $counter+1 }] set event_type "HTTP_DISABLED" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when SERVER_CLOSED { set counter [expr { $counter+1 }] set event_type "SERVER_CLOSED" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when SERVER_DATA { set counter [expr { $counter+1 }] set event_type "SERVER_DATA" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when SERVERSSL_DATA { set counter [expr { $counter+1 }] set event_type "SERVERSSL_DATA" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when SERVER_CONNECTED { set counter [expr { $counter+1 }] set event_type "SERVER_CONNECTED" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when CLIENTSSL_DATA { set counter [expr { $counter+1 }] set event_type "CLIENTSSL_DATA" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when CLIENTSSL_CLIENTCERT { set counter [expr { $counter+1 }] set event_type "CLIENTSSL_CLIENTCERT" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when CLIENTSSL_CLIENTHELLO { set counter [expr { $counter+1 }] set event_type "CLIENTSSL_CLIENTHELLO" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when CLIENTSSL_HANDSHAKE { set counter [expr { $counter+1 }] set event_type "CLIENTSSL_HANDSHAKE" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when CLIENTSSL_SERVERHELLO_SEND { set counter [expr { $counter+1 }] set event_type "CLIENTSSL_SERVERHELLO_SEND" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when SERVERSSL_CLIENTHELLO_SEND { set counter [expr { $counter+1 }] set event_type "SERVERSSL_CLIENTHELLO_SEND" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when SERVERSSL_HANDSHAKE { set counter [expr { $counter+1 }] set event_type "SERVERSSL_HANDSHAKE" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when SERVERSSL_SERVERHELLO { set counter [expr { $counter+1 }] set event_type "SERVERSSL_SERVERHELLO" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when LB_QUEUED { set counter [expr { $counter+1 }] set event_type "LB_QUEUED" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when LB_FAILED { set counter [expr { $counter+1 }] set event_type "LB_FAILED" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } when LB_SELECTED { set counter [expr { $counter+1 }] set event_type "LB_SELECTED" set curtime [expr { [clock clicks -milliseconds] - $start_time }] log local0. "virtual=[virtual], id=$md5_string, time=$curtime, event_order=$counter, event_type=$event_type" if { $static::json } { append json_log "\{\"virtual\":\"[virtual]\", \"id\":\"$md5_string\", \"time\":\"$curtime\", \"event_order\":\"$counter\", \"event_type\":\"$event_type\"\}," } } Code : 68686 Tested this on version: 11.5