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: