Duplicate messages in logs

hatifnatt · August 25, 2020, 9:32pm

I’m noticed that Haproxy emits same message twice, with prefix like [WARNING] 237/195948 (6) : and without it. I noticed this behavior while trying to run Haproxy in Docker, but with regular syslog setup situation exactly the same.

# docker run -it --rm --name haproxy -v /root/haproxy:/etc/haproxy -p 9101:9101/tcp -p 5432:5432/tcp haproxy:2.0 -f /etc/haproxy/haproxy.cfg
Proxy stats_prometheus started.
Proxy master started.
Proxy replicas started.
[NOTICE] 237/211032 (1) : New worker #1 (7) forked
[WARNING] 237/211032 (7) : Server master/dev-db-02 is DOWN, reason: Layer7 wrong status, code: 503, info: "HTTP status check returned code <3C>503<3E>", check duration: 1ms. 2 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.
Server master/dev-db-02 is DOWN, reason: Layer7 wrong status, code: 503, info: "HTTP status check returned code <3C>503<3E>", check duration: 1ms. 2 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.
[WARNING] 237/211033 (7) : Server master/dev-db-03 is DOWN, reason: Layer7 wrong status, code: 503, info: "HTTP status check returned code <3C>503<3E>", check duration: 2ms. 1 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.
Server master/dev-db-03 is DOWN, reason: Layer7 wrong status, code: 503, info: "HTTP status check returned code <3C>503<3E>", check duration: 2ms. 1 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.
[WARNING] 237/211033 (7) : Server replicas/dev-db-01 is DOWN, reason: Layer7 wrong status, code: 503, info: "HTTP status check returned code <3C>503<3E>", check duration: 5ms. 2 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.
Server replicas/dev-db-01 is DOWN, reason: Layer7 wrong status, code: 503, info: "HTTP status check returned code <3C>503<3E>", check duration: 5ms. 2 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.
Connect from 172.17.0.1:45992 to 172.17.0.2:5432 (master/TCP)
Connect from 172.17.0.1:46014 to 172.17.0.2:5432 (master/TCP)

It looks like prefixed messages are emitted by master process (pid 1 in container) and non prefixed ones by worker process (pid 7).

Configuration.

global
    log stdout format raw local0
    maxconn 100
    stats timeout 30s
    pidfile /run/haproxy.pid

defaults
    log global
    mode    tcp
    retries 2
    timeout client 30m
    timeout connect 4s
    timeout server 30m
    timeout check 5s
    option  dontlognull
    default-server init-addr last,libc,none

resolvers localdns
    parse-resolv-conf

listen stats_prometheus
    bind *:9101
    mode http
    option http-use-htx
    http-request use-service prometheus-exporter if { path /metrics }
    stats enable
    stats uri /stats

listen master
    bind *:5432
    option httpchk OPTIONS /master
    http-check expect status 200
    default-server inter 3s fall 3 rise 2 on-marked-down shutdown-sessions
    server dev-db-01 dev-db-01.domain.tld:5432 maxconn 120 check resolvers localdns port 8008
    server dev-db-02 dev-db-02.domain.tld:5432 maxconn 120 check resolvers localdns port 8008
    server dev-db-03 dev-db-03.domain.tld:5432 maxconn 120 check resolvers localdns port 8008

listen replicas
    bind *:5433
    option httpchk OPTIONS /replica
    http-check expect status 200
    default-server inter 3s fall 3 rise 2 on-marked-down shutdown-sessions
    server dev-db-01 dev-db-01.domain.tld:5432 maxconn 120 check resolvers localdns port 8008
    server dev-db-02 dev-db-02.domain.tld:5432 maxconn 120 check resolvers localdns port 8008
    server dev-db-03 dev-db-03.domain.tld:5432 maxconn 120 check resolvers localdns port 8008

If log line completely omitted from global section I still get logs like

# docker run -it --rm --name haproxy -v /root/haproxy:/etc/haproxy -p 9101:9101/tcp haproxy:2.0 -f /etc/haproxy/haproxy.cfg
[NOTICE] 237/204228 (1) : New worker #1 (6) forked
[WARNING] 237/204229 (6) : Server master/dev-db-02 is DOWN, reason: Layer7 wrong status, code: 503, info: "HTTP status check returned code <3C>503<3E>", check duration: 1ms. 2 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.
[WARNING] 237/204229 (6) : Server master/dev-db-03 is DOWN, reason: Layer7 wrong status, code: 503, info: "HTTP status check returned code <3C>503<3E>", check duration: 2ms. 1 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.
[WARNING] 237/204230 (6) : Server replicas/dev-db-01 is DOWN, reason: Layer7 wrong status, code: 503, info: "HTTP status check returned code <3C>503<3E>", check duration: 5ms. 2 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.
^C[WARNING] 237/205847 (1) : Exiting Master process...
[ALERT] 237/205847 (1) : Current worker #1 (6) exited with code 130 (Interrupt)
[WARNING] 237/205847 (1) : All workers exited. Exiting... (130)

But no connections like

Connect from 172.17.0.1:45992 to 172.17.0.2:5432 (master/TCP)
Connect from 172.17.0.1:46014 to 172.17.0.2:5432 (master/TCP)

are logged.

Question - it is possible to get rid of duplicates while still preserving all other log messages? I.e. it’s possible to suppress messages like

[WARNING] 237/204229 (6) : Server master/dev-db-02 is DOWN...

from master process while still preserving messages like

[NOTICE] 237/204228 (1) : New worker #1 (6) forked

and leaving worker messages

Server master/dev-db-02 is DOWN...

intact.

lukastribus · August 25, 2020, 9:57pm

Try the quite configuration (or the -q) parameter. This should limit the stdout output to what’s is actually configured with the log keyword, hopefully getting rid of the duplicates.

hatifnatt · August 26, 2020, 11:03am

I have tried -q parameter already, when it present it’s almost no logs.

# docker run -it --rm --name haproxy -v /root/haproxy:/etc/haproxy -p 9101:9101/tcp haproxy:2.0 -f /etc/haproxy/haproxy.cfg -q
Proxy stats_prometheus started.
Proxy master started.
Proxy replicas started.

That’s all, no status for checks, no connections logs.

lukastribus · August 26, 2020, 12:34pm

That’s what you want, isn’t it? You then configure logging as required via the log keyword.

hatifnatt · August 26, 2020, 1:12pm

Logging is configured.

global
    log stdout format raw local0
...
defaults
    log global
...

but with -q parameter almost no logs are emitted, at least to stdout. Probably if logging will be configured using syslog then log will be populated.

lukastribus · August 26, 2020, 1:37pm

Let me research that, because this doesn’t sound like expected behavior.

Can you share the output of haproxy -vv?

hatifnatt · August 26, 2020, 1:47pm

HA-Proxy version 2.0.17 2020/07/31 - https://haproxy.org/
Build options :
  TARGET  = linux-glibc
  CPU     = generic
  CC      = gcc
  CFLAGS  = -O2 -g -fno-strict-aliasing -Wdeclaration-after-statement -fwrapv -Wno-unused-label -Wno-sign-compare -Wno-unused-parameter -Wno-old-style-declaration -Wno-ignored-qualifiers -Wno-clobbered -Wno-missing-field-initializers -Wno-implicit-fallthrough -Wno-stringop-overflow -Wno-cast-function-type -Wtype-li
mits -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

Feature list : +EPOLL -KQUEUE -MY_EPOLL -MY_SPLICE +NETFILTER -PCRE -PCRE_JIT +PCRE2 +PCRE2_JIT +POLL -PRIVATE_CACHE +THREAD -PTHREAD_PSHARED -REGPARM -STATIC_PCRE -STATIC_PCRE2 +TPROXY +LINUX_TPROXY +LINUX_SPLICE +LIBCRYPT +CRYPT_H -VSYSCALL +GETADDRINFO +OPENSSL +LUA +FUTEX +ACCEPT4 -MY_ACCEPT4 +ZLIB -SLZ +CPU_AF
FINITY +TFO +NS +DL +RT -DEVICEATLAS -51DEGREES -WURFL -SYSTEMD -OBSOLETE_LINKER +PRCTL +THREAD_DUMP -EVPORTS

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

Built with multi-threading support (MAX_THREADS=64, default=2).
Built with OpenSSL version : OpenSSL 1.1.1d  10 Sep 2019
Running on OpenSSL version : OpenSSL 1.1.1d  10 Sep 2019
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 transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT IP_FREEBIND
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 PCRE2 version : 10.32 2018-09-10
PCRE2 library supports JIT : yes
Encrypted password support via crypt(3): yes
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)
              h2 : mode=HTX        side=FE|BE     mux=H2
              h2 : mode=HTTP       side=FE        mux=H2
       <default> : mode=HTX        side=FE|BE     mux=H1
       <default> : mode=TCP|HTTP   side=FE|BE     mux=PASS

Available services :
        prometheus-exporter

Available filters :
        [SPOE] spoe
        [COMP] compression
        [CACHE] cache
        [TRACE] trace

Topic		Replies	Views
Am I running HAProxy twice? Help!	1	664	October 8, 2020
Nothing useful in the logs? Help!	1	1028	March 21, 2016
HAProxy re-executing Master process Help!	2	1223	September 13, 2021
Multiple processes after restarting/reloading HAproxy? Help!	0	833	August 16, 2016
HAProxy v1.9.2 crash during reload (or shortly thereafter) Help!	11	1182	February 7, 2019

Duplicate messages in logs

Related Topics