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

[ingard]

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

[Kai_Wilke]

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

[JRahm]

FYI @Kai_Wilke, you can access the TCP flags in the FLOW_INIT event with the DATAGRAM::tcp flags command.

[ingard]

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]

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]

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