Forum Discussion

adamjones73_136's avatar
adamjones73_136
Icon for Nimbostratus rankNimbostratus
Jul 17, 2015
Solved

iRule help for server response time

Hi folks, new to iRules and programming in general.

 

I'm logging server response times with this simple iRule:

 

when HTTP_REQUEST {

 

set http_request_time [clock clicks -milliseconds]

 

}

 

when HTTP_RESPONSE {

 

set http_response_time [clock clicks -milliseconds]

 

log local0. "Time to response = [expr $http_response_time - $http_request_time]"

 

}

 

How would I expand the iRule so that only responses taking longer than 1000ms are logged?

 

And for those responses over 1000ms I would like to log requested URI, client IP address & port, and server IP address & port.

 

I have tried variations on the following but can't get it right, and would appreciate some help!

 

when HTTP_REQUEST {

 

set http_request_time [clock clicks -milliseconds]

 

}

 

when HTTP_RESPONSE {

 

set http_response_time [clock clicks -milliseconds]

 

}

 

if {[expr $http_response_time - $http_request_time] > 1000

 

} then {

 

log local0. "Server response took longer than 1000ms. TCP connection from [IP::client_addr]:[TCP::client_port] to [IP::local_addr]:[TCP::local_port]. Requested URI is [HTTP::uri]"

 

}

 

Thanks in advance

 

application delivery
devops
iRules
  • VernonWells's avatar
    VernonWells
    Jul 17, 2015

    You are very close! A few things:

    1. conditionals in Tcl are implicitly wrapped in an expr, so there is no need to rewrap the expression;
    2. there is no then sub-command/keyword;
    3. all code must be in an event block;
    4. IP::local_addr and TCP::local_port have two contexts: the clientside (which means the Virtual Server VIP:port) and the serverside (which means the source address and port for the proxy connection toward the Pool Member). If you are not explicit about which context you mean, the context appropriate for the event will be used. Thus, for HTTP_RESPONSE, the implicit context is serverside, so to mean "VIP:port", you must explicitly disambiguate using the clientside command;
    5. HTTP::uri is not available in HTTP_RESPONSE so you must retrieve and store the value in HTTP_REQUEST.

    A few references regarding this:

     

    when HTTP_REQUEST {
    set http_request_time [clock clicks -milliseconds]
    set request_uri [HTTP::uri]
}

when HTTP_RESPONSE {
    if { [clock clicks -milliseconds] - $http_request_time > 1000 } { 
        log local0. "Server response took longer than 1000ms. TCP connection from [IP::client_addr]:[TCP::client_port] to [clientside [IP::local_addr]]:[clientside [TCP::local_port]]. Requested URI is $request_uri"
    }
}

     

    For production usage, you should consider either using High-Speed Logging or, better yet, the built-in HTTP Request Logging Profile employing CLIENT_IP, CLIENT_PORT, VIRTUAL_IP, VIRTUAL_PORT, HTTP_URI and RESPONSE_MSECS in the template. This would log every request, but you could process the (remotely deposited) logs for those that take longer than a threshold (like 1000 ms).

6 Replies

Sort By
  • Kevin_Stewart's avatar
    Kevin_Stewart
    Icon for Employee rankEmployee
    Jul 17, 2015

    You're pretty close.

    log requested URI, client IP address & port, and server IP address & port.

     

    when HTTP_REQUEST {
    set http_request_time [clock clicks -milliseconds]
    set uri [HTTP::uri]
    set clientip [IP::client_addr]
    set clientport [TCP::client_port]
}
when HTTP_RESPONSE {
    set http_response_time [clock clicks -milliseconds]

    if { [expr $http_response_time - $http_request_time] > 1000 } {
        log local0. "Server response took longer than 1000ms. TCP connection from ${clientip}:${clientport} to [IP::local_addr]:[TCP::local_port]. Requested URI is ${uri}"
    }
}

     

  • VernonWells's avatar
    VernonWells
    Icon for Employee rankEmployee
    Jul 17, 2015

    You are very close! A few things:

    1. conditionals in Tcl are implicitly wrapped in an expr, so there is no need to rewrap the expression;
    2. there is no then sub-command/keyword;
    3. all code must be in an event block;
    4. IP::local_addr and TCP::local_port have two contexts: the clientside (which means the Virtual Server VIP:port) and the serverside (which means the source address and port for the proxy connection toward the Pool Member). If you are not explicit about which context you mean, the context appropriate for the event will be used. Thus, for HTTP_RESPONSE, the implicit context is serverside, so to mean "VIP:port", you must explicitly disambiguate using the clientside command;
    5. HTTP::uri is not available in HTTP_RESPONSE so you must retrieve and store the value in HTTP_REQUEST.

    A few references regarding this:

     

    when HTTP_REQUEST {
    set http_request_time [clock clicks -milliseconds]
    set request_uri [HTTP::uri]
}

when HTTP_RESPONSE {
    if { [clock clicks -milliseconds] - $http_request_time > 1000 } { 
        log local0. "Server response took longer than 1000ms. TCP connection from [IP::client_addr]:[TCP::client_port] to [clientside [IP::local_addr]]:[clientside [TCP::local_port]]. Requested URI is $request_uri"
    }
}

     

    For production usage, you should consider either using High-Speed Logging or, better yet, the built-in HTTP Request Logging Profile employing CLIENT_IP, CLIENT_PORT, VIRTUAL_IP, VIRTUAL_PORT, HTTP_URI and RESPONSE_MSECS in the template. This would log every request, but you could process the (remotely deposited) logs for those that take longer than a threshold (like 1000 ms).

    • strain17's avatar
      strain17
      Icon for Nimbostratus rankNimbostratus
      Jan 08, 2016
      Hi, If we use the built-in Request Logging profile, how would we correlate a particular request to a response? Thanks!
  • adamjones73_136's avatar
    adamjones73_136
    Icon for Nimbostratus rankNimbostratus
    Jul 17, 2015

    Kevin and Vernon, thanks for your helpful replies.

    I have updated the iRule like this:

     

    when HTTP_REQUEST {
    set http_request_time [clock clicks -milliseconds]
    set request_uri [HTTP::uri]
}
when HTTP_RESPONSE {   
    if { [clock clicks -milliseconds] - $http_request_time > 1000 } { 
    log local0. "Server response took longer than 1000ms. TCP connection from [IP::client_addr]:[TCP::client_port] to [LB::server addr]:[LB::server port]. Requested URI is $request_uri"
    }
}

     

    I am now logging the full requested uri to the pool member. This will assist a great deal in troubleshooting.

    Cheers

  • adamjones73_136's avatar
    adamjones73_136
    Icon for Nimbostratus rankNimbostratus
    Jul 17, 2015

    I will look into using HSL or the HTTP Request Logging Profile for the Prod environment, as you suggest

     

    Thanks