search

haproxy / haproxy

HAProxy Load Balancer's development branch (mirror of git.haproxy.org)
https://git.haproxy.org/
Other
5.04k stars 800 forks source link

Abrupt close of connection on stroking connect timeout #2375

Closed lafolle closed 11 months ago

lafolle commented 11 months ago

Detailed Description of the Problem

We use haproxy as a load balancer in front of a k8 service. The clients reuse TCP connections to make HTTP requests.

At times we observe, that clients get a bad gateway error (502) from haproxy. On investigation we found that haproxy actively closed the connection after serving multiple requests on that same connection. The connection was closed for a request which was unable to connect to the allotted server in the backend (connect failed because timeout connect stroked after 100ms). For this failed request, haproxy does emit a log, stating 503 response code, but what client sees is just abrupt close of connection.

image

Expected Behavior

The client should get back 503, rather than abrupt close of connection. From the docs:

sC: The "timeout connect" stroke before a connection to the server could complete. When this happens in HTTP mode, the status code is likely a 503 or 504 here

Steps to Reproduce the Behavior

Steps

  1. Run haproxy w/ the configuration given below
  2. Trigger connect timeout when communicating w/ backend server. I do it locally by setting connect timeout 100ms in haproxy container and slowing down the network in the server container by tc qdisc add dev eth0 root netem delay 110ms
  3. Fire curl requests

Commands

curl requests:

curl -v -H 'content-type: application/json' \
    "http://${HAPROXY_WEBPORT}/garbage" \
    "http://${HAPROXY_WEBPORT}/garbage"
  1. First request gets back 503 in response
  2. Second request reuses connection from first request
  3. Connection closes for second request
  4. curl retries with a new connection that successfully returns 503

Output:

*   Trying 0.0.0.0:56582...
* Connected to 0.0.0.0 (127.0.0.1) port 56582 (#0)
> POST /garbage HTTP/1.1
> Host: 0.0.0.0:56582
> User-Agent: curl/7.77.0
> Accept: */*
> content-type: application/json
> dw-trace: pri=1
> Content-Length: 14
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 503 Service Unavailable
< content-length: 107
< cache-control: no-cache
< content-type: text/html
<
<html><body><h1>503 Service Unavailable</h1>
No server is available to handle this request.
</body></html>
* Connection #0 to host 0.0.0.0 left intact

dnslookup: 0.005740 | connect: 0.005955 | appconnect: 0.000000 | pretransfer: 0.006021 | starttransfer: 0.213194 | total: 0.213265 | size: 107
* Found bundle for host 0.0.0.0: 0x6000024008a0 [serially]
* Can not multiplex, even if we wanted to!
* Re-using existing connection! (#0) with host 0.0.0.0
* Connected to 0.0.0.0 (127.0.0.1) port 56582 (#0)
> POST /garbage1 HTTP/1.1
> Host: 0.0.0.0:56582
> User-Agent: curl/7.77.0
> Accept: */*
> content-type: application/json
> dw-trace: pri=1
> Content-Length: 14
>
* Connection died, retrying a fresh connect(retry count: 1)
* Closing connection 0
* Issue another request to this URL: 'http://0.0.0.0:56582/garbage1'
* Hostname 0.0.0.0 was found in DNS cache
*   Trying 0.0.0.0:56582...
* Connected to 0.0.0.0 (127.0.0.1) port 56582 (#1)
> POST /garbage1 HTTP/1.1
> Host: 0.0.0.0:56582
> User-Agent: curl/7.77.0
> Accept: */*
> content-type: application/json
> dw-trace: pri=1
> Content-Length: 14
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 503 Service Unavailable
< content-length: 107
< cache-control: no-cache
< content-type: text/html
<
<html><body><h1>503 Service Unavailable</h1>
No server is available to handle this request.
</body></html>
* Connection #1 to host 0.0.0.0 left intact

Logs

Note: status code for all 3 requests is 503, even for second request. 

<134>Dec  4 22:31:11 ingress[8]: {"program":"haproxy","tr":"","dw-trace":"","haproxy_dt":"04/Dec/2023:22:31:10.944","connection":{"termination_state":"sC","actconn":1,"feconn":1,"beconn":0,"srvconn":0},"queue_backend":0,"queue_srv":0,"haproxy_times":{"th":0,"ti":0,"tR":1,"tq":1,"tw":104,"tc":-1,"tr":-1,"ta":208,"td":-1,"tt":208},"retries":"+1","request":{"duration_milliseconds":208},"client":{"ips":["172.27.0.1"],"port":"48492"},"server":{"ip":"172.27.0.4","port":"80","name":""},"http":{"request":{"method":"POST","target":"/garbage","path":"/garbage","bytes":164},"version":"HTTP/1.1","response":{"status_code":503,"bytes":222}},"backend":{"name":"loadtest_service_http"},"target_server":{"name":"srv000"}}

<134>Dec  4 22:31:11 ingress[8]: {"program":"haproxy","tr":"","dw-trace":"","haproxy_dt":"04/Dec/2023:22:31:11.154","connection":{"termination_state":"sC","actconn":1,"feconn":1,"beconn":0,"srvconn":0},"queue_backend":0,"queue_srv":0,"haproxy_times":{"th":0,"ti":0,"tR":1,"tq":1,"tw":103,"tc":-1,"tr":-1,"ta":209,"td":-1,"tt":209},"retries":"+1","request":{"duration_milliseconds":209},"client":{"ips":["172.27.0.1"],"port":"48492"},"server":{"ip":"172.27.0.4","port":"80","name":""},"http":{"request":{"method":"POST","target":"/garbage1","path":"/garbage1","bytes":165},"version":"HTTP/1.1","response":{"status_code":503,"bytes":0}},"backend":{"name":"loadtest_service_http"},"target_server":{"name":"srv000"}}

<134>Dec  4 22:31:11 ingress[8]: {"program":"haproxy","tr":"","dw-trace":"","haproxy_dt":"04/Dec/2023:22:31:11.365","connection":{"termination_state":"sC","actconn":1,"feconn":1,"beconn":0,"srvconn":0},"queue_backend":0,"queue_srv":0,"haproxy_times":{"th":0,"ti":1,"tR":1,"tq":2,"tw":104,"tc":-1,"tr":-1,"ta":211,"td":-1,"tt":212},"retries":"+1","request":{"duration_milliseconds":211},"client":{"ips":["172.27.0.1"],"port":"48502"},"server":{"ip":"172.27.0.4","port":"80","name":""},"http":{"request":{"method":"POST","target":"/garbage1","path":"/garbage1","bytes":165},"version":"HTTP/1.1","response":{"status_code":503,"bytes":222}},"backend":{"name":"loadtest_service_http"},"target_server":{"name":"srv000"}}

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
    daemon
    unix-bind mode 0600
    nbthread 1
    stats socket /var/run/haproxy_admin.sock level admin expose-fd listeners mode 600
    maxconn 100000
    hard-stop-after 15s
    log stdout format rfc3164 local0
    log-tag ingress
    lua-prepend-path /etc/haproxy/lua/?.lua
    lua-load /usr/local/etc/haproxy/lua/services.lua
    spread-checks 5
    tune.http.logurilen 2500

defaults
    log global
    maxconn 100000
    option dontlognull
    option http-server-close
    option http-keep-alive
    timeout client          50s
    timeout client-fin      50s
    timeout connect         5s
    timeout http-keep-alive 1m
    timeout http-request    5s
    timeout queue           5s
    timeout server          50s
    timeout server-fin      50s
    timeout tunnel          1h
    http-reuse     always
    default-server pool-purge-delay 5m
    retries 1 # retry-on connection failure is enabled by default but default retries is 3.
    option redispatch 1

backend loadtest_service_http
    mode http
    timeout connect 100ms
    timeout http-keep-alive 100000s
    timeout http-request 100000s
    timeout server 10s
    option httpchk
    http-check send meth GET uri /v1/healthcheck/ ver HTTP/1.0
    http-request set-header X-Original-Forwarded-For %[hdr(x-forwarded-for)] if { hdr(x-forwarded-for) -m found }
    http-request del-header x-forwarded-for
    option forwardfor
    option http-server-close
    server srv000 loadtest_service_0:3142 weight 1 maxconn 200 check inter 10s
    server srv001 loadtest_service_1:3142 weight 1 maxconn 200 check inter 10s

frontend _front_http
    mode http
    bind :80
    log-format '%{+Q,+E}o{"program":"haproxy","tr":%[capture.req.hdr(0),regsub(tr=,),regsub(;.*,),json(utf8s)],"dw-trace":%[capture.req.hdr(0),json(utf8s)],"haproxy_dt":"%t","connection":{"termination_state":"%ts","actconn":%ac,"feconn":%fc,"beconn":%bc,"srvconn":%sc},"queue_backend":%bq,"queue_srv":%sq,"haproxy_times":{"th":%Th,"ti":%Ti,"tR":%TR,"tq":%Tq,"tw":%Tw,"tc":%Tc,"tr":%Tr,"ta":%Ta,"td":%Td,"tt":%Tt},"retries":"%rc","request":{"duration_milliseconds":%Ta},"client":{"ips":[%ci],"port":"%cp"},"server":{"ip":%fi,"port":"%fp","name":%[capture.req.hdr(1),json(utf8s)]},"http":{"request":{"method":%HM,"target":%HU,"path":%HP,"bytes":%U},"version":%HV,"response":{"status_code":%ST,"bytes":%B}},"backend":{"name":%b},"target_server":{"name":%s}}'
    http-request set-var(req.path) path
    http-request set-var(req.host) hdr(host),field(1,:)
    http-request set-var(req.base) var(req.host),concat(\#,req.path)
    http-request set-header X-Forwarded-Proto http

    default_backend loadtest_service_http

Output of haproxy -vv

haproxy -vv Note, same behavior is observed for haproxy version 2.2 to 2.8, inclusive.


root@af0529f22a9c:/# haproxy -vv
HA-Proxy version 2.2.31-d69335f 2023/08/19 - https://haproxy.org/
Status: long-term supported branch - will stop receiving fixes around Q2 2025.
Known bugs: http://www.haproxy.org/bugs/bugs-2.2.31.html
Running on: Linux 5.15.49-linuxkit-pr #1 SMP Thu May 25 07:17:40 UTC 2023 x86_64
Build options :
  TARGET  = linux-glibc
  CPU     = generic
  CC      = gcc
  CFLAGS  = -O2 -g -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-stringop-overflow -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_GETADDRINFO=1 USE_OPENSSL=1 USE_LUA=1 USE_ZLIB=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 +NETFILTER +NS -OBSOLETE_LINKER +OPENSSL -PCRE +PCRE2 +PCRE2_JIT -PCRE_JIT +POLL +PRCTL -PRIVATE_CACHE -PTHREAD_PSHARED +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=8).
Built with OpenSSL version : OpenSSL 1.1.1w  11 Sep 2023
Running on OpenSSL version : OpenSSL 1.1.1w  11 Sep 2023
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.3
Built with network namespace support.
Built with zlib version : 1.2.11
Running on zlib version : 1.2.11
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.36 2020-12-04
PCRE2 library supports JIT : yes
Encrypted password support via crypt(3): yes
Built with gcc compiler version 10.2.1 20210110
Built with the Prometheus exporter as a service

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)
            fcgi : mode=HTTP       side=BE        mux=FCGI
       <default> : mode=HTTP       side=FE|BE     mux=H1
              h2 : mode=HTTP       side=FE|BE     mux=H2
       <default> : mode=TCP        side=FE|BE     mux=PASS

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


### Last Outputs and Backtraces

_No response_

### Additional Information

_No response_
lafolle commented 11 months ago

(Comment went > 65k chars. Adding extra infor here)

Trace

Cmd

echo “trace h1 event +any;trace h1 level developer;trace h1 verbosity simple;trace h1 sink stdout;trace h1 start now” | socat stdio /var/run/haproxy_admin.sock

Output

[00|h1|4|/mux_h1.c:687] h1_init(): entering
[00|h1|4|/mux_h1.c:552] h1s_create(): entering : [F] - h1c=0x5646ddbbd5c0(0x00008000)
[00|h1|4|/mux_h1.c:517] h1s_new_cs(): entering : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|2|/mux_h1.c:530] notify the mux can use splicing : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|/mux_h1.c:539] h1s_new_cs(): leaving : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|/mux_h1.c:626] h1s_create(): leaving : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|/mux_h1.c:742] h1_init(): leaving : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|mux_h1.c:2359] h1_io_cb(): in : [F] - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|4|mux_h1.c:2224] h1_send(): entering : [F] - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|4|mux_h1.c:2262] h1_send(): leaving with everything sent : [F] - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|4|mux_h1.c:2274] h1_send(): leaving : [F] - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|4|mux_h1.c:2119] h1_recv(): entering : [F] - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|3|mux_h1.c:2175] data received : [F] - VAL=205 - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|4|mux_h1.c:2209] h1_recv(): leaving : [F] - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|4|mux_h1.c:2288] h1_process(): entering : [F] - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|4|mux_h1.c:2328] h1_process(): leaving : [F] - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|4|mux_h1.c:2800] h1_rcv_buf(): entering : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - VAL=15312 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|mux_h1.c:1471] h1_process_input(): entering : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - VAL=15312 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
         htx=0x5646ddba7aa0(size=16336,data=0,used=0,wrap=NO,flags=0x00000000,extra=0,first=-1,head=-1,tail=-1,tail_addr=0,head_addr=0,end_addr=0)
[00|h1|1|mux_h1.c:1496] parsing message headers : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
ingress-haproxy_idbbd770(0x00000010)
[00|h1|4|mux_h1.c:1297] h1_process_headers(): leaving : [F] [MSG_DATA, MSG_RPBEFORE] - VAL=191 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|0|mux_h1.c:1501] rcvd H1 request headers : [F] [MSG_DATA, MSG_RPBEFORE] - VAL=191 - "POST /v1/work/noauth/?client=loadtest&titleID=1111 HTTP/1.1" - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
         htx=0x5646ddba7aa0(size=16336,data=186,used=8,wrap=NO,flags=0x00000000,extra=14,first=0,head=0,tail=7,tail_addr=186,head_addr=0,end_addr=0)
[00|h1|1|mux_h1.c:1512] parsing message payload : [F] [MSG_DATA, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|mux_h1.c:1319] h1_process_data(): entering : [F] [MSG_DATA, MSG_RPBEFORE] - VAL=15062 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
ingress-haproxy_i_ingress-1     | [00|h1|2|mux_h1.c:1345] notify the mux can't use splicing anymore : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|mux_h1.c:1357] h1_process_data(): leaving : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=14 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|1|mux_h1.c:1517] rcvd H1 request payload data : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=14 - "POST /v1/work/noauth/?client=loadtest&titleID=1111 HTTP/1.1" - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
         htx=0x5646ddba7aa0(size=16336,data=200,used=9,wrap=NO,flags=0x00000000,extra=0,first=0,head=0,tail=8,tail_addr=200,head_addr=0,end_addr=0)
[00|h1|4|mux_h1.c:1415] h1_process_eom(): entering : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=15040 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|mux_h1.c:1450] h1_process_eom(): leaving : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=1 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000410)
[00|h1|0|mux_h1.c:1534] H1 request fully rcvd : [F] [MSG_DONE, MSG_RPBEFORE] - "POST /v1/work/noauth/?client=loadtest&titleID=1111 HTTP/1.1" - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000410)
         htx=0x5646ddba7aa0(size=16336,data=201,used=10,wrap=NO,flags=0x00000010,extra=0,first=0,head=0,tail=9,tail_addr=201,head_addr=0,end_addr=0)
[00|h1|2|mux_h1.c:1546] switch h1c in busy mode : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00000410)
[00|h1|4|mux_h1.c:1608] h1_process_input(): leaving : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=201 - "POST /v1/work/noauth/?client=loadtest&titleID=1111 HTTP/1.1" - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00000410)
         htx=0x5646ddba7aa0(size=16336,data=201,used=10,wrap=NO,flags=0x00000010,extra=0,first=0,head=0,tail=9,tail_addr=201,head_addr=0,end_addr=0)
[00|h1|4|mux_h1.c:2820] h1_rcv_buf(): leaving : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=201 - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00000410)
[00|h1|4|mux_h1.c:2771] h1_subscribe(): subscribe(recv) : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00000410)
[00|h1|4|/mux_h1.c:687] h1_init(): entering
[00|h1|4|/mux_h1.c:552] h1s_create(): entering : [B] - h1c=0x5646ddbc2eb0(0x00008000)
[00|h1|4|/mux_h1.c:626] h1s_create(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|/mux_h1.c:742] h1_init(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2836] h1_snd_buf(): entering : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - VAL=261 - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2843] h1_snd_buf(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2775] h1_subscribe(): subscribe(send) : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2359] h1_io_cb(): in : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2119] h1_recv(): entering : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|2|mux_h1.c:2189] failed to receive data, subscribing : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2209] h1_recv(): le0x5646ddbc2ebaving : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2745] h1_unsubscribe(): unsubscribe(send) : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2544] h1_detach(): entering : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|/mux_h1.c:640] h1s_destroy(): in : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2614] h1_detach(): killing dead connection : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|/mux_h1.c:763] h1_release(): in
[00|h1|4|/mux_h1.c:770] h1_release(): freeing h1c : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2712] h1_shutw_conn(): entering : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2720] h1_shutw_conn(): leaving : [B] - h1c=0x5646ddbc2eb0(0x00004000)
[00|h1|4|/mux_h1.c:819] h1_release(): freeing conn
[00|h1|4|mux_h1.c:2628] h1_detach(): leaving
[00|h1|4|/mux_h1.c:687] h1_init(): entering
[00|h1|4|/mux_h1.c:552] h1s_create(): entering : [B] - h1c=0x5646ddbc2eb0(0x00008000)
[00|h1|4|/mux_h1.c:626] h1s_create(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|/mux_h1.c:742] h1_init(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2836] h1_snd_buf(): entering : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - VAL=261 - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2843] h1_snd_buf(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2775] h1_subscribe(): subscribe(send) : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2359] h1_io_cb(): in : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2119] h1_recv(): entering : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|2|mux_h1.c:2189] failed to receive data, subscribing : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2209] h1_recv(): leaving : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2425] h1_timeout_task(): in
[00|h1|4|mux_h1.c:2453] h1_timeout_task(): leaving (not more h1c)
[00|h1|4|mux_h1.c:2836] h1_snd_buf(): entering : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=222 - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00000410)
[00|h1|4|mux_h1.c:1637] h1_process_output(): entering : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=222 - "HTTP/1.1 503 Service Unavailable" - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00000410)
         htx=0x5646ddba3a90(size=16336,data=222,used=7,wrap=NO,flags=0x00000018,extra=0,first=-1,head=0,tail=6,tail_addr=222,head_addr=0,end_addr=0)
[00|h1|0|mux_h1.c:1754] sending response headers : [F] [MSG_DONE, MSG_RPBEFORE] - "HTTP/1.1 503 Service Unavailable" - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00000410)
         htx=0x5646ddba3a90(size=16336,data=222,used=7,wrap=NO,flags=0x00000018,extra=0,first=-1,head=0,tail=6,tail_addr=222,head_addr=0,end_addr=0)
[00|h1|1|mux_h1.c:1887] H1 response headers xferred : [F] [MSG_DONE, MSG_LAST_LF] - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00004410)
[00|h1|1|mux_h1.c:1938] sending message data : [F] [MSG_DONE, MSG_DATA] - VAL=107 - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00004410)
         htx=0x5646ddba3a90(size=16336,data=108,used=2,wrap=NO,flags=0x00000018,extra=0,first=-1,head=5,tail=6,tail_addr=222,head_addr=0,end_addr=114)
[00|h1|1|mux_h1.c:1967] H1 response payload data xferred : [F] [MSG_DONE, MSG_DATA] - VAL=107 - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00004410)
[00|h1|2|mux_h1.c:2022] h1c no more busy : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|0|mux_h1.c:2025] H1 response fully xferred : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00004410)
imux_ngress-haproxy_ingress-1     | [00|h1|4|mux_h1.c:2075] h1_process_output(): leaving : [F] [MSG_DONE, MSG_DONE] - VAL=222 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00004410)
         htx=0x5646ddba3a90(size=16336,data=0,used=0,wrap=NO,flags=0x00000000,extra=0,first=-1,head=-1,tail=-1,tail_addr=0,head_addr=0,end_addr=0)
[00|h1|4|mux_h1.c:2224] h1_send(): entering : [F] - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|3|mux_h1.c:2241] data sent : [F] - VAL=214 - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|4|mux_h1.c:2262] h1_send(): leaving with everything sent : [F] - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|4|mux_h1.c:2274] h1_send(): leaving : [F] - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|4|mux_h1.c:2891] h1_snd_buf(): leaving : [F] [MSG_DONE, MSG_DONE] - VAL=222 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|mux_h1.c:2677] h1_shutw(): entering : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|2|mux_h1.c:2690] keep connection alive (upg_h2c|want_kal) : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|mux_h1.c:2702] h1_shutw(): leaving : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|mux_h1.c:2641] h1_shutr(): entering : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|2|mux_h1.c:2653] keep connection alive (upg_h2c|want_kal) : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|mux_h1.c:2665] h1_shutr(): leaving : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00004410)
<134>Dec  4 20:47:23 ingress[8]: {"program":"haproxy-backpressure","tr":"pri=1","dw-trace":"pri=1","haproxy_dt":"04/Dec/2023:20:47:23.674","connection":{"termination_state":"sC","actconn":1,"feconn":1,"beconn":0,"srvconn":0},"queue_backend":0,"queue_srv":0,"haproxy_times":{"th":0,"ti":0,"tR":1,"tq":1,"tw":102,"tc":-1,"tr":-1,"ta":208,"td":-1,"tt":208},"retries":"+1","request":{"duration_milliseconds":208},"client":{"ips":["172.27.0.1"],"port":"43280"},"server":{"ip":"172.27.0.4","port":"80","name":"0.0.0.0:55082"},"http":{"request":{"method":"POST","target":"/v1/work/noauth/?client=loadtest&titleID=1111","path":"/v1/work/noauth/","bytes":201},"version":"HTTP/1.1","response":{"status_code":503,"bytes":222}},"backend":{"name":"loadtest_service_http"},"target_server":{"name":"srv000"}}
[00|h1|4|mux_h1.c:2745] h1_unsubscribe(): unsubscribe(send) : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646d0x5bc3060(0x00000010)
[00|h1|4|mux_h1.c:2544] h1_detach(): entering : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|/mux_h1.c:640] h1s_destroy(): in : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2614] h1_detach(): killing dead connection : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|/mux_h1.c:763] h1_release(): in
[00|h1|4|/mux_h1.c:770] h1_release(): freeing h1c : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2712] h1_shutw_conn(): entering : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2720] h1_shutw_conn(): leaving : [B] - h1c=0x5646ddbc2eb0(0x00004000)
[00|h1|4|/mux_h1.c:819] h1_release(): freeing conn
[00|h1|4|mux_h1.c:2628] h1_detach(): leaving
[00|h1|4|mux_h1.c:2742] h1_unsubscribe(): unsubscribe(recv) : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|mux_h1.c:2544] h1_detach(): entering : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|/mux_h1.c:640] h1s_destroy(): in : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|2|/mux_h1.c:657] set idle mode on h1c, waiting for the next request : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbbd5c0(0x00018000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|/mux_h1.c:493] h1_refresh_timeout(): refreshing connection's timeout : [F] - h1c=0x5646ddbbd5c0(0x00018000)
[00|h1|4|mux_h1.c:2628] h1_detach(): leaving
ing-haproxy_ingress-1     | [00|h1|4|mux_h1.c:2425] h1_timeout_task(): in
[00|h1|4|mux_h1.c:2453] h1_timeout_task(): leaving (not more h1c)
[00|h1|4|mux_h1.c:2359] h1_io_cb(): in : [F] - h1c=0x5646ddbbd5c0(0x00018000)
[00|h1|4|mux_h1.c:2224] h1_send(): entering : [F] - h1c=0x5646ddbbd5c0(0x00018000)
[00|h1|4|mux_h1.c:2262] h1_send(): leaving with everything sent : [F] - h1c=0x5646ddbbd5c0(0x00018000)
[00|h1|4|mux_h1.c:2274] h1_send(): leaving : [F] - h1c=0x5646ddbbd5c0(0x00018000)
[00|h1|4|mux_h1.c:2119] h1_recv(): entering : [F] - h1c=0x5646ddbbd5c0(0x00018000)
[00|h1|3|mux_h1.c:2175] data received : [F] - VAL=205 - h1c=0x5646ddbbd5c0(0x00018000)
[00|h1|4|mux_h1.c:2209] h1_recv(): leaving : [F] - h1c=0x5646ddbbd5c0(0x00018000)
ing [00|h1|4|mux_h1.c:2288] h1_process(): entering : [F] - h1c=0x5646ddbbd5c0(0x00018000)
[00|h1|2|mux_h1.c:2298] K/A incoming connection, create new H1 stream : [F] - h1c=0x5646ddbbd5c0(0x00018000)
[00|h1|4|/mux_h1.c:552] h1s_create(): entering : [F] - h1c=0x5646ddbbd5c0(0x00018000)
[00|h1|4|/mux_h1.c:517] h1s_new_cs(): entering : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
[00|h1|2|/mux_h1.c:530] notify the mux can use splicing : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
[00|h1|4|/mux_h1.c:539] h1s_new_cs(): leaving : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
ing0x00000000) h1s=0x5646ddbbd770(0x00000090)
[00|h1|4|mux_h1.c:2328] h1_process(): leaving : [F] - h1c=0x5646ddbbd5c0(0x00000000)
[00|h1|4|mux_h1.c:2800] h1_rcv_buf(): entering : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - VAL=15312 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
[00|h1|4|mux_h1.c:1471] h1_process_input(): entering : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - VAL=15312 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
         htx=0x5646ddba7aa0(size=16336,data=0,used=0,wrap=NO,flags=0x00000000,extra=0,first=-1,head=-1,tail=-1,tail_addr=0,head_addr=0,end_addr=0)
[00|h1|1|mux_h1.c:1496] parsing message headers : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
ingRE] - VAL=15312 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
[00|h1|4|mux_h1.c:1297] h1_process_headers(): leaving : [F] [MSG_DATA, MSG_RPBEFORE] - VAL=191 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
[00|h1|0|mux_h1.c:1501] rcvd H1 request headers : [F] [MSG_DATA, MSG_RPBEFORE] - VAL=191 - "POST /v1/work/noauth/?client=loadtest&titleID=1111 HTTP/1.1" - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
         htx=0x5646ddba7aa0(size=16336,data=186,used=8,wrap=NO,flags=0x00000000,extra=14,first=0,head=0,tail=7,tail_addr=186,head_addr=0,end_addr=0)
[00|h1|1|mux_h1.c:1512] parsing message payload : [F] [MSG_DATA, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
ing0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
[00|h1|2|mux_h1.c:1345] notify the mux can't use splicing anymore : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
[00|h1|4|mux_h1.c:1357] h1_process_data(): leaving : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=14 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
[00|h1|1|mux_h1.c:1517] rcvd H1 request payload data : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=14 - "POST /v1/work/noauth/?client=loadtest&titleID=1111 HTTP/1.1" - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000090)
         htx=0x5646ddba7aa0(size=16336,data=200,used=9,wrap=NO,flags=0x00000000,extra=0,first=0,head=0,tail=8,tail_addr=200,head_addr=0,end_addr=0)
ingx5646ddbbd770(0x00000090)
[00|h1|4|mux_h1.c:1450] h1_process_eom(): leaving : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=1 - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000490)
[00|h1|0|mux_h1.c:1534] H1 request fully rcvd : [F] [MSG_DONE, MSG_RPBEFORE] - "POST /v1/work/noauth/?client=loadtest&titleID=1111 HTTP/1.1" - h1c=0x5646ddbbd5c0(0x00000000) h1s=0x5646ddbbd770(0x00000490)
         htx=0x5646ddba7aa0(size=16336,data=201,used=10,wrap=NO,flags=0x00000010,extra=0,first=0,head=0,tail=9,tail_addr=201,head_addr=0,end_addr=0)
[00|h1|2|mux_h1.c:1546] switch h1c in busy mode : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00000490)
ing40) h1s=0x5646ddbbd770(0x00000490)
         htx=0x5646ddba7aa0(size=16336,data=201,used=10,wrap=NO,flags=0x00000010,extra=0,first=0,head=0,tail=9,tail_addr=201,head_addr=0,end_addr=0)
[00|h1|4|mux_h1.c:2820] h1_rcv_buf(): leaving : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=201 - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00000490)
[00|h1|4|mux_h1.c:2771] h1_subscribe(): subscribe(recv) : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00000490)
[00|h1|4|/mux_h1.c:687] h1_init(): entering
[00|h1|4|/mux_h1.c:552] h1s_create(): entering : [B] - h1c=0x5646ddbc2eb0(0x00008000)
[00|h1|4|/mux_h1.c:626] h1s_create(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
ingaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2836] h1_snd_buf(): entering : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - VAL=261 - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2843] h1_snd_buf(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2775] h1_subscribe(): subscribe(send) : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2359] h1_io_cb(): in : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2119] h1_recv(): entering : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|2|mux_h1.c:2189] failed to receive data, subscribing : [B] - h1c=0x5646ddbc2eb0(0x00000000)
ingaproxy_ingress-1     | [00|h1|4|mux_h1.c:2209] h1_recv(): leaving : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|/mux_h1.c:687] h1_init(): entering
[00|h1|4|/mux_h1.c:552] h1s_create(): entering : [B] - h1c=0x5646ddbc2fb0(0x00008000)
[00|h1|4|/mux_h1.c:626] h1s_create(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00000010)
[00|h1|4|/mux_h1.c:742] h1_init(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00000010)
[00|h1|4|mux_h1.c:2775] h1_subscribe(): subscribe(send) : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00000010)
[00|h1|4|mux_h1.c:2359] h1_io_cb(): in : [B] - h1c=0x5646ddbc2fb0(0x00000000)
ing : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|2|mux_h1.c:2189] failed to receive data, subscribing : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|4|mux_h1.c:2209] h1_recv(): leaving : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|4|mux_h1.c:2745] h1_unsubscribe(): unsubscribe(send) : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2544] h1_detach(): entering : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|/mux_h1.c:640] h1s_destroy(): in : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2614] h1_detach(): killing dead connection : [B] - h1c=0x5646ddbc2eb0(0x00000000)
ingse(): in
[00|h1|4|/mux_h1.c:770] h1_release(): freeing h1c : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2712] h1_shutw_conn(): entering : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2720] h1_shutw_conn(): leaving : [B] - h1c=0x5646ddbc2eb0(0x00004000)
[00|h1|4|/mux_h1.c:819] h1_release(): freeing conn
[00|h1|4|mux_h1.c:2628] h1_detach(): leaving
[00|h1|4|/mux_h1.c:687] h1_init(): entering
[00|h1|4|/mux_h1.c:552] h1s_create(): entering : [B] - h1c=0x5646ddbc2eb0(0x00008000)
[00|h1|4|/mux_h1.c:626] h1s_create(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
ing46ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2836] h1_snd_buf(): entering : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - VAL=261 - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2843] h1_snd_buf(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2775] h1_subscribe(): subscribe(send) : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2359] h1_io_cb(): in : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2119] h1_recv(): entering : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|2|mux_h1.c:2189] failed to receive data, subscribing : [B] - h1c=0x5646ddbc2eb0(0x00000000)
ingecv(): leaving : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2425] h1_timeout_task(): in
[00|h1|4|mux_h1.c:2453] h1_timeout_task(): leaving (not more h1c)
[00|h1|4|mux_h1.c:2359] h1_io_cb(): in : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|4|mux_h1.c:2224] h1_send(): entering : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|4|mux_h1.c:2100] h1_wake_stream_for_send(): in : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00000010)
[00|h1|4|mux_h1.c:2262] h1_send(): leaving with everything sent : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|4|mux_h1.c:2274] h1_send(): leaving : [B] - h1c=0x5646ddbc2fb0(0x00000000)
ing46ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00000010)
[00|h1|4|mux_h1.c:1637] h1_process_output(): entering : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - VAL=82 - "GET /v1/healthcheck/ HTTP/1.0" - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00000010)
         htx=0x5646ddba3a90(size=16336,data=82,used=5,wrap=NO,flags=0x00000010,extra=0,first=0,head=0,tail=4,tail_addr=82,head_addr=0,end_addr=0)
[00|h1|0|mux_h1.c:1739] sending request headers : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - "GET /v1/healthcheck/ HTTP/1.0" - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00000010)
         htx=0x5646ddba3a90(size=16336,data=82,used=5,wrap=NO,flags=0x00000010,extra=0,first=0,head=0,tail=4,tail_addr=82,head_addr=0,end_addr=0)
ing00040)
[00|h1|1|mux_h1.c:1887] H1 request headers xferred : [B] [MSG_LAST_LF, MSG_RPBEFORE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
[00|h1|0|mux_h1.c:2025] H1 request fully xferred : [B] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
[00|h1|4|mux_h1.c:2075] h1_process_output(): leaving : [B] [MSG_DONE, MSG_RPBEFORE] - VAL=82 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
         htx=0x5646ddba3a90(size=16336,data=0,used=0,wrap=NO,flags=0x00000000,extra=0,first=-1,head=-1,tail=-1,tail_addr=0,head_addr=0,end_addr=0)
[00|h1|4|mux_h1.c:2224] h1_send(): entering : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|3|mux_h1.c:2241] data sent : [B] - VAL=51 - h1c=0x5646ddbc2fb0(0x00000000)
ingnd(): leaving with everything sent : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|4|mux_h1.c:2274] h1_send(): leaving : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|4|mux_h1.c:2891] h1_snd_buf(): leaving : [B] [MSG_DONE, MSG_RPBEFORE] - VAL=82 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
[00|h1|4|mux_h1.c:2800] h1_rcv_buf(): entering : [B] [MSG_DONE, MSG_RPBEFORE] - VAL=16336 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
[00|h1|4|mux_h1.c:1471] h1_process_input(): entering : [B] [MSG_DONE, MSG_RPBEFORE] - VAL=16336 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
         htx=0x5646ddba3a90(size=16336,data=0,used=0,wrap=NO,flags=0x00000000,extra=0,first=-1,head=-1,tail=-1,tail_addr=0,head_addr=0,end_addr=0)
ing, MSG_RPBEFORE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
[00|h1|4|mux_h1.c:1232] h1_process_headers(): entering : [B] [MSG_DONE, MSG_RPBEFORE] - VAL=16336 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
[00|h1|4|mux_h1.c:1252] h1_process_headers(): leaving on missing data or error : [B] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
[00|h1|4|mux_h1.c:1297] h1_process_headers(): leaving : [B] [MSG_DONE, MSG_RPBEFORE] - VAL=0 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
[00|h1|4|mux_h1.c:1608] h1_process_input(): leaving : [B] [MSG_DONE, MSG_RPBEFORE] - VAL=0 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
ing,end_addr=0)
[00|h1|4|mux_h1.c:2820] h1_rcv_buf(): leaving : [B] [MSG_DONE, MSG_RPBEFORE] - VAL=0 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
[00|h1|4|mux_h1.c:2771] h1_subscribe(): subscribe(recv) : [B] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
[00|h1|4|mux_h1.c:2677] h1_shutw(): entering : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00000040) h1s=0x5646ddbbd770(0x00000490)
[00|h1|4|mux_h1.c:2712] h1_shutw_conn(): entering : [F] - h1c=0x5646ddbbd5c0(0x00002040)
[00|h1|4|mux_h1.c:2720] h1_shutw_conn(): leaving : [F] - h1c=0x5646ddbbd5c0(0x00004040)
[00|h1|4|mux_h1.c:2702] h1_shutw(): leaving : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00004040) h1s=0x5646ddbbd770(0x00000490)
ingutr(): entering : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00004040) h1s=0x5646ddbbd770(0x00000490)
[00|h1|2|mux_h1.c:2648] shutdown on connection (error|rd_sh|wr_sh) : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00004040) h1s=0x5646ddbbd770(0x00000490)
[00|h1|4|mux_h1.c:2665] h1_shutr(): leaving : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00004040) h1s=0x5646ddbbd770(0x00000490)
ing082"},"http":{"request":{"method":"POST","target":"/v1/work/noauth/?client=loadtest&titleID=1111","path":"/v1/work/noauth/","bytes":201},"version":"HTTP/1.1","response":{"status_code":503,"bytes":0}},"backend":{"name":"loadtest_service_http"},"target_server":{"name":"srv000"}}
[00|h1|4|mux_h1.c:2745] h1_unsubscribe(): unsubscribe(send) : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2544] h1_detach(): entering : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|/mux_h1.c:640] h1s_destroy(): in : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2614] h1_detach(): killing dead connection : [B] - h1c=0x5646ddbc2eb0(0x00000000)
ingn
[00|h1|4|/mux_h1.c:770] h1_release(): freeing h1c : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2712] h1_shutw_conn(): entering : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2720] h1_shutw_conn(): leaving : [B] - h1c=0x5646ddbc2eb0(0x00004000)
[00|h1|4|/mux_h1.c:819] h1_release(): freeing conn
[00|h1|4|mux_h1.c:2628] h1_detach(): leaving
[00|h1|4|mux_h1.c:2742] h1_unsubscribe(): unsubscribe(recv) : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00004040) h1s=0x5646ddbbd770(0x00000490)
[00|h1|4|mux_h1.c:2544] h1_detach(): entering : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbbd5c0(0x00004040) h1s=0x5646ddbbd770(0x00000490)
ingh1s=0x5646ddbbd770(0x00000490)
[00|h1|4|mux_h1.c:2614] h1_detach(): killing dead connection : [F] - h1c=0x5646ddbbd5c0(0x00004000)
[00|h1|4|/mux_h1.c:763] h1_release(): in
[00|h1|4|/mux_h1.c:770] h1_release(): freeing h1c : [F] - h1c=0x5646ddbbd5c0(0x00004000)
[00|h1|4|/mux_h1.c:819] h1_release(): freeing conn
[00|h1|4|mux_h1.c:2628] h1_detach(): leaving
[00|h1|4|mux_h1.c:2425] h1_timeout_task(): in
[00|h1|4|mux_h1.c:2453] h1_timeout_task(): leaving (not more h1c)
[00|h1|4|mux_h1.c:2425] h1_timeout_task(): in
[00|h1|4|mux_h1.c:2453] h1_timeout_task(): leaving (not more h1c)
[00|h1|4|/mux_h1.c:687] h1_init(): entering
ingg : [F] - h1c=0x5646ddbc3130(0x00008000)
[00|h1|4|/mux_h1.c:517] h1s_new_cs(): entering : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|2|/mux_h1.c:530] notify the mux can use splicing : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|/mux_h1.c:539] h1s_new_cs(): leaving : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|/mux_h1.c:626] h1s_create(): leaving : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|/mux_h1.c:742] h1_init(): leaving : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
ing6ddbc3130(0x00000000)
[00|h1|4|mux_h1.c:2224] h1_send(): entering : [F] - h1c=0x5646ddbc3130(0x00000000)
[00|h1|4|mux_h1.c:2262] h1_send(): leaving with everything sent : [F] - h1c=0x5646ddbc3130(0x00000000)
[00|h1|4|mux_h1.c:2274] h1_send(): leaving : [F] - h1c=0x5646ddbc3130(0x00000000)
[00|h1|4|mux_h1.c:2119] h1_recv(): entering : [F] - h1c=0x5646ddbc3130(0x00000000)
[00|h1|3|mux_h1.c:2175] data received : [F] - VAL=205 - h1c=0x5646ddbc3130(0x00000000)
[00|h1|4|mux_h1.c:2209] h1_recv(): leaving : [F] - h1c=0x5646ddbc3130(0x00000000)
[00|h1|4|mux_h1.c:2288] h1_process(): entering : [F] - h1c=0x5646ddbc3130(0x00000000)
[00|h1|4|mux_h1.c:2328] h1_process(): leaving : [F] - h1c=0x5646ddbc3130(0x00000000)
ing0] h1_rcv_buf(): entering : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - VAL=15312 - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|mux_h1.c:1471] h1_process_input(): entering : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - VAL=15312 - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
         htx=0x5646ddba7aa0(size=16336,data=0,used=0,wrap=NO,flags=0x00000000,extra=0,first=-1,head=-1,tail=-1,tail_addr=0,head_addr=0,end_addr=0)
[00|h1|1|mux_h1.c:1496] parsing message headers : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|mux_h1.c:1232] h1_process_headers(): entering : [F] [MSG_RQBEFORE, MSG_RPBEFORE] - VAL=15312 - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
ing0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|0|mux_h1.c:1501] rcvd H1 request headers : [F] [MSG_DATA, MSG_RPBEFORE] - VAL=191 - "POST /v1/work/noauth/?client=loadtest&titleID=1111 HTTP/1.1" - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
         htx=0x5646ddba7aa0(size=16336,data=186,used=8,wrap=NO,flags=0x00000000,extra=14,first=0,head=0,tail=7,tail_addr=186,head_addr=0,end_addr=0)
[00|h1|1|mux_h1.c:1512] parsing message payload : [F] [MSG_DATA, MSG_RPBEFORE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|mux_h1.c:1319] h1_process_data(): entering : [F] [MSG_DATA, MSG_RPBEFORE] - VAL=15062 - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
ing5646ddbbd770(0x00000010)
[00|h1|4|mux_h1.c:1357] h1_process_data(): leaving : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=14 - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|1|mux_h1.c:1517] rcvd H1 request payload data : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=14 - "POST /v1/work/noauth/?client=loadtest&titleID=1111 HTTP/1.1" - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
         htx=0x5646ddba7aa0(size=16336,data=200,used=9,wrap=NO,flags=0x00000000,extra=0,first=0,head=0,tail=8,tail_addr=200,head_addr=0,end_addr=0)
[00|h1|4|mux_h1.c:1415] h1_process_eom(): entering : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=15040 - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000010)
[00|h1|4|mux_h1.c:1450] h1_process_eom(): leaving : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=1 - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000410)
inggress-haproxy_ingress-1     | [00|h1|0|mux_h1.c:1534] H1 request fully rcvd : [F] [MSG_DONE, MSG_RPBEFORE] - "POST /v1/work/noauth/?client=loadtest&titleID=1111 HTTP/1.1" - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00000410)
         htx=0x5646ddba7aa0(size=16336,data=201,used=10,wrap=NO,flags=0x00000010,extra=0,first=0,head=0,tail=9,tail_addr=201,head_addr=0,end_addr=0)
[00|h1|2|mux_h1.c:1546] switch h1c in busy mode : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbc3130(0x00000040) h1s=0x5646ddbbd770(0x00000410)
[00|h1|4|mux_h1.c:1608] h1_process_input(): leaving : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=201 - "POST /v1/work/noauth/?client=loadtest&titleID=1111 HTTP/1.1" - h1c=0x5646ddbc3130(0x00000040) h1s=0x5646ddbbd770(0x00000410)
ing0)
[00|h1|4|mux_h1.c:2820] h1_rcv_buf(): leaving : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=201 - h1c=0x5646ddbc3130(0x00000040) h1s=0x5646ddbbd770(0x00000410)
[00|h1|4|mux_h1.c:2771] h1_subscribe(): subscribe(recv) : [F] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbc3130(0x00000040) h1s=0x5646ddbbd770(0x00000410)
[00|h1|4|/mux_h1.c:687] h1_init(): entering
[00|h1|4|/mux_h1.c:552] h1s_create(): entering : [B] - h1c=0x5646ddbc2eb0(0x00008000)
[00|h1|4|/mux_h1.c:626] h1s_create(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|/mux_h1.c:742] h1_init(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
ingFORE] - VAL=261 - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2843] h1_snd_buf(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2775] h1_subscribe(): subscribe(send) : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2359] h1_io_cb(): in : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2119] h1_recv(): entering : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|2|mux_h1.c:2189] failed to receive data, subscribing : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2209] h1_recv(): leaving : [B] - h1c=0x5646ddbc2eb0(0x00000000)
ing)
[00|h1|4|mux_h1.c:2224] h1_send(): entering : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|4|mux_h1.c:2262] h1_send(): leaving with everything sent : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|4|mux_h1.c:2274] h1_send(): leaving : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|4|mux_h1.c:2119] h1_recv(): entering : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|3|mux_h1.c:2175] data received : [B] - VAL=61 - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|4|mux_h1.c:2090] h1_wake_stream_for_recv(): in : [B] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004040)
[00|h1|2|mux_h1.c:2198] read0 on connection : [B] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004048)
inging : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|4|mux_h1.c:2288] h1_process(): entering : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|2|mux_h1.c:2314] read0 on connection : [B] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004048)
[00|h1|4|mux_h1.c:2328] h1_process(): leaving : [B] - h1c=0x5646ddbc2fb0(0x00000000)
[00|h1|4|mux_h1.c:2800] h1_rcv_buf(): entering : [B] [MSG_DONE, MSG_RPBEFORE] - VAL=16336 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004048)
[00|h1|4|mux_h1.c:1471] h1_process_input(): entering : [B] [MSG_DONE, MSG_RPBEFORE] - VAL=16336 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004048)
         htx=0x5646ddb9fa80(size=16336,data=0,used=0,wrap=NO,flags=0x00000000,extra=0,first=-1,head=-1,tail=-1,tail_addr=0,head_addr=0,end_addr=0)
ingingress-1     | [00|h1|1|mux_h1.c:1496] parsing message headers : [B] [MSG_DONE, MSG_RPBEFORE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004048)
[00|h1|4|mux_h1.c:1232] h1_process_headers(): entering : [B] [MSG_DONE, MSG_RPBEFORE] - VAL=16336 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004048)
[00|h1|4|mux_h1.c:1297] h1_process_headers(): leaving : [B] [MSG_DONE, MSG_DONE] - VAL=61 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004048)
[00|h1|0|mux_h1.c:1501] rcvd H1 response headers : [B] [MSG_DONE, MSG_DONE] - VAL=61 - "HTTP/1.1 200 OK" - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004048)
         htx=0x5646ddb9fa80(size=16336,data=72,used=4,wrap=NO,flags=0x00000000,extra=0,first=0,head=0,tail=3,tail_addr=72,head_addr=0,end_addr=0)
ingDONE] - VAL=16232 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004048)
[00|h1|4|mux_h1.c:1450] h1_process_eom(): leaving : [B] [MSG_DONE, MSG_DONE] - VAL=1 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004448)
[00|h1|0|mux_h1.c:1534] H1 response fully rcvd : [B] [MSG_DONE, MSG_DONE] - "HTTP/1.1 200 OK" - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004448)
         htx=0x5646ddb9fa80(size=16336,data=73,used=5,wrap=NO,flags=0x00000010,extra=0,first=0,head=0,tail=4,tail_addr=73,head_addr=0,end_addr=0)
[00|h1|4|mux_h1.c:1608] h1_process_input(): leaving : [B] [MSG_DONE, MSG_DONE] - VAL=73 - "HTTP/1.1 200 OK" - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004448)
         htx=0x5646ddb9fa80(size=16336,data=73,used=5,wrap=NO,flags=0x00000010,extra=0,first=0,head=0,tail=4,tail_addr=73,head_addr=0,end_addr=0)
ingaproxy_ingress-1     | [00|h1|4|mux_h1.c:2820] h1_rcv_buf(): leaving : [B] [MSG_DONE, MSG_DONE] - VAL=73 - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004448)
[00|h1|4|mux_h1.c:2677] h1_shutw(): entering : [B] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004448)
[00|h1|2|mux_h1.c:2684] shutdown on connection (error|rd_sh|wr_sh) : [B] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc2fb0(0x00000000) h1s=0x5646ddbc37e0(0x00004448)
[00|h1|4|mux_h1.c:2712] h1_shutw_conn(): entering : [B] - h1c=0x5646ddbc2fb0(0x00002100)
[00|h1|4|mux_h1.c:2720] h1_shutw_conn(): leaving : [B] - h1c=0x5646ddbc2fb0(0x00004100)
[00|h1|4|mux_h1.c:2702] h1_shutw(): leaving : [B] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc2fb0(0x00004100) h1s=0x5646ddbc37e0(0x00004448)
ing_DONE, MSG_DONE] - h1c=0x5646ddbc2fb0(0x00004100) h1s=0x5646ddbc37e0(0x00004448)
[00|h1|2|mux_h1.c:2648] shutdown on connection (error|rd_sh|wr_sh) : [B] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc2fb0(0x00004100) h1s=0x5646ddbc37e0(0x00004448)
[00|h1|4|mux_h1.c:2665] h1_shutr(): leaving : [B] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc2fb0(0x00004100) h1s=0x5646ddbc37e0(0x00004448)
[00|h1|4|mux_h1.c:2359] h1_io_cb(): in : [B] - h1c=0x5646ddbc2fb0(0x00004100)
[00|h1|4|mux_h1.c:2224] h1_send(): entering : [B] - h1c=0x5646ddbc2fb0(0x00004100)
[00|h1|4|mux_h1.c:2262] h1_send(): leaving with everything sent : [B] - h1c=0x5646ddbc2fb0(0x00004100)
[00|h1|4|mux_h1.c:2274] h1_send(): leaving : [B] - h1c=0x5646ddbc2fb0(0x00004100)
ing100)
[00|h1|4|/mux_h1.c:372] h1_recv_allowed(): recv not allowed because of (error|read0) on connection : [B] - h1c=0x5646ddbc2fb0(0x00004100)
[00|h1|4|mux_h1.c:2127] h1_recv(): leaving on !recv_allowed : [B] - h1c=0x5646ddbc2fb0(0x00004100)
[00|h1|2|mux_h1.c:2198] read0 on connection : [B] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc2fb0(0x00004100) h1s=0x5646ddbc37e0(0x00004448)
[00|h1|4|mux_h1.c:2209] h1_recv(): leaving : [B] - h1c=0x5646ddbc2fb0(0x00004100)
[00|h1|4|mux_h1.c:2288] h1_process(): entering : [B] - h1c=0x5646ddbc2fb0(0x00004100)
[00|h1|2|mux_h1.c:2314] read0 on connection : [B] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc2fb0(0x00004100) h1s=0x5646ddbc37e0(0x00004448)
ing0(0x00004448)
[00|h1|4|/mux_h1.c:471] h1_refresh_timeout(): refreshing connection's timeout (half-closed) : [B] - h1c=0x5646ddbc2fb0(0x00004100)
[00|h1|4|mux_h1.c:2328] h1_process(): leaving : [B] - h1c=0x5646ddbc2fb0(0x00004100)
[00|h1|4|mux_h1.c:2544] h1_detach(): entering : [B] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc2fb0(0x00004100) h1s=0x5646ddbc37e0(0x00004448)
[00|h1|4|/mux_h1.c:640] h1s_destroy(): in : [B] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc2fb0(0x00004100) h1s=0x5646ddbc37e0(0x00004448)
[00|h1|4|mux_h1.c:2614] h1_detach(): killing dead connection : [B] - h1c=0x5646ddbc2fb0(0x00004100)
[00|h1|4|/mux_h1.c:763] h1_release(): in
[00|h1|4|/mux_h1.c:770] h1_release(): freeing h1c : [B] - h1c=0x5646ddbc2fb0(0x00004100)
ing: freeing conn
[00|h1|4|mux_h1.c:2628] h1_detach(): leaving
[00|h1|4|mux_h1.c:2425] h1_timeout_task(): in
[00|h1|4|mux_h1.c:2453] h1_timeout_task(): leaving (not more h1c)
[00|h1|4|mux_h1.c:2745] h1_unsubscribe(): unsubscribe(send) : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2544] h1_detach(): entering : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|/mux_h1.c:640] h1s_destroy(): in : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2614] h1_detach(): killing dead connection : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|/mux_h1.c:763] h1_release(): in
inghaproxy_ingress-1     | [00|h1|4|/mux_h1.c:770] h1_release(): freeing h1c : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2712] h1_shutw_conn(): entering : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2720] h1_shutw_conn(): leaving : [B] - h1c=0x5646ddbc2eb0(0x00004000)
[00|h1|4|/mux_h1.c:819] h1_release(): freeing conn
[00|h1|4|mux_h1.c:2628] h1_detach(): leaving
[00|h1|4|/mux_h1.c:687] h1_init(): entering
[00|h1|4|/mux_h1.c:552] h1s_create(): entering : [B] - h1c=0x5646ddbc2eb0(0x00008000)
[00|h1|4|/mux_h1.c:626] h1s_create(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
ing0000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2836] h1_snd_buf(): entering : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - VAL=261 - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2843] h1_snd_buf(): leaving : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2775] h1_subscribe(): subscribe(send) : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2359] h1_io_cb(): in : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2119] h1_recv(): entering : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|2|mux_h1.c:2189] failed to receive data, subscribing : [B] - h1c=0x5646ddbc2eb0(0x00000000)
ing[B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2425] h1_timeout_task(): in
[00|h1|4|mux_h1.c:2453] h1_timeout_task(): leaving (not more h1c)
[00|h1|4|mux_h1.c:2836] h1_snd_buf(): entering : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=222 - h1c=0x5646ddbc3130(0x00000040) h1s=0x5646ddbbd770(0x00000410)
[00|h1|4|mux_h1.c:1637] h1_process_output(): entering : [F] [MSG_DONE, MSG_RPBEFORE] - VAL=222 - "HTTP/1.1 503 Service Unavailable" - h1c=0x5646ddbc3130(0x00000040) h1s=0x5646ddbbd770(0x00000410)
         htx=0x5646ddb9fa80(size=16336,data=222,used=7,wrap=NO,flags=0x00000018,extra=0,first=-1,head=0,tail=6,tail_addr=222,head_addr=0,end_addr=0)
[00|h1|0|mux_h1.c:1754] sending response headers : [F] [MSG_DONE, MSG_RPBEFORE] - "HTTP/1.1 503 Service Unavailable" - h1c=0x5646ddbc3130(0x00000040) h1s=0x5646ddbbd770(0x00000410)
         htx=0x5646ddb9fa80(size=16336,data=222,used=7,wrap=NO,flags=0x00000018,extra=0,first=-1,head=0,tail=6,tail_addr=222,head_addr=0,end_addr=0)
[00|h1|1|mux_h1.c:1887] H1 response headers xferred : [F] [MSG_DONE, MSG_LAST_LF] - h1c=0x5646ddbc3130(0x00000040) h1s=0x5646ddbbd770(0x00004410)
[00|h1|1|mux_h1.c:1938] sending message data : [F] [MSG_DONE, MSG_DATA] - VAL=107 - h1c=0x5646ddbc3130(0x00000040) h1s=0x5646ddbbd770(0x00004410)
         htx=0x5646ddb9fa80(size=16336,data=108,used=2,wrap=NO,flags=0x00000018,extra=0,first=-1,head=5,tail=6,tail_addr=222,head_addr=0,end_addr=114)
[00|h1|1|mux_h1.c:1967] H1 response payload data xferred : [F] [MSG_DONE, MSG_DATA] - VAL=107 - h1c=0x5646ddbc3130(0x00000040) h1s=0x5646ddbbd770(0x00004410)
[00|h1|2|mux_h1.c:2022] h1c no more busy : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|0|mux_h1.c:2025] H1 response fully xferred : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|mux_h1.c:2075] h1_process_output(): leaving : [F] [MSG_DONE, MSG_DONE] - VAL=222 - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00004410)
         htx=0x5646ddb9fa80(size=16336,data=0,used=0,wrap=NO,flags=0x00000000,extra=0,first=-1,head=-1,tail=-1,tail_addr=0,head_addr=0,end_addr=0)
[00|h1|4|mux_h1.c:2224] h1_send(): entering : [F] - h1c=0x5646ddbc3130(0x00000000)
[00|h1|3|mux_h1.c:2241] data sent : [F] - VAL=214 - h1c=0x5646ddbc3130(0x00000000)
[00|h1|4|mux_h1.c:2262] h1_send(): leaving with everything sent : [F] - h1c=0x5646ddbc3130(0x00000000)
[00|h1|4|mux_h1.c:2274] h1_send(): lea0x5646ddbving : [F] - h1c=0x5646ddbc3130(0x00000000)
[00|h1|4|mux_h1.c:2891] h1_snd_buf(): leaving : [F] [MSG_DONE, MSG_DONE] - VAL=222 - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|mux_h1.c:2677] h1_shutw(): entering : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|2|mux_h1.c:2690] keep connection alive (upg_h2c|want_kal) : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|mux_h1.c:2702] h1_shutw(): leaving : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|mux_h1.c:2641] h1_shutr(): entering : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|2|mux_h1.c:2653] keep connection alive (upg_h2c|want_kal) : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|mux_h1.c:2665] h1_shutr(): leaving : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00004410)
<134>Dec  4 20:47:24 ingress[8]: {"program":"haproxy-backpressure","tr":"pri=1","dw-trace":"pri=1","haproxy_dt":"04/Dec/2023:20:47:24.089","connection":{"termination_state":"sC","actconn":1,"feconn":1,"beconn":0,"srvconn":0},"queue_backend":0,"queue_srv":0,"haproxy_times":{"th":0,"ti":1,"tR":2,"tq":3,"tw":102,"tc":-1,"tr":-1,"ta":207,"td":-1,"tt":208},"retries":"+1","request":{"duration_milliseconds":207},"client":{"ips":["172.27.0.1"],"port":"43286"},"server":{"ip":"172.27.0.4","port":"80","name":"0.0.0.0:55082"},"http":{"request":{"method":"POST","target":"/v1/work/noauth/?client=loadtest&titleID=1111","path":"/v1/work/noauth/","bytes":201},"version":"HTTP/1.1","response":{"status_code":503,"bytes":222}},"backend":{"name":"loadtest_service_http"},"target_server":{"name":"srv000"}}
[00|h1|4|mux_h1.c:2745] h1_unsubscribe(): unsubscribe(send) : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2544] h1_detach(): entering : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|/mux_h1.c:640] h1s_destroy(): in : [B] [MSG_RQBEFORE, MSG_RPBEFORE] - h1c=0x5646ddbc2eb0(0x00000000) h1s=0x5646ddbc3060(0x00000010)
[00|h1|4|mux_h1.c:2614] h1_detach(): killing dead connection : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|/mux_h1.c:763] h1_release(): in
[00|h1|4|/mux_h1.c:770] h1_release(): freeing h1c : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2712] h1_shutw_conn(): entering : [B] - h1c=0x5646ddbc2eb0(0x00000000)
[00|h1|4|mux_h1.c:2720] h1_shutw_conn(): leaving : [B] - h1c=0x5646ddbc2eb0(0x00004000)
[00|h1|4|/mux_h1.c:819] h1_release(): freeing conn
[00|h1|4|mux_h1.c:2628] h1_detach(): leaving
[00|h1|4|mux_h1.c:2742] h1_unsubscribe(): unsubscribe(recv) : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|mux_h1.c:2544] h1_detach(): entering : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|/mux_h1.c:640] h1s_destroy(): in : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc3130(0x00000000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|2|/mux_h1.c:657] set idle mode on h1c, waiting for the next request : [F] [MSG_DONE, MSG_DONE] - h1c=0x5646ddbc3130(0x00018000) h1s=0x5646ddbbd770(0x00004410)
[00|h1|4|/mux_h1.c:493] h1_refresh_timeout(): refreshing connection's timeout : [F] - h1c=0x5646ddbc3130(0x00018000)
[00|h1|4|mux_h1.c:2628] h1_detach(): leaving
[00|h1|4|mux_h1.c:2425] h1_timeout_task(): in
[00|h1|4|mux_h1.c:2453] h1_timeout_task(): leaving (not more h1c)
[00|h1|4|mux_h1.c:2359] h1_io_cb(): in : [F] - h1c=0x5646ddbc3130(0x00018000)
[00|h1|4|mux_h1.c:2224] h1_send(): entering : [F] - h1c=0x5646ddbc3130(0x00018000)
[00|h1|4|mux_h1.c:2262] h1_send(): leaving with everything sent : [F] - h1c=0x5646ddbc3130(0x00018000)
[00|h1|4|mux_h1.c:2274] h1_send(): leaving : [F] - h1c=0x5646ddbc3130(0x00018000)
[00|h1|4|mux_h1.c:2119] h1_recv(): entering : [F] - h1c=0x5646ddbc3130(0x00018000)
[00|h1|4|/mux_h1.c:372] h1_recv_allowed(): recv not allowed because of (error|read0) on connection : [F] - h1c=0x5646ddbc3130(0x00018000)
[00|h1|4|mux_h1.c:2209] h1_recv(): leaving : [F] - h1c=0x5646ddbc3130(0x00018000)
[00|h1|4|mux_h1.c:2288] h1_process(): entering : [F] - h1c=0x5646ddbc3130(0x00018000)
[00|h1|4|/mux_h1.c:763] h1_release(): in
[00|h1|4|/mux_h1.c:770] h1_release(): freeing h1c : [F] - h1c=0x5646ddbc3130(0x00018000)
[00|h1|4|mux_h1.c:2712] h1_shutw_conn(): entering : [F] - h1c=0x5646ddbc3130(0x00018000)
[00|h1|4|mux_h1.c:2720] h1_shutw_conn(): leaving : [F] - h1c=0x5646ddbc3130(0x0001c000)
[00|h1|4|/mux_h1.c:819] h1_release(): freeing conn
[00|h1|4|mux_h1.c:2333] h1_process(): leaving after releasing the connection
[00|h1|4|mux_h1.c:2425] h1_timeout_task(): in
[00|h1|4|mux_h1.c:2453] h1_timeout_task(): leaving (not more h1c)

strace

Command

strace -t -ff -p 8 -e trace=network

Output

strace: Process 8 attached
22:31:10 accept4(8, {sa_family=AF_INET, sin_port=htons(48492), sin_addr=inet_addr("172.27.0.1")}, [128->16], SOCK_NONBLOCK) = 12
22:31:10 setsockopt(12, SOL_TCP, TCP_NODELAY, [1], 4) = 0
22:31:10 accept4(8, 0x7ffe0bae2830, [128], SOCK_NONBLOCK) = -1 EAGAIN (Resource temporarily unavailable)
22:31:10 recvfrom(12, "POST /garbage HTTP/1.1\r\nHost: 0."..., 16320, 0, NULL, NULL) = 168
22:31:10 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 13
22:31:10 setsockopt(13, SOL_TCP, TCP_NODELAY, [1], 4) = 0
22:31:10 connect(13, {sa_family=AF_INET, sin_port=htons(3142), sin_addr=inet_addr("172.27.0.2")}, 16) = -1 EINPROGRESS (Operation now in progress)
22:31:10 recvfrom(13, 0x563aa9991a50, 16320, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
22:31:11 shutdown(13, SHUT_WR)          = 0
22:31:11 setsockopt(13, SOL_SOCKET, SO_LINGER, {l_onoff=1, l_linger=0}, 8) = 0
22:31:11 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 13
22:31:11 setsockopt(13, SOL_TCP, TCP_NODELAY, [1], 4) = 0
22:31:11 connect(13, {sa_family=AF_INET, sin_port=htons(3142), sin_addr=inet_addr("172.27.0.3")}, 16) = -1 EINPROGRESS (Operation now in progress)
22:31:11 recvfrom(13, 0x563aa9991a50, 16320, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
22:31:11 sendto(12, "HTTP/1.1 503 Service Unavailable"..., 214, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 214
22:31:11 getsockname(12, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("172.27.0.4")}, [128->16]) = 0
22:31:11 getsockopt(12, SOL_IP, 0x50 /* IP_??? */, "\2\0\0P\254\33\0\4\0\0\0\0\0\0\0\0", [16]) = 0
22:31:11 shutdown(13, SHUT_WR)          = 0
22:31:11 setsockopt(13, SOL_SOCKET, SO_LINGER, {l_onoff=1, l_linger=0}, 8) = 0
22:31:11 recvfrom(12, "POST /garbage1 HTTP/1.1\r\nHost: 0"..., 16320, 0, NULL, NULL) = 169
22:31:11 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 13
22:31:11 setsockopt(13, SOL_TCP, TCP_NODELAY, [1], 4) = 0
22:31:11 connect(13, {sa_family=AF_INET, sin_port=htons(3142), sin_addr=inet_addr("172.27.0.2")}, 16) = -1 EINPROGRESS (Operation now in progress)
22:31:11 recvfrom(13, 0x563aa9991a50, 16320, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
22:31:11 shutdown(13, SHUT_WR)          = 0
22:31:11 setsockopt(13, SOL_SOCKET, SO_LINGER, {l_onoff=1, l_linger=0}, 8) = 0
22:31:11 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 13
22:31:11 setsockopt(13, SOL_TCP, TCP_NODELAY, [1], 4) = 0
22:31:11 connect(13, {sa_family=AF_INET, sin_port=htons(3142), sin_addr=inet_addr("172.27.0.3")}, 16) = -1 EINPROGRESS (Operation now in progress)
22:31:11 recvfrom(13, 0x563aa9991a50, 16320, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
22:31:11 shutdown(12, SHUT_WR)          = 0
22:31:11 shutdown(13, SHUT_WR)          = 0
22:31:11 setsockopt(13, SOL_SOCKET, SO_LINGER, {l_onoff=1, l_linger=0}, 8) = 0
22:31:11 accept4(8, {sa_family=AF_INET, sin_port=htons(48502), sin_addr=inet_addr("172.27.0.1")}, [128->16], SOCK_NONBLOCK) = 12
22:31:11 setsockopt(12, SOL_TCP, TCP_NODELAY, [1], 4) = 0
22:31:11 accept4(8, 0x7ffe0bae2830, [128], SOCK_NONBLOCK) = -1 EAGAIN (Resource temporarily unavailable)
22:31:11 recvfrom(12, "POST /garbage1 HTTP/1.1\r\nHost: 0"..., 16320, 0, NULL, NULL) = 169
22:31:11 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 13
22:31:11 setsockopt(13, SOL_TCP, TCP_NODELAY, [1], 4) = 0
22:31:11 connect(13, {sa_family=AF_INET, sin_port=htons(3142), sin_addr=inet_addr("172.27.0.2")}, 16) = -1 EINPROGRESS (Operation now in progress)
22:31:11 recvfrom(13, 0x563aa9991a50, 16320, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
22:31:11 shutdown(13, SHUT_WR)          = 0
22:31:11 setsockopt(13, SOL_SOCKET, SO_LINGER, {l_onoff=1, l_linger=0}, 8) = 0
22:31:11 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 13
22:31:11 setsockopt(13, SOL_TCP, TCP_NODELAY, [1], 4) = 0
22:31:11 connect(13, {sa_family=AF_INET, sin_port=htons(3142), sin_addr=inet_addr("172.27.0.3")}, 16) = -1 EINPROGRESS (Operation now in progress)
22:31:11 recvfrom(13, 0x563aa9991a50, 16320, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
22:31:11 sendto(12, "HTTP/1.1 503 Service Unavailable"..., 214, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 214
22:31:11 getsockname(12, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("172.27.0.4")}, [128->16]) = 0
22:31:11 getsockopt(12, SOL_IP, 0x50 /* IP_??? */, "\2\0\0P\254\33\0\4\0\0\0\0\0\0\0\0", [16]) = 0
22:31:11 shutdown(13, SHUT_WR)          = 0
22:31:11 setsockopt(13, SOL_SOCKET, SO_LINGER, {l_onoff=1, l_linger=0}, 8) = 0
capflam commented 11 months ago

What you described is the expected behavior. On a reused client HTTP connection, a network error on server side is not reported to the client. The connection is just closed. It is mandatory to notify the client must retry. It is not specific to HAProxy (or any proxy). And indeed, curl retries. The same happens for 502, except no log message is emitted for 502 in this case. It is just an alive server that closes a idle connection. 503 are reported because it is an error and it remains a useful info for admins.

Here it does not matter the first response was a 503. This could have been a 200, it is the same. No response is returned to allow retry.

lafolle commented 11 months ago

Thanks @capflam that is super helpful! I wonder if this behavior is documented somewhere?

Question: I don't understand why the first request returns 503 while its only for the second request, on the same connection, that 503 is not returned (only logged) and the connection is closed. Envoy differs in behavior here. It returns 503 for both.

*   Trying 0.0.0.0:61238...
* Connected to 0.0.0.0 (127.0.0.1) port 61238 (#0)
> POST /garbage HTTP/1.1
> Host: 0.0.0.0:61238
> User-Agent: curl/7.77.0
> Accept: */*
> content-type: application/json
> dw-trace: pri=1
> Content-Length: 14
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 503 Service Unavailable
< content-length: 91
< content-type: text/plain
< date: Tue, 05 Dec 2023 18:27:14 GMT
< server: envoy
<
* Connection #0 to host 0.0.0.0 left intact
upstream connect error or disconnect/reset before headers. reset reason: connection failure

dnslookup: 0.006753 | connect: 0.006973 | appconnect: 0.000000 | pretransfer: 0.007042 | starttransfer: 0.013605 | total: 0.013683 | size: 91
* Found bundle for host 0.0.0.0: 0x600002d04780 [serially]
* Can not multiplex, even if we wanted to!
* Re-using existing connection! (#0) with host 0.0.0.0
* Connected to 0.0.0.0 (127.0.0.1) port 61238 (#0)
> POST /garbage HTTP/1.1
> Host: 0.0.0.0:61238
> User-Agent: curl/7.77.0
> Accept: */*
> content-type: application/json
> dw-trace: pri=1
> Content-Length: 14
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 503 Service Unavailable
< content-length: 91
< content-type: text/plain
< date: Tue, 05 Dec 2023 18:27:14 GMT
< server: envoy
<
* Connection #0 to host 0.0.0.0 left intact
upstream connect error or disconnect/reset before headers. reset reason: connection failure

Ideally, i'd prefer what envoy does, return 503 to the client whenever proxy is unable to establish a connection w/ backend server. As there is nothing wrong with client connection. Surely i'm missing something.