Enable logging for error 408 / http keep-alive timeout

Help!
1

Hi all,
I recently discovered an issue with lost traffic due too HTTP keep-alive race condition while running haproxy 1.6.3. Currently, I would like to setup haproxy to log occurences of 408 being pushed from server to client.

The traffic was being sent exactly every 30s while haproxy timeout was also set to 30s.

timeout connect 5000
timeout client 30000
timeout server 30000

I realized that some traffic is being lost due to http keep-alive race condition after a session with wireshark (see the attached image

http-keep-alive-race-condition-example-408
http-keep-alive-race-condition-example-408.png1295×216 75.5 KB
).
Frequently, haproxy timeout triggered and the client would send traffic at the exactly same moment. I assume haproxy send 408 with FIN,ACK (encrypted). The client did not recoginze 408 sent by haproxy - instead it got an EOF error. The fix was to set haproxy timeout to something less round so it does not clash with client sending traffic.

Haproxy did not log 408 with the below logging setup.

Is it possible to log 408 / http keep-alive timeout occurrences in haproxy log?

Our haproxy logging config:

log     global
log 127.0.0.1 local0

option httplog
log global

option http-buffer-request
declare capture request len 400
http-request capture req.body id 0
# log just body: log-format {"%[capture.req.hdr(0)]"}

# declare a placeholder for content inside request headers
capture request  header TrickToCaptureContent len 400

capture request  header Host len 25
capture request  header Content-Length len 10
capture request  header Content-Type len 20
capture request  header Date len 15
capture request  header Referer len 20

capture response header Server len 25
capture response header Content-Length len 10
capture response header Cache-Control len 8
capture request  header Content-Type len 20
capture request  header Date len 25
capture response header Via len 20
capture response header Location len 20
capture request  header X-Application-Context len 15

capture cookie USER_TOKEN len 15

log-format httpsfrontend\ %{+Q}o\ %{-Q}ci\ -\ -\ [%T]\ %r\ %ST\ %B\ \"\"\ \"\"\ %cp\ %ms\ %ft\ %b\ %s\ \%Tq\ %Tw\ %Tc\ %Tr\ %Tt\ %tsc\ %ac\ %fc\ %bc\ %sc\ %rc\ %sq\ %bq\ COOKIES:\ %CC\ %CS\ REQUEST_CONTENT_AND_HEADERS:\ %hr\ HEADERS_RESPONSE:\ %hs

This condition is described in more detail here

Regards, Artur

2

408 is definitely logged by default in haproxy, along with a cR closed code. I don’t have time right know to run your setup through a local repro here, but you will definitely see in a standard logging configuration.

You can disable the 408 behavior with option http-ignore-probes, but you may loose data when you hit this race condition.

My recommendation would be to fix the http client to handle 408 errors as per the HTTP spec.