Crash on dynamic_cast

[sudheerv]

Seeing this crash in ats9 in prod.

It's a bit strange that dynamic_cast would crash this way. Http2ClientSession is no longer a subclass of PluginIdentity and only PluginVC now is derived from PluginIdentity, but it's odd that instead of returning a nullptr, dynamic_cast is causing a SegFault on attempting to do that.

Everything else about the pointer seems fine (i.e it seems to be a valid SSL VC pointer). Given that, this dynamic_cast is not required anymore (ie no real netvc is of type PluginIdentity anymore, I'm going to try just guarding it with is_internal_request() check to see if it helps. It's still pretty strange that it's crashing like this though.

(gdb) bt
#0  0x00002b88ea38987e in __cxxabiv1::__dynamic_cast (src_ptr=0x2b89451cb5d0, src_type=0x81dd48 <typeinfo for NetVConnection>, dst_type=dst_type@entry=0x7c49d8 <typeinfo for PluginIdentity>, src2dst=src2dst@entry=-2)
    at ../../.././libstdc++-v3/libsupc++/dyncast.cc:71
#1  0x000000000071d0e8 in ProxyTransaction::new_transaction (this=this@entry=0x2b894a65e240, from_early_data=<optimized out>) at ProxyTransaction.cc:46
#2  0x0000000000523c11 in new_transaction (this=0x2b894a65ded0) at Http1ClientSession.cc:473
#3  Http1ClientSession::state_keep_alive (this=0x2b894a65ded0, event=100, data=<optimized out>) at Http1ClientSession.cc:388
#4  0x0000000000770393 in handleEvent (data=0x2b89451cb7b0, event=100, this=0x2b894a65ded0) at /home/svinukon/Traffic/ATS/ats9/ats-core_trunk/ats9/src/iocore/eventsystem/I_Continuation.h:190
#5  read_signal_and_update (vc=0x2b89451cb5d0, event=100) at UnixNetVConnection.cc:83
#6  UnixNetVConnection::readSignalAndUpdate (this=this@entry=0x2b89451cb5d0, event=event@entry=100) at UnixNetVConnection.cc:1016
#7  0x0000000000741d53 in SSLNetVConnection::net_read_io (this=0x2b89451cb5d0, nh=0x2b88ef623d80, lthread=<optimized out>) at SSLNetVConnection.cc:671
#8  0x0000000000760208 in NetHandler::process_ready_list (this=this@entry=0x2b88ef623d80) at UnixNet.cc:412
#9  0x00000000007604fd in NetHandler::waitForActivity (this=0x2b88ef623d80, timeout=<optimized out>) at UnixNet.cc:547
#10 0x00000000007be9ba in EThread::execute_regular (this=this@entry=0x2b88ef620000) at UnixEThread.cc:266
#11 0x00000000007bec82 in EThread::execute (this=0x2b88ef620000) at UnixEThread.cc:327
#12 0x00000000007bd029 in spawn_thread_internal (a=0x2b88ec163ec0) at Thread.cc:92
#13 0x00002b88e9ee3dd5 in start_thread () from /lib64/libpthread.so.0
#14 0x00002b88eac94ead in clone () from /lib64/libc.so.6
(gdb) p *this


(gdb) p *this
$66 = {<Continuation> = {<force_VFPT_to_top> = {_vptr.force_VFPT_to_top = 0x825448 <vtable for NetHandler+16>}, handler = (int (Continuation::*)(Continuation * const, int, void *)) 0x75f8d0 <NetHandler::mainNetEvent(int, Event*)>, mutex = {
      m_ptr = 0x2b88ec51d780}, link = {<SLink<Continuation>> = {next = 0x0}, prev = 0x0}, control_flags = {raw_flags = 0}, thread_affinity = 0x0}, <EThread::LoopTailHandler> = {_vptr.LoopTailHandler = 0x825478 <vtable for NetHandler+64>}, 
  thread = 0x2b88ef620000, trigger_event = 0x0, read_ready_list = {<DLL<NetEvent, NetEvent::Link_read_ready_link>> = {head = 0x0}, tail = 0x0}, write_ready_list = {<DLL<NetEvent, NetEvent::Link_write_ready_link>> = {head = 0x2b89451cb780}, 
    tail = 0x2b89451cb780}, open_list = {<DLL<NetEvent, NetEvent::Link_open_link>> = {head = 0x2b8945367a00}, tail = 0x2b8949e724c0}, cop_list = {head = 0x2b891a03b070}, read_enable_list = {al = {head = {s = {pointer = 0x0, version = 0}, 
        data = 0x00000000000000000000000000000000}, name = 0x7fc219 "AtomicSLL", offset = 136}}, write_enable_list = {al = {head = {s = {pointer = 0x0, version = 0}, data = 0x00000000000000000000000000000000}, name = 0x7fc219 "AtomicSLL", offset = 248}}, 
  keep_alive_queue = {<DLL<NetEvent, NetEvent::Link_keep_alive_queue_link>> = {head = 0x2b899dee1e20}, tail = 0x2b89451e70a0}, keep_alive_queue_size = 4, active_queue = {<DLL<NetEvent, NetEvent::Link_active_queue_link>> = {head = 0x2b8945333cb0}, 
    tail = 0x2b89451cb780}, active_queue_size = 51, static global_config = {max_connections_in = 100000, max_connections_active_in = 10000, inactive_threshold_in = 0, transaction_no_activity_timeout_in = 0, keep_alive_no_activity_timeout_in = 0, 
    default_inactivity_timeout = 300}, config = {max_connections_in = 100000, max_connections_active_in = 10000, inactive_threshold_in = 0, transaction_no_activity_timeout_in = 0, keep_alive_no_activity_timeout_in = 0, default_inactivity_timeout = 300}, 
  max_connections_per_thread_in = 2083, max_connections_active_per_thread_in = 208, static CONFIG_ITEM_COUNT = 6, static config_value_affects_per_thread_value = {<std::_Base_bitset<1>> = {_M_w = 3}, <No data fields>}, 
  static active_thread_types = {<std::_Base_bitset<1>> = {_M_w = 1}, <No data fields>}}

(gdb) p ne->nh
$63 = (NetHandler *) 0x2b88ef623d80
(gdb) p *ne->nh
$64 = {<Continuation> = {<force_VFPT_to_top> = {_vptr.force_VFPT_to_top = 0x825448 <vtable for NetHandler+16>}, handler = (int (Continuation::*)(Continuation * const, int, void *)) 0x75f8d0 <NetHandler::mainNetEvent(int, Event*)>, mutex = {
      m_ptr = 0x2b88ec51d780}, link = {<SLink<Continuation>> = {next = 0x0}, prev = 0x0}, control_flags = {raw_flags = 0}, thread_affinity = 0x0}, <EThread::LoopTailHandler> = {_vptr.LoopTailHandler = 0x825478 <vtable for NetHandler+64>}, 
  thread = 0x2b88ef620000, trigger_event = 0x0, read_ready_list = {<DLL<NetEvent, NetEvent::Link_read_ready_link>> = {head = 0x0}, tail = 0x0}, write_ready_list = {<DLL<NetEvent, NetEvent::Link_write_ready_link>> = {head = 0x2b89451cb780}, 
    tail = 0x2b89451cb780}, open_list = {<DLL<NetEvent, NetEvent::Link_open_link>> = {head = 0x2b8945367a00}, tail = 0x2b8949e724c0}, cop_list = {head = 0x2b891a03b070}, read_enable_list = {al = {head = {s = {pointer = 0x0, version = 0}, 
        data = 0x00000000000000000000000000000000}, name = 0x7fc219 "AtomicSLL", offset = 136}}, write_enable_list = {al = {head = {s = {pointer = 0x0, version = 0}, data = 0x00000000000000000000000000000000}, name = 0x7fc219 "AtomicSLL", offset = 248}}, 
  keep_alive_queue = {<DLL<NetEvent, NetEvent::Link_keep_alive_queue_link>> = {head = 0x2b899dee1e20}, tail = 0x2b89451e70a0}, keep_alive_queue_size = 4, active_queue = {<DLL<NetEvent, NetEvent::Link_active_queue_link>> = {head = 0x2b8945333cb0}, 
    tail = 0x2b89451cb780}, active_queue_size = 51, static global_config = {max_connections_in = 100000, max_connections_active_in = 10000, inactive_threshold_in = 0, transaction_no_activity_timeout_in = 0, keep_alive_no_activity_timeout_in = 0, 
    default_inactivity_timeout = 300}, config = {max_connections_in = 100000, max_connections_active_in = 10000, inactive_threshold_in = 0, transaction_no_activity_timeout_in = 0, keep_alive_no_activity_timeout_in = 0, default_inactivity_timeout = 300}, 
  max_connections_per_thread_in = 2083, max_connections_active_per_thread_in = 208, static CONFIG_ITEM_COUNT = 6, static config_value_affects_per_thread_value = {<std::_Base_bitset<1>> = {_M_w = 3}, <No data fields>}, 
  static active_thread_types = {<std::_Base_bitset<1>> = {_M_w = 1}, <No data fields>}}
(gdb) p ne->read
$65 = {enabled = 1, vio = {cont = 0x2b894a65ded0, nbytes = 9223372036854775807, ndone = 845, op = 1, buffer = {mbuf = 0x2b89a3328460, entry = 0x0}, vc_server = 0x2b89451cb5d0, mutex = {m_ptr = 0x2b8955727080}, _disabled = false}, 
  ready_link = {<SLink<NetEvent>> = {next = 0x0}, prev = 0x0}, enable_link = {next = 0x0}, in_enabled_list = 0, triggered = 1}
(gdb) p ((UnixNetVConnection*)client_vc)->con.fd
$33 = 1522
(gdb) p ((UnixNetVConnection*)client_vc)->read  
$34 = {enabled = 1, vio = {cont = 0x2b894a65ded0, nbytes = 9223372036854775807, ndone = 845, op = 1, buffer = {mbuf = 0x2b89a3328460, entry = 0x0}, vc_server = 0x2b89451cb5d0, mutex = {m_ptr = 0x2b8955727080}, _disabled = false}, 
  ready_link = {<SLink<NetEvent>> = {next = 0x0}, prev = 0x0}, enable_link = {next = 0x0}, in_enabled_list = 0, triggered = 1}
(gdb) p ((UnixNetVConnection*)client_vc)->write
$35 = {enabled = 0, vio = {cont = 0x2b894a65ded0, nbytes = 0, ndone = 0, op = 2, buffer = {mbuf = 0x2b89b929eb40, entry = 0x2b89b929eb80}, vc_server = 0x2b89451cb5d0, mutex = {m_ptr = 0x2b8955727080}, _disabled = false}, ready_link = {<SLink<NetEvent>> = {
      next = 0x0}, prev = 0x0}, enable_link = {next = 0x0}, in_enabled_list = 0, triggered = 1}
(gdb) p client_vc
$36 = (NetVConnection *) 0x2b89451cb5d0
(gdb) p client_vc->sslHandshakeStatus
There is no member or method named sslHandshakeStatus.
(gdb) p ((SSLNetVConnection*)client_vc)->sslHandshakeStatus
$37 = SSL_HANDSHAKE_DONE
(gdb) p ((SSLNetVConnection*)client_vc)->sslSessionCacheHit
$38 = false
(gdb) p ((SSLNetVConnection*)client_vc)->sslHandshakeBeginTime
$39 = 1591308764913487983
(gdb) p ((SSLNetVConnection*)client_vc)->handShakeBuffer      
$40 = (MIOBuffer *) 0x0
(gdb) p ((SSLNetVConnection*)client_vc)->sslVerifyCallback
$41 = (void *) 0x0
(gdb) p ((SSLNetVConnection*)client_vc)->sslVerifyCallbackArgs
$42 = (void *) 0x0
(gdb) p ((SSLNetVConnection*)client_vc)->sslTotalBytesSent    
$43 = 2847060
(gdb) p ((SSLNetVConnection*)client_vc)->sslHandshakeEndTime
$44 = 1591308765090272100
(gdb) p ((SSLNetVConnection*)client_vc)->sslLastWriteTime   
$45 = 0
(gdb) p ((SSLNetVConnection*)client_vc)->_serverName     
$46 = {_M_t = {
    _M_t = {<std::_Tuple_impl<0, char*, std::default_delete<char []> >> = {<std::_Tuple_impl<1, std::default_delete<char []> >> = {<std::_Head_base<1, std::default_delete<char []>, true>> = {<std::default_delete<char []>> = {<No data fields>}, <No data fields>}, <No data fields>}, <std::_Head_base<0, char*, false>> = {_M_head_impl = 0x2b8949e7d340 "dms-src.linkedin.com"}, <No data fields>}, <No data fields>}}}
(gdb) p ((SSLNetVConnection*)client_vc)->protocol_mask
$47 = 0
(gdb) p ((SSLNetVConnection*)client_vc)->protocol_mask_set
$48 = false
(gdb) p ((SSLNetVConnection*)client_vc)->early_data_buf   
$49 = (MIOBuffer *) 0x0
(gdb) p ((SSLNetVConnection*)client_vc)->read_from_early_data
$50 = 0
(gdb) p ((SSLNetVConnection*)client_vc)->verify_cert         
$51 = (X509_STORE_CTX *) 0x0
(gdb) p ((SSLNetVConnection*)client_vc)->ssl        
$52 = (SSL *) 0x2b898d47b000
(gdb) p *((SSLNetVConnection*)client_vc)->ssl
$53 = {version = 771, type = 0, method = 0x2b88e949d940 <tlsv1_2_server_method_data.22516>, rbio = 0x2b8949e82380, wbio = 0x2b88fc249900, bbio = 0x0, rwstate = 1, in_handshake = 0, handshake_func = 0x2b88e9261c80 <ossl_statem_accept>, server = 1, 
  new_session = 0, quiet_shutdown = 0, shutdown = 0, state = 4, rstate = 1, init_buf = 0x100000001, init_msg = 0x100000002, init_num = 0, init_off = 0, packet = 0x0, packet_length = 0, s2 = 0x0, s3 = 0x0, d1 = 0x0, read_ahead = 1572261892, msg_callback = 0x0, 
  msg_callback_arg = 0x0, hit = 2137786880, param = 0x0, cipher_list = 0x0, cipher_list_by_id = 0x0, mac_flags = 0, enc_read_ctx = 0x2b893036f740, read_hash = 0x0, expand = 0x0, enc_write_ctx = 0x0, write_hash = 0x0, compress = 0x0, cert = 0xffffffff00000000, 
  sid_ctx_length = 4294967295, sid_ctx = '\000' <repeats 28 times>, "\200|\360I", session = 0x0, generate_session_id = 0x0, verify_mode = 0, verify_callback = 0x0, info_callback = 0x0, error = 0, error_code = 0, kssl_ctx = 0x0, psk_client_callback = 0x0, 
  psk_server_callback = 0x0, ctx = 0x0, debug = 0, verify_result = 0, ex_data = {sk = 0x0, dummy = 0}, client_CA = 0x0, references = 0, options = 0, mode = 0, max_cert_list = 0, first_packet = 0, client_version = 0, max_send_fragment = 0, 
  tlsext_debug_cb = 0x0, tlsext_debug_arg = 0x0, tlsext_hostname = 0x0, servername_done = 0, tlsext_status_type = 0, tlsext_status_expected = 0, tlsext_ocsp_ids = 0x0, tlsext_ocsp_exts = 0x0, tlsext_ocsp_resp = 0x0, tlsext_ocsp_resplen = 0, 
  tlsext_ticket_expected = 0, tlsext_ecpointformatlist_length = 0, tlsext_ecpointformatlist = 0x0, tlsext_ellipticcurvelist_length = 0, tlsext_ellipticcurvelist = 0x0, tlsext_opaque_prf_input = 0x0, tlsext_opaque_prf_input_len = 0, tlsext_session_ticket = 0x0, 
  tls_session_ticket_ext_cb = 0x0, tls_session_ticket_ext_cb_arg = 0x0, tls_session_secret_cb = 0x0, tls_session_secret_cb_arg = 0x0, initial_ctx = 0x0, next_proto_negotiated = 0x0, next_proto_negotiated_len = 0 '\000', srtp_profiles = 0x0, srtp_profile = 0x0, 
  tlsext_heartbeat = 0, tlsext_hb_pending = 0, tlsext_hb_seq = 0, renegotiate = 0, alpn_client_proto_list = 0x0, alpn_client_proto_list_len = 0}
(gdb) p *((SSLNetVConnection*)client_vc)->curHook
Cannot access memory at address 0x0
(gdb) p ((SSLNetVConnection*)client_vc)->curHook
$54 = (APIHook *) 0x0
(gdb) p ((SSLNetVConnection*)client_vc)->sslVerifyCallback
$55 = (void *) 0x0
(gdb) p ((SSLNetVConnection*)client_vc)->sslVerifyCallbackOptions
There is no member or method named sslVerifyCallbackOptions.
(gdb) p ((SSLNetVConnection*)client_vc)->sslVerifyCallbackArgs   
$56 = (void *) 0x0

[sudheerv]

Dug into this some more and it turns out this is likely related to the issue #6849 and #6850.

The root cause seems to be that the default max_iobuffer_size which is supposed to be an iobuffer size index (and not the raw size) and is used in figuring out the iobuffer index for a caller that asks for a IOBuffer (without explicitly passing in a max), is sometimes garbage. This results in corrupting IOBuffers and ends in weird crashes like a few of these.

(gdb) p max_iobuffer_size
$1 = 8245894515088831029

(gdb) bt
#0  0x00002b1926ed987e in __cxxabiv1::__dynamic_cast (src_ptr=0x2b19e1b0baf0, src_type=src_type@entry=0x7c1498 <typeinfo for Continuation>, dst_type=dst_type@entry=0x7c5188 <typeinfo for PluginUserArgsMixin>, src2dst=src2dst@entry=-2) at ../../.././libstdc++-v3/libsupc++/dyncast.cc:71
#1  0x00000000004e17ce in TSUserArgGet (data=<optimized out>, arg_idx=0) at traffic_server/InkAPI.cc:6200
#2  0x00002b193e022144 in atscppapi::utils::internal::getTransaction (ats_txn_handle=ats_txn_handle@entry=0x2b19e1b0baf0) at utils_internal.cc:178
#3  0x00002b193e0230ce in (anonymous namespace)::handleTransactionEvents (cont=0x2b192abf4ec0, event=TS_EVENT_HTTP_READ_RESPONSE_HDR, edata=0x2b19e1b0baf0) at utils_internal.cc:76
#4  0x00000000004d7231 in INKContInternal::handle_event (this=0x2b192abf4ec0, event=60006, edata=0x2b19e1b0baf0) at traffic_server/InkAPI.cc:1096
#5  0x00000000004ef7e6 in Continuation::handleEvent (this=0x2b192abf4ec0, event=event@entry=60006, data=data@entry=0x2b19e1b0baf0) at /home/svinukon/Traffic/ATS/ats9/ats-core_trunk/ats9/src/iocore/eventsystem/I_Continuation.h:193
#6  0x00000000004e9517 in APIHook::invoke (this=this@entry=0x2b1928d6df80, event=60006, edata=edata@entry=0x2b19e1b0baf0) at traffic_server/InkAPI.cc:1333
#7  0x000000000054c987 in HttpSM::state_api_callout (this=0x2b19e1b0baf0, event=<optimized out>, data=<optimized out>) at HttpSM.cc:1499
#8  0x000000000054db4b in HttpSM::state_read_server_response_header (this=0x2b19e1b0baf0, event=100, data=0x2b19f25c9130) at HttpSM.cc:2026
#9  0x000000000054fa58 in HttpSM::main_handler (this=0x2b19e1b0baf0, event=100, data=0x2b19f25c9130) at HttpSM.cc:2729
#10 0x000000000076fbbe in handleEvent (data=0x2b19f25c9130, event=100, this=0x2b19e1b0baf0) at /home/svinukon/Traffic/ATS/ats9/ats-core_trunk/ats9/src/iocore/eventsystem/I_Continuation.h:193
#11 read_signal_and_update (vc=0x2b19f25c8f50, event=100) at UnixNetVConnection.cc:83
#12 UnixNetVConnection::readSignalAndUpdate (this=this@entry=0x2b19f25c8f50, event=event@entry=100) at UnixNetVConnection.cc:1016
#13 0x000000000073f64d in SSLNetVConnection::net_read_io (this=0x2b19f25c8f50, nh=0x2b192aa23d80, lthread=<optimized out>) at SSLNetVConnection.cc:674
#14 0x000000000075de68 in NetHandler::process_ready_list (this=this@entry=0x2b192aa23d80) at UnixNet.cc:412
#15 0x000000000075e15d in NetHandler::waitForActivity (this=0x2b192aa23d80, timeout=<optimized out>) at UnixNet.cc:547
#16 0x00000000007bbc0a in EThread::execute_regular (this=this@entry=0x2b192aa20000) at UnixEThread.cc:266
#17 0x00000000007bbe92 in EThread::execute (this=0x2b192aa20000) at UnixEThread.cc:327
#18 0x00000000007ba1e9 in spawn_thread_internal (a=0x2b1928d63a40) at Thread.cc:92
#19 0x00002b1926a33dd5 in start_thread () from /lib64/libpthread.so.0
#20 0x00002b19277e4ead in clone () from /lib64/libc.so.6
(gdb) p max_iobuffer_size
$1 = 8245894515088831029
(gdb) 

[sudheerv]

Ran ASAN in prod (couldn't run it for longer than an hour before maxing out CPU) and our staging/integration environment (over a day, slow burn as the qps is lower) and found a few heap corruption (in our internal plugins and libraries) and heap overflow issues (#6916 ). After fixing those, the occurrence of this crash dropped significantly (from once every 3-4 hours to 1-2/day).