ATS-8.0.3 crash in SSL_do_handshake

[liangzhaorong]

using version:

• jemalloc-5.2.0
• openssl-1.1.1c
• trafficserver-8.0.3

I use openssl-1.1.1 ~ openssl-1.1.1c to test and crash frequently.

diags.log print:

[Jun 17 06:14:28.410] {0x2b1a6cb05700} ERROR: <SSLNetVConnection.cc:1450 (sslClientHandShakeEvent)> SSL connection failed for 'svc.ptsharp.gitv.tv': error:24067044:random number generator:rand_pool_add:internal error

traffic.out print:

Jun 17 06:14:28  traffic_manager: traffic_server: received signal 11 (Segmentation fault)
Jun 17 06:14:28  traffic_manager: traffic_server - STACK TRACE:
Jun 17 06:14:28  traffic_manager: /usr/bin/traffic_server(crash_logger_invoke(int, siginfo_t*, void*)+0x8e)[0x491d9e]
Jun 17 06:14:28  traffic_manager: /lib64/libpthread.so.0(+0xf5e0)[0x2b1a640ca5e0]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libcrypto.so.1.1(+0x83b45)[0x2b1a63783b45]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libcrypto.so.1.1(+0x1892c8)[0x2b1a638892c8]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libcrypto.so.1.1(+0x19e620)[0x2b1a6389e620]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libcrypto.so.1.1(EVP_EncryptUpdate+0x6d)[0x2b1a6389e873]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libcrypto.so.1.1(EVP_CipherUpdate+0x45)[0x2b1a6389e259]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libcrypto.so.1.1(+0x1e0d0c)[0x2b1a638e0d0c]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libcrypto.so.1.1(RAND_DRBG_generate+0x29f)[0x2b1a638e21a2]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libcrypto.so.1.1(RAND_DRBG_bytes+0xdb)[0x2b1a638e22cf]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libcrypto.so.1.1(+0x1e2830)[0x2b1a638e2830]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libcrypto.so.1.1(RAND_bytes+0x3b)[0x2b1a638e3d4f]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libssl.so.1.1(+0x34677)[0x2b1a63486677]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libssl.so.1.1(+0x62a88)[0x2b1a634b4a88]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libssl.so.1.1(+0x6040f)[0x2b1a634b240f]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libssl.so.1.1(+0x5f8be)[0x2b1a634b18be]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libssl.so.1.1(+0x5f37e)[0x2b1a634b137e]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libssl.so.1.1(SSL_do_handshake+0xeb)[0x2b1a63497f97]
Jun 17 06:14:28  traffic_manager: /usr/lib64/trafficserver/vendor/lib/libssl.so.1.1(SSL_connect+0x31)[0x2b1a6349431a]
Jun 17 06:14:28  traffic_manager: /usr/bin/traffic_server(SSLConnect(ssl_st*)+0x1d)[0x6bdebd]
Jun 17 06:14:28  traffic_manager: /usr/bin/traffic_server(SSLNetVConnection::sslClientHandShakeEvent(int&)+0x3f)[0x6a667f]
Jun 17 06:14:28  traffic_manager: /usr/bin/traffic_server(SSLNetVConnection::sslStartHandShake(int, int&)+0x7d)[0x6a70ad]
Jun 17 06:14:28  traffic_manager: /usr/bin/traffic_server(write_to_net_io(NetHandler*, UnixNetVConnection*, EThread*)+0x63a)[0x6e03ba]
Jun 17 06:14:28  traffic_manager: /usr/bin/traffic_server(NetHandler::process_ready_list()+0x27f)[0x6c9aff]
Jun 17 06:14:28  traffic_manager: /usr/bin/traffic_server(NetHandler::waitForActivity(long)+0x26d)[0x6c9dbd]
Jun 17 06:14:28  traffic_manager: /usr/bin/traffic_server(EThread::execute_regular()+0x6e9)[0x713539]
Jun 17 06:14:28  traffic_manager: /usr/bin/traffic_server[0x711b3a]
Jun 17 06:14:28  traffic_manager: /lib64/libpthread.so.0(+0x7e25)[0x2b1a640c2e25]
Jun 17 06:14:28  traffic_manager: /lib64/libc.so.6(clone+0x6d)[0x2b1a64df334d]

core.dump print:

#0  aesni_ecb_encrypt () at crypto/aes/aesni-x86_64.s:624
624	crypto/aes/aesni-x86_64.s: No such file or directory.
Missing separate debuginfos, use: debuginfo-install trafficserver-8.0.3-75.rc2.el7.x86_64
(gdb) bt full
#0  aesni_ecb_encrypt () at crypto/aes/aesni-x86_64.s:624
No locals.
#1  0x00002b5cf88312c8 in aesni_ecb_cipher (ctx=0x2b5cfb05cfc0, out=0x2b5d099a90b8 "", 
    in=0x2b5cfb04f268 "!\327Ya\346\b\376A\v\336\004=\252;\232$Ȃ\337]", len=16) at crypto/evp/e_aes.c:319
        bl = 16
#2  0x00002b5cf8846620 in evp_EncryptDecryptUpdate (ctx=0x2b5cfb05cfc0, out=0x2b5d099a90b8 "", outl=0x2b5d05003ad4, 
    in=0x2b5cfb04f268 "!\327Ya\346\b\376A\v\336\004=\252;\232$Ȃ\337]", inl=16) at crypto/evp/evp_enc.c:333
        i = 0
        j = 0
        bl = 16
        cmpl = 16
#3  0x00002b5cf8846873 in EVP_EncryptUpdate (ctx=0x2b5cfb05cfc0, out=0x2b5d099a90b8 "", outl=0x2b5d05003ad4, 
    in=0x2b5cfb04f268 "!\327Ya\346\b\376A\v\336\004=\252;\232$Ȃ\337]", inl=16) at crypto/evp/evp_enc.c:385
No locals.
#4  0x00002b5cf8846259 in EVP_CipherUpdate (ctx=0x2b5cfb05cfc0, out=0x2b5d099a90b8 "", outl=0x2b5d05003ad4, 
    in=0x2b5cfb04f268 "!\327Ya\346\b\376A\v\336\004=\252;\232$Ȃ\337]", inl=16) at crypto/evp/evp_enc.c:213
No locals.
#5  0x00002b5cf8888d0c in drbg_ctr_generate (drbg=0x2b5cfb04f180, out=0x2b5d099a90b8 "", outlen=32, adin=0x0, adinlen=0)
    at crypto/rand/drbg_ctr.c:340
        outl = 16
        ctr = 0x2b5cfb04f228
#6  0x00002b5cf888a1a2 in RAND_DRBG_generate (drbg=0x2b5cfb04f180, out=0x2b5d099a90b8 "", outlen=32, prediction_resistance=0, adin=0x0, adinlen=0)
    at crypto/rand/drbg_lib.c:638
        reseed_required = 0
#7  0x00002b5cf888a2cf in RAND_DRBG_bytes (drbg=0x2b5cfb04f180, out=0x2b5d099a90b8 "", outlen=32) at crypto/rand/drbg_lib.c:679
        additional = 0x0
        additional_len = 0
        chunk = 32
        ret = 0
#8  0x00002b5cf888a830 in drbg_bytes (out=0x2b5d099a90b8 "", count=32) at crypto/rand/drbg_lib.c:968
        ret = 11100
        drbg = 0x2b5cfb04f180
#9  0x00002b5cf888bd4f in RAND_bytes (buf=0x2b5d099a90b8 "", num=32) at crypto/rand/rand_lib.c:836
        meth = 0x2b5cf8bd1800 <rand_meth>
#10 0x00002b5cf842e677 in ssl_fill_hello_random (s=0x2b5d09988000, server=0, result=0x2b5d099a90b8 "", len=32, dgrd=DOWNGRADE_NONE)
    at ssl/s3_lib.c:4589
        send_time = 0
        ret = 161281536
#11 0x00002b5cf845ca88 in tls_construct_client_hello (s=0x2b5d09988000, pkt=0x2b5d05003cd0) at ssl/statem/statem_clnt.c:1153
        p = 0x2b5d099a90b8 ""
        sess_id_len = 47678592942080
        i = 1
        protverr = 0
        comp = 0x2b5d05003cd0
        sess = 0x0
        session_id = 0x1f841b721 <Address 0x1f841b721 out of bounds>
#12 0x00002b5cf845a40f in write_state_machine (s=0x2b5d09988000) at ssl/statem/statem.c:843
        st = 0x2b5d09988048
        ret = 11100
        transition = 0x2b5cf845bbd9 <ossl_statem_client_write_transition>
        pre_work = 0x2b5cf845bf82 <ossl_statem_client_pre_work>
        post_work = 0x2b5cf845c0ab <ossl_statem_client_post_work>
        get_construct_message_f = 0x2b5cf845c46c <ossl_statem_client_construct_message>
        cb = 0x0
        confunc = 0x2b5cf845c91e <tls_construct_client_hello>
        mt = 1
        pkt = {buf = 0x2b5d09800700, staticbuf = 0x0, curr = 4, written = 4, maxsize = 18446744073709551615, subs = 0x2b5d099c13f0}
#13 0x00002b5cf84598be in state_machine (s=0x2b5d09988000, server=0) at ssl/statem/statem.c:443
        buf = 0x0
        cb = 0x0
        st = 0x2b5d09988048
        ret = -1
        ssret = 57
#14 0x00002b5cf845937e in ossl_statem_connect (s=0x2b5d09988000) at ssl/statem/statem.c:250
No locals.
#15 0x00002b5cf843ff97 in SSL_do_handshake (s=0x2b5d09988000) at ssl/ssl_lib.c:3599
        ret = 1
#16 0x00002b5cf843c31a in SSL_connect (s=0x2b5d09988000) at ssl/ssl_lib.c:1653
No locals.
#17 0x00000000006bdebd in SSLConnect(ssl_st*) ()
No symbol table info available.
#18 0x00000000006a667f in SSLNetVConnection::sslClientHandShakeEvent(int&) ()
No symbol table info available.
#19 0x00000000006a70ad in SSLNetVConnection::sslStartHandShake(int, int&) ()
No symbol table info available.
#20 0x00000000006e03ba in write_to_net_io(NetHandler*, UnixNetVConnection*, EThread*) ()
No symbol table info available.
#21 0x00000000006c9aff in NetHandler::process_ready_list() ()
No symbol table info available.
#22 0x00000000006c9dbd in NetHandler::waitForActivity(long) ()
No symbol table info available.
#23 0x0000000000713539 in EThread::execute_regular() ()
No symbol table info available.
#24 0x0000000000711b3a in spawn_thread_internal(void*) ()
No symbol table info available.
#25 0x00002b5cf906ae25 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#26 0x00002b5cf9d9b34d in clone () from /lib64/libc.so.6
No symbol table info available.

openssl-1.1.0h ats-8.0.3

crash:

(gdb) bt
#0  OPENSSL_sk_num (st=st@entry=0x253339253945252f) at crypto/stack/stack.c:281
#1  0x00002aea4e0a4bed in sk_ASN1_OBJECT_num (sk=0x253339253945252f) at include/openssl/asn1.h:535
#2  X509_VERIFY_PARAM_set1_policies (param=param@entry=0x2aea6ef2f310, policies=0x253339253945252f) at crypto/x509/x509_vpm.c:383
#3  0x00002aea4e0a53f7 in X509_VERIFY_PARAM_inherit (dest=0x2aea6ef2f310, src=0x2aea5066b320) at crypto/x509/x509_vpm.c:217
#4  0x00002aea4dc9d8f3 in SSL_new (ctx=0x2aea50624700) at ssl/ssl_lib.c:734
#5  0x00000000006a25a6 in make_ssl_connection(ssl_ctx_st*, SSLNetVConnection*) ()
#6  0x00000000006a7133 in SSLNetVConnection::sslStartHandShake(int, int&) ()
#7  0x00000000006e0aca in write_to_net_io(NetHandler*, UnixNetVConnection*, EThread*) ()
#8  0x00000000006ca20f in NetHandler::process_ready_list() ()
#9  0x00000000006ca4cd in NetHandler::waitForActivity(long) ()
#10 0x0000000000713c49 in EThread::execute_regular() ()
#11 0x000000000071224a in spawn_thread_internal(void*) ()
#12 0x00002aea4e5b9dc5 in start_thread () from /lib64/libpthread.so.0
#13 0x00002aea4f2e821d in clone () from /lib64/libc.so.6

[zwoop]

@shinrich Can you take a look please ?

[shinrich]

@liangzhaorong are you seeing this on shutdown? Staring with openssl-1.1.1b (maybe c?). There was a change in openssl on the library shutdown which clears a key mutex. @duke8253 was been working through solutions for us in 2019. We have been seeing this in a couple different scenarios.

1. There was a problem with starting up the system, and exit() is called but some ET_NET threads are already up and running. Internally, we are trying to roll out a build that uses _exit() instead of exit() on start up failure shutdown.

2. We had some plugin threads that were doing openssl crypto operations. @duke8253 spent a lot of time improving the shutdown notification lifecycles, so plugins get an opportunity to shutdown worker threads before the openssl library is unloaded. With those changes rolled back into our internal version, this failure case has been addressed, but this doesn't look like your issue.

[liangzhaorong]

The crash occurred while the program was running. A crash occurred a few days ago. Print as follows(version: openssl-1.1.0h ats-8.0.3):

#0  0x0000000000000000 in ?? ()
#1  0x00002aec7bd2cc28 in ssl_security (s=s@entry=0x2af112390000, op=op@entry=9, bits=bits@entry=0, nid=<optimized out>, other=other@entry=0x0)
    at ssl/ssl_cert.c:1080
#2  0x00002aec7bd3dd96 in state_machine (s=0x2af112390000, server=0) at ssl/statem/statem.c:298
#3  0x00002aec7bd35dc9 in SSL_do_handshake (s=0x2af112390000) at ssl/ssl_lib.c:3220
#4  0x00000000006bdd3d in SSLConnect(ssl_st*) ()
#5  0x00000000006a65af in SSLNetVConnection::sslClientHandShakeEvent(int&) ()
#6  0x00000000006a6fdd in SSLNetVConnection::sslStartHandShake(int, int&) ()
#7  0x00000000006e0aca in write_to_net_io(NetHandler*, UnixNetVConnection*, EThread*) ()
#8  0x00000000006ca20f in NetHandler::process_ready_list() ()
#9  0x00000000006ca4cd in NetHandler::waitForActivity(long) ()
#10 0x0000000000713c49 in EThread::execute_regular() ()
#11 0x000000000071224a in spawn_thread_internal(void*) ()
#12 0x00002aec7c653dc5 in start_thread () from /lib64/libpthread.so.0
#13 0x00002aec7d38221d in clone () from /lib64/libc.so.6

@shinrich

[shinrich]

Could you try one of the openssl 1.1.1 builds (1.1.1c preferably)? Looking through the openssl code referenced in your callstacks it looks like a corruption of the openssl data structures. We didn't stay on openssl 1.1.0 very long at all. To get the TLS 1.3 support we moved to 1.1.1x quickly.

[bryancall]

If this is still an issue please reopen