Forum Discussion

ingard's avatar
ingard
Icon for Nimbostratus rankNimbostratus
Jan 25, 2016

irule to log slow and/or tcp profile timed out requests to backend

Hi

 

I'm trying to identify which requests are causing our backends to stop responding/hang/fail. I was thinking some sort of timer and/or catch the tcp timeout rst maybe? I've been trying to figure out what event to attach this rule to and maybe it would be CLIENT_CLOSED but I'm struggling to see how to go about this. I don't want to log every request that ends with a client_closed obviously, but only the ones where there is no response. Any ideas out there?

 

kind regards ingard

 

application delivery
iRules
LTM
  • Kai_Wilke's avatar
    Kai_Wilke
    Icon for MVP rankMVP
    Jan 25, 2016

    Hi Ingard,

    unfortunately there is no way to access TCP flags (PSH, RST, etc.) using iRules.

    But you may try this snipped as a starting point to identify slow server responses...

     

    when RULE_INIT {
    set static::timeout 10000   ; msec
}
when HTTP_REQUEST {
    set debug(request_url) "[HTTP::host][HTTP::uri]"
    set debug(id) [after $static::timeout {
            log local0.warn "$static::timeout msec timeout reached for \"$debug(request_url)\""
    }]
}
when HTTP_RESPONSE {
    after cancel $debug(id)
    unset -nocomplain debug
}
when CLIENT_CLOSED {
    if { [info exist debug(request_url)] } then {
        log local0.warn "Connection closed without HTTP response for \"$debug(request_url)\""
    }
}

     

    Cheers, Kai

  • ingard's avatar
    ingard
    Icon for Nimbostratus rankNimbostratus
    Feb 01, 2016

    Hi Kai and thanks for this! We're testing it right now. Do you know though, if there is any way to add which backend the request is sent to? I know we have variables like [LB::server addr]:[LB::server port], but they are not available in HTTP_REQUEST. Would I be able to switch the logic in HTTP_REQUEST to lets say LB_SELECTED?

     

    kind regards Ingard

     

  • Kai_Wilke's avatar
    Kai_Wilke
    Icon for MVP rankMVP
    Feb 01, 2016

    Hi Ingard,

    of course, you can also include other events and/or other variables to the log output.

    Here is a quick sample using the LB_SELECTED event to include the [LB::server addr] of the selected pool member...

     

    when RULE_INIT {
    set static::timeout 10000  ; msec
}
when LB_SELECTED {
    set debug(request_url) "[HTTP::host][HTTP::uri]"
    set debug(server_addr) "[LB::server addr]"
    set debug(id) [after $static::timeout {
            log local0.warn "$static::timeout msec timeout reached on Node \"$debug(server_addr)\" for \"$debug(request_url)\""
    }]
}
when HTTP_RESPONSE {
    after cancel $debug(id)
    unset -nocomplain debug
}
when CLIENT_CLOSED {
    if { [info exist debug(request_url)] } then {
        log local0.warn "Connection closed without HTTP response on Node \"$debug(server_addr)\" for \"$debug(request_url)\""
    }
}

     

    Cheers, Kai

  • Kai_Wilke's avatar
    Kai_Wilke
    Icon for MVP rankMVP
    Feb 02, 2016

    Hi Ingard,

    I've added additional error handles to avoid any can't read "debug(xyz)": no such variable errors. In addition I've moved the [after] code to the HTTP_REQUEST_SEND event to not depend on the LB_SELECTED getting triggered.

     

    when RULE_INIT {
    set static::timeout 10000  ; msec
}
when HTTP_REQUEST {
    set debug(request_url) "[HTTP::host][HTTP::uri]"
}
when HTTP_REQUEST_SEND {
    set debug(server_addr) "[LB::server addr]"
    set debug(id) [after $static::timeout {
        if { [info exist debug(server_addr)] and [info exist debug(request_url)] } then {
            log local0.warn "$static::timeout msec timeout reached on Node \"$debug(server_addr)\" for \"$debug(request_url)\""
        } elseif { [info exist debug(request_url)] } then {
            log local0.warn "$static::timeout msec timeout reached on Node \"UNKNOWN\" for \"$debug(request_url)\""
        }
    }]
}
when HTTP_RESPONSE {
    if { [info exist debug(id)] } then {
        after cancel $debug(id)
    }
    unset -nocomplain debug
}
when CLIENT_CLOSED {
    if { [info exist debug(server_addr)] and [info exist debug(request_url)] } then {
        log local0.warn "Connection closed without HTTP response on Node \"$debug(server_addr)\" for \"$debug(request_url)\""
    } elseif { [info exist debug(request_url)] } then {
        log local0.warn "Connection closed without HTTP response on Node \"UNKNOWN\" for \"$debug(request_url)\""
    }
}

     

    Cheers, Kai