Crash due to bug in Thread Context migration

[sudheerv]

Ran into the below crash in ATS9 after a couple of weeks of running stable. This crash happens about every other minute on some random box out of the 100s of boxes we've in production.

(gdb) bt
#0  0x00002b74100ed31e in asn1_string_embed_free () from /lib/libcrypto.so.1.1
#1  0x00002b74100f8eaf in asn1_primitive_free () from /lib/libcrypto.so.1.1
#2  0x00002b74100f8e89 in asn1_primitive_free () from /lib/libcrypto.so.1.1
#3  0x00002b74100f9240 in asn1_template_free () from /lib/libcrypto.so.1.1
#4  0x00002b74100f8fde in asn1_item_embed_free () from /lib/libcrypto.so.1.1
#5  0x00002b74100f9240 in asn1_template_free () from /lib/libcrypto.so.1.1
#6  0x00002b74100f8fde in asn1_item_embed_free () from /lib/libcrypto.so.1.1
#7  0x00002b74100f9240 in asn1_template_free () from /lib/libcrypto.so.1.1
#8  0x00002b74100f8fde in asn1_item_embed_free () from /lib/libcrypto.so.1.1
#9  0x00002b74100f9240 in asn1_template_free () from /lib/libcrypto.so.1.1
#10 0x00002b74100f8fde in asn1_item_embed_free () from /lib/libcrypto.so.1.1
#11 0x00002b74100f9185 in ASN1_item_free () from /lib/libcrypto.so.1.1
#12 0x00002b7410246f11 in OPENSSL_sk_pop_free () from /lib/libcrypto.so.1.1
#13 0x00002b740fe03eca in SSL_SESSION_free () from /lib/libssl.so.1.1
#14 0x00002b740fdfdbba in SSL_free () from /lib/libssl.so.1.1
#15 0x0000000000736c78 in SSLNetVConnection::clear (this=0x2b7592c85aa0) at SSLNetVConnection.cc:928
#16 0x0000000000737374 in SSLNetVConnection::free (this=0x2b7592c85aa0, t=0x2b7413c06000) at SSLNetVConnection.cc:972
#17 0x000000000075d2af in NetHandler::free_netevent (this=0x2b7413c0a0a0, ne=ne@entry=0x2b7592c85c50) at UnixNet.cc:364
#18 0x000000000076f27e in read_signal_and_update (vc=0x2b7592c85aa0, event=100) at UnixNetVConnection.cc:104
#19 UnixNetVConnection::readSignalAndUpdate (this=this@entry=0x2b7592c85aa0, event=event@entry=100) at UnixNetVConnection.cc:1017
#20 0x000000000073d6f3 in SSLNetVConnection::net_read_io (this=0x2b7592c85aa0, nh=0x2b7413c0a0a0, lthread=<optimized out>) at SSLNetVConnection.cc:671
#21 0x000000000075d5e8 in NetHandler::process_ready_list (this=this@entry=0x2b7413c0a0a0) at UnixNet.cc:412
#22 0x000000000075d8dd in NetHandler::waitForActivity (this=0x2b7413c0a0a0, timeout=<optimized out>) at UnixNet.cc:547
#23 0x00000000007ba06a in EThread::execute_regular (this=this@entry=0x2b7413c06000) at UnixEThread.cc:266
#24 0x00000000007ba332 in EThread::execute (this=0x2b7413c06000) at UnixEThread.cc:327
#25 0x00000000007b86d9 in spawn_thread_internal (a=0x2b7412d69680) at Thread.cc:92
#26 0x00002b7410a93dd5 in start_thread () from /lib64/libpthread.so.0
#27 0x00002b7411844ead in clone () from /lib64/libc.so.6

gdb) f 17
#17 0x00000000007372e4 in SSLNetVConnection::free (this=0x2af8721f6080, t=0x2af795e20000) at SSLNetVConnection.cc:972
972	SSLNetVConnection.cc: No such file or directory.
(gdb) p this->netvc_context
$1 = NET_VCONNECTION_OUT
(gdb) p this->submit_time
$2 = 0
(gdb) p this->next_inactivity_timeout_at
$3 = 1596887517136946771
(gdb) p this->inactivity_timeout
There is no member or method named inactivity_timeout.
(gdb) p this->inactivity_timeout_in
$4 = 120000000000
(gdb) p this->next_activity_timeout_at
$5 = 0
(gdb) p this->read
$1 = {enabled = 0, vio = {cont = 0x0, nbytes = 0, ndone = 0, op = 0, buffer = {mbuf = 0x0, entry = 0x0}, vc_server = 0x2b7592c85aa0, mutex = {m_ptr = 0x2b75b9f668b0}, _disabled = false}, ready_link = {<SLink<NetEvent>> = {next = 0x0}, 
    prev = 0x0}, enable_link = {next = 0x0}, in_enabled_list = 0, triggered = 1}

Note: PR #7096 addresses an issue introduced by this PR.

[oknet]

It seems the SSL object was broken due to one or more SPECIAL requests, because only one box ran into the crash.

Usually there must be a load balancer or dns server to direct the request to the cache server. A SPECIAL request will always be send to the same server within a period of time. When the LB's session times out or the dns record expires, another cache server will be selected.

You will see another random box runs into the crash but the last one runs stably.

[shinrich]

@oknet by SPECIAL, I assume you mean a malformed or malicious client request?

[oknet]

@shinrich Yes, I think so, based on the limited information :
This crash happens about every other minute on some random box out of the 100s of boxes we've in production.

But @sudheerv described a possibility in #7097, which I think may also be correct.

[sudheerv]

After over 2 months of debugging, finally found the root cause of the issue. The issue is mainly caused by changing the (read) mutex from the server vc before acquiring from and releasing to the pool. The net i/o read (including EOS) is meant to be synchronized with the read vio mutex (which is the session pool mutex before acquiring from the pool and the HttpTunnel’s mutex before releasing to the pool) but in the process of disabling the i/o, the mutex is changed by calling do_io_read() with null continuation. This lets in a net read and also makes the “closed” flag checking unreliable in the net_read_io() corrupting the ssl or other heap memory.

Reproduced the behavior by tweaking the mutex windows and tested a fix that by tightening the windows and ensuring the mutex is preserved while the session acquire/release process is completed.

These issues are mostly specific to using global session sharing and for some reason having a lot of transform plugins acting on the server vc, seems to expose the race condition more.

In the process of debugging this, added a couple of mechanisms that helped -

1. tracking a VC event/callback history much like the SM history
2. ssl -> vc book keeping to catch and prevent double deletes (this has caught a couple of bugs doing double deletes)