H2 BAD_ACCESS at Mutex_lock under load

[maskit]

I saw this crash twice. I was running five h2load processes with 100 streams per each.

* thread #6, name = '[ET_NET 11]', stop reason = EXC_BAD_ACCESS (code=1, address=0x50)
    frame #0: 0x0000000100021162 traffic_server`Mutex_lock(location=0x0000000003a05928, ahandler=0x0000000000000000, m=0x0000000000000000, t=0x0000000002404000) at I_Lock.h:409
   406 	  ProxyMutex *m, EThread *t)
   407 	{
   408 	  ink_assert(t != 0);
-> 409 	  if (m->thread_holding != t) {
   410 	    ink_mutex_acquire(&m->the_mutex);
   411 	    m->thread_holding = t;
   412 	    ink_assert(m->thread_holding);
(lldb) bt
* thread #6, name = '[ET_NET 11]', stop reason = EXC_BAD_ACCESS (code=1, address=0x50)
  * frame #0: 0x0000000100021162 traffic_server`Mutex_lock(location=0x0000000003a05928, ahandler=0x0000000000000000, m=0x0000000000000000, t=0x0000000002404000) at I_Lock.h:409
    frame #1: 0x00000001000512ee traffic_server`MutexLock::MutexLock(this=0x0000000003a05940, location=0x0000000003a05928, ahandler=0x0000000000000000, am=0x000000000279f120, t=0x0000000002404000) at I_Lock.h:507
    frame #2: 0x000000010003f1e5 traffic_server`MutexLock::MutexLock(this=0x0000000003a05940, location=0x0000000003a05928, ahandler=0x0000000000000000, am=0x000000000279f120, t=0x0000000002404000) at I_Lock.h:506
    frame #3: 0x00000001001a502f traffic_server`Http2ConnectionState::send_a_data_frame(this=0x0000000000cf9e58, stream=0x000000000279f100, payload_length=0x0000000003a05a28) at Http2ConnectionState.cc:1258
    frame #4: 0x00000001001a326a traffic_server`Http2ConnectionState::send_data_frames_depends_on_priority(this=0x0000000000cf9e58) at Http2ConnectionState.cc:1219
    frame #5: 0x00000001001a1401 traffic_server`Http2ConnectionState::main_event_handler(this=0x0000000000cf9e58, event=2254, edata=0x0000000002828380) at Http2ConnectionState.cc:880
    frame #6: 0x000000010001e0f0 traffic_server`Continuation::handleEvent(this=0x0000000000cf9e58, event=2254, data=0x0000000002828380) at I_Continuation.h:153
    frame #7: 0x000000010033da95 traffic_server`EThread::process_event(this=0x0000000002404000, e=0x0000000002828380, calling_code=2254) at UnixEThread.cc:122
    frame #8: 0x000000010033e1c9 traffic_server`EThread::execute(this=0x0000000002404000) at UnixEThread.cc:234
    frame #9: 0x000000010033ce2c traffic_server`spawn_thread_internal(a=0x00000000009070f0) at Thread.cc:91
    frame #10: 0x000000000075093b libsystem_pthread.dylib`_pthread_body + 180
    frame #11: 0x0000000000750887 libsystem_pthread.dylib`_pthread_start + 286
    frame #12: 0x000000000075008d libsystem_pthread.dylib`thread_start + 13

(lldb) p *stream
(Http2Stream) $8 = {
(snip)
  header_blocks_length = 12
  request_header_length = 12
  recv_end_stream = true
  send_end_stream = false
  sent_request_header = false
  response_header_done = true
  request_sent = false
  is_first_transaction_flag = false
(snip)
  trailing_header = false
  body_done = false
  chunked = false
  closed = true
  reentrancy_count = 0
  terminate_stream = true
  data_length = 0
  bytes_sent = 41940160
(snip)
  cross_thread_event = 0x0000000000000000
  active_timeout = 300000000000
  active_event = 0x0000000000000000
  inactive_timeout = 30000000000
  inactive_timeout_at = 0
  inactive_event = 0x0000000000000000
  read_event = 0x0000000000000000
  write_event = 0x0000000000000000
}

[maskit]

It seems to happen after active timeout. I can reproduce with the command below:
h2load -c 5 -n 1000 -m 1000 https://localhost:8443/bigfile

[maskit]

It happens if h2 stream priority is enabled.
CONFIG proxy.config.http2.stream_priority_enabled INT 1

[scw00]

Hi @maskit , How to re-produce this case ? Do I need to terminate the client immediately ? I Can't re-produce it on my local machine.

[maskit]

I just ran h2load with the options above, and it happened sometimes. I'll update if I could reproduce the crash again on master.

[maskit]

I didn't see this crash during tests for #2738. Maybe fixed with other issues.

[maskit]

Process 36881 stopped
* thread #2, name = '[ET_NET 18]', stop reason = EXC_BAD_ACCESS (code=1, address=0x50)
    frame #0: 0x0000000100021d22 traffic_server`Mutex_lock(location=0x000000000633f770, ahandler=0x0000000000000000, m=0x0000000000000000, t=0x00000000042ea000) at I_Lock.h:408
   405    ProxyMutex *m, EThread *t)
   406  {
   407    ink_assert(t != 0);
-> 408    if (m->thread_holding != t) {
   409      ink_mutex_acquire(&m->the_mutex);
   410      m->thread_holding = t;
   411      ink_assert(m->thread_holding);
Target 0: (traffic_server) stopped.
(lldb) bt
* thread #2, name = '[ET_NET 18]', stop reason = EXC_BAD_ACCESS (code=1, address=0x50)
  * frame #0: 0x0000000100021d22 traffic_server`Mutex_lock(location=0x000000000633f770, ahandler=0x0000000000000000, m=0x0000000000000000, t=0x00000000042ea000) at I_Lock.h:408
    frame #1: 0x00000001000533ae traffic_server`MutexLock::MutexLock(this=0x000000000633f788, location=0x000000000633f770, ahandler=0x0000000000000000, am=0x00000000069c6f20, t=0x00000000042ea000) at I_Lock.h:506
    frame #2: 0x0000000100040ba5 traffic_server`MutexLock::MutexLock(this=0x000000000633f788, location=0x000000000633f770, ahandler=0x0000000000000000, am=0x00000000069c6f20, t=0x00000000042ea000) at I_Lock.h:505
    frame #3: 0x00000001001b13ae traffic_server`Http2ConnectionState::send_a_data_frame(this=0x00000000007fd638, stream=0x00000000069c6f00, payload_length=0x000000000633f908) at Http2ConnectionState.cc:1278
    frame #4: 0x00000001001af2fa traffic_server`Http2ConnectionState::send_data_frames_depends_on_priority(this=0x00000000007fd638) at Http2ConnectionState.cc:1239
    frame #5: 0x00000001001ad491 traffic_server`Http2ConnectionState::main_event_handler(this=0x00000000007fd638, event=2254, edata=0x0000000000832180) at Http2ConnectionState.cc:880
    frame #6: 0x000000010001ecc0 traffic_server`Continuation::handleEvent(this=0x00000000007fd638, event=2254, data=0x0000000000832180) at I_Continuation.h:153
    frame #7: 0x0000000100354403 traffic_server`EThread::process_event(this=0x00000000042ea000, e=0x0000000000832180, calling_code=2254) at UnixEThread.cc:130

It happened right after I closed this issue...

[maskit]

It seems that the Http2Stream instance is already destroyed. ProxyClientTransaction::destroy() calls this->mutex.clear().

[shinrich]

Here is an ASAN I get with priority enabled in our 7.1.1 build + maskit's even stream fix and the stream cleanup race fix.

==43140==ERROR: AddressSanitizer: heap-use-after-free on address 0x602000609338 at pc 0x0000008796f7 bp 0x2aabd70488d0 sp 0x2aabd70488c8
READ of size 8 at 0x602000609338 thread T7 ([ET_NET 5])
    #0 0x8796f6 in Http2DependencyTree<Http2Stream*>::_top(Http2DependencyTree<Http2Stream*>::Node*) ../../../../trafficserver/proxy/http2/Http2DependencyTree.h:291
    #1 0x87829e in Http2DependencyTree<Http2Stream*>::top() ../../../../trafficserver/proxy/http2/Http2DependencyTree.h:304
    #2 0x8700c7 in Http2ConnectionState::send_data_frames_depends_on_priority() ../../../../trafficserver/proxy/http2/Http2ConnectionState.cc:1209
    #3 0x86d084 in Http2ConnectionState::main_event_handler(int, void*) ../../../../trafficserver/proxy/http2/Http2ConnectionState.cc:889
    #4 0x5f9dd6 in Continuation::handleEvent(int, void*) ../../../../trafficserver/iocore/eventsystem/I_Continuation.h:153
    #5 0xb58f18 in EThread::process_event(Event*, int) ../../../../trafficserver/iocore/eventsystem/UnixEThread.cc:122
    #6 0xb5960b in EThread::execute() ../../../../trafficserver/iocore/eventsystem/UnixEThread.cc:188
    #7 0xb57600 in spawn_thread_internal ../../../../trafficserver/iocore/eventsystem/Thread.cc:85
    #8 0x2aabd06d1aa0 in start_thread (/lib64/libpthread.so.0+0x7aa0)
    #9 0x2aabd0deabcc in __clone (/lib64/libc.so.6+0xe8bcc)

0x602000609338 is located 8 bytes inside of 16-byte region [0x602000609330,0x602000609340)
freed by thread T7 ([ET_NET 5]) here:
    #0 0x58f21a in operator delete(void*) (/home/y/bin64/traffic_server+0x58f21a)
    #1 0x865409 in Http2DependencyTree<Http2Stream*>::Node::~Node() ../../../../trafficserver/proxy/http2/Http2DependencyTree.h:67
    #2 0x877fea in Http2DependencyTree<Http2Stream*>::remove(Http2DependencyTree<Http2Stream*>::Node*) ../../../../trafficserver/proxy/http2/Http2DependencyTree.h:225
    #3 0x86f2ad in Http2ConnectionState::delete_stream(Http2Stream*) ../../../../trafficserver/proxy/http2/Http2ConnectionState.cc:1127
    #4 0x870594 in Http2ConnectionState::send_data_frames_depends_on_priority() ../../../../trafficserver/proxy/http2/Http2ConnectionState.cc:1235
    #5 0x86d084 in Http2ConnectionState::main_event_handler(int, void*) ../../../../trafficserver/proxy/http2/Http2ConnectionState.cc:889
    #6 0x5f9dd6 in Continuation::handleEvent(int, void*) ../../../../trafficserver/iocore/eventsystem/I_Continuation.h:153
    #7 0xb58f18 in EThread::process_event(Event*, int) ../../../../trafficserver/iocore/eventsystem/UnixEThread.cc:122
    #8 0xb5960b in EThread::execute() ../../../../trafficserver/iocore/eventsystem/UnixEThread.cc:188
    #9 0xb57600 in spawn_thread_internal ../../../../trafficserver/iocore/eventsystem/Thread.cc:85
    #10 0x2aabd06d1aa0 in start_thread (/lib64/libpthread.so.0+0x7aa0)

previously allocated by thread T7 ([ET_NET 5]) here:
    #0 0x58ecda in operator new(unsigned long) (/home/y/bin64/traffic_server+0x58ecda)
    #1 0x8788b7 in Http2DependencyTree<Http2Stream*>::Node::Node(unsigned int, unsigned int, unsigned int, Http2DependencyTree<Http2Stream*>::Node*, Http2Stream*) ../../../../trafficserver/proxy/http2/Http2DependencyTree.h:61
    #2 0x877419 in Http2DependencyTree<Http2Stream*>::add(unsigned int, unsigned int, unsigned int, bool, Http2Stream*) ../../../../trafficserver/proxy/http2/Http2DependencyTree.h:174
    #3 0x867d5e in rcv_headers_frame ../../../../trafficserver/proxy/http2/Http2ConnectionState.cc:300
    #4 0x86d565 in Http2ConnectionState::main_event_handler(int, void*) ../../../../trafficserver/proxy/http2/Http2ConnectionState.cc:907
    #5 0x5f9dd6 in Continuation::handleEvent(int, void*) ../../../../trafficserver/iocore/eventsystem/I_Continuation.h:153
    #6 0x85da4a in send_connection_event ../../../../trafficserver/proxy/http2/Http2ClientSession.cc:58
    #7 0x862f1f in Http2ClientSession::do_complete_frame_read() ../../../../trafficserver/proxy/http2/Http2ClientSession.cc:478
    #8 0x8633c1 in Http2ClientSession::state_process_frame_read(int, VIO*, bool) ../../../../trafficserver/proxy/http2/Http2ClientSession.cc:515
    #9 0x861c55 in Http2ClientSession::state_start_frame_read(int, void*) ../../../../trafficserver/proxy/http2/Http2ClientSession.cc:408
    #10 0x860b7d in Http2ClientSession::main_event_handler(int, void*) ../../../../trafficserver/proxy/http2/Http2ClientSession.cc:313
    #11 0x5f9dd6 in Continuation::handleEvent(int, void*) ../../../../trafficserver/iocore/eventsystem/I_Continuation.h:153
    #12 0xb0a631 in read_signal_and_update ../../../../trafficserver/iocore/net/UnixNetVConnection.cc:144
    #13 0xb1122b in UnixNetVConnection::readSignalAndUpdate(int) ../../../../trafficserver/iocore/net/UnixNetVConnection.cc:1092
    #14 0xad0240 in SSLNetVConnection::net_read_io(NetHandler*, EThread*) ../../../../trafficserver/iocore/net/SSLNetVConnection.cc:596
    #15 0xaf7891 in NetHandler::mainNetEvent(int, Event*) ../../../../trafficserver/iocore/net/UnixNet.cc:499
    #16 0x5f9dd6 in Continuation::handleEvent(int, void*) ../../../../trafficserver/iocore/eventsystem/I_Continuation.h:153
    #17 0xb58f18 in EThread::process_event(Event*, int) ../../../../trafficserver/iocore/eventsystem/UnixEThread.cc:122
    #18 0xb59d62 in EThread::execute() ../../../../trafficserver/iocore/eventsystem/UnixEThread.cc:266
    #19 0xb57600 in spawn_thread_internal ../../../../trafficserver/iocore/eventsystem/Thread.cc:85
    #20 0x2aabd06d1aa0 in start_thread (/lib64/libpthread.so.0+0x7aa0)

Thread T7 ([ET_NET 5]) created by T0 ([TS_MAIN]) here:
    #0 0x52fed4 in pthread_create (/home/y/bin64/traffic_server+0x52fed4)
    #1 0xb57093 in ink_thread_create /home/shinrich/new-build/_build/asan_build/../../trafficserver/lib/ts/ink_thread.h:152
    #2 0xb57721 in Thread::start(char const*, void*, unsigned long, std::function<void ()> const&) ../../../../trafficserver/iocore/eventsystem/Thread.cc:102

[maskit]

@shinrich Can you try this out on your box?

diff --git a/proxy/http2/Http2Stream.cc b/proxy/http2/Http2Stream.cc
index 23eff855b..751b15291 100644
--- a/proxy/http2/Http2Stream.cc
+++ b/proxy/http2/Http2Stream.cc
@@ -326,6 +326,8 @@ Http2Stream::do_io_close(int /* flags */)
     if (parent && this->is_client_state_writeable()) {
       // Make sure any trailing end of stream frames are sent
       // Wee will be removed at send_data_frames or closing connection phase
+      Http2ClientSession *h2_parent = static_cast<Http2ClientSession *>(parent);
+      SCOPED_MUTEX_LOCK(lock, h2_parent->connection_state.mutex, this_ethread());
       static_cast<Http2ClientSession *>(parent)->connection_state.send_data_frames(this);
     }

send_data_frames() calls delete_stream(), and delete_stream() calls dependency_tree.remove(node)). If we call this without the lock, it could break dependency_tree.

[shinrich]

Hmm. That is part of your stream release fix, right? Oh, I see this is an addition. Will set it up and give it a go.