haproxy icon indicating copy to clipboard operation
haproxy copied to clipboard

HAProxy crashes with Segmentation fault err

Open mieszko4 opened this issue 2 years ago • 19 comments

Detailed Description of the Problem

HAProxy crashes with Segmentation fault err after executing Runtime API commands through socat.

Expected Behavior

HAProxy should not crash.

Steps to Reproduce the Behavior

  1. Execute one-by-one add server NEW_SERVER weight 10 maxconn 100000 on-marked-down shutdown-sessions check;set NEW_SERVER state ready;enable health NEW_SERVER 10 times
  2. Have 1000 active WebSocket connections
  3. Execute one-by-one add server NEW_SERVER weight 10 maxconn 100000 on-marked-down shutdown-sessions check;set NEW_SERVER state ready;enable health NEW_SERVER 10 times. This is the same as step (1)
  4. Execute one-by-one set server OLD_SERVER state drain 10 times
  5. Execute one-by-one set server OLD_SERVER state maint;del server OLD_SERVER 10 times

HAProxy crashes during step (5) after 5th execution.

Do you have any idea what may have caused this?

The crash does not happen all the time. It tends to happen when there are more active WebSocket connections.

This looks like it it related to bug fix BUG/MEDIUM: server/cli: don't delete a dynamic server that has streams which was applied in 2.9-dev6 but not applied in version which I am using.

However, in this bug description it says:

Indeed, when the server option "on-marked-down shutdown-sessions" is not used, server streams are not purged when srv enters maintenance mode.

But I am adding dynamic server with on-marked-down shutdown-sessions so I am not sure if that bug fix applies.

It looks to me that set server OLD_SERVER state maint does not purge all server streams all the time. And if that happens, then calling del server OLD_SERVER crashes the server.

Do you have an idea how to solve the issue?

No response

What is your configuration?

global
    log stdout format raw local0
    nbthread 1

    stats socket ipv4@*:9901 level admin

defaults
    mode http
    timeout connect 5s
    timeout client 30s
    timeout server 30s

    log global
    option httplog

frontend sonic_alb
    bind *:9902

    http-request set-var(txn.room_id,ifnotexists) url_param(token),word(2,.),ub64dec,json_query('$.room_id','int')
    
    acl is_root path eq /
    acl has_room_id var(txn.room_id) -m int gt 0

    http-request reject unless is_root has_room_id
    default_backend sonic_workers

backend sonic_workers
    balance roundrobin

    stick on var(txn.room_id)

    stick-table type integer size 456m srvkey name

    option httpchk
    http-check send meth GET uri /health

Output of haproxy -vv

HAProxy version 2.8.3-86e043a 2023/09/07 - https://haproxy.org/
Status: long-term supported branch - will stop receiving fixes around Q2 2028.
Known bugs: http://www.haproxy.org/bugs/bugs-2.8.3.html
Running on: Linux 6.2.0-1014-aws #14~22.04.1-Ubuntu SMP Thu Oct  5 22:43:45 UTC 2023 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_GETADDRINFO=1 USE_OPENSSL=1 USE_LUA=1 USE_PROMEX=1 USE_PCRE2=1 USE_PCRE2_JIT=1
  DEBUG   = -DDEBUG_STRICT -DDEBUG_MEMORY_POOLS

Feature list : -51DEGREES +ACCEPT4 +BACKTRACE -CLOSEFROM +CPU_AFFINITY +CRYPT_H -DEVICEATLAS +DL -ENGINE +EPOLL -EVPORTS +GETADDRINFO -KQUEUE -LIBATOMIC +LIBCRYPT +LINUX_CAP +LINUX_SPLICE +LINUX_TPROXY +LUA +MATH -MEMORY_PROFILING +NETFILTER +NS -OBSOLETE_LINKER +OPENSSL -OPENSSL_WOLFSSL -OT -PCRE +PCRE2 +PCRE2_JIT -PCRE_JIT +POLL +PRCTL -PROCCTL +PROMEX -PTHREAD_EMULATION -QUIC +RT +SHM_OPEN +SLZ +SSL -STATIC_PCRE -STATIC_PCRE2 -SYSTEMD +TFO +THREAD +THREAD_DUMP +TPROXY -WURFL -ZLIB

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

Built with multi-threading support (MAX_TGROUPS=16, MAX_THREADS=256, default=2).
Built with OpenSSL version : OpenSSL 1.1.1w  11 Sep 2023
Running on OpenSSL version : OpenSSL 1.1.1w  11 Sep 2023
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.
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 :
	[BWLIM] bwlim-in
	[BWLIM] bwlim-out
	[CACHE] cache
	[COMP] compression
	[FCGI] fcgi-app
	[SPOE] spoe
	[TRACE] trace

Last Outputs and Backtraces

2023-10-24 10:50:37.539+00	172.44.XX.YYY:59067 [24/Oct/2023:10:50:01.086] sonic_alb sonic_workers/i-0d142a1496ec5b010 0/0/1/1/36227 101 10480 - - ---- 890/890/887/40/0 0/0 "GET /?token=TOKEN&isAccepted=1&appState=active&clientVersion=4.13.2 HTTP/1.1"			
2023-10-24 10:50:37.539+00	172.44.XX.YYY:46619 [24/Oct/2023:10:43:28.740] sonic_alb sonic_workers/i-0cb99edf08d14b2f1 0/0/1/2/428622 101 138613 - - ---- 888/888/886/104/0 0/0 "GET /?token=TOKEN&isAccepted=1&appState=active&clientVersion=4.13.2 HTTP/1.1"		
2023-10-24 10:50:38.540+00	[NOTICE]   (1) : haproxy version is 2.8.3-86e043a		
2023-10-24 10:50:38.540+00	[NOTICE]   (1) : path to executable is /usr/local/sbin/haproxy		
2023-10-24 10:50:38.540+00	[ALERT]    (1) : Current worker (8) exited with code 139 (Segmentation fault)		
2023-10-24 10:50:38.540+00	[ALERT]    (1) : exit-on-failure: killing every processes with SIGTERM		
2023-10-24 10:50:38.540+00	[WARNING]  (1) : All workers exited. Exiting... (139)

Additional Information

HAProxy is run in docker: Docker version 24.0.6, build ed223bc Docker is run on EC2: Ubuntu 22.04

mieszko4 avatar Oct 25 '23 00:10 mieszko4

Hi @mieszko4

Thanks for the report!

Well apparently I was wrong to assume that on-marked-down shutdown-session would help to workaround the issue since in this case streams are simply scheduled for shutdown when the server is put in maintenance: it is not a synchronous operation. So I think that it's possible that some streams still point to the about to be deleted server without the patch you mentioned.

As such, it could explain why you still encounter the bug from #2298, and should hopefully be solved by applying BUG/MEDIUM: server/cli: don't delete a dynamic server that has streams

Darlelet avatar Oct 25 '23 07:10 Darlelet

Thnx @Darlelet for the explanation!

From my understanding, BUG/MEDIUM: server/cli: don't delete a dynamic server that has streams will solve the crash, however, it will fail to delete the server and it will output Server still has connections attached to it, cannot remove it..

I got few questions in that case:

  1. Is there a plan to make set server OLD_SERVER state maint synchronous so that del server OLD_SERVER can be a always-pass operation (when using on-marked-down shutdown-session)?

  2. What is the recommended way for waiting for all streams to complete before calling del server OLD_SERVER? Is it just periodically calling show servers conn?

mieszko4 avatar Oct 25 '23 07:10 mieszko4

From my understanding, BUG/MEDIUM: server/cli: don't delete a dynamic server that has streams will solve the crash, however, it will fail to delete the server and it will output Server still has connections attached to it, cannot remove it..

That is correct indeed, in your case I understand that it might be annoying. Unfortunately I'm unable to answer to your questions, hopefully @capflam or @wtarreau will have an opinion on this

Darlelet avatar Oct 25 '23 08:10 Darlelet

Hello,

there are urrently no such plans because you never know how long you'll need to wait. One approach that should theoretically work (not tested myself) is to chain the 3 following operations:

  • set server OLD_SERVER state maint
  • shutdown sessions server OLD_SERVER
  • del server OLD_SERVER

It would be nice to give this a try and see if that makes it more convenient for you.

wtarreau avatar Oct 25 '23 09:10 wtarreau

shutdown sessions server OLD_SERVER

Unfortunately I think it will do as if on-marked-down shutdown-session was set and server is put under maintenance:

srv_shutdown_streams() will be called, which will cause stream_shutdown() to be called for each stream that the server has.

But stream_shutdown() will only schedule the shutdown and will return immediately, so the server might still have streams attached to it if the del server cli is handled shortly after :(

/* kill a stream and set the termination flags to <why> (one of SF_ERR_*) */
void stream_shutdown(struct stream *stream, int why)
{
        if (stream->scb->flags & (SC_FL_SHUT_DONE|SC_FL_SHUT_WANTED))
                return;

        sc_schedule_shutdown(stream->scb);
        sc_schedule_abort(stream->scb);
        stream->task->nice = 1024;
        if (!(stream->flags & SF_ERR_MASK))
                stream->flags |= why;
        task_wakeup(stream->task, TASK_WOKEN_OTHER);
}

Darlelet avatar Oct 25 '23 10:10 Darlelet

Ah yes indeed, so it can take a little bit of time. I don't have any short-term solution then. Ideally we'd need to have the ability to wait for shutdowns to complete or fail (i.e. wait if the server is down, don't wait otherwise), but it would only be delay-based since we don't have any event to state that a server has no more connection.

wtarreau avatar Oct 25 '23 11:10 wtarreau

Thxn for the answers!

So, in current LTS (2.8.3), I need to check if server has still active connections before deleting it.

To solve this, I was thinking about doing the following:

  1. Execute set server OLD_SERVER state maint
  2. Execute show servers conn periodically every 1s until used_cur === 0 and idle_cur === 0
  3. Execute del server OLD_SERVER

WDYT?

I am also wondering if there is a simpler way. Could I just wait for some time that would guarantee me that there are no more connections before deleting the server? If yes, what would be the timeout value?

mieszko4 avatar Oct 27 '23 10:10 mieszko4

It should definitely work. Note that normally the shutdown should be almost immediate (i.e. a matter of a few milliseconds) so your 1s delay will definitely cover for this.

wtarreau avatar Oct 28 '23 08:10 wtarreau

Note that normally the shutdown should be almost immediate (i.e. a matter of a few milliseconds) so your 1s delay will definitely cover for this.

Thanks! Is that also the case for ongoing WebSocket connections? (as opposed to normal HTTP requests)

bfelbo avatar Oct 30 '23 11:10 bfelbo

Yes! What happens when you send a "shutdown sessions" order is that it wakes the respective streams up with a message indicating they must immediately terminate. From this point the task in question cannot do anything else but close everything and quit. It's very similar in spirit to the SIGTERM in UNIX systems (except that in our cases tasks don't have the option to ignore the signal). And just as with processes dealing with signals, it requires a very small amount of time for this to be handled asynchronously and to complete, this is measured in milliseconds but it cannot be zero precisely because it's asynchronous. But the type of traffic passing through it, the difference between requests and tunnels doesn't matter, every transfer in progress will be instantly aborted without having the option to make any further progress, so you may never witness any remains of such a connection in progress after your 1-second pause, that's highly sufficient.

wtarreau avatar Oct 30 '23 13:10 wtarreau

Thnx @wtarreau!

I tried "1s delay" solution and I still run into issue with del server OLD_SERVER in specific case.

Order of events:

  1. At the same time: Terminate server (i.e. forcefully kill the server) + Reconnect WebSocket client
  2. Execute set server OLD_SERVER state main
  3. Sleep 1s
  4. Execute del server OLD_SERVER

I am consistently getting Server still has connections attached to it, cannot remove it. output from (4). HAProxy does not crash in this case.


If I move "Terminating server" step after "Execute set server OLD_SERVER state main" + "Execute del server OLD_SERVER" steps then there is never an issue.

Looks like set server OLD_SERVER state main hangs on ongoing connection. I guess it got left with a hanging HTTP stream initialising WebSocket connection upgrade and we would need to sleep for connection timeout before running del server OLD_SERVER. In that case "Sleep 1s" is not enough time.

This behaviour surprises me, because I would expect connections to be dropped right away regardless of the connection state because on-marked-down shutdown-session is used.

Is my reasoning right? Is this expected behaviour?

mieszko4 avatar Oct 31 '23 09:10 mieszko4

Another HAProxy crash happened. However, it is not Segmentation fault so I am not sure if this is related to this issue.

It happened during (5) "Execute one-by-one set server OLD_SERVER state maint;del server OLD_SERVER 10 times" During that step (but before set server OLD_SERVER state maint;del server OLD_SERVER) there is a server clean up:

  • WebSocket listener is stopped so that no new socket connections can happen
  • All WebSocket sockets are forcefully closed at once (~240 sockets at once)

Based on logs, crash happened during or right after closing sockets but before set server OLD_SERVER state maint;del server OLD_SERVER. The crash happened after 3rd iteration - in total ~700 sockets were closed and it took ~9s.

In the logs I see ha_panic so https://github.com/haproxy/haproxy/issues/138 might be related because a lot of current connections went down, too.

I am not sure how to interpret this logs so would be very helpful if someone could comment on this :) Is it expected for HAProxy to crash when there forcefully closing a log of current connections?

Logs:

2023-10-31 10:48:27.577+00	Thread 1 is about to kill the process.
2023-10-31 10:48:27.577+00	*>Thread 1 : id=0x7fb656bb6180 act=1 glob=0 wq=1 rq=0 tl=0 tlsz=0 rqsz=0
2023-10-31 10:48:27.577+00	      1/1    stuck=1 prof=0 harmless=0 isolated=0
2023-10-31 10:48:27.577+00	             cpu_ns: poll=12464177335522 now=12467047647443 diff=2870311921
2023-10-31 10:48:27.577+00	             curr_task=0x55d4b1eebfd0 (task) calls=1 last=0
2023-10-31 10:48:27.577+00	               fct=0x55d4afd6a9c0(process_stream) ctx=0x55d4b560d410
2023-10-31 10:48:27.577+00	             strm=0x55d4b560d410,400800 src=172.44.15.252 fe=sonic_alb be=sonic_alb dst=unknown
2023-10-31 10:48:27.577+00	             txn=0x55d4b560d7a0,0 txn.req=MSG_BODY,0 txn.rsp=MSG_RPBEFORE,0
2023-10-31 10:48:27.577+00	             rqf=808001 rqa=34 rpf=80000000 rpa=0
2023-10-31 10:48:27.577+00	             scf=0x55d4b2e4d350,EST,420 scb=0x55d4b1b010e0,INI,21
2023-10-31 10:48:27.577+00	             af=(nil),0 sab=(nil),0
2023-10-31 10:48:27.578+00	172.43.11.71:33935 [31/Oct/2023:10:48:27.017] sonic_alb sonic_alb/<NOSRV> -1/-1/-1/-1/0 400 0 - - CR-- 22/22/0/0/0 0/0 "<BADREQ>"
2023-10-31 10:48:27.579+00	172.42.2.143:37082 [31/Oct/2023:10:48:27.094] sonic_alb sonic_alb/<NOSRV> -1/-1/-1/-1/0 400 0 - - CR-- 16/16/0/0/0 0/0 "<BADREQ>"
2023-10-31 10:48:27.579+00	             cof=0x55d4b61353b0,80000300:H1(0x55d4b5e38150)/RAW((nil))/tcpv4(1925)
2023-10-31 10:48:27.579+00	             cob=(nil),0:NONE((nil))/NONE((nil))/NONE(-1)
2023-10-31 10:48:27.579+00	             call trace(16):
2023-10-31 10:48:27.579+00	             | 0x55d4afe40501 [eb ba 66 66 2e 0f 1f 84]: ha_thread_dump+0x91/0x93
2023-10-31 10:48:27.579+00	             | 0x55d4afe4070e [64 49 8b 54 24 10 64 49]: main+0x17fede
2023-10-31 10:48:27.579+00	             | 0x55d4afe40992 [58 c3 66 66 2e 0f 1f 84]: ha_panic+0x52/0x54
2023-10-31 10:48:27.579+00	             | 0x7fb656ee5140 [48 c7 c0 0f 00 00 00 0f]: libpthread:+0x13140
2023-10-31 10:48:27.579+00	             | 0x55d4afd7ce8d [3d c7 00 00 00 77 f4 0f]: main+0xbc65d
2023-10-31 10:48:27.579+00	             | 0x55d4afd83766 [49 b9 04 00 00 00 05 00]: http_wait_for_request+0x9c6/0x105a
2023-10-31 10:48:27.579+00	             | 0x55d4afd6ba2d [85 c0 0f 84 4b ff ff ff]: process_stream+0x106d/0x3878
2023-10-31 10:48:27.58+00	[NOTICE]   (1) : haproxy version is 2.8.3-86e043a
2023-10-31 10:48:27.58+00	[NOTICE]   (1) : path to executable is /usr/local/sbin/haproxy
2023-10-31 10:48:27.58+00	[ALERT]    (1) : Current worker (8) exited with code 134 (Aborted)
2023-10-31 10:48:27.58+00	[ALERT]    (1) : exit-on-failure: killing every processes with SIGTERM
2023-10-31 10:48:27.58+00	[WARNING]  (1) : All workers exited. Exiting... (134)

mieszko4 avatar Nov 01 '23 14:11 mieszko4

I tried "1s delay" solution and I still run into issue with del server OLD_SERVER in specific case.

Order of events:

  1. At the same time: Terminate server (i.e. forcefully kill the server) + Reconnect WebSocket client
  2. Execute set server OLD_SERVER state main
  3. Sleep 1s
  4. Execute del server OLD_SERVER

I am consistently getting Server still has connections attached to it, cannot remove it. output from (4). HAProxy does not crash in this case.

@wtarreau Any suggestions what to do here?

Perhaps it'd be make sense to add a way in HAProxy to forcefully drop connections?

bfelbo avatar Nov 29 '23 12:11 bfelbo

Server still has connections attached to it, cannot remove it. happened again during one of the deployments. It is not critical err for us but would be great to fix it.

EDIT: ~I see that there might be a fix for it already in 2.8.5 (https://git.haproxy.org/?p=haproxy-2.8.git;a=commitdiff;h=f4bec87). We will try it out :)~ Nevermind, I see this fix is for QUIC

mieszko4 avatar Dec 14 '23 18:12 mieszko4

Hope you don't mind me bumping this issue as Server still has connections attached to it, cannot remove it. is causing frequent deployment issues for us.

Would really appreciate any guidance here and your thoughts on whether it'd make sense to give HAProxy the ability to forcefully drop connections 🙏

bfelbo avatar Dec 20 '23 13:12 bfelbo

Current workaround for this issue is to retry del server OLD_SERVER after waiting for 2s.

mieszko4 avatar Feb 08 '24 14:02 mieszko4

I'm wondering if it's possible that there's still an ongoing check immediately after the moment the server is disabled and that we don't wait for it. I've been experimenting with enforcing a delay (the CLI was not designed for this initially so it's not trivial) and I'm now leaning towards instead having a separate command to wait for a server to become fully unused. I think it could possibly have other uses. I'm still on it and will get back here with more news once I have some.

wtarreau avatar Feb 08 '24 18:02 wtarreau

What I thought was wrong, there's refcounting in the checks so a running check will not dereference a freed server (and I tried of course). I'll work on the timers first.

wtarreau avatar Feb 08 '24 19:02 wtarreau

If you're interested, I've just added a "wait" command on the CLI so that you can now chain your commands, e.g. "disable server p1/s1; wait 2s; del server p1/s1". I now want to support passing an optional condition on it, and one of these conditions should definitely be whether or not the server is still in use.

wtarreau avatar Feb 08 '24 20:02 wtarreau

a srv-unsued condition was added to wait command. For instance:

disable server px/srv1
shutdown sessions server px/srv1
wait 2s srv-unused px/srv1
del server px/srv1"

@wtarreau, with this option, can we consider the issue as fixed ?

capflam avatar Feb 29 '24 15:02 capflam

Thnx for adding wait command :rocket: I see it is available in 3.0 and documented in https://docs.haproxy.org/dev/management.html#9.3-wait.

Just wanted to make sure that I am understanding this well:

  • 2s in the example is the max time for waiting
  • if px/srv1 will shutdown all sessions in 1s then wait will succeed after 1s
  • if after 2s px/srv1 will still have sessions then wait will fail after 2s

Is that right?


We will wait for 3.0 to become stable before we use this feature in production. But I think we can close this issue already. Thnx again!

mieszko4 avatar Feb 29 '24 19:02 mieszko4

Yes, you understood it perfectly! I hope we'll find a way to make "del server" operate in the background by itself on the server, but we figured it causes significant other trouble (typically we may need to rename the server so that you can easily re-add one with the same name if needed). So it's possible that we'll drop that srv-unused wait condition before 3.0-final if we find a better way. Also, I wanted to rename that option to something like "srv-removable" which is more explicit and more exact. Just keep this in mind next time you want to have a look :-)

wtarreau avatar Feb 29 '24 21:02 wtarreau

Awesome, thnx!

mieszko4 avatar Mar 06 '24 07:03 mieszko4