ATS 9 using a continuation which is deleted

[bryancall]

#0  0x00002b8df1c3e207 in raise () from /lib64/libc.so.6
#0  0x00002b8df1c3e207 in raise () from /lib64/libc.so.6
#1  0x00002b8df1c3f8f8 in abort () from /lib64/libc.so.6
#2  0x00002b8def1a862b in ink_abort (message_format=message_format@entry=0x2b8def211e47 "%s:%d: failed assertion `%s`") at ink_error.cc:99
#3  0x00002b8def1a5de5 in _ink_assert (expression=expression@entry=0x73d750 "!\"Plugin tries to use a continuation which is deleted\"", file=file@entry=0x7407c9 "traffic_server/InkAPI.cc", line=line@entry=1088) at ink_assert.cc:37
#4  0x00000000004d3c84 in INKContInternal::handle_event (this=<optimized out>, event=<optimized out>, edata=<optimized out>) at traffic_server/InkAPI.cc:1088
#5  0x00000000004e604e in handleEvent (data=0x2b8f7ee26000, event=60007, this=0x2b8f4e144bc0) at //build_release_posix-x86_64_gcc_8/trafficserver9/iocore/eventsystem/I_Continuation.h:190
#6  handleEvent (data=0x2b8f7ee26000, event=60007, this=0x2b8f4e144bc0) at //build_release_posix-x86_64_gcc_8/trafficserver9/iocore/eventsystem/I_Continuation.h:186
#7  APIHook::invoke(int, void*) const () at traffic_server/InkAPI.cc:1338
#8  0x000000000053ec9c in HttpSM::state_api_callout(int, void*) () at HttpSM.cc:1435
#9  0x0000000000541773 in main_handler (data=0x2b8fa839b900, event=2, this=0x2b8f7ee26000) at HttpSM.cc:2568
#10 HttpSM::main_handler (this=0x2b8f7ee26000, event=2, data=0x2b8fa839b900) at HttpSM.cc:2538
#11 0x0000000000736bfb in handleEvent (data=0x2b8fa839b900, event=2, this=0x2b8f7ee26000) at I_Continuation.h:190
#12 handleEvent (data=0x2b8fa839b900, event=2, this=0x2b8f7ee26000) at I_Continuation.h:186
#13 EThread::process_event(Event*, int) () at UnixEThread.cc:136
#14 0x0000000000737abc in EThread::execute_regular (this=this@entry=0x2b8df569c400) at UnixEThread.cc:249
#15 0x0000000000737eaa in execute (this=0x2b8df569c400) at UnixEThread.cc:338
#16 EThread::execute (this=0x2b8df569c400) at UnixEThread.cc:316
#17 0x0000000000736309 in spawn_thread_internal (a=0x2b8df3b93ec0) at Thread.cc:92
#18 0x00002b8df0fd0dd5 in start_thread () from /lib64/libpthread.so.0
#19 0x00002b8df1d05ead in clone () from /lib64/libc.so.6

[shinrich]

Updating with notes I've made internally on tracking this issue for the past month or so.

The immediate problem is that a handler is being called on a deleted continuation.

{location = {file = 0x7543bf "HttpSM.cc", func = 0x758050 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", 
        line = 1417}, event = 34463, reentrancy = 1}, {location = {file = 0x7543bf "HttpSM.cc", 
        func = 0x758050 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, reentrancy = 1}, {location = {
        file = 0x7543bf "HttpSM.cc", func = 0x758050 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x7543bf "HttpSM.cc", func = 0x758050 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", 
        line = 1349}, event = 2, reentrancy = 1}, {location = {file = 0x7543bf "HttpSM.cc", 
        func = 0x758050 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, reentrancy = 1}

So the hook invocation was unable to get the continuation lock, so it rescheduled for 10ms into the future. Eventually something deleted the continuation, making the mutex null, so we got the weak lock, but then the deleted continuation was invoked the dead magic number assertion twigged.

This is a hook on the SEND_RESPONSE_HDR hook. Unfortunately, there is not enough state left in the core to figure out what plugin was causing the lock contention. And I have no idea who would have deleted the continuation in the middle of the hook invocations

After a few more cores, the history looks like we have a deadlock on the continuation lock

(gdb) print history
$11 = {history = {{location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
---Type <return> to continue, or q <return> to quit---
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1349}, event = 2, 
      reentrancy = 1}, {location = {file = 0x758d4a "HttpSM.cc", func = 0x75c990 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1417}, event = 34463, 
      reentrancy = 1}}, history_pos = 1268}

Locally I added an assert to trigger after the continuation has spun for 10 times trying to get the cur_hook->m_cont->mutex. After another week, got the assert to trigger.

(gdb) bt
#0  0x00002b004dfe2207 in raise () from /lib64/libc.so.6
#1  0x00002b004dfe38f8 in abort () from /lib64/libc.so.6
#2  0x00002b004b54c61b in ink_abort (message_format=message_format@entry=0x2b004b5b5e27 "%s:%d: failed assertion `%s`") at ink_error.cc:99
#3  0x00002b004b549dd5 in _ink_assert (expression=expression@entry=0x754851 "_cont_lock_miss_count < 10", file=file@entry=0x7543bf "HttpSM.cc", 
    line=line@entry=1402) at ink_assert.cc:37
#4  0x000000000053f92c in HttpSM::state_api_callout(int, void*) () at HttpSM.cc:1402
#5  0x0000000000541cd3 in main_handler (data=0x2b00838031c0, event=2, this=0x2b01f3e63000) at HttpSM.cc:2557
#6  HttpSM::main_handler (this=0x2b01f3e63000, event=2, data=0x2b00838031c0) at HttpSM.cc:2527
#7  0x0000000000736d1f in handleEvent (data=0x2b00838031c0, event=2, this=0x2b01f3e63000) at I_Continuation.h:167
#8  handleEvent (data=0x2b00838031c0, event=2, this=0x2b01f3e63000) at I_Continuation.h:163
#9  EThread::process_event(Event*, int) () at UnixEThread.cc:136
#10 0x0000000000737bac in EThread::execute_regular (this=this@entry=0x2b00521dd6c0) at UnixEThread.cc:249
#11 0x0000000000737fe6 in execute (this=0x2b00521dd6c0) at UnixEThread.cc:338
#12 EThread::execute (this=0x2b00521dd6c0) at UnixEThread.cc:316
#13 0x0000000000736289 in spawn_thread_internal (a=0x2b004ecdf540) at Thread.cc:92
#14 0x00002b004d374dd5 in start_thread () from /lib64/libpthread.so.0
#15 0x00002b004e0a9ead in clone () from /lib64/libc.so.6

Thread 37 is the holder of the mutex. Unfortunately it's stack is kind of blown up. I don't think it is corrupted, but I think that is somewhat normal once the code is in lua land for our builds.

(gdb) bt
#0  0x00002b0089b9ddc7 in gc_sweep () from /lib64/libluajit-5.1.so.2
#1  0x00002b0089bc321c in gc_onestep () from /lib64/libluajit-5.1.so.2
#2  0x00002b0089bdf608 in lua_gc () from /lib64/libluajit-5.1.so.2
#3  0x00002b008997edaa in ?? ()
#4  0x00002b004ec4aa00 in ?? ()
#5  0x0000000000000000 in ?? ()

Looking at the history field of the HttpSM, it appears that this was a POST operation. The hook is happening after reading the server response header.

One interesting thing about the cur_hook->m_cont->mutex. The nthread_holding was 0xfff00001. I think that this means the mutex was taken from a EThread object. When the thread object is created, the corresponding mutex has its nthread_holding decremented by 1024*1024. I assume that the mutex corresponds to the EThread on thread 37, but I cannot easily pull that value from the stack.

@SolidWallOfCode reminded me that schedule() will assign the thread mutex to a continuation if the continuation does not already have a mutex assigned. I verified in the code that this logic is indeed still there. I added another assert to catch that case, but that may not have been in an official build and has probably been replaced.

So this leaves some questions

Why do we have a ET_NET thread running a lua jit tying up things for at least 100ms in garbage collection?
What plugin does this continuation correspond to?

It seems like automatically putting a mutex on a condition seems like a really bad idea. Particularly if it is the thread mutex. For global continuation, this guarantees cross thread contention. I think we would be better off with an assert or creating a unique mutex for the continuation on the fly. @duke8253 do you have thoughts on this?

This crash hasn't triggered on our test builds for the past couple weeks. Perhaps it has been fixed? Or perhaps I haven't been as diligent in keeping our canary going.

We have in our older production builds been seeing some crash/corruptions in lua land.

[calavera]

This crash hasn't triggered on our test builds for the past couple weeks. Perhaps it has been fixed? Or perhaps I haven't been as diligent in keeping our canary going.

Has anyone seen this error lately? @shinrich, @bryancall ?

[shinrich]

Yes, just pushed up a PR which addressed it for us.

[zwoop]

Remember to remove Project and Milestone!