timeout http-keep-alive is not respected when set higher than timeout client

[suligap]

Detailed Description of the Problem

The effective keep-alive timeout for connections to a frontend matches the frontend's timeout client instead of timeout http-keep-alive when the latter is set higher. Client connections are being closed after timeout client elapses with this configuration. When timeout http-keep-alive is lower than timeout client, the behavior is correct, ie. connections are closed faster than timeout client.

The same behavior is true if we replace timeout http-keep-alive with timeout http-request, ie. when timeout http-request is set to higher value than timeout client, the effective keepalive timeout is equal to timeout client.

Expected Behavior

timeout http-keep-alive:

By default, the time to wait for a new request in case of keep-alive is set
by "timeout http-request". However this is not always convenient because some
people want very short keep-alive timeouts in order to release connections
faster, and others prefer to have larger ones but still have short timeouts
once the request has started to present itself.
...
If this parameter is not set, the "http-request" timeout applies, and if both
are not set, "timeout client" still applies at the lower level. It should be
set in the frontend to take effect, unless the frontend is in TCP mode, in
which case the HTTP backend's timeout will be used.

The expected behavior is for the client connections to stay established when fast but infrequent (sent in intervals higher than timeout client) requests are being sent over these connections.

Steps to Reproduce the Behavior

1. Set a frontend's timeout http-keep-alive to a value higher than its timeout client and/or timeout http-request. Reload haproxy.
2. Establish a client connection and send a new request over that connection every N seconds, where N is higher than client timeout but lower than timeout http-keep-alive, eg:

$ python3 - << EOF
import time, requests
session = requests.Session()
while True:
    print(session.get("http://localhost:15000/"))
    time.sleep(3)
EOF

3. Observe that established connections being closed by haproxy after timeout client elapses after each request.

Do you have any idea what may have caused this?

No response

Do you have an idea how to solve the issue?

No response

What is your configuration?

global
    log /dev/log        local0
    log /dev/log        local1 notice
    chroot /var/lib/haproxy
    stats socket /run/haproxy/admin.sock mode 660 level admin expose-fd listeners
    stats timeout 30s
    user haproxy
    group haproxy
    daemon

defaults
    log global
    mode        http
    option      httplog
    option      dontlognull
    timeout connect 5000
    timeout client  50000
    timeout server  50000

frontend app-5000
   bind 0.0.0.0:15000
   timeout client 2000
   timeout http-keep-alive 10000
   default_backend app

backend app
   balance roundrobin
   server s localhost:5000

Output of haproxy -vv

HAProxy version 2.4.22-0ubuntu0.22.04.2 2023/08/14 - https://haproxy.org/
Status: long-term supported branch - will stop receiving fixes around Q2 2026.
Known bugs: http://www.haproxy.org/bugs/bugs-2.4.22.html
Running on: Linux 5.15.0-87-generic #97-Ubuntu SMP Mon Oct 2 21:09:21 UTC 2023 x86_64
Build options :
  TARGET  = linux-glibc
  CPU     = generic
  CC      = cc
  CFLAGS  = -O2 -g -O2 -flto=auto -ffat-lto-objects -flto=auto -ffat-lto-objects -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -Wall -Wextra -Wdeclaration-after-statement -fwrapv -Wno-address-of-packed-member -Wno-unused-label -Wno-sign-compare -Wno-unused-parameter -Wno-clobbered -Wno-missing-field-initializers -Wno-cast-function-type -Wtype-limits -Wshift-negative-value -Wshift-overflow=2 -Wduplicated-cond -Wnull-dereference
  OPTIONS = USE_PCRE2=1 USE_PCRE2_JIT=1 USE_OPENSSL=1 USE_LUA=1 USE_SLZ=1 USE_SYSTEMD=1 USE_PROMEX=1
  DEBUG   = 

Feature list : -51DEGREES +ACCEPT4 +BACKTRACE -CLOSEFROM +CPU_AFFINITY +CRYPT_H -DEVICEATLAS +DL +EPOLL -EVPORTS +FUTEX +GETADDRINFO -KQUEUE +LIBCRYPT +LINUX_SPLICE +LINUX_TPROXY +LUA -MEMORY_PROFILING +NETFILTER +NS -OBSOLETE_LINKER +OPENSSL -OT -PCRE +PCRE2 +PCRE2_JIT -PCRE_JIT +POLL +PRCTL -PRIVATE_CACHE -PROCCTL +PROMEX -PTHREAD_PSHARED -QUIC +RT +SLZ -STATIC_PCRE -STATIC_PCRE2 +SYSTEMD +TFO +THREAD +THREAD_DUMP +TPROXY -WURFL -ZLIB

Default settings :
  bufsize = 16384, maxrewrite = 1024, maxpollevents = 200

Built with multi-threading support (MAX_THREADS=64, default=4).
Built with OpenSSL version : OpenSSL 3.0.2 15 Mar 2022
Running on OpenSSL version : OpenSSL 3.0.2 15 Mar 2022
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports : TLSv1.0 TLSv1.1 TLSv1.2 TLSv1.3
Built with Lua version : Lua 5.3.6
Built with the Prometheus exporter as a service
Built with network namespace support.
Built with libslz for stateless compression.
Compression algorithms supported : identity("identity"), deflate("deflate"), raw-deflate("deflate"), gzip("gzip")
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT IP_FREEBIND
Built with PCRE2 version : 10.39 2021-10-29
PCRE2 library supports JIT : yes
Encrypted password support via crypt(3): yes
Built with gcc compiler version 11.4.0

Available polling systems :
      epoll : pref=300,  test result OK
       poll : pref=200,  test result OK
     select : pref=150,  test result OK
Total: 3 (3 usable), will use epoll.

Available multiplexer protocols :
(protocols marked as <default> cannot be specified using 'proto' keyword)
              h2 : mode=HTTP       side=FE|BE     mux=H2       flags=HTX|CLEAN_ABRT|HOL_RISK|NO_UPG
            fcgi : mode=HTTP       side=BE        mux=FCGI     flags=HTX|HOL_RISK|NO_UPG
              h1 : mode=HTTP       side=FE|BE     mux=H1       flags=HTX|NO_UPG
       <default> : mode=HTTP       side=FE|BE     mux=H1       flags=HTX
            none : mode=TCP        side=FE|BE     mux=PASS     flags=NO_UPG
       <default> : mode=TCP        side=FE|BE     mux=PASS     flags=

Available services : prometheus-exporter
Available filters :
        [SPOE] spoe
        [CACHE] cache
        [FCGI] fcgi-app
        [COMP] compression
        [TRACE] trace


Linux ubuntu-123 5.15.0-87-generic #97-Ubuntu SMP Mon Oct 2 21:09:21 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Last Outputs and Backtraces

No response

Additional Information

No response

[capflam]

I'm unable to reproduce the issue. It works as expected on my side, on the latest 2.4 (2.4.24) but also on 2.4.22. It seems it is pretty easy for you to reproduce the issue on a isolated environment. You may enable the H1 traces to figure out what happens using the following command on the CLI socket:

(echo "trace h1 sink buf0; trace h1 level developer; trace h1 verbosity complete; trace h1 start now; show events buf0 -w" ; cat ) | socat - /run/haproxy/admin.sock

To disable traces, just use trace 0 command.

[suligap]

Thanks for looking @capflam. Executing the following test on same instance as before (open a connection and send a request, wait 6 seconds, send another request over the same connection if it exists (create a new one if needed), wait 6 seconds):

python3 - << EOF
import time, requests
session = requests.Session()
for _ in range(2):
    print(session.get("http://haproxy:15000/"))
    time.sleep(6)
EOF

---

Scenario 1 timeout http-request higher than timeout client:

config:

global
    log /dev/log        local0
    log /dev/log        local1 notice
    chroot /var/lib/haproxy
    stats socket /run/haproxy/admin.sock mode 660 level admin expose-fd listeners
    stats timeout 30s
    user haproxy
    group haproxy
    daemon

defaults
    log global
    mode        http
    option      httplog
    option      dontlognull
    timeout connect 5000
    timeout client  50000
    timeout server  50000

frontend app-5000
   bind 0.0.0.0:15000
   timeout client 3500
   timeout http-request 15000
   default_backend app

backend app
   balance roundrobin
   server s localhost:5000

trace: here

---

Scenario 2 timeout http-keep-alive higher than timeout client:

config:

...
frontend app-5000
   bind 0.0.0.0:15000
   timeout client 3500
   timeout http-keep-alive 15000
   default_backend app
...

trace: here

I'm still observing the issue.

[capflam]

My bad, there is indeed an issue. I was fooled because I'd expect an error in logs or on python side. But in fact, the script silently re-open a new connection. But there is indeed a timeout while it should not. Reading the code, the issue is obvious. I will fix it. Many thanks !