infinite loop of kevent returning EINVAL on macOS

Detailed Description of the Problem

I noticed haproxy was using ~100% CPU on my machine (Big Sur 11.4, HAProxy version 2.4.1-1ce7d49). It was not responding on port 19000 and was not writing anything to the log. Unfortunately the log got clobbered but I didn't note anything unusual, the last line was about a service going down and the mtime on the logfile was >24h old.

so, I tried dtruss on the process which showed an endless stream of:

kevent(0x4, 0x0, 0x0)		 = -1 22
kevent(0x4, 0x0, 0x0)		 = -1 22
kevent(0x4, 0x0, 0x0)		 = -1 22

22 = EINVAL; per the manpage: "The specified time limit or filter is invalid".

After a restart it was back to normal.
Another dev at my company said that other people see this issue periodically, I will try to collect more data on how frequently it is happening.

Expected Behavior

haproxy should not get stuck in a hard loop...

Steps to Reproduce the Behavior

not sure, it just happened randomly while haproxy was running.

Do you have any idea what may have caused this?

looking at ev_kqueue.cc, either timeout or kev (which dtruss helpfully doesn't show us, although I guess we wouldn't see the contents anyways) must be malformed, so retrying doesn't help.

I saw some similar looking issues: #635, "haproxy hang", "time wrap caused kevent infinite loop"

complete speculation on on my part is running out of fds may be part of it, since that has caused other issues for us in the past, but I didn't look for evidence of that at the time. even if that is the case, I'd argue it should be handled more gracefully.

Do you have an idea how to solve the issue?

could HAproxy handle EINVAL differently (also proposed in one of the earlier issues I linked to)?
Or, perhaps more generally, one or both of:

instead of while (1) put a limit on the number of retries before we give up (and perhaps exit?).
if there is an error, sleep so we don't keep retrying with no delay.

What is your configuration?

# dev haproxy globals
global
    master-worker
    log stdout local0
    pidfile /usr/local/var/run/haproxy.pid
    maxconn 2000

defaults
    log global
    mode http
    timeout connect 300000
    timeout client 300000
    timeout server 300000
    option redispatch
    retries 3
    option httpclose
    option httplog
    option forwardfor

listen stats
    bind *:19000
    stats enable
    stats uri /haproxy_stats
    stats uri /

defaults YYY
    mode http
    option httplog
    log global
    option redispatch
    retries 3
    option httpclose
    option abortonclose

    timeout client 60s
    timeout connect 5s
    timeout server 60s
    timeout queue 60s

    balance roundrobin
    cookie TARGET rewrite
    default-server maxconn 10 rise 1 fall 1 inter 5m fastinter 1s downinter 1s error-limit 1 on-error mark-down

frontend YYY
    bind *:7099

# 16 backends redacted

defaults ZZZ
    mode http
    option httplog
    log global
    option redispatch
    retries 3
    option httpclose
    option abortonclose

    timeout client 60s
    timeout connect 5s
    timeout server 4h
    timeout queue 4h

    balance roundrobin
    cookie TARGET rewrite
    option httpchk HEAD /service/hitme/test
    default-server maxconn 10 rise 1 fall 1 inter 5m fastinter 1s downinter 1s error-limit 1 on-error mark-down

frontend ZZZ
    bind *:7098

# 28 backends redacted

Output of `haproxy -vv`

HAProxy version 2.4.1-1ce7d49 2021/06/17 - https://haproxy.org/
Status: long-term supported branch - will stop receiving fixes around Q2 2026.
Known bugs: http://www.haproxy.org/bugs/bugs-2.4.1.html
Running on: Darwin 20.5.0 Darwin Kernel Version 20.5.0: Sat May  8 05:10:33 PDT 2021; root:xnu-7195.121.3~9/RELEASE_X86_64 x86_64
Build options :
  TARGET  = generic
  CPU     = generic
  CC      = clang
  CFLAGS  =
  OPTIONS = USE_KQUEUE=1 USE_PCRE=1 USE_POLL=1 USE_THREAD=1 USE_OPENSSL=1 USE_ZLIB=1
  DEBUG   =

Feature list : -EPOLL +KQUEUE -NETFILTER +PCRE -PCRE_JIT -PCRE2 -PCRE2_JIT +POLL -PRIVATE_CACHE +THREAD -PTHREAD_PSHARED -BACKTRACE -STATIC_PCRE -STATIC_PCRE2 +TPROXY -LINUX_TPROXY -LINUX_SPLICE -LIBCRYPT -CRYPT_H -GETADDRINFO +OPENSSL -LUA -FUTEX -ACCEPT4 -CLOSEFROM +ZLIB -SLZ -CPU_AFFINITY -TFO -NS -DL -RT -DEVICEATLAS -51DEGREES -WURFL -SYSTEMD -OBSOLETE_LINKER -PRCTL -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=1).
Built with OpenSSL version : OpenSSL 1.1.1k  25 Mar 2021
Running on OpenSSL version : OpenSSL 1.1.1k  25 Mar 2021
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports : TLSv1.0 TLSv1.1 TLSv1.2 TLSv1.3
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:
Built with PCRE version : 8.45 2021-06-15
Running on PCRE version : 8.45 2021-06-15
PCRE library supports JIT : no (USE_PCRE_JIT not set)
Encrypted password support via crypt(3): no
Built with clang compiler version 12.0.5 (clang-1205.0.22.9)

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 multiplexer protocols :
(protocols marked as <default> cannot be specified using 'proto' keyword)
              h2 : mode=HTTP       side=FE|BE     mux=H2       flags=HTX|CLEAN_ABRT|HOL_RISK|NO_UPG
            fcgi : mode=HTTP       side=BE        mux=FCGI     flags=HTX|HOL_RISK|NO_UPG
              h1 : mode=HTTP       side=FE|BE     mux=H1       flags=HTX|NO_UPG
       <default> : mode=HTTP       side=FE|BE     mux=H1       flags=HTX
            none : mode=TCP        side=FE|BE     mux=PASS     flags=NO_UPG
       <default> : mode=TCP        side=FE|BE     mux=PASS     flags=

Available services : none

Available filters :
	[SPOE] spoe
	[CACHE] cache
	[FCGI] fcgi-app
	[COMP] compression
	[TRACE] trace

Last Outputs and Backtraces

No response

Additional Information

No response

ok, after writing all that, I realized since status is -1 we should break out of the loop here so something a bit different must be happening (_do_poll called in a loop?)

The 2.4.2 was released few days ago. Could you try it ?

I guess we should preferably search around the possibility of a negative time again :-/

@mr-salty

@mr-salty how did you build haproxy ? It's not normal that your CFLAGS line is empty, and it's particularly lacking a few options such as -fwrapv that we've added a while ago to support wrapping arithmetic that the original code relies on, with recent compilers. And this one used to be responsible for some cases of invalid timestamps causing pollers to loop.

I think I'll add a runtime check in the code to make sure this one was not disabled.

Could you please apply the attached patch ? It will detect the bugs and fail if your options are invalid.
build.diff.txt

I am using the homebrew pre-built binary.

looking at https://github.com/Homebrew/homebrew-core/blame/master/Formula/haproxy.rb - it does muck with CFLAGS but that hasn't been changed in 9 years (!) so it's probably overdue for an update. I can play around with building it myself and send them a PR.

I did update my machine to 2.4.2 the other day and haven't seen any issues yet, although AFAIK the problem only happened to me the one time in 5 months. I asked other devs at my company to keep an eye out as well.

Indeed, so that definitely justifies at least a sensitivity to integer wrapping. The thing is that compilers recently started to find it fun to break 40 years of properly working code by abusing undefined behaviors that used to work well for everyone, and now you can't get a properly working C program without at least a bit of options to calm some of their useless creativity. Thus I'll merge the proposed patch above to catch these earlier. Regarding the fact that it doesn't happen often, the most likely cause is that it will hit only after 49.7 days of uptime (when the internal time wraps).

By the way the simplest fix for the package above would be to pass their optimizations to CPU_CFLAGS instead of CFLAGS (the latter contains a concatenation of the various flags sources). It's worth noting that their variable was entirely empty, resulting in the loss of even -O2, and that ought to be addressed.

BUILD: add detection of missing important CFLAGS

Fix source code miscompiled error.

BUILD: add detection of missing important CFLAGS

Navigation Menu

Repository navigation

infinite loop of `kevent` returning `EINVAL` on macOS #1315

Detailed Description of the Problem

Expected Behavior

Steps to Reproduce the Behavior

Do you have any idea what may have caused this?

Do you have an idea how to solve the issue?

What is your configuration?

Output of `haproxy -vv`

Last Outputs and Backtraces

Additional Information

6 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

infinite loop of kevent returning EINVAL on macOS #1315

Description

Detailed Description of the Problem

Expected Behavior

Steps to Reproduce the Behavior

Do you have any idea what may have caused this?

Do you have an idea how to solve the issue?

What is your configuration?

Output of haproxy -vv

Last Outputs and Backtraces

Additional Information

Activity

mr-salty commented on Jul 8, 2021

capflam commented on Jul 9, 2021

wtarreau commented on Jul 10, 2021

wtarreau commented on Jul 13, 2021

wtarreau commented on Jul 13, 2021

mr-salty commented on Jul 14, 2021

wtarreau commented on Jul 14, 2021

wtarreau commented on Jul 14, 2021

6 remaining items

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

infinite loop of `kevent` returning `EINVAL` on macOS #1315

Output of `haproxy -vv`