Cyril Bonté <[email protected]> writes:
Hello,
> Im' not sure you saw Samuel Reed's mail.
> He reported a similar issue some hours ago (High load average under
> 1.8 with multiple draining processes). It would be interesting to find
> a common configuration to reproduce the issue, so I add him to the thread.
I've been observing the same error messages Emmanuel reports, using
1.8.3 and nbthread. I tried to simplify & anonymize my configuration so
I could share a version which reproduces the problem, but didn't
succeed: the problem disappears at some point in the process, and I'm
unable figure out exactly which change makes the difference :-(
So here are all the observations I gathered, hoping this will help move
a step further:
- disabling "nbthread", as well as setting "nbthread 1", makes the
problem go away.
- when exposed to client requests, I only observed high CPU load on one
instance out of the three I have, which receeded after a restart of
haproxy. When working in isolation (no client requests), I never
noticed high CPU load.
- the more complex the config gets, the easiest it is to reproduce the
issue. By "complex" I mean: more frontends, backend and servers
defined, conditionnally routing traffic to each other based on ACLs,
SSL enabled, dns resolver enabled and used in server statements,
various healthchecks on servers.
- at some point when simplyfing the config, the problem becomes
transient, then eventually stops happening. But there doesn't seem to
be exacly one configuration keyword which triggers the issue.
- I also noticed a few log messages go missing from time to time. Not
sure about this though, it could also be a problem further downstream
in my logging pipeline.
- I've seen the problem happen on systems both with and without the
spectre/meltdown kernel patches.
Last but not least, by continuously reloading haproxy (SIGUSR2) and
running strace against it until the problem occured, I was able to get
this sequence of events (slightly redacted, with a couple of comments
in-line), which seem to show some incorrect actions on file descriptiors
between concurrent threads:
# thread 12167 opens an UDP socket to the DNS server defined in the resolvers
# section of my config, and starts sending queries:
[pid 12167] socket(PF_INET, SOCK_DGRAM, IPPROTO_UDP) = 16
[pid 12167] connect(16, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("10.10.0.2")}, 16) = 0
[pid 12167] fcntl(16, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
[...]
[pid 12167] sendto(16,
"\37\350\1\0\0\1\0\0\0\0\0\1\tprivate-0\10backends\4"..., 78, 0, NULL, 0) = 78
[pid 12167] sendto(16,
"\265\327\1\0\0\1\0\0\0\0\0\1\tprivate-1\10backends\4"..., 78, 0, NULL, 0) = 78
[...]
[pid 12167] sendto(16, "\341\21\1\0\0\1\0\0\0\0\0\1\nprivate-23\10backends"...,
79, 0, NULL, 0) = 79
[pid 12167] sendto(16, "\\\223\1\0\0\1\0\0\0\0\0\1\nprivate-24\10backends"...,
79, 0, NULL, 0) = 79
# thread 12166 gets created, and closes an fd it didn't create, which
# happens to be the socket opened to the DNS server:
strace: Process 12166 attached
[pid 12167] sendto(16,
"\316\352\1\0\0\1\0\0\0\0\0\1\nprivate-25\10backends"..., 79, 0, NULL, 0
<unfinished ...>
[pid 12166] set_robust_list(0x7ff9bc9aa9e0, 24 <unfinished ...>
[pid 12167] <... sendto resumed> ) = 79
[pid 12166] <... set_robust_list resumed> ) = 0
[pid 12166] gettimeofday({1516289044, 684014}, NULL) = 0
[pid 12167] sendto(16, "\37\367\1\0\0\1\0\0\0\0\0\1\nprivate-26\10backends"...,
79, 0, NULL, 0 <unfinished ...>
[pid 12166] mmap(NULL, 134217728, PROT_NONE,
MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0 <unfinished ...>
[pid 12167] <... sendto resumed> ) = 79
[pid 12167] sendto(16, "\224\10\1\0\0\1\0\0\0\0\0\1\nprivate-27\10backends"...,
79, 0, NULL, 0) = 79
[pid 12166] <... mmap resumed> ) = 0x7ff9ac000000
[pid 12167] sendto(16, "\25 \1\0\0\1\0\0\0\0\0\1\nprivate-28\10backends"...,
79, 0, NULL, 0) = 79
[pid 12166] munmap(0x7ff9b0000000, 67108864) = 0
[pid 12167] sendto(16, "\275\n\1\0\0\1\0\0\0\0\0\1\nprivate-29\10backends"...,
79, 0, NULL, 0 <unfinished ...>
[pid 12166] mprotect(0x7ff9ac000000, 135168, PROT_READ|PROT_WRITE <unfinished
...>
[pid 12167] <... sendto resumed> ) = 79
[pid 12166] <... mprotect resumed> ) = 0
[pid 12167] sendto(16,
"\312\360\1\0\0\1\0\0\0\0\0\1\nprivate-30\10backends"..., 79, 0, NULL, 0
<unfinished ...>
[pid 12166] mmap(NULL, 8003584, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 12167] <... sendto resumed> ) = 79
[pid 12167] sendto(16, "\247e\1\0\0\1\0\0\0\0\0\1\nprivate-31\10backends"...,
79, 0, NULL, 0) = 79
[pid 12166] <... mmap resumed> ) = 0x7ff9baa65000
[pid 12167] sendto(16, "_k\1\0\0\1\0\0\0\0\0\1\tprivate-0\nbackoffic"..., 80,
0, NULL, 0 <unfinished ...>
[pid 12166] close(16 <unfinished ...>
# from now on, thread 12167 gets "Bad file descriptor" back when sending
# DNS queries:
[pid 12167] <... sendto resumed> ) = 80
[pid 12167] sendto(16, "\355\25\1\0\0\1\0\0\0\0\0\1\tprivate-1\nbackoffic"...,
80, 0, NULL, 0 <unfinished ...>
[pid 12166] <... close resumed> ) = 0
[pid 12167] <... sendto resumed> ) = -1 EBADF (Bad file descriptor)
[pid 12167] sendto(16, "?\217\1\0\0\1\0\0\0\0\0\1\tprivate-2\nbackoffic"...,
80, 0, NULL, 0 <unfinished ...>
[pid 12166] fcntl(15, F_SETFL, O_RDONLY|O_NONBLOCK <unfinished ...>
[pid 12167] <... sendto resumed> ) = -1 EBADF (Bad file descriptor)
[pid 12166] <... fcntl resumed> ) = 0
# meanwhile thread 12166 opens a TCP socket to a server declared in my config
# using it's IP address, I assume to send a healthcheck:
[pid 12164] <... sched_setaffinity resumed> ) = 0
[pid 12164] sched_setaffinity(58, 128, [2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0, 0, 0, 0, 0, 558d19fa65d0, 558d19eacee0, 7ffdfc793f70, 0, 0, 7ff9c82dc2b1,
7ffdfc793fb8, 7ffdfc793f78, 700000000, 558d19eaab30, 0, dd0973282a659c8a,
558d19eacee0, 7ffdfc793f70, ...] <unfinished ...>
[pid 12166] <... socket resumed> ) = 16
[pid 12166] fcntl(16, F_SETFL, O_RDONLY|O_NONBLOCK <unfinished ...>
[pid 12164] <... sched_setaffinity resumed> ) = 0
[pid 12166] <... fcntl resumed> ) = 0
[pid 12166] setsockopt(16, SOL_TCP, TCP_NODELAY, [1], 4 <unfinished ...>
[pid 12164] sched_setaffinity(59, 128, [4, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0, 0, 0, 0, 0, 558d19fa65d0, 558d19eacee0, 7ffdfc793f70, 0, 0, 7ff9c82dc2b1,
7ffdfc793fb8, 7ffdfc793f78, 700000000, 558d19eaab30, 0, dd0973282a659c8a,
558d19eacee0, 7ffdfc793f70, ...] <unfinished ...>
[pid 12166] <... setsockopt resumed> ) = 0
[pid 12164] <... sched_setaffinity resumed> ) = -1 EINVAL (Invalid argument)
[pid 12166] setsockopt(16, SOL_TCP, TCP_QUICKACK, [0], 4 <unfinished ...>
[pid 12164] sched_setaffinity(60, 128, [8, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0, 0, 0, 0, 0, 558d19fa65d0, 558d19eacee0, 7ffdfc793f70, 0, 0, 7ff9c82dc2b1,
7ffdfc793fb8, 7ffdfc793f78, 700000000, 558d19eaab30, 0, dd0973282a659c8a,
558d19eacee0, 7ffdfc793f70, ...]) = -1 EINVAL (Invalid argument)
[pid 12166] <... setsockopt resumed> ) = 0
[pid 12164] gettimeofday( <unfinished ...>
[pid 12166] connect(16, {sa_family=AF_INET, sin_port=htons(8080),
sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in
progress)
# ... then thread 12165 gets created and immediatly closes 12166's socket:
strace: Process 12165 attached
[pid 12165] set_robust_list(0x7ff9bd1ab9e0, 24 <unfinished ...>
[pid 12164] <... gettimeofday resumed> {1516289044, 692533}, NULL) = 0
[pid 12165] <... set_robust_list resumed> ) = 0
[pid 12165] gettimeofday({1516289044, 692598}, NULL) = 0
[pid 12164] mmap(NULL, 8003584, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 12165] mmap(0x7ff9b0000000, 67108864, PROT_NONE,
MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7ff9b0000000
[pid 12165] mprotect(0x7ff9b0000000, 135168, PROT_READ|PROT_WRITE) = 0
[pid 12165] mmap(NULL, 8003584, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff9ba2c3000
[pid 12165] close(16) = 0
[pid 12165] fcntl(15, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
[pid 12165] gettimeofday({1516289044, 693546}, NULL) = 0
[pid 12165] gettimeofday({1516289044, 693652}, NULL) = 0
[pid 12165] epoll_wait(3, [], 200, 0) = 0
[pid 12165] gettimeofday({1516289044, 693836}, NULL) = 0
[pid 12166] gettimeofday( <unfinished ...>
# ... 12164 (which seems to be the father or manager thread) tries to do
# the same thing, and fails:
[pid 12164] <... mmap resumed> ) = 0x7ff9b9b21000
[pid 12164] close(16) = -1 EBADF (Bad file descriptor)
[pid 12164] fcntl(15, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
[pid 12164] gettimeofday({1516289044, 696511}, NULL) = 0
[pid 12164] gettimeofday({1516289044, 696557}, NULL) = 0
[pid 12164] epoll_wait(3, [], 200, 0) = 0
[pid 12164] gettimeofday({1516289044, 696623}, NULL) = 0
[pid 12166] <... gettimeofday resumed> {1516289044, 700259}, NULL) = 0
[pid 12166] epoll_wait(3, [], 200, 0) = 0
[pid 12166] gettimeofday({1516289044, 700345}, NULL) = 0
# and when 12166 wants to use this socket, it obviously gets an error back too:
[pid 12166] getsockname(16, 0x7ff9ac012368, 0x7ff9bc9a7c0c) = -1 EBADF (Bad
file descriptor)
[pid 12164] getpid() = 57
[pid 12164] getpid() = 57
# shortly after, log messages get sent out, indicating servers are considered
# out of order:
[pid 12164] sendmsg(6, {msg_name(110)={sa_family=AF_LOCAL,
sun_path="/dev/log"}, msg_iov(8)=[{"<145>Jan 18 15:24:04 ", 21}, {"haproxy",
10}, {"[", 1}, {"57", 2}, {"]: ", 3}, {"", 0}, {"Server blue/blue0 is DOWN,
reason: Socket error, check duration: 0ms. 31 active and 1 backup servers left.
0 sessions active, 0 requeued, 0 remaining in queue.", 159}, {"\n", 1}],
msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 214
[pid 12164] getpid() = 57
[pid 12164] sendmsg(6, {msg_name(110)={sa_family=AF_LOCAL,
sun_path="/dev/log"}, msg_iov(8)=[{"<149>Jan 18 15:24:04 ", 21}, {"haproxy",
10}, {"[", 1}, {"57", 2}, {"]: ", 3}, {"", 0}, {"Server blue/blue0 was DOWN and
now enters maintenance.", 54}, {"\n", 1}], msg_controllen=0, msg_flags=0},
MSG_DONTWAIT|MSG_NOSIGNAL) = 109
[pid 12164] getpid() = 57
[...]
In this specific situation, HAProxy is not able to recover by itself. I
assume due to how maintenance mode with DNS resolution works. But I've
also seen a case (when no DNS was involved) where the backend server
was seen offline, then online again, despite the actual service behind
HAProxy was up and running the whole time.
Thanks !
Marc
