Crash on Http2ConnectionState::release_stream()

[masaori335]

We got this crash on 8.0.x. This looks pretty similar to #4158. So #4158 (adding null check) could be workaround fix. But it looks like there is a race on shutdown which we should fix.

[ 0  ] libc-2.12.so       __libc_waitpid                                               ( :undefined                   ) 
[ 1  ] traffic_server     crash_logger_invoke                                          ( Crash.cc:165                 ) 
[ 2  ] libc-2.12.so       0x2b0b38dfd570                                               ( :undefined                   ) 
[ 3  ] traffic_server     Http2ConnectionState::release_stream(Http2Stream*)           ( Http2ConnectionState.cc:1261 ) 
[ 4  ] traffic_server     Http2Stream::destroy()                                       ( Http2Stream.cc:730           ) 
[ 5  ] traffic_server     Http2Stream::terminate_if_possible()                         ( Http2Stream.cc:380           ) 
[ 6  ] traffic_server     Http2Stream::main_event_handler(int, void*)                  ( Http2Stream.cc:131           ) 
[ 7  ] traffic_server     handleEvent                                                  ( I_Continuation.h:160         ) 
[ 8  ] traffic_server     EThread::process_event(Event*, int)                          ( UnixEThread.cc:131           ) 
[ 9  ] traffic_server     EThread::process_queue(Queue<Event, Event::Link_link>*, i... ( UnixEThread.cc:170           ) 
[ 10 ] traffic_server     EThread::execute_regular()                                   ( UnixEThread.cc:230           ) 
[ 11 ] traffic_server     spawn_thread_internal                                        ( Thread.cc:85                 ) 
[ 12 ] libpthread-2.12.so start_thread                                                 ( :undefined                   )

trafficserver/proxy/http2/Http2ConnectionState.cc

Lines 1257 to 1265 in 8c50c75

	if (fini_received) {
	// We were shutting down, go ahead and terminate the session
	// this is a member of Http2ConnectionState and will be freed
	// when ua_session is destroyed
	ua_session->destroy();
	// Can't do this because we just destroyed right here ^,
	// or we can use a local variable to do it.
	// ua_session = nullptr;

[zwoop]

Here's a more detailed stack trace:

(gdb) bt full
#0  0x00002b0b38e778dd in waitpid () from /lib64/libc.so.6
No symbol table info available.
#1  0x0000559a4e823a94 in crash_logger_invoke (signo=11, info=0x2b0b4130b730, ctx=0x2b0b4130b600) at traffic_server/Crash.cc:165
        status = 0
#2  <signal handler called>
No symbol table info available.
#3  0x0000559a4e8eebbd in Http2ConnectionState::release_stream (this=0x2b462a029cb0, stream=<optimized out>) at Http2ConnectionState.cc:1261
        lock = {m = {m_ptr = 0x2b3dd1f97950}, locked_p = true}
#4  0x0000559a4e8e2975 in Http2Stream::destroy (this=0x2b4a06bee400) at Http2Stream.cc:730
        h2_parent = <optimized out>
        lock = <optimized out>
        end_time = <optimized out>
        lock = <optimized out>
#5  0x0000559a4e8e06d6 in Http2Stream::terminate_if_possible (this=0x2b4a06bee400) at Http2Stream.cc:380
        h2_parent = <optimized out>
        lock = <optimized out>
#6  0x0000559a4e8df306 in Http2Stream::main_event_handler (this=0x2b4a06bee400, event=103, edata=<optimized out>) at Http2Stream.cc:131
        e = <optimized out>
        this_thread = <optimized out>
        lock = <optimized out>
#7  0x0000559a4ea3ad80 in Continuation::handleEvent (this=<optimized out>, event=<optimized out>, data=<optimized out>) at ./I_Continuation.h:160
No locals.
#8  EThread::process_event (this=0x2b0b3cc0d1c0, e=0x2b47449e6480, calling_code=103) at UnixEThread.cc:131
        c_temp = <optimized out>
        lock = <optimized out>
#9  0x0000559a4ea3b01b in EThread::process_queue (this=0x2b0b3cc0d1c0, NegativeQueue=0x2b0b4130bdc0, ev_count=0x2b0b4130bde4, nq_count=0x2b0b4130bde0) at UnixEThread.cc:170
No locals.
#10 0x0000559a4ea3b4cb in EThread::execute_regular (this=0x2b0b3cc0d1c0) at UnixEThread.cc:230
        sleep_time = <optimized out>
        done_one = <optimized out>
        METRIC_INIT = {_loop_time = {_start = 0, _min = 9223372036854775807, _max = 0}, _events = {_min = 2147483647, _max = 0, _total = 0}, _count = 0, _wait = 0}
        delta = 0
        next_time = 0
        nq_count = 5399
        prev_metric = 0x2b0b3cd115c0
        ev_count = 5400
        loop_start_time = <optimized out>
        loop_finish_time = <optimized out>
#11 0x0000559a4ea3a3ec in spawn_thread_internal (a=0x2b0b3a154d80) at Thread.cc:85
        p = 0x2b0b3a154d80
#12 0x00002b0b39166aa1 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#13 0x00002b0b38eb3c4d in clone () from /lib64/libc.so.6
No symbol table info available.

[zwoop]

I think this was fixed in a639581. I'm going to close this.

[masaori335]

Unfortunately, we and @zizhong still see this crash with a639581.

[zwoop]

Yeh, the crasher is less frequent, but still happens. Seems we just reduce the window of the race condition?

[zwoop]

Masaori added a "history" feature, which I'm including here:

From frame #3 (Http2ConnectionState::release_stream):

$2 = {history = {{location = {file = 0x556774d56dd8 "Http2ConnectionState.cc", func = 0x556774d56ff0 "delete_stream", line = 1241}, event = 34463, reentrancy = 1}, {location = {
        file = 0x556774d56dd8 "Http2ConnectionState.cc", func = 0x556774d5698c "main_event_handler", line = 915}, event = 34463, reentrancy = 1}, {location = {
        file = 0x556774d56dd8 "Http2ConnectionState.cc", func = 0x556774d5702f "release_stream", line = 1272}, event = 34463, reentrancy = 1}, {location = {
        file = 0x556774d56dd8 "Http2ConnectionState.cc", func = 0x556774d5702f "release_stream", line = 1272}, event = 34463, reentrancy = 0}, {location = {
        file = 0x556774d56dd8 "Http2ConnectionState.cc", func = 0x556774d5702f "release_stream", line = 1272}, event = 34463, reentrancy = 0}, {location = {file = 0x0,
        func = 0x0, line = 0}, event = 0, reentrancy = 0} <repeats 60 times>}, history_pos = 5}

and from frame #4 (Http2Stream::destroy):

$2 = {history = {{location = {file = 0x556774d552e4 "Http2Stream.cc", func = 0x556774d5540e "send_tracked_event", line = 467}, event = 103, reentrancy = 0}, {location = {
        file = 0x556774d552e4 "Http2Stream.cc", func = 0x556774d5538b "terminate_if_possible", line = 386}, event = 34463, reentrancy = 0}, {location = {
        file = 0x556774d552e4 "Http2Stream.cc", func = 0x556774d406e8 "destroy", line = 740}, event = 34463, reentrancy = 0}, {location = {file = 0x0, func = 0x0, line = 0},
      event = 0, reentrancy = 0} <repeats 62 times>}, history_pos = 3}

[zwoop]

Here's the updated trace / history from latest crash / build:

(gdb) bt full
#0  0x00007fc3969068dd in waitpid () from /lib64/libc.so.6
No symbol table info available.
#1  0x000056375b224d24 in crash_logger_invoke (signo=11, info=0x7fc38b70b6f0, ctx=0x7fc38b70b5c0) at traffic_server/Crash.cc:165
        status = 0
#2  <signal handler called>
No symbol table info available.
#3  0x000056375b2f0635 in Http2ConnectionState::release_stream (this=0x7fc257fd3350, stream=<optimized out>) at Http2ConnectionState.cc:1284
        lock = <optimized out>
#4  0x000056375b2e394e in Http2Stream::destroy (this=0x7f89e383cbe0) at Http2Stream.cc:734
        h2_parent = <optimized out>
        lock = <optimized out>
        end_time = <optimized out>
        lock = <optimized out>
#5  0x000056375b2e152c in Http2Stream::terminate_if_possible (this=0x7f89e383cbe0) at Http2Stream.cc:384
        h2_parent = <optimized out>
        lock = <optimized out>
#6  0x000056375b2e02bf in Http2Stream::main_event_handler (this=0x7f89e383cbe0, event=103, edata=0x7f9b9caf6180) at Http2Stream.cc:133
        e = 0x7f9b9caf6180
        lock = <optimized out>
#7  0x000056375b43ce70 in Continuation::handleEvent (this=<optimized out>, event=<optimized out>, data=<optimized out>) at ./I_Continuation.h:160
No locals.
#8  EThread::process_event (this=0x7fc39120d740, e=0x7f9b9caf6180, calling_code=103) at UnixEThread.cc:131
        c_temp = <optimized out>
        lock = <optimized out>
#9  0x000056375b43d10b in EThread::process_queue (this=0x7fc39120d740, NegativeQueue=0x7fc38b70bdc0, ev_count=0x7fc38b70bde4, nq_count=0x7fc38b70bde0) at UnixEThread.cc:170
No locals.
#10 0x000056375b43d5bb in EThread::execute_regular (this=0x7fc39120d740) at UnixEThread.cc:230
        sleep_time = <optimized out>
        done_one = <optimized out>
        METRIC_INIT = {_loop_time = {_start = 0, _min = 9223372036854775807, _max = 0}, _events = {_min = 2147483647, _max = 0, _total = 0}, _count = 0, _wait = 0}
        delta = 0
        next_time = 0
        nq_count = 3621
        prev_metric = 0x7fc3913149f0
        ev_count = 3622
        loop_start_time = <optimized out>
        loop_finish_time = <optimized out>
#11 0x000056375b43c4dc in spawn_thread_internal (a=0x7fc3959fb140) at Thread.cc:85
        p = 0x7fc3959fb140
#12 0x00007fc396644aa1 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#13 0x00007fc396942c4d in clone () from /lib64/libc.so.6
No symbol table info available.
(gdb) frame 3
#3  0x000056375b2f0635 in Http2ConnectionState::release_stream (this=0x7fc257fd3350, stream=<optimized out>) at Http2ConnectionState.cc:1284
1284	        ua_session->destroy();
(gdb) p _history
$1 = {history = {{location = {file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466db0 "create_stream", line = 1101}, event = 0, reentrancy = 1}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dbe "delete_stream", line = 1242}, event = 34463, reentrancy = 1}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1251}, event = 34463, reentrancy = 0}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1255}, event = 1, reentrancy = 0}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1262}, event = 34463, reentrancy = 0}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1266}, event = 34463, reentrancy = 0}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1268}, event = 34463, reentrancy = 0}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b46674c "main_event_handler", line = 915}, event = 34463, reentrancy = 1}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1251}, event = 34463, reentrancy = 1}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1260}, event = 34463, reentrancy = 1}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1266}, event = 34463, reentrancy = 1}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1268}, event = 34463, reentrancy = 1}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1283}, event = 34463, reentrancy = 1}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1298}, event = 34463, reentrancy = 1}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1251}, event = 34463, reentrancy = 0}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1260}, event = 34463, reentrancy = 0}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1266}, event = 34463, reentrancy = 0}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1268}, event = 34463, reentrancy = 0}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1283}, event = 34463, reentrancy = 0}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1298}, event = 34463, reentrancy = 0}, {location = {
        file = 0x56375b466b98 "Http2ConnectionState.cc", func = 0x56375b466dfd "release_stream", line = 1283}, event = 34463, reentrancy = 0}, {location = {file = 0x0,
        func = 0x0, line = 0}, event = 0, reentrancy = 0} <repeats 44 times>}, history_pos = 21}
(gdb) f 4
#4  0x000056375b2e394e in Http2Stream::destroy (this=0x7f89e383cbe0) at Http2Stream.cc:734
734	    h2_parent->connection_state.release_stream(this);
(gdb) p _history
$2 = {history = {{location = {file = 0x56375b46509f "Http2Stream.cc", func = 0x56375b4651c9 "send_tracked_event", line = 464}, event = 103, reentrancy = 0}, {location = {
        file = 0x56375b46509f "Http2Stream.cc", func = 0x56375b465146 "terminate_if_possible", line = 383}, event = 34463, reentrancy = 0}, {location = {
        file = 0x56375b46509f "Http2Stream.cc", func = 0x56375b4504a8 "destroy", line = 733}, event = 34463, reentrancy = 0}, {location = {file = 0x0, func = 0x0, line = 0},
      event = 0, reentrancy = 0} <repeats 62 times>}, history_pos = 3}
(gdb) f 5
#5  0x000056375b2e152c in Http2Stream::terminate_if_possible (this=0x7f89e383cbe0) at Http2Stream.cc:384
384	    destroy();
(gdb) p _history
$3 = {history = {{location = {file = 0x56375b46509f "Http2Stream.cc", func = 0x56375b4651c9 "send_tracked_event", line = 464}, event = 103, reentrancy = 0}, {location = {
        file = 0x56375b46509f "Http2Stream.cc", func = 0x56375b465146 "terminate_if_possible", line = 383}, event = 34463, reentrancy = 0}, {location = {
        file = 0x56375b46509f "Http2Stream.cc", func = 0x56375b4504a8 "destroy", line = 733}, event = 34463, reentrancy = 0}, {location = {file = 0x0, func = 0x0, line = 0},
      event = 0, reentrancy = 0} <repeats 62 times>}, history_pos = 3}
(gdb) f 6
#6  0x000056375b2e02bf in Http2Stream::main_event_handler (this=0x7f89e383cbe0, event=103, edata=0x7f9b9caf6180) at Http2Stream.cc:133
133	  terminate_if_possible();
(gdb) p _history
$4 = {history = {{location = {file = 0x56375b46509f "Http2Stream.cc", func = 0x56375b4651c9 "send_tracked_event", line = 464}, event = 103, reentrancy = 0}, {location = {
        file = 0x56375b46509f "Http2Stream.cc", func = 0x56375b465146 "terminate_if_possible", line = 383}, event = 34463, reentrancy = 0}, {location = {
        file = 0x56375b46509f "Http2Stream.cc", func = 0x56375b4504a8 "destroy", line = 733}, event = 34463, reentrancy = 0}, {location = {file = 0x0, func = 0x0, line = 0},
      event = 0, reentrancy = 0} <repeats 62 times>}, history_pos = 3}