Repository navigation
EPOLLHUP or EPOLLRDHUP during connection establishment leads to a wrong decision that a backend is down #1863
Description
Detailed Description of the Problem
Sometimes (quite frequently under load) haproxy marks a backend as being down even though the liveness check (httpchk) is successful.
Expected Behavior
Backends should not be marked as down if they aren't really down.
Steps to Reproduce the Behavior
It is easy for me to reproduce it - just start about 10 simultaneous curl clients to pass requests continuously through haproxy at localhost. I have the feeling that this won't be easy for everybody, though...
Do you have any idea what may have caused this?
-
After connect() is called on the socket that will be used for the liveness check, the socket file descriptor is added to an epoll descriptor. Occasionally (but frequently enough under load) epoll_wait() returns the following two events for the socket fd before the socket gets connected:
EPOLLIN|EPOLLHUP|EPOLLRDHUP
EPOLLIN|EPOLLRDHUP
These two events are always returned by the same call to epoll_wait() and always in this order (as witnessed by strace). -
As a result of EPOLLHUP, _do_poll() in ev_epoll.c calls fd_update_events() with FD_EV_SHUT_W set. In the latter, the condition below the following comment:
/* SHUTW reported while FD was active for writes is an error */
is true, and FD_POLL_ERR gets set in fdtab[fd].state.
This flag never gets reset. -
I have no idea what this EPOLLHUP means for a not-yet-connected socket, but there is a comment in sock_conn_check() in sock.c that suggest that this is to be expected. The comment is long and starts with:
/* Here we have 2 cases :
Since FD_POLL_ERR is set, connect() gets called again. It returns 0 and the connection to the backend is established. -
The liveness check proceeds as usual - the request is sent and the response is received (as witnessed by strace).
-
Eventually, raw_sock_to_buf() in raw_sock.c gets called. Check its very end, after the label read0 and remember that FD_POLL_ERR is still set in fdtab[conn->handle.fd].state. conn->flags gets CO_FL_ERROR set and this leads to the liveness check to be considered as failed.
Do you have an idea how to solve the issue?
I suspect that the trouble comes from FD_POLL_ERR not being reset before the second call to connect(). If I put the following line:
fdtab[fd].state &= ~(FD_POLL_ERR|FD_POLL_HUP);
in sock_conn_check() after the following comment:
/* error present, fall through common error check path */
the issue seems to get solved.
What is your configuration?
global
maxconn 50000
defaults
log stdout local0 notice
mode tcp
maxconn 50000
option redispatch
option tcpka
balance roundrobin
default-server inter 2s fall 2 rise 2
timeout connect 5s
timeout client 50s
timeout server 50s
timeout tunnel 12h
timeout http-keep-alive 1s
timeout http-request 15s
timeout queue 30s
timeout tarpit 60s
backend bbb
mode http
option httpchk GET /liveness
server ...Output of haproxy -vv
HAProxy version 2.6.5-987a4e2 2022/09/03 - 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.5.html
Running on: Linux 5.4.0-122-generic #138~18.04.1-Ubuntu SMP Fri Jun 24 14:14:03 UTC 2022 x86_64
Build options :
TARGET = linux-glibc
CPU = generic
CC = cc
CFLAGS = -O2 -g -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_STATIC_PCRE2=1 USE_OPENSSL=1 USE_LUA=1 USE_ZLIB=1 USE_DL=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=2).
Built with OpenSSL version : OpenSSL 1.1.1 11 Sep 2018
Running on OpenSSL version : OpenSSL 1.1.1 11 Sep 2018
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.4.4
Built with network namespace support.
Support for malloc_trim() is enabled.
Built with zlib version : 1.2.11
Running on zlib version : 1.2.11
Compression algorithms supported : identity("identity"), deflate("deflate"), raw-deflate("deflate"), gzip("gzip")
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT IP_FREEBIND
Built with PCRE2 version : 10.40 2022-04-14
PCRE2 library supports JIT : yes
Encrypted password support via crypt(3): yes
Built with gcc compiler version 7.5.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)
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 : none
Available filters :
[CACHE] cache
[COMP] compression
[FCGI] fcgi-app
[SPOE] spoe
[TRACE] trace
Last Outputs and Backtraces
[WARNING] (...) : Server bbb is DOWN, reason: Socket error, check duration: 2ms. 2 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.
...
[WARNING] (...) : Backup Server bbb is DOWN, reason: Socket error, check duration: 2ms. 1 active and 1 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.
Additional Information
No response
Activity
wtarreau commentedon Sep 16, 2022
Thanks for your report, will have a look at it ASAP, sorry for the delay.
wtarreau commentedon Sep 17, 2022
So a few points on this. First, if you get EPOLLHUP, it means the server closed, possibly with a response but not necessarily. Since it happened in response to a connect() and the FD was being polled for writes, it indicates the connect() call didn't succeed so the request wasn't sent. As such the response you're getting there is not the response to the health check but a failure reported by the server (or the server just closed because there were too many connections for it).
Regardless, haproxy should not return a misleading error here. It should accurately report what happened (and possibly any pending response the server might have sent, which could contain precious information about what the server was not happy with).
Your deep analysis of the sequence is particularly useful because, as you saw, it shows we're abusing FD_POLL_ERR. But that one must not be cleared (though in your test that was useful to confirm the cause), because a socket cannot be only temporarily in error, once in error, it's dead.
For me the problem here is that POLL_HUP was mapped to FD_EV_SHUT_RW since commit 6b30898 ("MEDIUM: fd: do not use the FD_POLL_* flags in the pollers anymore") in 2.1, and I can't find any valid reason why. Oh yes I've just found the reason why. I have a length test log here from the same date as the commit showing that when RDHUP is reported, then HUP is reported only if the sending side was previously closed. Even if that's true in practice with data transfers, it's a bad idea to make this shortcut because as you've seen, connect() does poll for writes but doesn't try to transfer anything hence and doesn't have to suffer from this shortcut.
Individually, none of these operations are fundamentally wrong, as they help determine a maximum of information from what's reported by the poller. But I do think that we should not set POLL_ERR when the output is closed while it's being polled for writes. The first reason is that this is a sticky flag and that it was not really reported by the lower layer here so we can be wrong (as was the case here), the second reason is that if it's reported we can expect getsockopt(SO_ERROR) to return an error and here it's not the case. As such, I think that the best solution is to undo a part of commit 2aaeee3, that is, to remove the assignment of FD_POLL_ERR in fd_update_events() below the comment saying "SHUTW reported while FD was active for writes is an error", because this is the one that guesses wrong here. Anyway its sole purpose was to avoid a few send() errors on aborted connections, but these are totally marginal. And if we decided that we needed to reintroduce it, then we'd adopt distinct poll-for-writes mechanisms, with one indicating we're polling for a connect() instead.
As such I would appreciate it if you could test with this:
Thank you!
gbrdead commentedon Sep 27, 2022
Thank you for the response and sorry for taking me so long to test your fix proposal.
I forgot to mention, but "Socket error" is not the only reason I see. There is one more that is very frequent:
reason: Layer7 invalid response
Your fix proposal does not fix the "Layer7 invalid response" reason. It fixes only the "Socket error" reason.
My pseudo-fix fixes both.
I sometimes get "Layer6 invalid response, info: SSL handshake failure (various errors here)" even with my pseudo-fix. However, these might be real - they are very infrequent and the way I reproduce the situation loads the CPU of the VM haproxy is running on. I am running haproxy itself and 10 concurrent curl's accessing a backend through haproxy at localhost.
wtarreau commentedon Sep 27, 2022
Interesting. That's stranger then because it would indicate that either the error is set at another point, and/or that there are incorrect checks at some point. The problem with clearing the error is that it will be lost and may seriously result in stuck connections or such situations where an error event is lost. Errors should never be cleared. I'll have a check at sock_conn_check(), maybe it sets the error while there are still pending data and it should not do it.
gbrdead commentedon Sep 27, 2022
I think I can explain this situation, too. Mind you, I haven't got the time to check the behaviour at runtime, I just analyzed the source. Here is a modification of the original description for the "Layer7 invalid response" case:
Unlike in the original description, let's assume that we receive only the following event:
EPOLLIN|EPOLLRDHUP
(and that we do not receive the one with EPOLLHUP).
As a result of EPOLLRDHUP, _do_poll() in ev_epoll.c calls fd_update_events() with FD_EV_SHUT_R set and FD_EV_SHUT_W unset. In the latter, FD_POLL_HUP gets set in fdtab[fd].state but FD_POLL_ERR stays unset.
In sock_conn_check() in sock.c we reach the comment:
/* error present, fall through common error check path */
(i.e., just like in the original description - we go to wait only if both FD_POLL_HUP and FD_POLL_ERR are unset).
This explains why my pseudo-fix works for this case, too.
...
fdtab[conn->handle.fd].state & (FD_POLL_ERR|FD_POLL_HUP)) == FD_POLL_HUP is true upon entry to the function (unlike in the original description) and we go to read0. The response from the backend is never read and haproxy assumes an application level error.
[-]EPOLLHUP during connection establishment leads to a wrong decision that a backend is down[/-][+]EPOLLHUP or EPOLLRDHUP during connection establishment leads to a wrong decision that a backend is down[/+]56 remaining items
wtarreau commentedon Apr 19, 2024
I forgot that there's this dirty special case for HUP as well, so it's not just a matter of disabling RDHUP support :-( For this one I'm not sure how to proceed since it will affect all platforms, some more thinking is deserved. Maybe we'll end up with a configurable mask but I find this ugly :-/
capflam commentedon Nov 5, 2024
A gentle ping to make the issue more visible :)
BUG/MEDIUM: sock: Remove FD_POLL_HUP during connect() if FD_POLL_ERR …
capflam commentedon Nov 27, 2024
FYI, A fix was finally pushed. It was backported as far as 2.8 for now. But it should be backported as far as 2.4.
BUG/MEDIUM: sock: Remove FD_POLL_HUP during connect() if FD_POLL_ERR …
BUG/MEDIUM: sock: Remove FD_POLL_HUP during connect() if FD_POLL_ERR …
BUG/MEDIUM: sock: Remove FD_POLL_HUP during connect() if FD_POLL_ERR …
BUG/MEDIUM: sock: Remove FD_POLL_HUP during connect() if FD_POLL_ERR …