Rolling upgrade from HAProxy 2.4.17 to 2.6.1 triggers assertion failure
Detailed Description of the Problem
On one server I've upgraded the binary of running instance of HAProxy 2.4.17 to 2.6.1 and then reloaded the configuration to start the new version.
The new worker immediately died because it triggered an assertion:
Jul 13 13:04:32 *snip* systemd[1]: Reloading HAProxy Load Balancer.
Jul 13 13:04:32 *snip* haproxy[2055]: [WARNING] (2055) : Reexecuting Master process
[…]
Jul 13 13:04:33 *snip* haproxy[2055]: [NOTICE] (2055) : New worker (1652416) forked
Jul 13 13:04:33 *snip* haproxy[2055]: [NOTICE] (2055) : Loading success.
Jul 13 13:04:33 *snip* haproxy[1652416]: FATAL: bug condition "fd < 0 || fd >= global.maxsock" matched at include/haproxy/fd.h:333
Jul 13 13:04:33 *snip* haproxy[1652416]: call trace(7):
Jul 13 13:04:33 *snip* haproxy[1652416]: | 0x559fddd1c174 [c6 04 25 01 00 00 00 00]: main-0xadc
Jul 13 13:04:33 *snip* haproxy[1652416]: | 0x559fdde62fd5 [85 c0 0f 84 69 02 00 00]: main+0x146385
Jul 13 13:04:33 *snip* haproxy[1652416]: | 0x559fddd1e85a [31 c0 e8 4f bf 1a 00 31]: main+0x1c0a/0x2deb
[…]
Jul 13 13:04:33 *snip* haproxy[2055]: [NOTICE] (2055) : haproxy version is 2.6.1-1~bpo11+1
Jul 13 13:04:33 *snip* haproxy[2055]: [NOTICE] (2055) : path to executable is /usr/sbin/haproxy
Jul 13 13:04:33 *snip* haproxy[2055]: [ALERT] (2055) : Current worker (1652416) exited with code 139 (Segmentation fault)
Jul 13 13:04:33 *snip* haproxy[2055]: [ALERT] (2055) : exit-on-failure: killing every processes with SIGTERM
Jul 13 13:04:33 *snip* systemd[1]: Reloaded HAProxy Load Balancer.
Jul 13 13:04:33 *snip* haproxy[2055]: [WARNING] (2055) : Former worker (841245) exited with code 143 (Terminated)
Jul 13 13:04:33 *snip* haproxy[2055]: [WARNING] (2055) : Former worker (180551) exited with code 143 (Terminated)
Jul 13 13:04:33 *snip* haproxy[2055]: [ALERT] (2055) : Current worker (1369587) exited with code 143 (Terminated)
Jul 13 13:04:33 *snip* haproxy[2055]: [WARNING] (2055) : All workers exited. Exiting... (139)
Jul 13 13:04:33 *snip* systemd[1]: haproxy.service: Main process exited, code=exited, status=139/n/a
Jul 13 13:04:33 *snip* systemd[1]: haproxy.service: Failed with result 'exit-code'.
[…]
Jul 13 13:04:33 *snip* systemd[1]: haproxy.service: Scheduled restart job, restart counter is at 1.
Jul 13 13:04:33 *snip* systemd[1]: Stopped HAProxy Load Balancer.
[…]
Jul 13 13:04:33 *snip* systemd[1]: Starting HAProxy Load Balancer...
Jul 13 13:04:34 *snip* haproxy[1652444]: [NOTICE] (1652444) : New worker (1652464) forked
Jul 13 13:04:34 *snip* haproxy[1652444]: [NOTICE] (1652444) : Loading success.
Jul 13 13:04:34 *snip* systemd[1]: Started HAProxy Load Balancer.
Expected Behavior
I expected it not to die.
Steps to Reproduce the Behavior
- Upgrade HAProxy 2.4 to 2.6.
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 stdout format short daemon
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
set-dumpable
expose-experimental-directives
# Default SSL material locations
ca-base /etc/ssl/certs
crt-base /etc/haproxy/ssl
tune.ssl.default-dh-param 2048
# TLS 1.2-
ssl-default-bind-ciphers ECDHE+CHACHA20:ECDHE+AES128:ECDHE+AES256:!MD5
# TLS 1.3+
ssl-default-bind-ciphersuites TLS_AES_128_GCM_SHA256:TLS_AES_256_GCM_SHA384:TLS_CHACHA20_POLY1305_SHA256
# Require TLS 1.2 or higher
ssl-default-bind-options ssl-min-ver TLSv1.2 prefer-client-ciphers
maxconn 10000
Output of haproxy -vv
HAProxy version 2.6.1-1~bpo11+1 2022/06/22 - https://haproxy.org/
Status: long-term supported branch - will stop receiving fixes around Q2 2027.
Known bugs: http://www.haproxy.org/bugs/bugs-2.6.1.html
Running on: Linux 5.10.0-11-amd64 #1 SMP Debian 5.10.92-1 (2022-01-18) x86_64
Build options :
TARGET = linux-glibc
CPU = generic
CC = cc
CFLAGS = -O2 -g -O2 -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_PCRE2=1 USE_PCRE2_JIT=1 USE_OPENSSL=1 USE_LUA=1 USE_SLZ=1 USE_SYSTEMD=1 USE_PROMEX=1
DEBUG = -DDEBUG_STRICT -DDEBUG_MEMORY_POOLS
Feature list : +EPOLL -KQUEUE +NETFILTER -PCRE -PCRE_JIT +PCRE2 +PCRE2_JIT +POLL +THREAD +BACKTRACE -STATIC_PCRE -STATIC_PCRE2 +TPROXY +LINUX_TPROXY +LINUX_SPLICE +LIBCRYPT +CRYPT_H -ENGINE +GETADDRINFO +OPENSSL +LUA +ACCEPT4 -CLOSEFROM -ZLIB +SLZ +CPU_AFFINITY +TFO +NS +DL +RT -DEVICEATLAS -51DEGREES -WURFL +SYSTEMD -OBSOLETE_LINKER +PRCTL -PROCCTL +THREAD_DUMP -EVPORTS -OT -QUIC +PROMEX -MEMORY_PROFILING
Default settings :
bufsize = 16384, maxrewrite = 1024, maxpollevents = 200
Built with multi-threading support (MAX_THREADS=64, default=12).
Built with OpenSSL version : OpenSSL 1.1.1n 15 Mar 2022
Running on OpenSSL version : OpenSSL 1.1.1n 15 Mar 2022
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports : TLSv1.0 TLSv1.1 TLSv1.2 TLSv1.3
Built with Lua version : Lua 5.3.3
Built with the Prometheus exporter as a service
Built with network namespace support.
Support for malloc_trim() is enabled.
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.36 2020-12-04
PCRE2 library supports JIT : yes
Encrypted password support via crypt(3): yes
Built with gcc compiler version 10.2.1 20210110
Available polling systems :
epoll : pref=300, test result OK
poll : pref=200, test result OK
select : pref=150, test result OK
Total: 3 (3 usable), will use epoll.
Available multiplexer protocols :
(protocols marked as <default> cannot be specified using 'proto' keyword)
h2 : mode=HTTP side=FE|BE mux=H2 flags=HTX|HOL_RISK|NO_UPG
fcgi : mode=HTTP side=BE mux=FCGI flags=HTX|HOL_RISK|NO_UPG
<default> : mode=HTTP side=FE|BE mux=H1 flags=HTX
h1 : mode=HTTP side=FE|BE mux=H1 flags=HTX|NO_UPG
<default> : mode=TCP side=FE|BE mux=PASS flags=
none : mode=TCP side=FE|BE mux=PASS flags=NO_UPG
Available services : prometheus-exporter
Available filters :
[CACHE] cache
[COMP] compression
[FCGI] fcgi-app
[SPOE] spoe
[TRACE] trace
Last Outputs and Backtraces
Jul 13 13:04:33 *snip* haproxy[1652416]: FATAL: bug condition "fd < 0 || fd >= global.maxsock" matched at include/haproxy/fd.h:333
Jul 13 13:04:33 *snip* haproxy[1652416]: call trace(7):
Jul 13 13:04:33 *snip* haproxy[1652416]: | 0x559fddd1c174 [c6 04 25 01 00 00 00 00]: main-0xadc
Jul 13 13:04:33 *snip* haproxy[1652416]: | 0x559fdde62fd5 [85 c0 0f 84 69 02 00 00]: main+0x146385
Jul 13 13:04:33 *snip* haproxy[1652416]: | 0x559fddd1e85a [31 c0 e8 4f bf 1a 00 31]: main+0x1c0a/0x2deb
Additional Information
The initial attempt at the reload failed during config check, because option http-use-htx. The clean start after the assertion failure worked fine. It just killed some long-running connections.
Hmm that's particularly concerning, because that assert definitely detected a bug! Could you please try to pass it through gdb to figure the call trace, since it wasn't well resolved above ?
Thanks!
I'm afraid I don't have a core-dump, because the server is not properly set up for dumping. For obvious reasons I'd also like to avoid doing that again on the production machine if possible.
The only thing I have available is this in dmesg:
[8029871.666102] haproxy[1652416]: segfault at 1 ip 0000559fddd1c174 sp 00007ffd2b2f7640 error 6 in haproxy[559fddd17000+1d2000]
[8029871.666122] Code: e8 61 a0 16 00 e8 9c 97 16 00 c6 04 25 01 00 00 00 00 ba 03 00 00 00 48 8d 35 88 f4 1c 00 31 ff e8 41 a0 16 00 e8 7c 97 16 00 <c6> 04 25 01 00 00 00 00 ba 03 00 00 00 48 8d 35 20 56 1d 00 31 ff
The package is the 2.6.1 from Vincent for Debian 11. I have debug symbols installed.
I understand. Then could you please try to feed the addresses from the call trace (0x559fddd1c174 etc) through addr2line, in case it can decode the symbol location ? Maybe it will not be able but gdb can (use x/a 0x559fddd1c174 under gdb).
From addr2line -e $(which haproxy):
0x559fddd1c174
??:0
0x559fdde62fd5
??:0
0x559fddd1e85a
??:0
??:0
0xadc
addr2line: DWARF error: could not find variable specification at offset 1ff6f
??:0
0x146385
addr2line: DWARF error: could not find variable specification at offset 23495
addr2line: DWARF error: could not find variable specification at offset 234c0
addr2line: DWARF error: could not find variable specification at offset 234b4
addr2line: DWARF error: could not find variable specification at offset 234cc
./src/log.c:2947
0x1c0a
??:0
0x2deb
??:0
??:0
1d2000
./include/haproxy/channel.h:712
OK then you'll need to know the address for main (gdb can give it to you via x/a main), and from there we can also direcly resolve them (e.g x/a main+0xadc) or note the value from another machine and perform the operation where relevant after doing the math by hand (e.g addr2line -e haproxy <<< "$((MAIN+0xadc))").
Good news: I was able to reproduce the issue on another (testing) machine (running Debian 10 / Buster). I upgraded from 2.4.17 to 2.6.1 and HAProxy immediately crashed after the upgrade. The configuration is a little different, but the global section is similar:
Jul 13 13:46:37 *snip* haproxy[18143]: FATAL: bug condition "fd < 0 || fd >= global.maxsock" matched at include/haproxy/fd.h:333
Jul 13 13:46:37 *snip* haproxy[18143]: call trace(7):
Jul 13 13:46:37 *snip* haproxy[18143]: | 0x563fc3418ab3 [c6 04 25 01 00 00 00 00]: main+0x1a6b63
Jul 13 13:46:37 *snip* haproxy[18143]: | 0x563fc33bfb05 [85 c0 0f 84 6b 02 00 00]: main+0x14dbb5
Jul 13 13:46:37 *snip* haproxy[18143]: | 0x563fc3273b3d [31 c0 e8 2c 4f 1b 00 31]: main+0x1bed/0x2c5f
Jul 13 13:46:37 *snip* systemd[1]: Reloaded HAProxy Load Balancer.
Jul 13 13:46:37 *snip* haproxy[18143]: [NOTICE] (18143) : haproxy version is 2.6.1-1~bpo10+1
Jul 13 13:46:37 *snip* haproxy[18143]: [NOTICE] (18143) : path to executable is /usr/sbin/haproxy
Jul 13 13:46:37 *snip* haproxy[18143]: [WARNING] (18143) : Current worker (18145) exited with code 0 (Exit)
Jul 13 13:46:38 *snip* haproxy[18143]: [ALERT] (18143) : Current worker (19599) exited with code 139 (Segmentation fault)
Core was generated by `/usr/sbin/haproxy -sf 18145 -x /run/haproxy/admin.sock -Ws -f /run/haproxy/conf'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 ha_crash_now () at include/haproxy/bug.h:50
50 include/haproxy/bug.h: No such file or directory.
(gdb) t a a bt full
Thread 1 (Thread 0x7f7985cd4040 (LWP 19599)):
#0 ha_crash_now () at include/haproxy/bug.h:50
No locals.
#1 fd_insert (iocb=0x563fc34188e0 <mworker_accept_wrapper>, thread_mask=<optimized out>, owner=<optimized out>, fd=<optimized out>) at include/haproxy/fd.h:333
No locals.
#2 mworker_pipe_register_per_thread () at src/mworker.c:428
No locals.
#3 mworker_pipe_register_per_thread () at src/mworker.c:416
No locals.
#4 0x0000563fc33bfb05 in run_thread_poll_loop (data=<optimized out>) at src/haproxy.c:2904
ptaf = <optimized out>
ptif = 0x563fc514df60
ptdf = <optimized out>
ptff = <optimized out>
init_left = 0
init_mutex = {__data = {__lock = 1, __count = 0, __owner = 19599, __nusers = 1, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}},
__size = "\001\000\000\000\000\000\000\000\217L\000\000\001", '\000' <repeats 26 times>, __align = 1}
init_cond = {__data = {{__wseq = 0, __wseq32 = {__low = 0, __high = 0}}, {__g1_start = 0, __g1_start32 = {__low = 0, __high = 0}}, __g_refs = {0, 0}, __g_size = {0, 0}, __g1_orig_size = 0, __wrefs = 0,
__g_signals = {0, 0}}, __size = '\000' <repeats 47 times>, __align = 0}
#5 0x0000563fc3273b3d in main (argc=<optimized out>, argv=<optimized out>) at src/haproxy.c:3591
err = <optimized out>
retry = <optimized out>
limit = {rlim_cur = 18446744073709551615, rlim_max = 18446744073709551615}
pidfd = <optimized out>
intovf = <optimized out>
There's definitely something odd there. And the followiing commit that's planned for backport will hide it:
34aae2fd1 ("MEDIUM: mworker: set the iocb of the socketpair without using fd_insert()")
It used to trigger an issue that the FD was inserted twice, But it might just be hidden and not completely solved. I don't understand how we can end up with a wrong FD number. I'm wondering if the issue wouldn't be that the maxconn is now lower after rexec, in which case having a very low forced maxconn value isn't the best solution either and we'll have to figure a way to spot the highest known FD number to reset the maxconn at boot.
Could you please issue:
p proc_self->ipc_fd[1]
p global.maxsock
In your gdb with the core ? I'm pretty sure that ipc_fd[1] is higher than maxsock which might be around 200 or so.
It looks like this ipc_fd value is retrieved from HAPROXY_PROCESSES in an fd field. Thus we could keep a max of these values on startup and use it as a min for global.maxsock which is lower since 0a012aa16 ("BUG/MEDIUM: mworker: use default maxconn in wait mode") marked for backport to 2.5. An even better option would be to rename the fd using dup() to reassign lower values, something roughly like this (just typed here, not even compile-tested):
mworker.c:192
} else if (strncmp(subtoken, "fd=", 3) == 0) {
- child->ipc_fd[0] = atoi(subtoken+3);
+ int fd = atoi(subtoken+3);
+ int fd2 = dup(fd);
+ if (fd2 > fd)
+ close(fd2);
+ else if (fd2 > -1) {
+ close(fd);
+ fd = fd2;
+ }
+ BUG_ON(fd >= global.maxsock);
+ child->ipc_fd[0] = fd;
}
CCing @wlallemand who knows this part best.
In fact, I'm wondering if the way to reproduce the issue isn't simply to start with many listeners...
I can't reproduce it this way but it may also depend on the number of older processes. Thus I would amend the patch above like this:
- BUG_ON(fd >= global.maxsock);
+ if (fd >= global.maxsock)
+ global.maxsock = fd;
child->ipc_fd[0] = fd;
Or maybe in fact the socket is re-created by the new process by calling mworker_cli_sockpair_new() again. In my traces it indeed seems to be called upon each reload. But there is a bug in that code, it doesn't check the resulting FDs against global.maxsock like all other protocols do. That would report the error where it happens (i.e. upon creation of the new master-worker socketpair), and allow to decide what to do, typically raise the default socket count for the master to a higher value.
I'm still wondering why the FD is too high, it's possible that there's some fd leak somewhere else in the code in areas loading files, maps, Lua core or any such thing.
In your gdb with the core ? I'm pretty sure that ipc_fd[1] is higher than maxsock which might be around 200 or so.
You're wrong:
(gdb) p proc_self->ipc_fd[1]
$1 = -1
(gdb) p global.maxsock
$2 = 20055
When downgrading back to 2.4 I'm seeing:
Jul 14 09:25:46 *snip* haproxy[19710]: [NOTICE] (19710) : Reloading HAProxy
Jul 14 09:25:46 *snip* haproxy[19710]: [WARNING] (19710) : Failed to connect to the old process socket 'sockpair@3'
Jul 14 09:25:46 *snip* haproxy[19710]: [NOTICE] (19710) : haproxy version is 2.4.17-1~bpo10+1
Jul 14 09:25:46 *snip* haproxy[19710]: [NOTICE] (19710) : path to executable is /usr/sbin/haproxy
Jul 14 09:25:46 *snip* haproxy[19710]: [ALERT] (19710) : Failed to get the sockets from the old process!
Jul 14 09:25:46 *snip* haproxy[19710]: [WARNING] (19713) : Proxy http stopped (cumulated conns: FE: 98, BE: 0).
Jul 14 09:25:46 *snip* haproxy[19710]: Proxy http stopped (cumulated conns: FE: 98, BE: 0).
Jul 14 09:25:46 *snip* haproxy[19710]: [WARNING] (19713) : Proxy https stopped (cumulated conns: FE: 198, BE: 0).
Jul 14 09:25:46 *snip* haproxy[19710]: Proxy https stopped (cumulated conns: FE: 198, BE: 0).
Jul 14 09:25:46 *snip* haproxy[19710]: [WARNING] (19713) : Proxy smtp stopped (cumulated conns: FE: 16, BE: 0).
Jul 14 09:25:46 *snip* haproxy[19710]: Proxy smtp stopped (cumulated conns: FE: 16, BE: 0).
Jul 14 09:25:46 *snip* haproxy[19710]: [WARNING] (19713) : Proxy stats stopped (cumulated conns: FE: 0, BE: 0).
Jul 14 09:25:46 *snip* haproxy[19710]: [NOTICE] (19710) : New worker #1 (24377) forked
Jul 14 09:25:46 *snip* systemd[1]: Reloaded HAProxy Load Balancer.
Upgrading again reproduces the same crash:
Jul 14 09:27:37 *snip* haproxy[19710]: FATAL: bug condition "fd < 0 || fd >= global.maxsock" matched at include/haproxy/fd.h:333
Jul 14 09:27:37 *snip* haproxy[19710]: call trace(7):
Jul 14 09:27:37 *snip* haproxy[19710]: | 0x557773489ab3 [c6 04 25 01 00 00 00 00]: main+0x1a6b63
Jul 14 09:27:37 *snip* haproxy[19710]: | 0x557773430b05 [85 c0 0f 84 6b 02 00 00]: main+0x14dbb5
Jul 14 09:27:37 *snip* haproxy[19710]: | 0x5577732e4b3d [31 c0 e8 2c 4f 1b 00 31]: main+0x1bed/0x2c5f
Jul 14 09:27:37 *snip* systemd[1]: Reloaded HAProxy Load Balancer.
Jul 14 09:27:37 *snip* haproxy[19710]: [NOTICE] (19710) : haproxy version is 2.6.1-1~bpo10+1
Jul 14 09:27:37 *snip* haproxy[19710]: [NOTICE] (19710) : path to executable is /usr/sbin/haproxy
Jul 14 09:27:37 *snip* haproxy[19710]: [WARNING] (19710) : Current worker (24377) exited with code 0 (Exit)
Jul 14 09:27:37 *snip* haproxy[19710]: [ALERT] (19710) : Current worker (25871) exited with code 139 (Segmentation fault)
Jul 14 09:27:37 *snip* haproxy[19710]: [ALERT] (19710) : exit-on-failure: killing every processes with SIGTERM
Jul 14 09:27:37 *snip* haproxy[19710]: [WARNING] (19710) : Former worker (19713) exited with code 143 (Terminated)
Jul 14 09:27:37 *snip* haproxy[19710]: [WARNING] (19710) : All workers exited. Exiting... (139)
Jul 14 09:27:38 *snip* systemd[1]: haproxy.service: Main process exited, code=exited, status=139/n/a
Jul 14 09:27:38 *snip* systemd[1]: haproxy.service: Failed with result 'exit-code'.
Jul 14 09:27:38 *snip* systemd[1]: haproxy.service: Service RestartSec=100ms expired, scheduling restart.
Jul 14 09:27:38 *snip* systemd[1]: haproxy.service: Scheduled restart job, restart counter is at 2.
Jul 14 09:27:38 *snip* systemd[1]: Stopped HAProxy Load Balancer.
Jul 14 09:27:38 *snip* systemd[1]: Starting HAProxy Load Balancer...
What a mess! So it's an uncaught error, apparently around the creation of the master-worker socket. But I'm too clueless about that area to have a hint unfortunately. The problem I'm seeing is that in 2.4 there was possibly the same bug but we would happily fill random garbage into fdtab[-1], overwriting whatever was unlucky enough to be there. Now there's this boundary test and it proves to be useful, but I don't know why we're doing that.
If your in a patch-friendly mood to try to work around this problem, I would suggest to hack around this for now by changing the offending BUG_ON() at the entry of fd_insert() with:
if (fd < 0 || fd >= global.maxsock) {
ha_warning("Avoided a crash in fd_insert(%d) from here:\n", fd);
ha_backtrace_to_stderr();
return;
}
It will at least show the problem and where we come from but will not crash. The offending FD will be ignored. But I perfectly understand it if you don't want to patch your production, no worries!
As production is running fine and the error only appeared ONCE during the upgrade, I'll abstain from applying any patches, I wouldn't be able to test them anyway.
some clarification about how this works:
In the master before the fork:
- sock_get_old_sockets() is done first to get the bind from the previous process
- readcfgfile() ...
- mworker_proc_new() creates a new structure for the future worker
- mworker_cli_sockpair_new() creates a new socketpair in ipc_fd[] for the future worker ipc_fd[0] is the master side, ipc_fd[1] is the worker side. Create a listener sockpair@ in the global CLI proxy for the worker side.
- mworker_env_to_proc_list() parse the env which store the ipc_fd[0] for each remaining process. these FDs survive to an exec, we just need to know what number they have.
- if there is a master CLI, mworker_cli_proxy_create() creates a proxy for the master, listeners based on the -S arguments, and servers based on the mworker_proc list of processes (using sockpair@ipc_fd[0 for each).
After the fork, in the master:
- pass through the mworker_proc list and find the first child without a reload, it's supposed to be new one.
After the fork, in the child:
- pass through the mworker_proc list and find the first child without a reload, it's supposed to be the current one, close and free all the others, set proc_self with its address.
-
mworker_pipe_register_per_thread()is executed in the worker with the FD of the worker side, the proc_self->ipc_fd[1] is never inherited from the env, so if it's the wrong mworker_proc it would be set to -1.
My guess is that we got another "mworker_proc" with a reload value of 0, which came from a bug or an aborted reload in an old haproxy version? Which ipc_fd[1] is -1 because it never passed the socketpair creation step.
Also the fact there is 2 "Current worker exited" messages confirms this theory.
I could reproduce the issue, it looks like this is exactly the problem I mentioned above.
This small patch on top of v2.6.1 shows which mworker_proc structure is used:
diff --git a/src/mworker.c b/src/mworker.c
index 6a4fce48c..8b6134456 100644
--- a/src/mworker.c
+++ b/src/mworker.c
@@ -425,6 +425,8 @@ static int mworker_pipe_register_per_thread()
/* In multi-tread, we need only one thread to process
* events on the pipe with master
*/
+ ha_warning("proc_self->ipc_fd[1]: %d, proc_self->reloads: %d, proc_self->pid: %d\n", proc_self->ipc_fd[1], proc_self->reloads, proc_self->pid);
+
fd_insert(proc_self->ipc_fd[1], fdtab[proc_self->ipc_fd[1]].owner, mworker_accept_wrapper, tid_bit);
fd_want_recv(proc_self->ipc_fd[1]);
return 1;
$ ./haproxy -W -f issue-1785.cfg
[NOTICE] (22213) : New worker #1 (22215) forked
[WARNING] (22213) : Reexecuting Master process
[WARNING] (22215) : Proxy li4000 stopped (cumulated conns: FE: 0, BE: 0).
[WARNING] (22215) : Stopping frontend GLOBAL in 0 ms.
[NOTICE] (22213) : New worker #1 (22239) forked
[WARNING] (22213) : Former worker #1 (22215) exited with code 0 (Exit)
[WARNING] (22213) : Reexecuting Master process
[WARNING] (22239) : Proxy li4000 stopped (cumulated conns: FE: 0, BE: 0).
[WARNING] (22239) : Stopping frontend GLOBAL in 0 ms.
[NOTICE] (22213) : New worker (22266) forked
[NOTICE] (22213) : Loading success.
[NOTICE] (22213) : haproxy version is 2.6.1
[NOTICE] (22213) : path to executable is ./haproxy
[WARNING] (22213) : Current worker (22239) exited with code 0 (Exit)
[WARNING] (22266) : proc_self->ipc_fd[1]: -1, proc_self->reloads: 0, proc_self->pid: 22239
FATAL: bug condition "fd < 0 || fd >= global.maxsock" matched at include/haproxy/fd.h:333
call trace(8):
| 0x55c937e0b405 [c6 04 25 01 00 00 00 00]: main-0x7cb
| 0x55c937f4cc65 [85 c0 0f 84 5d 02 00 00]: main+0x141095
| 0x55c937e0d759 [31 c0 e8 20 71 1a 00 31]: main+0x1b89/0x2bbe
[ALERT] (22213) : Current worker (22266) exited with code 139 (Segmentation fault)
[ALERT] (22213) : exit-on-failure: killing every processes with SIGTERM
[WARNING] (22213) : All workers exited. Exiting... (139)
The reloads++ changed place between 2.4 and 2.6... Because of the reloads/failedreloads split. Resulting in a small inconsistency when upgrading... The previous process didn't had its reload variable incremented because of this... so the proc_self is set to the previous process, which have an ipc_fd[1] to -1, because it was supposed to be in the master.
It seems to be fixed and backported as far as 2.4. So I'm closing.