Welcome! Log In Create A New Profile

Advanced

haproxy 1.8.1 email-alert with log-health-checks, 100% cpu usage / mailbomb

Posted by PiBa-NL 
Hi List,

Hereby a seemingly new case of 100% cpu usage / mailbomb on FreeBSD 11.1.

Below seems to be the (close to) minimal config, there is no mailserver,
and no webserver listening on those ports.. The stats page is not
requested. (But without it haproxy wont start as it doesn't see any
bind's then..)

If a mailserver is listening, then 800+ mails are received..

Regards,
PiBa-NL / Pieter

defaults
    option log-health-checks
listen HAProxyLocalStats
    bind 127.0.0.1:42200 name localstats
    mode http
    stats enable
mailers globalmailers
    mailer ex01 127.0.0.1:3325
backend ServerTest_http_ipv4
    mode            http
    email-alert mailers            globalmailers
    email-alert level            info
    email-alert from            haproxy@pfsense.local
    email-alert to            me@me.tld
    server            ServerTest 127.0.0.1:33443 check inter 10000

[email protected]:~ # uname -a
FreeBSD  11.1-RELEASE-p4 FreeBSD 11.1-RELEASE-p4 #0: Tue Nov 14 06:12:40
UTC 2017 root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC
amd64

It produces like 600+ lines of console output, ive numbered some of the
lines and skipped most repeating ones..:
[email protected]:~ # haproxy -f /root/hapconf.conf
[WARNING] 337/193939 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection error during SSL handshake (Broken pipe)",
check duration: 0ms, status: 0/2 DOWN.
[WARNING] 337/193939 (44649) : Server ServerTest_http_ipv4/ServerTest is
DOWN. 0 active and 0 backup servers left. 0 sessions active, 0 requeued,
0 remaining in queue.
[ALERT] 337/193939 (44649) : backend 'ServerTest_http_ipv4' has no
server available!
[WARNING] 337/193939 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 1ms, status: 0/1 DOWN.
[WARNING] 337/193939 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
[WARNING] 337/193939 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
[WARNING] 337/193939 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
[WARNING] 337/193939 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
10[WARNING] 337/193939 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
[WARNING] 337/193939 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
[WARNING] 337/193939 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
[WARNING] 337/193939 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
[WARNING] 337/193939 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
.... repeating same line over and over...
203[WARNING] 337/193939 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
204[WARNING] 337/193942 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 3059ms, status: 0/1 DOWN.
205[WARNING] 337/193942 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
.... repeating same line over and over...
403[WARNING] 337/193942 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
404 [WARNING] 337/193945 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 3063ms, status: 0/1 DOWN.
405[WARNING] 337/193945 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
.... repeating same line over and over...
603[WARNING] 337/193945 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
604 [WARNING] 337/193948 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 3006ms, status: 0/1 DOWN.
605[WARNING] 337/193948 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
.... repeating same line over and over...
622 [WARNING] 337/193948 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "Connection refused at step 1 of tcp-check (connect)",
check duration: 0ms, status: 0/1 DOWN.
623 [WARNING] 337/193948 (44649) : Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: "TCPCHK error establishing connection at step 1:
Connection refused", check duration: 0ms, status: 0/1 DOWN.
at this point CPU starts using 100%


[email protected]:~ # /usr/local/bin/gdb --pid 44672
GNU gdb (GDB) 8.0.1 [GDB v8.0.1 for FreeBSD]
Copyright (C) 2017 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later
http://gnu.org/licenses/gpl.html
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-portbld-freebsd11.1".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
http://www.gnu.org/software/gdb/bugs/.
Find the GDB manual and other documentation resources online at:
http://www.gnu.org/software/gdb/documentation/.
For help, type "help".
Type "apropos word" to search for commands related to "word".
Attaching to process 44672
Reading symbols from /usr/local/sbin/haproxy...done.
Reading symbols from /lib/libcrypt.so.5...(no debugging symbols
found)...done.
Reading symbols from /lib/libz.so.6...(no debugging symbols found)...done.
Reading symbols from /lib/libthr.so.3...(no debugging symbols found)...done.
Reading symbols from /usr/local/lib/libssl.so.9...(no debugging symbols
found)...done.
Reading symbols from /usr/local/lib/libcrypto.so.9...(no debugging
symbols found)...done.
Reading symbols from /usr/local/lib/liblua-5.3.so...(no debugging
symbols found)...done.
Reading symbols from /lib/libm.so.5...(no debugging symbols found)...done.
Reading symbols from /lib/libc.so.7...(no debugging symbols found)...done.
Reading symbols from /libexec/ld-elf.so.1...(no debugging symbols
found)...done.
[Switching to LWP 100087 of process 44672]
0x0000000000502814 in enqueue_one_email_alert (p=0x8024cbc00,
s=0x8024df000, q=0x80243b600,
    msg=0x7fffffffdce0 "Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: \"TCPCHK error establishing connection at step 1:
Connection refused\", check duration: 0ms, stat"...) at src/checks.c:3394
3394            HA_SPIN_LOCK(EMAIL_ALERTS_LOCK, &q->lock);
(gdb) bt full
#0  0x0000000000502814 in enqueue_one_email_alert (p=0x8024cbc00,
s=0x8024df000, q=0x80243b600,
    msg=0x7fffffffdce0 "Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: \"TCPCHK error establishing connection at step 1:
Connection refused\", check duration: 0ms, stat"...) at src/checks.c:3394
        __pl_l = 0x80243b7d0
        __pl_r = 4294967300
        strs = {0x628738 "DATA\r\n", 0x0}
        strs = {0x62878d "QUIT\r\n", 0x0}
        alert = 0x8024a3000
        tcpcheck = 0x80258f540
        check = 0x80243b610
#1  0x00000000004fb0c2 in enqueue_email_alert (p=0x8024cbc00, s=0x8024df000,
    msg=0x7fffffffdce0 "Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: \"TCPCHK error establishing connection at step 1:
Connection refused\", check duration: 0ms, stat"...) at src/checks.c:3412
        i = 0
        mailer = 0x802432540
#2  0x00000000004fb02a in send_email_alert (s=0x8024df000, level=6,
format=0x63202d "%s") at src/checks.c:3443
        argp = {{gp_offset = 32, fp_offset = 48, overflow_arg_area =
0x7fffffffe100, reg_save_area = 0x7fffffffdbf0}}
        buf = "Health check for server ServerTest_http_ipv4/ServerTest
failed, reason: Layer4 connection problem, info: \"TCPCHK error
establishing connection at step 1: Connection refused\", check duration:
0ms, stat"...
        len = 212
        p = 0x8024cbc00
#3  0x00000000004f7b01 in set_server_check_status (check=0x80243b610,
status=8,
    desc=0x802464300 "Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: \"TCPCHK error establishing connection at step 1:
Connection refused\", check duration: 0ms, stat"...) at src/checks.c:294
        s = 0x8024df000
        prev_status = 1
        report = 0
#4  0x00000000004fd65e in tcpcheck_main (check=0x80243b610) at
src/checks.c:2812
        proto = 0x89c568 <proto_tcpv4>
        xprt = 0x89eec0 <raw_sock>
        contentptr = 0x80249dfe0 "\300.I\002\b"
        comment = 0x0
        next = 0x802492e80
        done = 0
        ret = 20480
        step = 1
        cs = 0x80249dfa0
        conn = 0x80243c480
        s = 0x8024df000
        t = 0x80242d0a0
        head = 0x80249dfe0
        retcode = 0
#5  0x000000000050155d in connect_conn_chk (t=0x80242d0a0) at
src/checks.c:1548
        check = 0x80243b610
        s = 0x8024df000
        cs = 0x0
        conn = 0x0
        proto = 0x1000800000000
        tcp_rule = 0x802492ec0
        ret = 0
        quickack = 0
#6  0x00000000005000a8 in process_chk_conn (t=0x80242d0a0) at
src/checks.c:2135
        check = 0x80243b610
        s = 0x8024df000
        cs = 0x0
        conn = 0x0
        rv = 8
        ret = 37835392
        expired = 1
---Type <return> to continue, or q <return> to quit---
#7  0x00000000004ff867 in process_chk (t=0x80242d0a0) at src/checks.c:2281
        check = 0x80243b610
#8  0x00000000004fac93 in process_email_alert (t=0x80242d0a0) at
src/checks.c:3152
        check = 0x80243b610
        q = 0x80243b600
        alert = 0x80249dfd0
#9  0x000000000058ccc6 in process_runnable_tasks () at src/task.c:229
        t = 0x80242d0a0
        i = 32767
        max_processed = 200
        rq_next = 0x0
        local_tasks = {0x0, 0xc008a6418, 0x7fffffffe650, 0x80254ed40,
0x8a6418 <timers>, 0x22d9539222d96e35, 0x1ffffe6c0, 0x0, 0x100000000,
0x0, 0x0, 0x0,
          0x8a6ed0 <applet_active_lock>, 0x0, 0x0, 0x7fffffffe698}
        local_tasks_count = 0
        final_tasks_count = 9072448
#10 0x000000000050da2b in run_poll_loop () at src/haproxy.c:2327
        next = 584674869
#11 0x000000000050b579 in run_thread_poll_loop (data=0x802446068) at
src/haproxy.c:2376
        ptif = 0x89ac68 <per_thread_init_list>
        ptdf = 0x202
#12 0x0000000000508429 in main (argc=3, argv=0x7fffffffeb58) at
src/haproxy.c:2940
        tids = 0x802446068
        threads = 0x802446070
        i = 1
        err = 0
        retry = 200
        limit = {rlim_cur = 2234, rlim_max = 2234}
        errmsg =
"\000\353\377\377\377\177\000\000x\353\377\377\377\177\000\000X\353\377\377\377\177\000\000\003\000\000\000\000\000\000\000\200\021\366~\311O/\374\240\030\212\000\000\000\000\000P\353\377\377\377\177\000\000x\353\377\377\377\177\000\000X\353\377\377\377\177\000\000\003\000\000\000\000\000\000\000\360\352\377\377\377\177\000\000RQ\341\001\b\000\000\000\001\000\000"
        pidfd = -1
(gdb) cont
Continuing.
^C
Program received signal SIGINT, Interrupt.
0x0000000000502855 in enqueue_one_email_alert (p=0x8024cbc00,
s=0x8024df000, q=0x80243b600,
    msg=0x7fffffffdce0 "Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: \"TCPCHK error establishing connection at step 1:
Connection refused\", check duration: 0ms, stat"...) at src/checks.c:3394
3394            HA_SPIN_LOCK(EMAIL_ALERTS_LOCK, &q->lock);
(gdb) bt full
#0  0x0000000000502855 in enqueue_one_email_alert (p=0x8024cbc00,
s=0x8024df000, q=0x80243b600,
    msg=0x7fffffffdce0 "Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: \"TCPCHK error establishing connection at step 1:
Connection refused\", check duration: 0ms, stat"...) at src/checks.c:3394
        __pl_r = 4294967300
        strs = {0x628738 "DATA\r\n", 0x0}
        strs = {0x62878d "QUIT\r\n", 0x0}
        alert = 0x8024a3000
        tcpcheck = 0x80258f540
        check = 0x80243b610
#1  0x00000000004fb0c2 in enqueue_email_alert (p=0x8024cbc00, s=0x8024df000,
    msg=0x7fffffffdce0 "Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: \"TCPCHK error establishing connection at step 1:
Connection refused\", check duration: 0ms, stat"...) at src/checks.c:3412
        i = 0
        mailer = 0x802432540
#2  0x00000000004fb02a in send_email_alert (s=0x8024df000, level=6,
format=0x63202d "%s") at src/checks.c:3443
        argp = {{gp_offset = 32, fp_offset = 48, overflow_arg_area =
0x7fffffffe100, reg_save_area = 0x7fffffffdbf0}}
        buf = "Health check for server ServerTest_http_ipv4/ServerTest
failed, reason: Layer4 connection problem, info: \"TCPCHK error
establishing connection at step 1: Connection refused\", check duration:
0ms, stat"...
        len = 212
        p = 0x8024cbc00
#3  0x00000000004f7b01 in set_server_check_status (check=0x80243b610,
status=8,
    desc=0x802464300 "Health check for server
ServerTest_http_ipv4/ServerTest failed, reason: Layer4 connection
problem, info: \"TCPCHK error establishing connection at step 1:
Connection refused\", check duration: 0ms, stat"...) at src/checks.c:294
        s = 0x8024df000
        prev_status = 1
        report = 0
#4  0x00000000004fd65e in tcpcheck_main (check=0x80243b610) at
src/checks.c:2812
        proto = 0x89c568 <proto_tcpv4>
        xprt = 0x89eec0 <raw_sock>
        contentptr = 0x80249dfe0 "\300.I\002\b"
        comment = 0x0
        next = 0x802492e80
        done = 0
        ret = 20480
        step = 1
        cs = 0x80249dfa0
        conn = 0x80243c480
        s = 0x8024df000
        t = 0x80242d0a0
        head = 0x80249dfe0
        retcode = 0
#5  0x000000000050155d in connect_conn_chk (t=0x80242d0a0) at
src/checks.c:1548
        check = 0x80243b610
        s = 0x8024df000
        cs = 0x0
        conn = 0x0
        proto = 0x1000800000000
        tcp_rule = 0x802492ec0
        ret = 0
        quickack = 0
#6  0x00000000005000a8 in process_chk_conn (t=0x80242d0a0) at
src/checks.c:2135
        check = 0x80243b610
        s = 0x8024df000
        cs = 0x0
        conn = 0x0
        rv = 8
        ret = 37835392
        expired = 1
#7  0x00000000004ff867 in process_chk (t=0x80242d0a0) at src/checks.c:2281
---Type <return> to continue, or q <return> to quit---
        check = 0x80243b610
#8  0x00000000004fac93 in process_email_alert (t=0x80242d0a0) at
src/checks.c:3152
        check = 0x80243b610
        q = 0x80243b600
        alert = 0x80249dfd0
#9  0x000000000058ccc6 in process_runnable_tasks () at src/task.c:229
        t = 0x80242d0a0
        i = 32767
        max_processed = 200
        rq_next = 0x0
        local_tasks = {0x0, 0xc008a6418, 0x7fffffffe650, 0x80254ed40,
0x8a6418 <timers>, 0x22d9539222d96e35, 0x1ffffe6c0, 0x0, 0x100000000,
0x0, 0x0, 0x0,
          0x8a6ed0 <applet_active_lock>, 0x0, 0x0, 0x7fffffffe698}
        local_tasks_count = 0
        final_tasks_count = 9072448
#10 0x000000000050da2b in run_poll_loop () at src/haproxy.c:2327
        next = 584674869
#11 0x000000000050b579 in run_thread_poll_loop (data=0x802446068) at
src/haproxy.c:2376
        ptif = 0x89ac68 <per_thread_init_list>
        ptdf = 0x202
#12 0x0000000000508429 in main (argc=3, argv=0x7fffffffeb58) at
src/haproxy.c:2940
        tids = 0x802446068
        threads = 0x802446070
        i = 1
        err = 0
        retry = 200
        limit = {rlim_cur = 2234, rlim_max = 2234}
        errmsg =
"\000\353\377\377\377\177\000\000x\353\377\377\377\177\000\000X\353\377\377\377\177\000\000\003\000\000\000\000\000\000\000\200\021\366~\311O/\374\240\030\212\000\000\000\000\000P\353\377\377\377\177\000\000x\353\377\377\377\177\000\000X\353\377\377\377\177\000\000\003\000\000\000\000\000\000\000\360\352\377\377\377\177\000\000RQ\341\001\b\000\000\000\001\000\000"
        pidfd = -1
(gdb) quit
A debugging session is active.

        Inferior 1 [process 44672] will be detached.

Quit anyway? (y or n) y
Detaching from program: /usr/local/sbin/haproxy, process 44672
[email protected]:~ #


[email protected]:~ # haproxy -vv
HA-Proxy version 1.8.1 2017/12/03
Copyright 2000-2017 Willy Tarreau <[email protected]>

Build options :
  TARGET  = freebsd
  CPU     = generic
  CC      = cc
  CFLAGS  = -pipe -g -fstack-protector -fno-strict-aliasing
-fno-strict-aliasing -Wdeclaration-after-statement -fwrapv
-Wno-address-of-packed-member -Wno-null-dereference -Wno-unused-label
-DFREEBSD_PORTS
  OPTIONS = USE_GETADDRINFO=1 USE_ZLIB=1 USE_CPU_AFFINITY=1
USE_ACCEPT4=1 USE_REGPARM=1 USE_OPENSSL=1 USE_LUA=1 USE_STATIC_PCRE=1
USE_PCRE_JIT=1

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

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 PCRE version : 8.40 2017-01-11
Running on PCRE version : 8.40 2017-01-11
PCRE library supports JIT : yes
Built with multi-threading support.
Encrypted password support via crypt(3): yes
Built with transparent proxy support using: IP_BINDANY IPV6_BINDANY
Built with Lua version : Lua 5.3.4
Built with OpenSSL version : OpenSSL 1.0.2m  2 Nov 2017
Running on OpenSSL version : OpenSSL 1.0.2m  2 Nov 2017
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports : SSLv3 TLSv1.0 TLSv1.1 TLSv1.2

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

Available filters :
        [TRACE] trace
        [COMP] compression
        [SPOE] spoe
Sorry, only registered users may post in this forum.

Click here to login