Worker crashes with a segmentation fault

[TimWolla]

Output of haproxy -vv and uname -a

Linux chrono 4.9.0-8-amd64 #1 SMP Debian 4.9.130-2 (2018-10-27) x86_64 GNU/Linux

HA-Proxy version 1.8.18-1~bpo9+1 2019/02/08
Copyright 2000-2019 Willy Tarreau <willy@haproxy.org>

Build options :
  TARGET  = linux2628
  CPU     = generic
  CC      = gcc
  CFLAGS  = -O2 -g -O2 -fdebug-prefix-map=/build/haproxy-lpnOTV/haproxy-1.8.18=. -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fno-strict-aliasing -Wdeclaration-after-statement -fwrapv -Wno-null-dereference -Wno-unused-label
  OPTIONS = USE_GETADDRINFO=1 USE_ZLIB=1 USE_REGPARM=1 USE_OPENSSL=1 USE_LUA=1 USE_SYSTEMD=1 USE_PCRE2=1 USE_PCRE2_JIT=1 USE_NS=1

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

Built with OpenSSL version : OpenSSL 1.1.0f  25 May 2017
Running on OpenSSL version : OpenSSL 1.1.0j  20 Nov 2018
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports : TLSv1.0 TLSv1.1 TLSv1.2
Built with Lua version : Lua 5.3.3
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT IP_FREEBIND
Encrypted password support via crypt(3): yes
Built with multi-threading support.
Built with PCRE2 version : 10.22 2016-07-29
PCRE2 library supports JIT : yes
Built with zlib version : 1.2.8
Running on zlib version : 1.2.8
Compression algorithms supported : identity("identity"), deflate("deflate"), raw-deflate("deflate"), gzip("gzip")
Built with network namespace support.

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 filters :
	[SPOE] spoe
	[COMP] compression
	[TRACE] trace

What's the configuration?

defaults
	unique-id-format %{+X}o\ FOO-%Ts%rt

frontend fe_http
	mode http
	bind *:8080
	unique-id-header X-Req-ID
	
	default_backend be_http

backend be_http
	mode http
	http-request set-header Host example.com

	server example example.com:80

Steps to reproduce the behavior

ab -c10 -n20  'http://localhost:8080/'

Actual behavior

==28476== Invalid read of size 8
==28476==    at 0x451792: __pool_get_first (memory.h:124)
==28476==    by 0x451792: pool_alloc_dirty (memory.h:154)
==28476==    by 0x451792: pool_alloc (memory.h:230)
==28476==    by 0x451792: http_process_request (proto_http.c:3770)
==28476==    by 0x485E65: process_stream (stream.c:1912)
==28476==    by 0x505E12: process_runnable_tasks (task.c:229)
==28476==    by 0x4B515A: run_poll_loop (haproxy.c:2416)
==28476==    by 0x4B515A: run_thread_poll_loop (haproxy.c:2482)
==28476==    by 0x41A939: main (haproxy.c:3085)
==28476==  Address 0x303643352d4f4f46 is not stack'd, malloc'd or (recently) free'd
==28476== 
==28476== 
==28476== Process terminating with default action of signal 11 (SIGSEGV)
==28476==  General Protection Fault
==28476==    at 0x451792: __pool_get_first (memory.h:124)
==28476==    by 0x451792: pool_alloc_dirty (memory.h:154)
==28476==    by 0x451792: pool_alloc (memory.h:230)
==28476==    by 0x451792: http_process_request (proto_http.c:3770)
==28476==    by 0x485E65: process_stream (stream.c:1912)
==28476==    by 0x505E12: process_runnable_tasks (task.c:229)
==28476==    by 0x4B515A: run_poll_loop (haproxy.c:2416)
==28476==    by 0x4B515A: run_thread_poll_loop (haproxy.c:2482)
==28476==    by 0x41A939: main (haproxy.c:3085)
==28476== 
==28476== HEAP SUMMARY:
==28476==     in use at exit: 943,354 bytes in 2,458 blocks
==28476==   total heap usage: 2,804 allocs, 346 frees, 1,221,346 bytes allocated
==28476== 
==28476== LEAK SUMMARY:
==28476==    definitely lost: 768 bytes in 6 blocks
==28476==    indirectly lost: 0 bytes in 0 blocks
==28476==      possibly lost: 134,998 bytes in 1,239 blocks
==28476==    still reachable: 807,588 bytes in 1,213 blocks
==28476==         suppressed: 0 bytes in 0 blocks
==28476== Rerun with --leak-check=full to see details of leaked memory
==28476== 
==28476== For counts of detected and suppressed errors, rerun with: -v
==28476== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
fish: “valgrind ./haproxy -d -f ./hapr…” terminated by signal SIGSEGV (Address boundary error)

GDB Stack from prod:

(gdb) cont
Continuing.

Program received signal SIGSEGV, Segmentation fault.
__pool_get_first (pool=0x559a84ca8bc0, pool=0x559a84ca8bc0) at include/common/memory.h:124
124	include/common/memory.h: No such file or directory.
(gdb) bt full
#0  __pool_get_first (pool=0x559a84ca8bc0, pool=0x559a84ca8bc0) at include/common/memory.h:124
        p = 0x352d4f4e4f524843
#1  pool_alloc_dirty (pool=0x559a84ca8bc0) at include/common/memory.h:154
        p = <optimized out>
#2  pool_alloc (pool=0x559a84ca8bc0) at include/common/memory.h:230
No locals.
#3  http_process_request (s=0x559a84f97ff0, req=0x559a84f98000, an_bit=2048) at src/proto_http.c:3770
        sess = 0x559a84f512c0
        txn = 0x559a84f98420
        msg = 0x559a84f98480
#4  0x0000559a84452d9f in process_stream (t=t@entry=0x559a84f98b50) at src/stream.c:1912
        max_loops = 199
        ana_list = 2048
        ana_back = 2048
        flags = <optimized out>
        s = 0x559a84f97ff0
        sess = <optimized out>
        rqf_last = <optimized out>
        rpf_last = 2147483648
        rq_prod_last = 7
        rq_cons_last = 0
        rp_cons_last = 7
        rp_prod_last = 0
        req_ana_back = <optimized out>
        req = 0x559a84f98000
        res = 0x559a84f98040
        si_f = 0x559a84f98238
        si_b = 0x559a84f98260
#5  0x0000559a844d75f4 in process_runnable_tasks () at src/task.c:229
        t = <optimized out>
        i = <optimized out>
        max_processed = 200
        local_tasks = {0x559a84f6b380, 0x559a84efb710, 0x559a84fa2cb0, 0xc6f77b1962545000, 0x1b, 0x559a84fa2cb0, 0x6c0, 0x0, 0x0, 0x1b, 0x0, 0x559a844cc7ea <conn_fd_handler+490>, 0x7ffd024f0af0, 0x500000004, 
          0x7ffd024f0af0, 0x7ffd024f0af0}
        local_tasks_count = <optimized out>
        final_tasks_count = <optimized out>
#6  0x0000559a84484d97 in run_poll_loop () at src/haproxy.c:2416
        next = <optimized out>
        exp = <optimized out>
#7  run_thread_poll_loop (data=<optimized out>) at src/haproxy.c:2482
        ptif = <optimized out>
        ptdf = <optimized out>
        start_lock = 0
#8  0x0000559a843e471a in main (argc=<optimized out>, argv=0x7ffd024f0fd8) at src/haproxy.c:3085
        tids = 0x559a84cb6fb0
        threads = 0x559a84ef75c0
        i = 1
        old_sig = {__val = {2048, 94122141193584, 140724642188592, 177, 178, 140724642188912, 140724642188688, 94122132735766, 94122133250393, 140724642188912, 206158430256, 140724642188912, 140724642188720, 
            14337063287711354880, 206158430240, 94122135496320}}
        blocked_sig = {__val = {18446744067199990583, 18446744073709551615 <repeats 15 times>}}
        err = <optimized out>
        retry = <optimized out>
        limit = {rlim_cur = 4056, rlim_max = 4056}
        errmsg = "\000\000\000\000\000\000\000\000P", '\000' <repeats 15 times>, "\003\000\000\000\060", '\000' <repeats 19 times>, "[\000\000\000n", '\000' <repeats 19 times>, "w\000\000\000|\000\000\000\340I\000\000\000\000\000\000\000+U\350O\177\000\000\bbQ\204"
        pidfd = <optimized out>
(gdb) cont
Continuing.

Program terminated with signal SIGSEGV, Segmentation fault.
The program no longer exists.
(gdb) quit

Expected behavior

Don't crash.

Do you have any idea what may have caused this?

Will add once I have more information.

Do you have an idea how to solve the issue?

Will add once I have more information.

[wtarreau]

It looks like this one could be a likely candidate : commit 56fd865 BUG/MEDIUM: stream: Don't forget to free s->unique_id in stream_free(). In stream_free(), free s->unique_id. We may still have one, because it's allocated in log.c::strm_log() no matter what, even if it's a TCP connection and thus it won't get free'd by http_end_txn(). (...) However I don't see why it would be, since s->unique_id is always cleared once freed.

[wtarreau]

I think I found it. The pool_free() in stream_free() doesn't reset unique_id to null so it experiences a second free() in http_end_txn(). This patch should fix it. diff --git a/src/stream.c b/src/stream.c index a96ddcb..df778b1 100644 --- a/src/stream.c +++ b/src/stream.c @@ -387,6 +387,7 @@ static void stream_free(struct stream *s) } pool_free(pool_head_uniqueid, s->unique_id); + s->unique_id = NULL; hlua_ctx_destroy(s->hlua); s->hlua = NULL;

[TimWolla]

This patch should fix it.

I can confirm that the patch fixes this issue in my test environment (where I managed to reproduce the issue).

Can we get a release for that? For my production servers I prefer the original Debian packages which are affected.

[wtarreau]

On Sun, Feb 10, 2019 at 08:15:39AM -0800, Tim Düsterhus wrote: I can confirm that the patch fixes this issue

Thanks for the test, I'm committing it.

Can we get a release for that?

Let's wait a few more days to be sure we don't miss anything else. Too many versions in little time cause more confusion than anything.