For more information regarding the security incident at F5, the actions we are taking to address it, and our ongoing efforts to protect our customers, click here.

Forum Discussion

dipta_03_149731's avatar
dipta_03_149731
Icon for Nimbostratus rankNimbostratus
Apr 05, 2016

Please explain the meaning for the Irule 'Response-time-logging-iRule':

when HTTP_REQUEST {
    set CLIENT_ADDR [IP::client_addr]
    set XFF [HTTP::header X-Forwarded-For]
    set ID "[TCP::local_port][expr { int(100000000 * rand()) }]"
    set REQUEST_RECEIVE [clock clicks -milliseconds]
    set URI "[HTTP::uri]"
}

when HTTP_REQUEST_SEND {
    set REQUEST_SEND [clock clicks -milliseconds]
    set REQUEST_WAIT [expr {$REQUEST_SEND - $REQUEST_RECEIVE}]
    log local0. "SRC:$CLIENT_ADDR  XFF:$XFF ID:$ID URI:$URI"
}

when HTTP_RESPONSE {
    set RESPONSE_TIME [expr {[clock clicks -milliseconds] - $REQUEST_SEND}]
    log local0. "SRC:$CLIENT_ADDR XFF:$XFF ID:$ID URI:$URI - HTTP[HTTP::status] $RESPONSE_TIME\ms/$REQUEST_WAIT\ms [LB::server addr]"
}

1 Reply

  • The purpose of this irule is to measure:
    1)  how long a HTTP request processing took in BIGIP before the request 
        was sent to the backend server
    2)  how long a HTTP request processing took from the time BIGIP forwarded
        the HTTP request to the backend till a HTTP response was received 
        from the backend.
    
     When there is an incoming http request to BIGIP from the client, 
     the following event will fire.
    
    when HTTP_REQUEST {
         store the client IP address in a variable "CLIENT_ADDR"
    
        set CLIENT_ADDR [IP::client_addr]
    
         store the HTTP X-Forwarded-For header value if present, in the incoming 
         http request in the variable "XFF"
    
        set XFF [HTTP::header X-Forwarded-For]
    
         In order to create a unique ID for this request, a simple technique
         is used here.  Store the local TCP port number where the HTTP request
         was received on BIGIP.  For e.g. on a https connection it is going to
         be 443 usually.  Generate a random number between 0 and 1 and multiply
         this with 100 million, to order to create a integer with 8 digits.
         For e.g. expr { rand() } may result in 0.206450634266.  So if you 
         multiply by 100 million, you get 20645063.  Now append this with the
         previously stored TCP port number so that you get 44320645063 
         which can be used as a unique ID.  This value is stored in the 
         variable "ID"
    
        set ID "[TCP::local_port][expr { int(100000000 * rand()) }]"
    
         store the current clock value in a high resolution format upto
         millisec resolution in the variable "REQUEST_RECEIVE"
    
        set REQUEST_RECEIVE [clock clicks -milliseconds]
    
         store the incoming HTTP URI (e.g. if your request is 
         https://www.abc.com/index.html then the URI is /index.html) in
         the variable "URI"
    
        set URI "[HTTP::uri]"
    }
    
     When BIGIP is about to forward the HTTP_REQUEST it received
     to the backend server, this event will fire.  
    
    when HTTP_REQUEST_SEND {
    
         store the clock value in milliseconds in the variable
         "REQUEST_SEND"
    
        set REQUEST_SEND [clock clicks -milliseconds]
    
         calculate: sent time (to the backend) minus received time (from the client) 
         will give the time took by the BIGIP to process the request before
         it is forwarded to the backend.  Store this in variable "REQUEST_WAIT"
    
        set REQUEST_WAIT [expr {$REQUEST_SEND - $REQUEST_RECEIVE}]
    
         Now log in /var/log/ltm the following: CLIENT_ADDR, XFF (if any),
         ID, URI
    
        log local0. "SRC:$CLIENT_ADDR  XFF:$XFF ID:$ID URI:$URI"
    }
    
     when BIGIP receives a HTTP response from the backend server, this 
     event is triggered.
    
    when HTTP_RESPONSE {
    
         Calculate: current time (in millisec) minus the time BIGIP sent the
         HTTP_REQUEST to the backend server (in millisec).  This gives the
         total time it took to receive a response from the backend from the 
         time BIGIP sent the request to backend.
    
        set RESPONSE_TIME [expr {[clock clicks -milliseconds] - $REQUEST_SEND}]
    
         Now log the following in /var/log/ltm:  CLIENT_ADDR, XFF, ID, URI, 
         the string HTTP appended with the HTTP response status (e.g. if you
         receive HTTP 200 OK, then this string will be HTTP200), total response
         time and request wait time in BIGIP (as explained previously)
    
        log local0. "SRC:$CLIENT_ADDR XFF:$XFF ID:$ID URI:$URI - HTTP[HTTP::status] $RESPONSE_TIME\ms/$REQUEST_WAIT\ms [LB::server addr]"
    }
    
    Finally when you attach this irule to a virtual server you will get a log line in 
    your /var/log/ltm like this when a client with IP address 10.10.51.1 trying to 
    access a backend server resource at 10.11.12.1 (https://virtual_server_ip/)
    
    Apr  6 01:12:11 mks116 info tmm1[17698]: Rule /Common/mks_response_time_logging_irule : SRC:10.10.51.1  XFF: ID:44366274814 URI:/
    Apr  6 01:12:11 mks116 info tmm1[17698]: Rule /Common/mks_response_time_logging_irule : SRC:10.10.51.1 XFF: ID:44366274814 URI:/ - HTTP200 2ms/0ms 10.11.12.1