Forum Discussion

RSpangler_17032's avatar
RSpangler_17032
Icon for Nimbostratus rankNimbostratus
Mar 24, 2017

Response time iRule error

Hello,

 

So I'm trying to implement code that will capture request and response times between the F5 and the backend servers. I found this spinet of code here, iRule Response time, and I'm trying to set it up to only log a certain URL as I do not need anything else that would be accosted with the pool.

 

Here is the code I tweeked:

 

when HTTP_REQUEST {
    if {([string tolower [HTTP::host]] contains "webtest")}{
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 {
if {([string tolower [HTTP::host]] contains "webtest")}{
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 {
if {([string tolower [HTTP::host]] contains "webtest")}{
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]"
}
}

When I go to save the code I get the following error:

 

Exception caught in LocalLB::urn:iControl:LocalLB/Rule::modify_rule()
Exception: Common::OperationFailed
primary_error_code   : 17236305 (0x01070151)
secondary_error_code : 0
error_string         : 01070151:3: Rule [/Common/Responce-times] error: /Common/Responce-times:20: error: [command is not valid in current event context (HTTP_RESPONSE)][HTTP::host]

I'm not sure what I'm missing or configured wrong here. Can anyone point me in the correct direction? Thank you for your help.

 

11 Replies

  • Or if anyone knows of a better way to get the response times for a single web site that would be great.

     

  • The error is saying that HTTP::host command is not valid in the HTTP_RESPONSE event. Basically, you don't have the host header in the response from the server, just in the request.

     

    You can work around that, saving the value of HTTP::host to a variable in the HTTP_REQUEST event, then you will be able to call that variable in the HTTP_RESPONSE event.

     

  • If your goal is to simply check the server's response time to a request, I'm including a small snippet of what I have done in the past.

    Probably the best time to capture the actual response time is between HTTP_REQUEST_SEND and HTTP_RESPONSE.

     

    ltm profile statistics DELAY_STAT {
        field1 total
        field2 webtest_total
        field3 webtest_slow
        field4 webtest_fast
    }
    
    ltm rule LOG-Delay {
        when RULE_INIT {
         what is a slow response in milliseconds
        set static::slow_response 2000
    }
    when HTTP_REQUEST_SEND {
        STATS::incr DELAY_STAT total
        clientside {
            if {[string tolower [HTTP::host]] contains "onpoint342labupgrade2013"} {
                STATS::incr DELAY_STAT webtest_total
                set URL [string tolower [HTTP::host]][HTTP::uri]
                set SENT [clock clicks -milliseconds]
            }
        }
    }
    when HTTP_RESPONE {
         exit event if variable is not set
        if {![info exists SENT]} { return }
    
        set TIME [expr {[clock clicks -milliseconds] - $SENT}]
        if {$TIME >= $static::slow_response} {
            STATS::incr DELAY_STAT webtest_slow
            log local0. "[HTTP::status]: Client [IP::client_addr]; \
            Server [IP::server_addr]:[TCP::server_port]; URL ${URL}; Time ${TIME}ms"
        } else {
            STATS::incr DELAY_STAT webtest_fast
        }
        unset SENT URL TIME
    }
    }
    

     

    As long as HTTP pipelining is not being used, and hopefully it's not, this would be fine.

    Notes

    1. If you expect a lot of logging, I recommend using HSL instead of the log command.
    2. I'm not logging every bit of information, you can add as needed.
    3. You should check out the request logging profile on the F5. It may be able to accomplish what you are looking for without an iRule, though I don't think you can control which URLs it is logging.
    4. I added STATS to track all/slow/fast requests. You would need to add the stats profile to the virtual server for it to work. In the past, I have found it handy to see how many requests were fast vs slow at a glance. Additional STATS fields can be added fairly easily to track other things without requiring you to sift through log messages.
    5. The delay between HTTP_REQUEST_SEND and HTTP_RESPONSE may not include the total response time. The HTTP_RESPONSE event fires when the F5 has received the complete HTTP header, which is not always the same as the response contents.
    • RSpangler_17032's avatar
      RSpangler_17032
      Icon for Nimbostratus rankNimbostratus

      This looks promising. Never setup and request logging profile. Is there a step by step doc somewhere?

       

    • Jeremy_Church_3's avatar
      Jeremy_Church_3
      Icon for Cirrus rankCirrus

      Hello,

       

      In the F5 GUI, there are field names listed in the help tab on the left.

       

      I find it easier to search for request logging on the internet. F5 documentation on request logging, though I am not sure about a step-by-step doc.

       

      It is really not complicated, but I have found the GUI configuration is buggy, at least in the version I was using. If you configure a Request Logging profile in the GUI, then list it in the CLI, you will know if there is a problem. If configured in the GUI, the F5 will save line breaks in the config if the fields listed do not fit on a single line. To work around this, I copy the config, remove the line breaks and merge the profile back into the CLI.

       

    • RSpangler_17032's avatar
      RSpangler_17032
      Icon for Nimbostratus rankNimbostratus

      OK, I found how to setup the Request Logging but it doesn't seem to be working for me. I know I'm not doing something right just haven't figured it out yet.

      I do have the iRule working but now I'm trying to figure out how I can get it to only log for the URL that I want and not every URL that comes through the VS. do you have an idea how I can accomplish this?

      This is the iRule I am using:

       

      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 HST "[HTTP::host]"
          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 HST:$HST'/'$URI"
      }
      
      when HTTP_RESPONSE {
          set RESPONSE_TIME [expr {[clock clicks -milliseconds] - $REQUEST_SEND}]
          log local0. "SRC:$CLIENT_ADDR XFF:$XFF ID:$ID HST:$HST$URI - HTTP[HTTP::status] $RESPONSE_TIME\ms/$REQUEST_WAIT\ms [LB::server addr]"
      }
      

       

      I want to somehow tell this to log only if the URL is ex. website1.com log if it is website2.com ignore as they will both come into the same VS on the F5.