TS Seg Fault on reschedule.

[xf6wang]

Seems to happen when there is lock contention and the event must be rescheduled. Blocks #3047

(gdb) bt
#0  0x00002b5a60938c4f in ink_atomiclist_push (l=0x100b10, item=0x1708280) at ink_queue.cc:525
#1  0x00000000007f7d62 in ProtectedQueue::enqueue (this=0x100b10, e=0x1708280, fast_signal=false) at ProtectedQueue.cc:52
#2  0x0000000000552445 in EThread::schedule (this=0x0, e=0x1708280, fast_signal=false) at /Users/alanwang/Desktop/trafficserver/iocore/eventsystem/P_UnixEThread.h:97
#3  0x0000000000552382 in EThread::schedule_in (this=0x0, cont=0x2b5aa1574ec0, t=10000000, callback_event=2, cookie=0x0)
    at /Users/alanwang/Desktop/trafficserver/iocore/eventsystem/P_UnixEThread.h:71
#4  0x00000000006484bf in HttpSM::state_api_callout (this=0x2b5aa1574ec0, event=0, data=0x0) at HttpSM.cc:1436
#5  0x00000000006566d6 in HttpSM::do_api_callout_internal (this=0x2b5aa1574ec0) at HttpSM.cc:5102
#6  0x00000000006658dd in HttpSM::do_api_callout (this=0x2b5aa1574ec0) at HttpSM.cc:350
#7  0x0000000000643fb6 in HttpSM::state_add_to_list (this=0x2b5aa1574ec0, event=0) at HttpSM.cc:378
#8  0x0000000000644937 in HttpSM::attach_client_session (this=0x2b5aa1574ec0, client_vc=0x2b5a7409d800, buffer_reader=0x2b5a7409d920) at HttpSM.cc:523
#9  0x0000000000576d5f in ProxyClientTransaction::new_transaction (this=0x2b5a7409d800) at ProxyClientTransaction.cc:60
#10 0x00000000006bbb2f in rcv_headers_frame (cstate=..., frame=...) at Http2ConnectionState.cc:339
#11 0x00000000006be5b4 in Http2ConnectionState::main_event_handler (this=0x2b5a7407b6b0, event=2253, edata=0x2b5a65b197a0) at Http2ConnectionState.cc:902
#12 0x0000000000534996 in Continuation::handleEvent (this=0x2b5a7407b6b0, event=2253, data=0x2b5a65b197a0)
    at /Users/alanwang/Desktop/trafficserver/iocore/eventsystem/I_Continuation.h:160
#13 0x00000000006b6aa7 in send_connection_event (cont=0x2b5a7407b6b0, event=2253, edata=0x2b5a65b197a0) at Http2ClientSession.cc:58
#14 0x00000000006b8f67 in Http2ClientSession::do_complete_frame_read (this=0x2b5a7407b3e0) at Http2ClientSession.cc:492
#15 0x00000000006b9157 in Http2ClientSession::state_process_frame_read (this=0x2b5a7407b3e0, event=100, vio=0x2b5ab001a3e0, inside_frame=false) at Http2ClientSession.cc:529
#16 0x00000000006b871c in Http2ClientSession::state_start_frame_read (this=0x2b5a7407b3e0, event=100, edata=0x2b5ab001a3e0) at Http2ClientSession.cc:422
#17 0x00000000006b7e5d in Http2ClientSession::main_event_handler (this=0x2b5a7407b3e0, event=100, edata=0x2b5ab001a3e0) at Http2ClientSession.cc:313
#18 0x0000000000534996 in Continuation::handleEvent (this=0x2b5a7407b3e0, event=100, data=0x2b5ab001a3e0)
    at /Users/alanwang/Desktop/trafficserver/iocore/eventsystem/I_Continuation.h:160
#19 0x00000000006b85d4 in Http2ClientSession::state_read_connection_preface (this=0x2b5a7407b3e0, event=100, edata=0x2b5ab001a3e0) at Http2ClientSession.cc:402
#20 0x00000000006b7e5d in Http2ClientSession::main_event_handler (this=0x2b5a7407b3e0, event=100, edata=0x2b5ab001a3e0) at Http2ClientSession.cc:313
#21 0x0000000000534996 in Continuation::handleEvent (this=0x2b5a7407b3e0, event=100, data=0x2b5ab001a3e0)
    at /Users/alanwang/Desktop/trafficserver/iocore/eventsystem/I_Continuation.h:160
#22 0x00000000007d1bed in read_signal_and_update (event=100, vc=0x2b5ab001a290) at UnixNetVConnection.cc:83
#23 0x00000000007d4c58 in UnixNetVConnection::readSignalAndUpdate (this=0x2b5ab001a290, event=100) at UnixNetVConnection.cc:1047
#24 0x00000000007ab888 in SSLNetVConnection::net_read_io (this=0x2b5ab001a290, nh=0x2b5a653dacd0, lthread=0x2b5a653d7010) at SSLNetVConnection.cc:609
#25 0x00000000007c8aca in NetHandler::process_ready_list (this=0x2b5a653dacd0) at UnixNet.cc:393
#26 0x00000000007c921e in NetHandler::waitForActivity (this=0x2b5a653dacd0, timeout=60000000) at UnixNet.cc:526
#27 0x00000000007fa0eb in EThread::execute_regular (this=0x2b5a653d7010) at UnixEThread.cc:271
#28 0x00000000007fa2b3 in EThread::execute (this=0x2b5a653d7010) at UnixEThread.cc:324
#29 0x00000000007f8ebf in spawn_thread_internal (a=0x16f0e20) at Thread.cc:85
#30 0x00002b5a622b1dc5 in start_thread () from /lib64/libpthread.so.0
#31 0x00002b5a62fe076d in clone () from /lib64/libc.so.6

[xf6wang]

openclose_h2.txt

[xf6wang]

^ change to openclose_h2.test.py to run autest

[masaori335]

I got similar crash while trying reproduce this crash.

(gdb) bt
#0  0x0000152fd44ee69b in raise () from /lib64/libc.so.6
#1  0x0000152fd44f04a0 in abort () from /lib64/libc.so.6
#2  0x0000152fd695bd22 in ink_abort (message_format=0x152fd697f14c "%s:%d: failed assertion `%s`") at ink_error.cc:99
#3  0x0000152fd6959423 in _ink_assert (expression=0x7de2a5 "t != nullptr", file=0x7de250 "/home/masaori/src/github.com/apache/trafficserver-master/iocore/eventsystem/I_Lock.h", line=285) at ink_assert.cc:37
#4  0x000000000053ab3c in Mutex_trylock (location=..., ahandler=0x0, m=0x152fd00022d0, t=0x0) at /home/masaori/src/github.com/apache/trafficserver-master/iocore/eventsystem/I_Lock.h:285
#5  0x000000000057e8e5 in Mutex_trylock (location=..., ahandler=0x0, m=..., t=0x0) at /home/masaori/src/github.com/apache/trafficserver-master/iocore/eventsystem/I_Lock.h:333
#6  0x000000000060cdb0 in HttpSM::state_api_callout (this=0x152faf94f590, event=0, data=0x0) at HttpSM.cc:1430
#7  0x000000000061c739 in HttpSM::do_api_callout_internal (this=0x152faf94f590) at HttpSM.cc:5102
#8  0x000000000062caa9 in HttpSM::do_api_callout (this=0x152faf94f590) at HttpSM.cc:350
#9  0x00000000006082ec in HttpSM::state_add_to_list (this=0x152faf94f590, event=0) at HttpSM.cc:378
#10 0x0000000000608d06 in HttpSM::attach_client_session (this=0x152faf94f590, client_vc=0x152fb0127800, buffer_reader=0x152fb0127928) at HttpSM.cc:523
#11 0x0000000000580e9d in ProxyClientTransaction::new_transaction (this=0x152fb0127800) at ProxyClientTransaction.cc:60
#12 0x0000000000685e53 in rcv_headers_frame (cstate=..., frame=...) at Http2ConnectionState.cc:339
#13 0x0000000000688a3a in Http2ConnectionState::main_event_handler (this=0x152fb0105ad8, event=2253, edata=0x152fceb5c720) at Http2ConnectionState.cc:902
#14 0x000000000053afde in Continuation::handleEvent (this=0x152fb0105ad8, event=2253, data=0x152fceb5c720) at /home/masaori/src/github.com/apache/trafficserver-master/iocore/eventsystem/I_Continuation.h:160
#15 0x0000000000680b32 in send_connection_event (cont=0x152fb0105ad8, event=2253, edata=0x152fceb5c720) at Http2ClientSession.cc:58
#16 0x00000000006831dd in Http2ClientSession::do_complete_frame_read (this=0x152fb0105800) at Http2ClientSession.cc:492
#17 0x00000000006833f5 in Http2ClientSession::state_process_frame_read (this=0x152fb0105800, event=100, vio=0x152fa401fd28, inside_frame=false) at Http2ClientSession.cc:529
#18 0x000000000068294a in Http2ClientSession::state_start_frame_read (this=0x152fb0105800, event=100, edata=0x152fa401fd28) at Http2ClientSession.cc:422
#19 0x0000000000682012 in Http2ClientSession::main_event_handler (this=0x152fb0105800, event=100, edata=0x152fa401fd28) at Http2ClientSession.cc:313
#20 0x000000000053afde in Continuation::handleEvent (this=0x152fb0105800, event=100, data=0x152fa401fd28) at /home/masaori/src/github.com/apache/trafficserver-master/iocore/eventsystem/I_Continuation.h:160
#21 0x00000000006827ca in Http2ClientSession::state_read_connection_preface (this=0x152fb0105800, event=100, edata=0x152fa401fd28) at Http2ClientSession.cc:402
#22 0x0000000000682012 in Http2ClientSession::main_event_handler (this=0x152fb0105800, event=100, edata=0x152fa401fd28) at Http2ClientSession.cc:313
#23 0x000000000053afde in Continuation::handleEvent (this=0x152fb0105800, event=100, data=0x152fa401fd28) at /home/masaori/src/github.com/apache/trafficserver-master/iocore/eventsystem/I_Continuation.h:160
#24 0x00000000007ac3e8 in read_signal_and_update (event=100, vc=0x152fa401fbd0) at UnixNetVConnection.cc:83
#25 0x00000000007af918 in UnixNetVConnection::readSignalAndUpdate (this=0x152fa401fbd0, event=100) at UnixNetVConnection.cc:1047
#26 0x00000000007852fc in SSLNetVConnection::net_read_io (this=0x152fa401fbd0, nh=0x152fcf082cd0, lthread=0x152fcf07f010) at SSLNetVConnection.cc:609
#27 0x00000000007a2d60 in NetHandler::process_ready_list (this=0x152fcf082cd0) at UnixNet.cc:393
#28 0x00000000007a352c in NetHandler::waitForActivity (this=0x152fcf082cd0, timeout=60000000) at UnixNet.cc:526
#29 0x00000000007d6487 in EThread::execute_regular (this=0x152fcf07f010) at UnixEThread.cc:271
#30 0x00000000007d6677 in EThread::execute (this=0x152fcf07f010) at UnixEThread.cc:324
#31 0x00000000007d5093 in spawn_thread_internal (a=0x1d8aba0) at Thread.cc:85
#32 0x0000152fd534a36d in start_thread () from /lib64/libpthread.so.0
#33 0x0000152fd45c8bbf in clone () from /lib64/libc.so.6

It looks like mutex->thread_holding is nullptr on frame 6.

trafficserver/proxy/http/HttpSM.cc

Line 1430 in e163947

plugin_lock = MUTEX_TAKE_TRY_LOCK(cur_hook->m_cont->mutex, mutex->thread_holding);

From @xf6wang 's back trace, mutex->thread_holding is nullptr on frame 4.

trafficserver/proxy/http/HttpSM.cc

Line 1436 in e163947

pending_action = mutex->thread_holding->schedule_in(this, HRTIME_MSECONDS(10));

Probably, this is side effect of #3141, because this mutex is Http2Stream's mutex.

[masaori335]

@xf6wang Nice catch!

[gksalil]

I am facing the same issue in my 6.2.2 server also. the stack trace is

#0 0x00007f0287feef67 in ink_atomiclist_push (l=0x100b10, item=0x55c7a3f56fa0) at ink_queue.cc:513
#1 0x000055c7a302a10f in ProtectedQueue::enqueue (this=0x100b10, e=0x55c7a3f56fa0, fast_signal=false) at ProtectedQueue.cc:52
#2 0x000055c7a2d95475 in EventProcessor::schedule (this=0x55c7a38c3840 , e=0x55c7a3f56fa0, etype=0, fast_signal=false) at ../iocore/eventsystem/P_UnixEventProcessor.h:80
#3 0x000055c7a2d95598 in EventProcessor::schedule_in (this=0x55c7a38c3840 , cont=0x55c7a3f4a4f0, t=0, et=0, callback_event=2, cookie=0x0) at ../iocore/eventsystem/P_UnixEventProcessor.h:132
#4 0x000055c7a2de610b in run_NormalStop () at Main.cc:1261
#5 0x000055c7a2de3ec8 in proxy_signal_handler (signo=15, info=0x7ffe72ea52b0) at Main.cc:407
#6
#7 0x00007f028622ed83 in __libc_read (fd=30, buf=0x7ffe72ea575f, nbytes=1) at ../sysdeps/unix/sysv/linux/read.c:27
#8 0x00007f0287fe8aee in ink_file_fd_readline (fd=30, bufsz=1024, buf=0x7ffe72ea5880 "") at ink_file.cc:106
#9 0x000055c7a2fd42bb in Store::read_config (this=0x55c7a38c14d0 ) at Store.cc:332
#10 0x000055c7a2fa2895 in ink_cache_init (v=(MODULE_VERSION_MAX)) at Cache.cc:3265
#11 0x000055c7a2de798a in main (argv=0x7ffe72ea5ec8) at Main.cc:1739
<<<<

Is there any fix which I can apply as patch in my server ?

Thanks
~S

[masaori335]

@gksalil First few stuck looks same, but I think these are not same issue. Because this is introduced by f35bc79 and it's not back-ported to 6.2.x branch.
Please file a new issue.

[gksalil]

@masaori335 thanks you so much for the reply
Yes I will file a new defect for this.