Skip to content

HTTP/2 Session & ConnectionState Cleanup#7845

Closed
masaori335 wants to merge 4 commits intoapache:masterfrom
masaori335:h2-cleanup-ssn-2
Closed

HTTP/2 Session & ConnectionState Cleanup#7845
masaori335 wants to merge 4 commits intoapache:masterfrom
masaori335:h2-cleanup-ssn-2

Conversation

@masaori335
Copy link
Copy Markdown
Contributor

@masaori335 masaori335 commented May 17, 2021

Part of address #6877. One of things makes HTTP/2 Session complicated is Http2ClientSession & Http2ConnectionState are calling each other as Continuation. To make this simple, I propose below.

1). Make Http2ConnectionState just a class
2). Introduce states of HTTP/2 session as Continuation Handler

Screen Shot 2021-07-07 at 15 50 21

https://gist.github.com/masaori335/f16a851b50bec2f69e4034844a40ab59#file-http2ssn-uml

@masaori335 masaori335 added this to the 10.0.0 milestone May 17, 2021
@masaori335 masaori335 self-assigned this May 17, 2021
@maskit
Copy link
Copy Markdown
Member

maskit commented May 18, 2021

I suggest making these changes below separately beforehand to make reading the diff easy a little:

  • Changing h2_proxy_ssn->connection_state.mutex to h2_proxy_ssn->mutex
  • Moving member function definitions inside class declaration to other places - it's hard to see if a function is moved, modified, or deleted

Comment thread proxy/http2/Http2ClientSession.cc Outdated
Comment on lines +420 to +426
connection_state.send_goaway_frame(connection_state.get_latest_stream_id_in(), Http2ErrorCode::HTTP2_ERROR_INTERNAL_ERROR);

case HTTP2_SESSION_EVENT_XMIT:
// Disable read - read is not needed by state_goaway
read_vio->done();

// Set nbyte to issue WRITE_COMPLETE event
int64_t len = _write_buffer_reader->read_avail();
write_vio->nbytes = write_vio->ndone + len;

// signal timeout event to txns
connection_state.cleanup_streams(event);
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It may be too early to start removing dup code, but I'd have this process in _switch_to_goaway_state. It'd also make debugging easy since we'd be able to set a breakpoint for the state change.

@bryancall
Copy link
Copy Markdown
Contributor

@masaori335 What is the state of this PR? Should it be reviewed?

@masaori335 masaori335 marked this pull request as ready for review June 27, 2021 22:59
@masaori335
Copy link
Copy Markdown
Contributor Author

It's ready to review. This passed AuTest and some additional tests in our lab.

I was planning to test this patch on production, but I'm not sure when I can do it. Because we haven't started testing 9.1.x.

@masaori335 masaori335 force-pushed the h2-cleanup-ssn-2 branch 2 times, most recently from 264a4f0 to 7ed597d Compare June 27, 2021 23:24
@masaori335 masaori335 requested a review from shinrich June 27, 2021 23:24
@shinrich
Copy link
Copy Markdown
Member

shinrich commented Jun 30, 2021

I pulled in this change and the other H2 cleanups into our 9.1 branch and tried it in production. It crashed pretty quickly with the following stack.

Looks like we are having problems on shutdown. The HttpSM (the cont in the read_vio) has already been deleted and its mutex has been cleared.

(gdb) bt
#0  Mutex_lock (t=0x2aebf5373c80, m=0x0) at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Lock.h:439
#1  Mutex_lock (t=0x2aebf5373c80, m=...) at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Lock.h:351
#2  MutexLock::MutexLock (this=0x2aebfbf094e0, am=..., t=0x2aebf5373c80)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Lock.h:439
#3  0x00000000006333d5 in Http2Stream::main_event_handler(int, void*) ()
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/include/tscore/ink_thread.h:124
#4  0x00000000007db23d in handleEvent (data=0x2aec33e039e0, event=104, this=0x2aee507b8e00) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:219
#5  handleEvent (data=0x2aec33e039e0, event=104, this=0x2aee507b8e00) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:215
#6  EThread::process_event(Event*, int) () at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:164
#7  0x00000000007db80e in EThread::process_queue (this=this@entry=0x2aebf5373c80, NegativeQueue=NegativeQueue@entry=0x2aebfbf09600, ev_count=ev_count@entry=0x2aebfbf095fc, 
    nq_count=nq_count@entry=0x2aebfbf095f8) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:199
#8  0x00000000007dbc74 in EThread::execute_regular (this=this@entry=0x2aebf5373c80) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:259
#9  0x00000000007dc2e2 in execute (this=0x2aebf5373c80) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:364
#10 EThread::execute (this=0x2aebf5373c80) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:342
#11 0x00000000007da92a in spawn_thread_internal (a=0x2aebefa863c0) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/Thread.cc:92
#12 0x00002aebede9dea5 in start_thread (arg=0x2aebfbf0b700) at pthread_create.c:307
#13 0x00002aebeebd49fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

The Http2Stream _history is

 {history = {{location = {file = 0x812320 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2Stream.cc", 
        func = 0x8126c0 <Http2Stream::send_tracked_event(Event*, int, VIO*)::__FUNCTION__> "send_tracked_event", line = 581}, event = 101, reentrancy = 0}, {location = {
        file = 0x812320 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2Stream.cc", func = 0x812740 <Http2Stream::main_event_handler(int, void*)::__FUNCTION__> "main_event_handler", line = 141}, 
      event = 101, reentrancy = 0}, {location = {file = 0x812320 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2Stream.cc", 
        func = 0x8126e0 <Http2Stream::initiating_close()::__FUNCTION__> "initiating_close", line = 515}, event = 34463, reentrancy = 0}, {location = {
        file = 0x812320 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2Stream.cc", func = 0x8126c0 <Http2Stream::send_tracked_event(Event*, int, VIO*)::__FUNCTION__> "send_tracked_event", 
        line = 581}, event = 104, reentrancy = 0}, {location = {file = 0x812320 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2Stream.cc", 
        func = 0x812740 <Http2Stream::main_event_handler(int, void*)::__FUNCTION__> "main_event_handler", line = 141}, event = 104, reentrancy = 0}, {location = {file = 0x0, func = 0x0, line = 0}, event = 0, 
      reentrancy = 0} <repeats 60 times>}, history_pos = 5}

It looks like the HttpSM history is also still around. The end of that is

 {location = {file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x7fe6c0 <HttpSM::setup_server_transfer()::__FUNCTION__> "setup_server_transfer", line = 6838}, event = 34463, reentrancy = 11}, {location = {
        file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x7fed20 <HttpSM::tunnel_handler_ua(int, HttpTunnelConsumer*)::__FUNCTION__> "tunnel_handler_ua", line = 3345}, 
      event = 104, reentrancy = 0}, {location = {file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x7fedc0 <HttpSM::tunnel_handler(int, void*)::__FUNCTION__> "tunnel_handler", line = 3015}, event = 2301, reentrancy = 1}, {location = {
        file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x7ff090 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, 
      reentrancy = 2}, {location = {file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x7ff070 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", 
        line = 1485}, event = 60000, reentrancy = 2}, {location = {file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x7ff090 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 3}, {location = {
        file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x7ff070 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 3}, {location = {file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x7ff090 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", 
        line = 1445}, event = 60000, reentrancy = 4}, {location = {file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x7ff070 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, reentrancy = 4}, {location = {
        file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x7ff090 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, 
      reentrancy = 5}, {location = {file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x7ff070 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", 
        line = 1485}, event = 60000, reentrancy = 5}, {location = {file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
---Type <return> to continue, or q <return> to quit---
        func = 0x7ff090 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 6}, {location = {
        file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x7ff070 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 6}, {location = {file = 0x7fad38 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x7fe668 <HttpSM::kill_this()::__FUNCTION__> "kill_this", line = 7157}, event = 34463, 
      reentrancy = 0}

It seems that the Http2Stream had already delivered an EOS which caused the HttpSM to clean itself up.

Will continue to poke around.

@shinrich
Copy link
Copy Markdown
Member

Got another core that looks the same before I could get the traffic off.

} else if (read_vio.cont && read_vio.op == VIO::READ) {
SCOPED_MUTEX_LOCK(lock, read_vio.cont->mutex, this_ethread());
read_vio.cont->handleEvent(event, &read_vio);
}
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This second clause is causing our use after free. Like 209 sends the EOS to our HttpTunnel which then causes everything to cleanup. Then in line 215 we try to access the HttpSM via the write_vio. Don't unnderstand why we need to do this two times.

  case VC_EVENT_ERROR:
  case VC_EVENT_EOS:
    if (e && e->cookie == &read_vio) {
      SCOPED_MUTEX_LOCK(lock, read_vio.mutex, this_ethread());
      read_vio.cont->handleEvent(event, &read_vio);
    } else if (e && e->cookie == &write_vio) {
      SCOPED_MUTEX_LOCK(lock, write_vio.mutex, this_ethread());
      write_vio.cont->handleEvent(event, &write_vio);
    }

    // This assuming stream on inbound side
    // TODO: make appropriate state
    if (recv_end_stream && write_vio.cont && write_vio.op == VIO::WRITE && write_vio.nbytes != 0) {
      SCOPED_MUTEX_LOCK(lock, write_vio.cont->mutex, this_ethread());
      write_vio.cont->handleEvent(event, &write_vio);
    } else if (read_vio.cont && read_vio.op == VIO::READ) {
      SCOPED_MUTEX_LOCK(lock, read_vio.cont->mutex, this_ethread());
      read_vio.cont->handleEvent(event, &read_vio);
    }

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Removing the second clause got rid of the quick use after free, but eventually a new core occurred.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for testing! It looks like I haven't tested cases in which Http2Stream schedules events to itself.

Don't unnderstand why we need to do this two times.

Right, we need only one time. We need a guard of null check of e for the second block.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

f57bde4 covers this (and probably the last crash on HttpSM::do_http_server_open).

@shinrich
Copy link
Copy Markdown
Member

shinrich commented Jun 30, 2021

After fixing the use-after-free, we get this crash after a few minutes. Still running the ASAN build, so no other obvious memory reuse problems before the crash.

At first glance the stack doesn't seem to have anything to do with http2, but the ua_txn is an Http2Stream and ua_txn->_proxy_ssn->_vc is null. So the assert that is trying to catch responses showing up on the wrong thread triggers.

(gdb) bt
#0  0x00002b0fea1e63d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:55
#1  0x00002b0fea1e7ac8 in __GI_abort () at abort.c:90
#2  0x00002b0fe798132c in ink_abort (message_format=message_format@entry=0x2b0fe79ff2a0 "%s:%d: failed assertion `%s`") at ../../../../../../_scm/trafficserver9.1/src/tscore/ink_error.cc:99
#3  0x00002b0fe797a1d2 in _ink_assert (expression=expression@entry=0x104c460 "vc && vc->thread == this_ethread()", file=file@entry=0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
    line=line@entry=2543) at ../../../../../../_scm/trafficserver9.1/src/tscore/ink_assert.cc:37
#4  0x000000000083a8b9 in HttpSM::state_cache_open_write(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:2543
#5  0x0000000000835a1d in HttpSM::main_handler(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:2745
#6  0x000000000095166d in handleEvent (data=0x6250050f1f10, event=1108, this=0x6250050f0100)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:219
#7  handleEvent (data=0x6250050f1f10, event=1108, this=0x6250050f0100)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:215
#8  HttpCacheSM::state_cache_open_write(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpCacheSM.cc:180
#9  0x0000000000caac8a in handleEvent (data=0x619000d9ad80, event=1108, this=0x6250050f1ea8)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:219
#10 handleEvent (data=0x619000d9ad80, event=1108, this=0x6250050f1ea8)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:215
#11 CacheVC::callcont (this=0x619000d9ad80, event=1108) at ../../../../../../_scm/trafficserver9.1/iocore/cache/P_CacheInternal.h:639
#12 0x0000000000ccd263 in CacheVC::openWriteStartDone(int, Event*) () at ../../../../../../_scm/trafficserver9.1/iocore/cache/CacheWrite.cc:1597
#13 0x0000000000ccf147 in Cache::open_write(Continuation*, ats::CryptoHash const*, HTTPInfo*, long, ats::CryptoHash const*, CacheFragType, char const*, int) ()
    at ../../../../../../_scm/trafficserver9.1/iocore/cache/CacheWrite.cc:1838
#14 0x0000000000c1382c in CacheProcessor::open_write (this=<optimized out>, cont=cont@entry=0x6250050f1ea8, expected_size=expected_size@entry=0, key=key@entry=0x2b0ff45d13c0, 
    request=request@entry=0x6250050f08a8, old_info=<optimized out>, pin_in_cache=0, type=CACHE_FRAG_TYPE_HTTP) at ../../../../../../_scm/trafficserver9.1/iocore/cache/Cache.cc:3251
#15 0x0000000000950593 in HttpCacheSM::open_write (this=this@entry=0x6250050f1ea8, key=key@entry=0x2b0ff45d13c0, url=url@entry=0x6250050f0238, request=request@entry=0x6250050f08a8, old_info=old_info@entry=0x0, 
    pin_in_cache=<optimized out>, retry=true, allow_multiple=false) at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpCacheSM.cc:373
#16 0x00000000007f3fd3 in HttpSM::do_cache_prepare_action(HttpCacheSM*, HTTPInfo*, bool, bool) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:4843
#17 0x000000000084f9c3 in do_cache_prepare_write (this=0x6250050f0100) at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:4773
#18 HttpSM::set_next_state() () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:7689
#19 0x000000000082cf35 in HttpSM::state_api_callout(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:1640
#20 0x0000000000838306 in HttpSM::state_api_callback(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:1447
#21 0x00000000006fbf77 in TSHttpTxnReenable () at ../../../../../_scm/trafficserver9.1/src/traffic_server/InkAPI.cc:6283
#22 0x00002b1032bace9b in ?? ()
#23 0x0000000000000026 in ?? ()
#24 0x00006190008f6b99 in ?? ()
#25 0x000060c000c9d780 in ?? ()
#26 0x00002b0ff45d1d30 in ?? ()
#27 0x00002b0ff45d1cd0 in ?? ()
#28 0x00006250050f0100 in ?? ()
#29 0x0000000041b58ab3 in ?? ()
#30 0x00002b1032bc54e0 in ?? ()
#31 0x00002b1032bacc70 in ?? ()
#32 0x000000000104e700 in ?? ()
#33 0x00002b0f00000000 in ?? ()
#34 0x00002b0fe799c8cc in StrList::_new_cell (this=0x561fe8ba39a, s=0x2b0ff45d1cd0 "\263\212\265A", len_not_counting_nul=19090144) at ../../../../../../_scm/trafficserver9.1/src/tscore/ink_string++.cc:87
#35 0x00000000006bb327 in INKContInternal::handle_event(int, void*) () at ../../../../../_scm/trafficserver9.1/src/traffic_server/InkAPI.cc:1137
#36 0x00000000006f3ab3 in handleEvent (data=0x6250050f0100, event=60015, this=<optimized out>)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:219
#37 handleEvent (data=0x6250050f0100, event=60015, this=<optimized out>)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:215
#38 APIHook::invoke(int, void*) const () at ../../../../../_scm/trafficserver9.1/src/traffic_server/InkAPI.cc:1374
#39 0x000000000082bb11 in HttpSM::state_api_callout(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:1568
#40 0x0000000000838306 in HttpSM::state_api_callback(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:1447
#41 0x00000000006fbf77 in TSHttpTxnReenable () at ../../../../../_scm/trafficserver9.1/src/traffic_server/InkAPI.cc:6283
---Type <return> to continue, or q <return> to quit---
#42 0x00002b100c233e3d in main_handler (cont=<optimized out>, event=<optimized out>, edata=<optimized out>) at ../../../../../_scm/trafficserver9.1/plugins/regex_revalidate/regex_revalidate.c:441
#43 0x00000000006bb327 in INKContInternal::handle_event(int, void*) () at ../../../../../_scm/trafficserver9.1/src/traffic_server/InkAPI.cc:1137
#44 0x00000000006f3ab3 in handleEvent (data=0x6250050f0100, event=60015, this=<optimized out>)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:219
#45 handleEvent (data=0x6250050f0100, event=60015, this=<optimized out>)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:215
#46 APIHook::invoke(int, void*) const () at ../../../../../_scm/trafficserver9.1/src/traffic_server/InkAPI.cc:1374
#47 0x000000000082bb11 in HttpSM::state_api_callout(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:1568
#48 0x0000000000838306 in HttpSM::state_api_callback(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:1447
#49 0x00000000006fbf77 in TSHttpTxnReenable () at ../../../../../_scm/trafficserver9.1/src/traffic_server/InkAPI.cc:6283
#50 0x00002b10012b7fed in carpLookup(tsapi_cont*, TSEvent, void*) () at _vcs/carp-9.1/carp/carp.cc:776
#51 0x00000000006bb327 in INKContInternal::handle_event(int, void*) () at ../../../../../_scm/trafficserver9.1/src/traffic_server/InkAPI.cc:1137
#52 0x00000000006f3ab3 in handleEvent (data=0x6250050f0100, event=60015, this=<optimized out>)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:219
#53 handleEvent (data=0x6250050f0100, event=60015, this=<optimized out>)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:215
#54 APIHook::invoke(int, void*) const () at ../../../../../_scm/trafficserver9.1/src/traffic_server/InkAPI.cc:1374
#55 0x000000000082bb11 in HttpSM::state_api_callout(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:1568
#56 0x00000000008509fb in HttpSM::set_next_state() () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:7456
#57 0x000000000082cf35 in HttpSM::state_api_callout(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:1640
#58 0x00000000008509fb in HttpSM::set_next_state() () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:7456
#59 0x0000000000833c9c in HttpSM::state_cache_open_read(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:2683
#60 0x0000000000835a1d in HttpSM::main_handler(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:2745
#61 0x000000000094f996 in handleEvent (data=0x6250050f1f10, event=1102, this=0x6250050f0100)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:219
#62 handleEvent (data=0x6250050f1f10, event=1102, this=0x6250050f0100)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:215
#63 HttpCacheSM::state_cache_open_read(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpCacheSM.cc:118
#64 0x0000000000caac8a in handleEvent (data=0x619002ed3380, event=1102, this=0x6250050f1ea8)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:219
#65 handleEvent (data=0x619002ed3380, event=1102, this=0x6250050f1ea8)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:215
#66 CacheVC::callcont (this=this@entry=0x619002ed3380, event=event@entry=1102) at ../../../../../../_scm/trafficserver9.1/iocore/cache/P_CacheInternal.h:639
#67 0x0000000000c9e3dc in CacheVC::openReadStartHead(int, Event*) () at ../../../../../../_scm/trafficserver9.1/iocore/cache/CacheRead.cc:1246
#68 0x0000000000c2a22e in CacheVC::handleReadDone(int, Event*) () at ../../../../../../_scm/trafficserver9.1/iocore/cache/Cache.cc:2298
#69 0x0000000000c3230b in AIOCallbackInternal::io_complete (this=0x619002ed3510, event=<optimized out>, data=<optimized out>)
    at /home/shinrich/build-new/_build/build_release_posix-x86_64_gcc_8/trafficserver9.1/build/../../../../_scm/trafficserver9.1/iocore/aio/P_AIO.h:121
#70 0x0000000000fc8e3d in handleEvent (data=0x609000105e30, event=1, this=<optimized out>) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:219
#71 handleEvent (data=0x609000105e30, event=1, this=<optimized out>) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:215
#72 EThread::process_event(Event*, int) () at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:164
#73 0x0000000000fca215 in EThread::process_queue (this=this@entry=0x2b0ff0a9c800, NegativeQueue=NegativeQueue@entry=0x2b0ff45d4460, ev_count=ev_count@entry=0x2b0ff45d4420, 
    nq_count=nq_count@entry=0x2b0ff45d43e0) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:199
#74 0x0000000000fcaf36 in EThread::execute_regular (this=this@entry=0x2b0ff0a9c800) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:259
#75 0x0000000000fcc082 in execute (this=0x2b0ff0a9c800) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:364
#76 EThread::execute (this=0x2b0ff0a9c800) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:342
#77 0x0000000000fc6f86 in spawn_thread_internal (a=0x60600007dae0) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/Thread.cc:92
#78 0x00002b0fe936fea5 in start_thread (arg=0x2b0ff45d6700) at pthread_create.c:307
#79 0x00002b0fea2ae9fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Stream _history

(gdb) print ((Http2Stream*)ua_txn)->_history
$4 = {history = {{location = {file = 0x10b0c20 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2Stream.cc", 
        func = 0x10b1de0 <Http2Stream::main_event_handler(int, void*)::__FUNCTION__> "main_event_handler", line = 141}, event = 104, reentrancy = 0}, {location = {file = 0x0, func = 0x0, line = 0}, event = 0, 
      reentrancy = 0} <repeats 64 times>}, history_pos = 1}

Session _history. Our stream had _id 1 and _state HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE, presumably because it had sent a header with no body.

(gdb) print ((Http2ClientSession *)ua_txn->_proxy_ssn)->_history
$6 = {history = {{location = {file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", func = 0x10a75e0 <Http2ClientSession::start()::__FUNCTION__> "start", line = 171}, 
      event = 34463, reentrancy = 0}, {location = {file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", 
        func = 0x10a75e0 <Http2ClientSession::start()::__FUNCTION__> "start", line = 172}, event = 34463, reentrancy = 0}, {location = {
        file = 0x10a9220 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ConnectionState.cc", 
        func = 0x10ace00 <Http2ConnectionState::send_connection_preface()::__FUNCTION__> "send_connection_preface", line = 1055}, event = 34463, reentrancy = 0}, {location = {
        file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", func = 0x10a74e0 <Http2ClientSession::state_open(int, void*)::__FUNCTION__> "state_open", line = 339}, 
      event = 100, reentrancy = 1}, {location = {file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", 
        func = 0x10a73a0 <Http2ClientSession::state_read_connection_preface(int, void*)::__FUNCTION__> "state_read_connection_preface", line = 517}, event = 100, reentrancy = 1}, {location = {
        file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", 
        func = 0x10a73a0 <Http2ClientSession::state_read_connection_preface(int, void*)::__FUNCTION__> "state_read_connection_preface", line = 540}, event = 34463, reentrancy = 1}, {location = {
        file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", func = 0x10a74e0 <Http2ClientSession::state_open(int, void*)::__FUNCTION__> "state_open", line = 339}, 
      event = 100, reentrancy = 2}, {location = {file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", 
        func = 0x10a7360 <Http2ClientSession::state_start_frame_read(int, void*)::__FUNCTION__> "state_start_frame_read", line = 570}, event = 100, reentrancy = 2}, {location = {
        file = 0x10a9220 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ConnectionState.cc", func = 0x10acdc0 <Http2ConnectionState::rcv_frame(Http2Frame const*)::__FUNCTION__> "rcv_frame", 
        line = 1087}, event = 34463, reentrancy = 0}, {location = {file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", 
        func = 0x10a72a0 <Http2ClientSession::do_complete_frame_read()::__FUNCTION__> "do_complete_frame_read", line = 672}, event = 34463, reentrancy = 2}, {location = {
        file = 0x10a9220 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ConnectionState.cc", func = 0x10acdc0 <Http2ConnectionState::rcv_frame(Http2Frame const*)::__FUNCTION__> "rcv_frame", 
        line = 1087}, event = 34463, reentrancy = 0}, {location = {file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", 
        func = 0x10a72a0 <Http2ClientSession::do_complete_frame_read()::__FUNCTION__> "do_complete_frame_read", line = 672}, event = 34463, reentrancy = 2}, {location = {
        file = 0x10a9220 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ConnectionState.cc", func = 0x10acdc0 <Http2ConnectionState::rcv_frame(Http2Frame const*)::__FUNCTION__> "rcv_frame", 
        line = 1087}, event = 34463, reentrancy = 0}, {location = {file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", 
        func = 0x10a72a0 <Http2ClientSession::do_complete_frame_read()::__FUNCTION__> "do_complete_frame_read", line = 672}, event = 34463, reentrancy = 2}, {location = {
        file = 0x10a9220 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ConnectionState.cc", func = 0x10acdc0 <Http2ConnectionState::rcv_frame(Http2Frame const*)::__FUNCTION__> "rcv_frame", 
        line = 1087}, event = 34463, reentrancy = 0}, {location = {file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", 
        func = 0x10a72a0 <Http2ClientSession::do_complete_frame_read()::__FUNCTION__> "do_complete_frame_read", line = 672}, event = 34463, reentrancy = 2}, {location = {
        file = 0x10a9220 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ConnectionState.cc", func = 0x10acdc0 <Http2ConnectionState::rcv_frame(Http2Frame const*)::__FUNCTION__> "rcv_frame", 
        line = 1087}, event = 34463, reentrancy = 0}, {location = {file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", 
        func = 0x10a72a0 <Http2ClientSession::do_complete_frame_read()::__FUNCTION__> "do_complete_frame_read", line = 672}, event = 34463, reentrancy = 2}, {location = {
        file = 0x10a9220 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ConnectionState.cc", func = 0x10acdc0 <Http2ConnectionState::rcv_frame(Http2Frame const*)::__FUNCTION__> "rcv_frame", 
        line = 1087}, event = 34463, reentrancy = 0}, {location = {file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", 
        func = 0x10a72a0 <Http2ClientSession::do_complete_frame_read()::__FUNCTION__> "do_complete_frame_read", line = 672}, event = 34463, reentrancy = 2}, {location = {
        file = 0x10a9220 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ConnectionState.cc", func = 0x10acdc0 <Http2ConnectionState::rcv_frame(Http2Frame const*)::__FUNCTION__> "rcv_frame", 
        line = 1087}, event = 34463, reentrancy = 0}, {location = {file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", 
        func = 0x10a72a0 <Http2ClientSession::do_complete_frame_read()::__FUNCTION__> "do_complete_frame_read", line = 672}, event = 34463, reentrancy = 2}, {location = {
        file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", func = 0x10a74e0 <Http2ClientSession::state_open(int, void*)::__FUNCTION__> "state_open", line = 339}, 
      event = 104, reentrancy = 1}, {location = {file = 0x10a5840 "../../../../../../_scm/trafficserver9.1/proxy/http2/Http2ClientSession.cc", 
        func = 0x10a71a0 <Http2ClientSession::_handle_vc_event(int, void*)::__FUNCTION__> "_handle_vc_event", line = 999}, event = 34463, reentrancy = 1}, {location = {file = 0x0, func = 0x0, line = 0}, 
      event = 0, reentrancy = 0} <repeats 41 times>}, history_pos = 24}

HttpSM history

(gdb) print history
$8 = {history = {{location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", 
        line = 1445}, event = 60000, reentrancy = 2}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, reentrancy = 2}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, 
      event = 60000, reentrancy = 3}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, reentrancy = 3}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, 
      event = 60000, reentrancy = 4}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, reentrancy = 4}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, 
      event = 60000, reentrancy = 5}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, reentrancy = 5}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fec0 <HttpSM::state_read_client_request_header(int, void*)::__FUNCTION__> "state_read_client_request_header", line = 701}, event = 100, reentrancy = 6}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fec0 <HttpSM::state_read_client_request_header(int, void*)::__FUNCTION__> "state_read_client_request_header", line = 701}, event = 102, reentrancy = 1}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fe40 <HttpSM::state_watch_for_client_abort(int, void*)::__FUNCTION__> "state_watch_for_client_abort", 
        line = 988}, event = 102, reentrancy = 2}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 2}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 2}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 3}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 3}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 4}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 4}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 5}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 5}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 6}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 6}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 7}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 7}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 8}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 8}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 9}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 9}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 10}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 10}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 11}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 11}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 12}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 12}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 13}, {location = {
---Type <return> to continue, or q <return> to quit---
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 13}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 14}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 14}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 15}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 15}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 16}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 16}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 17}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 17}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, event = 60000, reentrancy = 18}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, 
      reentrancy = 18}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104e700 <HttpSM::set_next_state()::__FUNCTION__> "set_next_state", line = 7579}, 
      event = 34463, reentrancy = 18}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104f020 <HttpSM::do_cache_lookup_and_read()::__FUNCTION__> "do_cache_lookup_and_read", line = 4748}, event = 7952, reentrancy = 18}, {location = {
        file = 0x10823a0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpCacheSM.cc", func = 0x1082da0 <HttpCacheSM::state_cache_open_read(int, void*)::__FUNCTION__> "state_cache_open_read", 
        line = 100}, event = 1102, reentrancy = -31073}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104f820 <HttpSM::state_cache_open_read(int, void*)::__FUNCTION__> "state_cache_open_read", line = 2654}, event = 1102, reentrancy = 1}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, 
      event = 60000, reentrancy = 2}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, reentrancy = 2}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, 
      event = 60000, reentrancy = 3}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, reentrancy = 3}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104fc60 <HttpSM::state_api_callback(int, void*)::__FUNCTION__> "state_api_callback", line = 1445}, 
      event = 60000, reentrancy = 4}, {location = {file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", 
        func = 0x104fc20 <HttpSM::state_api_callout(int, void*)::__FUNCTION__> "state_api_callout", line = 1485}, event = 60000, reentrancy = 4}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104e700 <HttpSM::set_next_state()::__FUNCTION__> "set_next_state", line = 7687}, event = 34463, 
      reentrancy = 4}, {location = {file = 0x10823a0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpCacheSM.cc", 
        func = 0x1082d60 <HttpCacheSM::state_cache_open_write(int, void*)::__FUNCTION__> "state_cache_open_write", line = 165}, event = 1108, reentrancy = -31073}, {location = {
        file = 0x1046ac0 "../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc", func = 0x104f860 <HttpSM::state_cache_open_write(int, void*)::__FUNCTION__> "state_cache_open_write", line = 2533}, 
      event = 1108, reentrancy = 5}

Comment thread proxy/http2/Http2ClientSession.cc Outdated
// No more read/write op
_vc->do_io_close();
_vc = nullptr;

Copy link
Copy Markdown
Member

@shinrich shinrich Jun 30, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I presume this is the immediate cause of the state_cache_open_write crash. In the core dying_event is set to 104. But presumably we did not get the HttpSM to stop directly as a result of the cleanup_streams() and the cache_write_open event snuck in before we could get everything shutdown.

In the current code the _vc->do_io_close() is not called until everything is shutdown and we are getting ready to free the Http2ClientSession object.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It looks like this is a race of callback from AIO and closing vc. Actually, I don't understand why HttpSM::state_cache_open_write needs the client vc. IMO, we can write to the cache without client vc.

In the current code the _vc->do_io_close() is not called until everything is shutdown and we are getting ready to free the Http2ClientSession object.

But this is what we have now. I'll adjust this PR to follow this assumption. However, in the long term, we might want to change the design - e.g. when a client is aborted & background-fill is working, we wouldn't want to keep resources for the aborted client.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

d53ac5c get rid of this and ignore VC events on state_aborted for just in case.

@shinrich
Copy link
Copy Markdown
Member

One last crash before I shutdown tonight. I moved the _vc->do_io_close back to the Http2ClientSession::free and traffic_server ran for many minutes. But eventually it crashed with the stack below. It looks like the server session timed out and signaled the HttpSM. But the ua_txn referenced a Http2Stream that had already at least partially cleaned up. Eventually causing a segfault. I didn't see any likely shutdown signal from the client in the HttpSM history.

(gdb) bt
#0  0x00000000005840ae in HttpSM::do_http_server_open(bool) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:4944
#1  0x0000000000587d5d in HttpSM::set_next_state() () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:7611
#2  0x000000000057c1c4 in HttpSM::state_read_server_response_header(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:2020
#3  0x000000000057ecbb in HttpSM::main_handler(int, void*) () at ../../../../../../_scm/trafficserver9.1/proxy/http/HttpSM.cc:2745
#4  0x00000000007996be in read_signal_and_update(int, UnixNetVConnection*) () at ../../../../../../_scm/trafficserver9.1/iocore/net/UnixNetVConnection.cc:83
#5  0x0000000000799b6b in UnixNetVConnection::mainEvent(int, Event*) () at ../../../../../../_scm/trafficserver9.1/iocore/net/UnixNetVConnection.cc:1160
#6  0x000000000078e555 in InactivityCop::check_inactivity (this=0x2ad5a18cd000, event=<optimized out>, e=<optimized out>) at ../../../../../../_scm/trafficserver9.1/iocore/net/UnixNet.cc:96
#7  0x00000000007db38d in handleEvent (data=0x2ad5a1801060, event=2, this=0x2ad5a18cd000) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:219
#8  handleEvent (data=0x2ad5a1801060, event=2, this=0x2ad5a18cd000) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/I_Continuation.h:215
#9  EThread::process_event(Event*, int) () at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:164
#10 0x00000000007dc0b4 in EThread::execute_regular (this=this@entry=0x2ad591f733c0) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:273
#11 0x00000000007dc432 in execute (this=0x2ad591f733c0) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:364
#12 EThread::execute (this=0x2ad591f733c0) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/UnixEThread.cc:342
#13 0x00000000007daa7a in spawn_thread_internal (a=0x2ad58ba86640) at ../../../../../../_scm/trafficserver9.1/iocore/eventsystem/Thread.cc:92
#14 0x00002ad589ec2ea5 in start_thread (arg=0x2ad59a701700) at pthread_create.c:307
#15 0x00002ad58abf99fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

@masaori335
Copy link
Copy Markdown
Contributor Author

I started a trial of this PR based on 9.1.0 (with various other cleanup PRs without ASan). I observed few metric changes below, but it has been running for a day without crashes, so far.

1). Inactive timeout cases are counted by http2.session_die_inactive and http2.connection_errors.
2). If clients send GOAWAY to closed the connection from their side, it counted by http2.session_die_error instead of http2.session_die_default.

@maskit
Copy link
Copy Markdown
Member

maskit commented Aug 31, 2021

You are going to fix the two metric issues above, right? At minimum closing connections with GOAWAY frame is not necessarily due to an error.

I hope #8281 didn't mess up your changes too much.

@masaori335
Copy link
Copy Markdown
Contributor Author

Yup, I'm going to fix them. At least, I'll rebase on the latest branch and deal with the #8281 change.

@bryancall
Copy link
Copy Markdown
Contributor

[approve ci]

@github-actions
Copy link
Copy Markdown

This pull request has been automatically marked as stale because it has not had recent activity. Marking it stale to flag it for further consideration by the community.

@github-actions github-actions Bot added the Stale label Jan 13, 2022
@github-actions github-actions Bot closed this Jan 21, 2022
@masaori335 masaori335 reopened this Jan 21, 2022
@github-actions github-actions Bot closed this Jan 29, 2022
@bryancall bryancall reopened this Mar 14, 2022
@github-actions github-actions Bot closed this Mar 22, 2022
@zwoop zwoop removed this from the 10.0.0 milestone Jan 17, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants