search

haproxy / haproxy

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

2.9.6 httpchk high CPU usage when check fails #2491

Closed donnyxray closed 3 months ago

donnyxray commented 6 months ago

Detailed Description of the Problem

I'm using haproxy to do a httpchk for nodes of a MariaDB Galera Cluster. This works fine as long as all cluster nodes are reachable. As soon as 1 or more nodes become unreachable (at the network level), haproxy's CPU usage spikes all the way up to 100%.

When attaching an strace it appears haproxy is trying to re-check the failing nodes over and over again without honoring the 2s interval that I configured.

[pid 143978] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=53, tv_nsec=794916781}) = 0
[pid 143978] connect(45, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 143978] connect(46, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.19")}, 16) = -1 EALREADY (Operation already in progress)
[pid 143978] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=53, tv_nsec=794940693}) = 0
[pid 143978] epoll_wait(14, [{events=EPOLLERR, data={u32=45, u64=45}}, {events=EPOLLERR, data={u32=46, u64=46}}], 200, 915) = 2
[pid 143978] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=53, tv_nsec=794956275}) = 0
[pid 143978] connect(45, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 143978] connect(46, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.19")}, 16) = -1 EALREADY (Operation already in progress)
[pid 143978] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=53, tv_nsec=794980067}) = 0
[pid 143978] epoll_wait(14, [{events=EPOLLERR, data={u32=45, u64=45}}, {events=EPOLLERR, data={u32=46, u64=46}}], 200, 914) = 2
[pid 143978] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=53, tv_nsec=794995729}) = 0
[pid 143978] connect(45, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 143978] connect(46, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.19")}, 16) = -1 EALREADY (Operation already in progress)
[pid 143978] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=53, tv_nsec=795019291}) = 0
[pid 143978] epoll_wait(14, [{events=EPOLLERR, data={u32=45, u64=45}}, {events=EPOLLERR, data={u32=46, u64=46}}], 200, 913) = 2
[pid 143978] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=53, tv_nsec=795042845}) = 0
[pid 143978] connect(45, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EHOSTUNREACH (No route to host)
[pid 143978] connect(46, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_

Expected Behavior

haproxy's CPU usage should not change (as much) just because a few nodes are down.

Steps to Reproduce the Behavior

I use 2.9.6 as provided by https://haproxy.debian.net/ . However, I have also tried 2.8.7 provided by this repository and 2.4.22 as it comes with Ubuntu Jammy.

Config found below.

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

    # Default SSL material locations
    ca-base /etc/ssl/certs
    crt-base /etc/ssl/private

    # See: https://ssl-config.mozilla.org/#server=haproxy&server-version=2.0.3&config=intermediate
        ssl-default-bind-ciphers ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384
        ssl-default-bind-ciphersuites TLS_AES_128_GCM_SHA256:TLS_AES_256_GCM_SHA384:TLS_CHACHA20_POLY1305_SHA256
        ssl-default-bind-options ssl-min-ver TLSv1.2 no-tls-tickets

defaults
    log global
    mode    http
    option  httplog
    option  dontlognull
        timeout connect 5000
        timeout client  50000
        timeout server  50000
    errorfile 400 /etc/haproxy/errors/400.http
    errorfile 403 /etc/haproxy/errors/403.http
    errorfile 408 /etc/haproxy/errors/408.http
    errorfile 500 /etc/haproxy/errors/500.http
    errorfile 502 /etc/haproxy/errors/502.http
    errorfile 503 /etc/haproxy/errors/503.http
    errorfile 504 /etc/haproxy/errors/504.http

listen galera
    bind 127.0.0.1:3308
        mode tcp
    option tcplog
    timeout connect  10s
    timeout server  1800s
    timeout client  1800s
        option httpchk
        default-server port 3307 inter 2s downinter 5s rise 3 fall 2 slowstart 60s maxconn 256 maxqueue 128 weight 100
    server web1      10.62.0.11:3306 check backup
        server web3      10.62.0.12:3306 check backup
        server web5      10.62.0.9:3306  check
        server web8      10.62.0.18:3306 check backup
        server web9      10.62.0.19:3306 check backup

Output of haproxy -vv

HAProxy version 2.9.6-1ppa1~jammy 2024/03/01 - https://haproxy.org/
Status: stable branch - will stop receiving fixes around Q1 2025.
Known bugs: http://www.haproxy.org/bugs/bugs-2.9.6.html
Running on: Linux 5.15.0-100-generic #110-Ubuntu SMP Wed Feb 7 13:27:48 UTC 2024 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 -Wundef -Wdeclaration-after-statement -Wfatal-errors -Wtype-limits -Wshift-negative-value -Wshift-overflow=2 -Wduplicated-cond -Wnull-dereference -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 -Wno-string-plus-int -Wno-atomic-alignment
  OPTIONS = USE_OPENSSL=1 USE_LUA=1 USE_SLZ=1 USE_SYSTEMD=1 USE_OT=1 USE_QUIC=1 USE_PROMEX=1 USE_PCRE2=1 USE_PCRE2_JIT=1 USE_QUIC_OPENSSL_COMPAT=1
  DEBUG   = -DDEBUG_STRICT -DDEBUG_MEMORY_POOLS

Feature list : -51DEGREES +ACCEPT4 +BACKTRACE -CLOSEFROM +CPU_AFFINITY +CRYPT_H -DEVICEATLAS +DL -ENGINE +EPOLL -EVPORTS +GETADDRINFO -KQUEUE -LIBATOMIC +LIBCRYPT +LINUX_CAP +LINUX_SPLICE +LINUX_TPROXY +LUA +MATH -MEMORY_PROFILING +NETFILTER +NS -OBSOLETE_LINKER +OPENSSL -OPENSSL_AWSLC -OPENSSL_WOLFSSL +OT -PCRE +PCRE2 +PCRE2_JIT -PCRE_JIT +POLL +PRCTL -PROCCTL +PROMEX -PTHREAD_EMULATION +QUIC +QUIC_OPENSSL_COMPAT +RT +SHM_OPEN +SLZ +SSL -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_TGROUPS=16, MAX_THREADS=256, default=12).
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
OpenSSL providers loaded : default
Built with Lua version : Lua 5.3.6
Built with the Prometheus exporter as a service
Built with network namespace support.
Built with OpenTracing 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)
       quic : mode=HTTP  side=FE     mux=QUIC  flags=HTX|NO_UPG|FRAMED
         h2 : mode=HTTP  side=FE|BE  mux=H2    flags=HTX|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 :
    [BWLIM] bwlim-in
    [BWLIM] bwlim-out
    [CACHE] cache
    [COMP] compression
    [FCGI] fcgi-app
    [  OT] opentracing
    [SPOE] spoe
    [TRACE] trace

Last Outputs and Backtraces

No response

Additional Information

No response

a-denoyelle commented 6 months ago

I also seem to detect spurrious activity on my side when using strace , but without any trace of CPU activity.

As an aside, I saw that initially you mentionned issue #2486 by using -de option but you removed your comment ? Was your observation not valid ?

a-denoyelle commented 6 months ago

Hum nevermind I was mixing various strace output, everything in fact works as expected so far I'm unable to reproduce similar conditions :/

capflam commented 6 months ago

I'm also unable to reproduce the issue with quick tests. @donnyxray, if you have a way to easily reproduce the issue, is it possible to enable health-check traces, at least the time to observe the issue ?

To do so, you may use the following script on the CLI: 

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

To disable traces, you should use trace 0 command.

Another question, you have tested 2.8.7 and 2.4.22. Does the same issue occur on these versions ?

donnyxray commented 6 months ago 
<0>2024-03-20T02:51:28.978072+08:00 [00|check|5|/check.c:1177] process_chk_conn(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc5a490(0x00001006) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978103+08:00 [00|check|5|c/check.c:469] set_server_check_status(): in : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc5a490(0x00000806) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978108+08:00 [00|check|3|/check.c:1324] init new health-check : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978117+08:00 [00|check|5|pcheck.c:2141] tcpcheck_main(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,-) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978125+08:00 [00|check|2|pcheck.c:2184] start rules evaluation : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,-) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978131+08:00 [00|check|2|pcheck.c:2208] eval connect rule : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978137+08:00 [00|check|5|pcheck.c:1076] tcpcheck_eval_connect(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978152+08:00 [00|check|5|pcheck.c:1163] tcpcheck_eval_connect(): set port : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=3307 check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x00000000) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978308+08:00 [00|check|5|pcheck.c:1249] tcpcheck_eval_connect(): try to install mux now : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10400300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978321+08:00 [00|check|5|pcheck.c:1313] tcpcheck_eval_connect(): not connected yet : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10400300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978328+08:00 [00|check|5|pcheck.c:1326] tcpcheck_eval_connect(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=0 check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10400300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978333+08:00 [00|check|5|pcheck.c:2322] tcpcheck_main(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10400300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978339+08:00 [00|check|5|/check.c:1365] process_chk_conn(): health-check not expired : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10400300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978344+08:00 [00|check|5|/check.c:1475] process_chk_conn(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10400300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978713+08:00 [00|check|5|/check.c:1058] wake_srv_chk(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978723+08:00 [00|check|5|pcheck.c:2141] tcpcheck_main(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978730+08:00 [00|check|2|pcheck.c:2156] resume rule evaluation : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=0 check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978735+08:00 [00|check|2|pcheck.c:2208] eval connect rule : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978741+08:00 [00|check|5|pcheck.c:1076] tcpcheck_eval_connect(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978747+08:00 [00|check|5|pcheck.c:1326] tcpcheck_eval_connect(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=2 check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978753+08:00 [00|check|2|pcheck.c:2218] eval send rule : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,1) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978783+08:00 [00|check|5|pcheck.c:1344] tcpcheck_eval_send(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,1) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978828+08:00 [00|check|4|pcheck.c:1501] send data : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,1) bi=0@(nil)+0/0 bo=16384@0x7fead7012f80+0/16384
     htx=0x7fead7012f80(size=16336,data=52,used=3,wrap=NO,flags=0x00000010,extra=0,first=0,head=0,tail=2,tail_addr=52,head_addr=0,end_addr=0)
        [0] type=HTX_BLK_REQ_SL    - size=36     - addr=0       OPTIONS / HTTP/1.0
        [1] type=HTX_BLK_HDR       - size=15     - addr=36      connection: close
        [2] type=HTX_BLK_EOH       - size=1      - addr=51      <empty>

<0>2024-03-20T02:51:28.978891+08:00 [00|check|5|pcheck.c:1522] tcpcheck_eval_send(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=2 check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,1) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978898+08:00 [00|check|2|pcheck.c:2224] eval expect rule : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978903+08:00 [00|check|5|pcheck.c:1561] tcpcheck_eval_recv(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978915+08:00 [00|check|5|pcheck.c:1612] tcpcheck_eval_recv(): waiting for response : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) bi=0@0x7fead7012f80+0/16384 bo=0@(nil)+0/0
     htx=0x7fead7012f80(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)
<0>2024-03-20T02:51:28.978920+08:00 [00|check|5|pcheck.c:1621] tcpcheck_eval_recv(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=0 check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978926+08:00 [00|check|5|pcheck.c:2322] tcpcheck_main(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.978931+08:00 [00|check|5|/check.c:1098] wake_srv_chk(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987016+08:00 [00|check|5|/check.c:1058] wake_srv_chk(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987027+08:00 [00|check|5|pcheck.c:2141] tcpcheck_main(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987033+08:00 [00|check|2|pcheck.c:2156] resume rule evaluation : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=2 check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987052+08:00 [00|check|2|pcheck.c:2224] eval expect rule : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987058+08:00 [00|check|5|pcheck.c:1561] tcpcheck_eval_recv(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987093+08:00 [00|check|4|pcheck.c:1615] data received : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=145 check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=16384@0x7fead7018f40+0/16384 bo=0@(nil)+0/0
     htx=0x7fead7018f40(size=16336,data=145,used=7,wrap=NO,flags=0x00000000,extra=18446744073709551615,first=0,head=0,tail=6,tail_addr=145,head_addr=0,end_addr=0)
        [0] type=HTX_BLK_RES_SL    - size=33     - addr=0       HTTP/1.1 200 OK
        [1] type=HTX_BLK_HDR       - size=11     - addr=33      server: nginx
        [2] type=HTX_BLK_HDR       - size=33     - addr=44      date: Tue, 19 Mar 2024 18:51:28 GMT
        [3] type=HTX_BLK_HDR       - size=36     - addr=77      content-type: text/html; charset=UTF-8
        [4] type=HTX_BLK_HDR       - size=19     - addr=113     vary: Accept-Encoding
        [5] type=HTX_BLK_EOH       - size=1      - addr=132     <empty>
        [6] type=HTX_BLK_DATA      - size=12     - addr=133   

<0>2024-03-20T02:51:28.987110+08:00 [00|check|5|pcheck.c:1621] tcpcheck_eval_recv(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=2 check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=16384@0x7fead7018f40+0/16384 bo=0@(nil)+0/0
     htx=0x7fead7018f40(size=16336,data=145,used=7,wrap=NO,flags=0x00000000,extra=18446744073709551615,first=0,head=0,tail=6,tail_addr=145,head_addr=0,end_addr=0)
        [0] type=HTX_BLK_RES_SL    - size=33     - addr=0       HTTP/1.1 200 OK
        [1] type=HTX_BLK_HDR       - size=11     - addr=33      server: nginx
        [2] type=HTX_BLK_HDR       - size=33     - addr=44      date: Tue, 19 Mar 2024 18:51:28 GMT
        [3] type=HTX_BLK_HDR       - size=36     - addr=77      content-type: text/html; charset=UTF-8
        [4] type=HTX_BLK_HDR       - size=19     - addr=113     vary: Accept-Encoding
        [5] type=HTX_BLK_EOH       - size=1      - addr=132     <empty>
        [6] type=HTX_BLK_DATA      - size=12     - addr=133   

<0>2024-03-20T02:51:28.987116+08:00 [00|check|5|pcheck.c:1650] tcpcheck_eval_expect_http(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=16384@0x7fead7018f40+0/16384 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987123+08:00 [00|check|3|pcheck.c:1933] expect rule succeeded : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=16384@0x7fead7018f40+0/16384 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987128+08:00 [00|check|5|pcheck.c:1940] tcpcheck_eval_expect_http(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=2 check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=16384@0x7fead7018f40+0/16384 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987134+08:00 [00|check|5|pcheck.c:2272] tcpcheck_main(): eval tcp-check result : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=16384@0x7fead7018f40+0/16384 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987140+08:00 [00|check|5|c/check.c:469] set_server_check_status(): in : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=16384@0x7fead7018f40+0/16384 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987152+08:00 [00|check|2|pcheck.c:2309] tcp-check passed : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=16384@0x7fead7018f40+0/16384 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987157+08:00 [00|check|5|pcheck.c:2322] tcpcheck_main(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987163+08:00 [00|check|5|/check.c:1098] wake_srv_chk(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987169+08:00 [00|check|5|/check.c:1058] wake_srv_chk(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987173+08:00 [00|check|5|/check.c:1098] wake_srv_chk(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987218+08:00 [00|check|5|/check.c:1177] process_chk_conn(): entering : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987224+08:00 [00|check|3|/check.c:1372] health-check complete or aborted : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc5a490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987306+08:00 [00|check|5|/check.c:1413] process_chk_conn(): report success : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc5a490(0x00000807) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987311+08:00 [00|check|3|c/check.c:632] health-check succeeded, set server RUNNING : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc5a490(0x00000807) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:28.987316+08:00 [00|check|5|/check.c:1475] process_chk_conn(): leaving : [H] SRV=web5 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc5a490(0x00001006) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375436+08:00 [03|check|5|/check.c:1177] process_chk_conn(): entering : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5b490(0x00001006) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375456+08:00 [03|check|5|c/check.c:469] set_server_check_status(): in : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5b490(0x00000806) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375459+08:00 [03|check|3|/check.c:1324] init new health-check : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375465+08:00 [03|check|5|pcheck.c:2141] tcpcheck_main(): entering : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feacfc540c0(0x00000000) - tcp-check=(HTTP,-) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375470+08:00 [03|check|2|pcheck.c:2184] start rules evaluation : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feacfc540c0(0x00000000) - tcp-check=(HTTP,-) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375474+08:00 [03|check|2|pcheck.c:2208] eval connect rule : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feacfc540c0(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375487+08:00 [03|check|5|pcheck.c:1076] tcpcheck_eval_connect(): entering : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feacfc540c0(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375493+08:00 [03|check|5|pcheck.c:1163] tcpcheck_eval_connect(): set port : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) - VAL=3307 check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x00000000) sc=0x7feacfc540c0(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375580+08:00 [03|check|5|pcheck.c:1249] tcpcheck_eval_connect(): try to install mux now : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x10400300) sc=0x7feacfc540c0(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375592+08:00 [03|check|5|pcheck.c:1313] tcpcheck_eval_connect(): not connected yet : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x10400300) sc=0x7feacfc540c0(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375595+08:00 [03|check|5|pcheck.c:1326] tcpcheck_eval_connect(): leaving : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) - VAL=0 check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x10400300) sc=0x7feacfc540c0(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375598+08:00 [03|check|5|pcheck.c:2322] tcpcheck_main(): leaving : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x10400300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375602+08:00 [03|check|5|/check.c:1365] process_chk_conn(): health-check not expired : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x10400300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.375605+08:00 [03|check|5|/check.c:1475] process_chk_conn(): leaving : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x10400300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754114+08:00 [03|check|5|/check.c:1177] process_chk_conn(): entering : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5c490(0x00001006) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754123+08:00 [03|check|5|c/check.c:469] set_server_check_status(): in : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5c490(0x00000806) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754125+08:00 [03|check|3|/check.c:1324] init new health-check : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5c490(0x00000807) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754129+08:00 [03|check|5|pcheck.c:2141] tcpcheck_main(): entering : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5c490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feacfc54000(0x00000000) - tcp-check=(HTTP,-) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754132+08:00 [03|check|2|pcheck.c:2184] start rules evaluation : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5c490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feacfc54000(0x00000000) - tcp-check=(HTTP,-) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754135+08:00 [03|check|2|pcheck.c:2208] eval connect rule : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5c490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feacfc54000(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754138+08:00 [03|check|5|pcheck.c:1076] tcpcheck_eval_connect(): entering : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5c490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feacfc54000(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754147+08:00 [03|check|5|pcheck.c:1163] tcpcheck_eval_connect(): set port : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/UNK(0) - VAL=3307 check=0x7feaddc5c490(0x00000807) - conn=0x7feacfc58000(0x00000000) sc=0x7feacfc54000(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754212+08:00 [03|check|5|pcheck.c:1249] tcpcheck_eval_connect(): try to install mux now : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5c490(0x00000807) - conn=0x7feacfc58000(0x10400300) sc=0x7feacfc54000(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754221+08:00 [03|check|5|pcheck.c:1313] tcpcheck_eval_connect(): not connected yet : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5c490(0x00000807) - conn=0x7feacfc58000(0x10400300) sc=0x7feacfc54000(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754225+08:00 [03|check|5|pcheck.c:1326] tcpcheck_eval_connect(): leaving : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/UNK(0) - VAL=0 check=0x7feaddc5c490(0x00000807) - conn=0x7feacfc58000(0x10400300) sc=0x7feacfc54000(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754227+08:00 [03|check|5|pcheck.c:2322] tcpcheck_main(): leaving : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5c490(0x00000807) - conn=0x7feacfc58000(0x10400300) sc=0x7feacfc54000(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754230+08:00 [03|check|5|/check.c:1365] process_chk_conn(): health-check not expired : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5c490(0x00000807) - conn=0x7feacfc58000(0x10400300) sc=0x7feacfc54000(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:29.754233+08:00 [03|check|5|/check.c:1475] process_chk_conn(): leaving : [H] SRV=web9 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5c490(0x00000807) - conn=0x7feacfc58000(0x10400300) sc=0x7feacfc54000(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255845+08:00 [00|check|5|/check.c:1177] process_chk_conn(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc58490(0x00001006) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255855+08:00 [00|check|5|c/check.c:469] set_server_check_status(): in : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc58490(0x00000806) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255857+08:00 [00|check|3|/check.c:1324] init new health-check : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255861+08:00 [00|check|5|pcheck.c:2141] tcpcheck_main(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,-) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255865+08:00 [00|check|2|pcheck.c:2184] start rules evaluation : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,-) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255868+08:00 [00|check|2|pcheck.c:2208] eval connect rule : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255870+08:00 [00|check|5|pcheck.c:1076] tcpcheck_eval_connect(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255874+08:00 [00|check|5|pcheck.c:1163] tcpcheck_eval_connect(): set port : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=3307 check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x00000000) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255933+08:00 [00|check|5|pcheck.c:1249] tcpcheck_eval_connect(): try to install mux now : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10400300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255941+08:00 [00|check|5|pcheck.c:1313] tcpcheck_eval_connect(): not connected yet : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10400300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255946+08:00 [00|check|5|pcheck.c:1326] tcpcheck_eval_connect(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=0 check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10400300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255951+08:00 [00|check|5|pcheck.c:2322] tcpcheck_main(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10400300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255954+08:00 [00|check|5|/check.c:1365] process_chk_conn(): health-check not expired : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10400300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.255956+08:00 [00|check|5|/check.c:1475] process_chk_conn(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10400300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256284+08:00 [00|check|5|/check.c:1058] wake_srv_chk(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256289+08:00 [00|check|5|pcheck.c:2141] tcpcheck_main(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256292+08:00 [00|check|2|pcheck.c:2156] resume rule evaluation : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=0 check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256295+08:00 [00|check|2|pcheck.c:2208] eval connect rule : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256298+08:00 [00|check|5|pcheck.c:1076] tcpcheck_eval_connect(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256301+08:00 [00|check|5|pcheck.c:1326] tcpcheck_eval_connect(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=2 check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256304+08:00 [00|check|2|pcheck.c:2218] eval send rule : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,1) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256307+08:00 [00|check|5|pcheck.c:1344] tcpcheck_eval_send(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,1) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256327+08:00 [00|check|4|pcheck.c:1501] send data : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,1) bi=0@(nil)+0/0 bo=16384@0x7fead7018f40+0/16384
     htx=0x7fead7018f40(size=16336,data=52,used=3,wrap=NO,flags=0x00000010,extra=0,first=0,head=0,tail=2,tail_addr=52,head_addr=0,end_addr=0)
        [0] type=HTX_BLK_REQ_SL    - size=36     - addr=0       OPTIONS / HTTP/1.0
        [1] type=HTX_BLK_HDR       - size=15     - addr=36      connection: close
        [2] type=HTX_BLK_EOH       - size=1      - addr=51      <empty>

<0>2024-03-20T02:51:30.256359+08:00 [00|check|5|pcheck.c:1522] tcpcheck_eval_send(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=2 check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,1) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256362+08:00 [00|check|2|pcheck.c:2224] eval expect rule : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256365+08:00 [00|check|5|pcheck.c:1561] tcpcheck_eval_recv(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256385+08:00 [00|check|5|pcheck.c:1612] tcpcheck_eval_recv(): waiting for response : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) bi=0@0x7fead7018f40+0/16384 bo=0@(nil)+0/0
     htx=0x7fead7018f40(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)
<0>2024-03-20T02:51:30.256389+08:00 [00|check|5|pcheck.c:1621] tcpcheck_eval_recv(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=0 check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256391+08:00 [00|check|5|pcheck.c:2322] tcpcheck_main(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.256394+08:00 [00|check|5|/check.c:1098] wake_srv_chk(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10000300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268616+08:00 [00|check|5|/check.c:1058] wake_srv_chk(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268621+08:00 [00|check|5|pcheck.c:2141] tcpcheck_main(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268625+08:00 [00|check|2|pcheck.c:2156] resume rule evaluation : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=2 check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268627+08:00 [00|check|2|pcheck.c:2224] eval expect rule : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268630+08:00 [00|check|5|pcheck.c:1561] tcpcheck_eval_recv(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268655+08:00 [00|check|4|pcheck.c:1615] data received : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=145 check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=16384@0x7fead7012f80+0/16384 bo=0@(nil)+0/0
     htx=0x7fead7012f80(size=16336,data=145,used=7,wrap=NO,flags=0x00000000,extra=18446744073709551615,first=0,head=0,tail=6,tail_addr=145,head_addr=0,end_addr=0)
        [0] type=HTX_BLK_RES_SL    - size=33     - addr=0       HTTP/1.1 200 OK
        [1] type=HTX_BLK_HDR       - size=11     - addr=33      server: nginx
        [2] type=HTX_BLK_HDR       - size=33     - addr=44      date: Tue, 19 Mar 2024 18:51:30 GMT
        [3] type=HTX_BLK_HDR       - size=36     - addr=77      content-type: text/html; charset=UTF-8
        [4] type=HTX_BLK_HDR       - size=19     - addr=113     vary: Accept-Encoding
        [5] type=HTX_BLK_EOH       - size=1      - addr=132     <empty>
        [6] type=HTX_BLK_DATA      - size=12     - addr=133   

<0>2024-03-20T02:51:30.268663+08:00 [00|check|5|pcheck.c:1621] tcpcheck_eval_recv(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=2 check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=16384@0x7fead7012f80+0/16384 bo=0@(nil)+0/0
     htx=0x7fead7012f80(size=16336,data=145,used=7,wrap=NO,flags=0x00000000,extra=18446744073709551615,first=0,head=0,tail=6,tail_addr=145,head_addr=0,end_addr=0)
        [0] type=HTX_BLK_RES_SL    - size=33     - addr=0       HTTP/1.1 200 OK
        [1] type=HTX_BLK_HDR       - size=11     - addr=33      server: nginx
        [2] type=HTX_BLK_HDR       - size=33     - addr=44      date: Tue, 19 Mar 2024 18:51:30 GMT
        [3] type=HTX_BLK_HDR       - size=36     - addr=77      content-type: text/html; charset=UTF-8
        [4] type=HTX_BLK_HDR       - size=19     - addr=113     vary: Accept-Encoding
        [5] type=HTX_BLK_EOH       - size=1      - addr=132     <empty>
        [6] type=HTX_BLK_DATA      - size=12     - addr=133   

<0>2024-03-20T02:51:30.268666+08:00 [00|check|5|pcheck.c:1650] tcpcheck_eval_expect_http(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=16384@0x7fead7012f80+0/16384 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268669+08:00 [00|check|3|pcheck.c:1933] expect rule succeeded : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=16384@0x7fead7012f80+0/16384 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268672+08:00 [00|check|5|pcheck.c:1940] tcpcheck_eval_expect_http(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) - VAL=2 check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=16384@0x7fead7012f80+0/16384 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268675+08:00 [00|check|5|pcheck.c:2272] tcpcheck_main(): eval tcp-check result : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=16384@0x7fead7012f80+0/16384 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268678+08:00 [00|check|5|c/check.c:469] set_server_check_status(): in : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=16384@0x7fead7012f80+0/16384 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268681+08:00 [00|check|2|pcheck.c:2309] tcp-check passed : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) - tcp-check=(HTTP,2) bi=16384@0x7fead7012f80+0/16384 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268683+08:00 [00|check|5|pcheck.c:2322] tcpcheck_main(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268689+08:00 [00|check|5|/check.c:1098] wake_srv_chk(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268692+08:00 [00|check|5|/check.c:1058] wake_srv_chk(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268695+08:00 [00|check|5|/check.c:1098] wake_srv_chk(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268718+08:00 [00|check|5|/check.c:1177] process_chk_conn(): entering : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268723+08:00 [00|check|3|/check.c:1372] health-check complete or aborted : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc58490(0x00000807) - conn=0x7feadc995ee0(0x10040300) sc=0x7feaddc27400(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268785+08:00 [00|check|5|/check.c:1413] process_chk_conn(): report success : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc58490(0x00000807) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268789+08:00 [00|check|3|c/check.c:632] health-check succeeded, set server RUNNING : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc58490(0x00000807) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.268794+08:00 [00|check|5|/check.c:1475] process_chk_conn(): leaving : [H] SRV=web1 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc58490(0x00001006) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386519+08:00 [03|check|5|/check.c:1058] wake_srv_chk(): entering : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x105c0300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386533+08:00 [03|check|5|pcheck.c:2141] tcpcheck_main(): entering : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x105c0300) sc=0x7feacfc540c0(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386536+08:00 [03|check|0|pcheck.c:2313] report connection error : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x105c0300) sc=0x7feacfc540c0(0x00000000) - tcp-check=(HTTP,0) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386539+08:00 [03|check|5|c/check.c:829] chk_report_conn_err(): entering : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) - VAL=0 check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x105c0300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386546+08:00 [03|check|5|c/check.c:469] set_server_check_status(): in : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/UNK(0) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x105c0300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386549+08:00 [03|check|5|c/check.c:981] chk_report_conn_err(): leaving : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x105c0300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386552+08:00 [03|check|5|pcheck.c:2322] tcpcheck_main(): leaving : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x105c0300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386560+08:00 [03|check|0|/check.c:1080] report connection error : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x105c0300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386563+08:00 [03|check|5|/check.c:1098] wake_srv_chk(): leaving : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x105c0300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386568+08:00 [03|check|5|/check.c:1058] wake_srv_chk(): entering : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x105c0300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386571+08:00 [03|check|5|/check.c:1098] wake_srv_chk(): leaving : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x105c0300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386574+08:00 [03|check|5|/check.c:1177] process_chk_conn(): entering : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x105c0300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386577+08:00 [03|check|3|/check.c:1372] health-check complete or aborted : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5b490(0x00000807) - conn=0x7feacfc580e0(0x105c0300) sc=0x7feacfc540c0(0x00000000) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386597+08:00 [03|check|5|/check.c:1403] process_chk_conn(): report failure : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5b490(0x00000807) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386602+08:00 [03|check|3|c/check.c:598] health-check failed, set server DOWN : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5b490(0x00000807) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.386604+08:00 [03|check|5|/check.c:1475] process_chk_conn(): leaving : [H] SRV=web8 status=0/3 DOWN - last=L4CON(8)/FAIL(2) check=0x7feaddc5b490(0x00001006) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.592121+08:00 [07|check|5|/check.c:1177] process_chk_conn(): entering : [H] SRV=web3 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc59490(0x00001006) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.592142+08:00 [07|check|5|c/check.c:469] set_server_check_status(): in : [H] SRV=web3 status=2/2 UP - last=L7OK(15)/PASS(3) check=0x7feaddc59490(0x00000806) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.592147+08:00 [07|check|3|/check.c:1324] init new health-check : [H] SRV=web3 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc59490(0x00000807) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.592155+08:00 [07|check|5|pcheck.c:2141] tcpcheck_main(): entering : [H] SRV=web3 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc59490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feacec54000(0x00000000) - tcp-check=(HTTP,-) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.592162+08:00 [07|check|2|pcheck.c:2184] start rules evaluation : [H] SRV=web3 status=2/2 UP - last=L7OK(15)/UNK(0) check=0x7feaddc59490(0x00000807) - conn=(nil)(0x00000000) sc=0x7feacec54000(0x00000000) - tcp-check=(HTTP,-) bi=0@(nil)+0/0 bo=0@(nil)+0/0
<0>2024-03-20T02:51:30.592169+08:00 [07|check|2|pcheck.c:2208] eval connect rule : [H] SRV=web3 status=2/2 UP - last=L7OK(15)/UNK(0) c
capflam commented 6 months ago

On this trace, there is no loop, at least from the health-checks point of view. Could you confirm you observed a connect storm when this trace was produced ?

donnyxray commented 6 months ago

Health check traces: haproxy.txt

Yes, 2.8.7 and 2.4.22 have the same issue.

The strace still looks like before:

[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643599903}) = 0
[pid 261566] epoll_ctl(6, EPOLL_CTL_MOD, 55, {events=EPOLLIN|EPOLLRDHUP, data={u32=55, u64=55}} <unfinished ...>
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16 <unfinished ...>
[pid 261566] <... epoll_ctl resumed>)   = 0
[pid 261569] <... connect resumed>)     = -1 EALREADY (Operation already in progress)
[pid 261566] clock_gettime(CLOCK_THREAD_CPUTIME_ID,  <unfinished ...>
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID,  <unfinished ...>
[pid 261566] <... clock_gettime resumed>{tv_sec=5, tv_nsec=504366543}) = 0
[pid 261569] <... clock_gettime resumed>{tv_sec=1912, tv_nsec=643659131}) = 0
[pid 261566] epoll_wait(6,  <unfinished ...>
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 998) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643703989}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643739433}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 997) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643771511}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643790887}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 996) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643807163}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643823325}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 996) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643839597}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643856001}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 995) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643871355}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643887691}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 995) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643903125}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643919641}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 994) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643935063}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643951019}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 994) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643966461}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=643983045}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 993) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644025639}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644063855}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 993) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644081889}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644100441}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 992) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644116145}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644132333}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 992) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644147771}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644164465}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 991) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644179903}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644196283}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 991) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644211533}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644227883}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 990) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644243231}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644259207}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 990) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644274489}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644291603}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 989) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644340869}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16 <unfinished ...>
[pid 261566] <... epoll_wait resumed>[{events=EPOLLIN|EPOLLRDHUP, data={u32=55, u64=55}}], 200, 1278) = 1
[pid 261569] <... connect resumed>)     = -1 EALREADY (Operation already in progress)
[pid 261566] clock_gettime(CLOCK_THREAD_CPUTIME_ID,  <unfinished ...>
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID,  <unfinished ...>
[pid 261566] <... clock_gettime resumed>{tv_sec=5, tv_nsec=504413481}) = 0
[pid 261569] <... clock_gettime resumed>{tv_sec=1912, tv_nsec=644379937}) = 0
[pid 261566] recvfrom(55,  <unfinished ...>
[pid 261569] epoll_wait(17,  <unfinished ...>
[pid 261566] <... recvfrom resumed>"HTTP/1.1 200 OK\r\nServer: nginx\r\nDate: Tue, 19 Mar 2024 20:52:21 GMT\r\nContent-Type: text/html; charset=UTF-8\r\nConnection: close\r\nVary: Accept-Encoding\r\n\r\nWSREP READY\n", 15360, 0, NULL, NULL) = 165
[pid 261569] <... epoll_wait resumed>[{events=EPOLLERR, data={u32=57, u64=57}}], 200, 989) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644409853}) = 0
[pid 261566] close(55 <unfinished ...>
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16 <unfinished ...>
[pid 261566] <... close resumed>)       = 0
[pid 261569] <... connect resumed>)     = -1 EALREADY (Operation already in progress)
[pid 261566] clock_gettime(CLOCK_THREAD_CPUTIME_ID,  <unfinished ...>
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID,  <unfinished ...>
[pid 261566] <... clock_gettime resumed>{tv_sec=5, tv_nsec=504734767}) = 0
[pid 261569] <... clock_gettime resumed>{tv_sec=1912, tv_nsec=644434323}) = 0
[pid 261566] epoll_wait(6,  <unfinished ...>
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 988) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644450911}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644467337}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 987) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644483297}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644499663}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 987) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644514907}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644531443}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 986) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644546503}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644562363}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 986) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644588250}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644605892}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 985) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644621696}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644638252}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 985) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644653756}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644670472}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 984) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644685806}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644702024}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 984) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644717530}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644733678}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 983) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644749470}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644765504}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 983) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644780706}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644796752}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 982) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644812544}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EALREADY (Operation already in progress)
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644828758}) = 0
[pid 261569] epoll_wait(17, [{events=EPOLLERR, data={u32=57, u64=57}}], 200, 982) = 1
[pid 261569] clock_gettime(CLOCK_THREAD_CPUTIME_ID, {tv_sec=1912, tv_nsec=644844108}) = 0
[pid 261569] connect(57, {sa_family=AF_INET, sin_port=htons(3307), sin_addr=inet_addr("10.62.0.18")}, 16) = -1 EHOSTUNREACH (No route to host)
wtarreau commented 5 months ago

I think we're on a dirty corner case where the system disagrees with itself by not reporting the error on connect() but seeing it on the socket. Could you please try to apply the following patch which takes special care of this situation ?

diff --git a/src/sock.c b/src/sock.c
index 2d7d920c68..f1dfea404e 100644
--- a/src/sock.c
+++ b/src/sock.c
@@ -818,6 +818,13 @@ int sock_conn_check(struct connection *conn)
        return 0;

  wait:
+       /* we may arrive here due to connect() misleadingly reporting EALREADY
+        * in some corner cases while the system disagrees and reports an error
+        * on the FD.
+        */
+       if (fdtab[fd].state & FD_POLL_ERR)
+               goto out_error;
+
        fd_cant_send(fd);
        fd_want_send(fd);
        return 0;
wtarreau commented 5 months ago

@donnyxray even playing with ICMP unreachables of various types (net, host, port, admin), TCP reset, locally unreachable routes etc I still cannot provoke this specific case. I'm also always seeing IN/OUT/HUP in addition to ERR being reported. I think I've never observed EPOLLERR alone in fact. That's quite strangee. There's really something weird about this setup but I can't figure what. I'm wondering if it could be a matter of lack of source ports (though it should not return that fast with EINPROGRESS) or anything else, or maybe the source IP vanishing under us, I really don't know. Anyway I've prepared a commit with the patch above explaining this situation. I'll wait a bit in case you have the opportunity to test it, otherwise I'll eventually merge it.

wtarreau commented 5 months ago

Now fixed in master.