Assertion failure: `event == HTTP_TUNNEL_EVENT_DONE` in HttpSM

[maskit]

This assertion, which is in the initial commit, fails on master (f75eaf8) but not 9.0.x.

Fatal: HttpSM.cc:2937: failed assertion `event == HTTP_TUNNEL_EVENT_DONE`
2020-08-11 11:37:06.467130+0900 traffic_server[74010:19298151] Fatal: HttpSM.cc:2937: failed assertion `event == HTTP_TUNNEL_EVENT_DONE`
Process 74010 stopped
* thread #2, name = '[ET_NET 0]', stop reason = signal SIGABRT
    frame #0: 0x00007fff6fa7633a libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff6fa7633a <+10>: jae    0x7fff6fa76344            ; <+20>
    0x7fff6fa7633c <+12>: movq   %rax, %rdi
    0x7fff6fa7633f <+15>: jmp    0x7fff6fa70629            ; cerror_nocancel
    0x7fff6fa76344 <+20>: retq   
Target 0: (traffic_server) stopped.
(lldb) bt
* thread #2, name = '[ET_NET 0]', stop reason = signal SIGABRT
  * frame #0: 0x00007fff6fa7633a libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff6fb32e60 libsystem_pthread.dylib`pthread_kill + 430
    frame #2: 0x00007fff6f9fd808 libsystem_c.dylib`abort + 120
    frame #3: 0x000000010312770a libtscore.10.dylib`ink_abort(message_format="%s:%d: failed assertion `%s`") at ink_error.cc:99:3
    frame #4: 0x000000010311d427 libtscore.10.dylib`::_ink_assert(expression="event == HTTP_TUNNEL_EVENT_DONE", file="HttpSM.cc", line=2937) at ink_assert.cc:37:3
    frame #5: 0x00000001002fcbd8 traffic_server`HttpSM::tunnel_handler(this=0x000000010dd7b280, event=106, data=0x000000010dc35e00) at HttpSM.cc:2937:3
    frame #6: 0x00000001002db92c traffic_server`HttpSM::main_handler(this=0x000000010dd7b280, event=106, data=0x000000010dc35e00) at HttpSM.cc:2665:5
    frame #7: 0x000000010000afb5 traffic_server`Continuation::handleEvent(this=0x000000010dd7b280, event=106, data=0x000000010dc35e00) at I_Continuation.h:219:12
    frame #8: 0x000000010071de2c traffic_server`Http2Stream::signal_read_event(this=0x000000010dc35b40, event=106) at Http2Stream.cc:643:26
    frame #9: 0x000000010071c7dc traffic_server`Http2Stream::main_event_handler(this=0x000000010dc35b40, event=106, edata=0x000062c000006400) at Http2Stream.cc:103:13
    frame #10: 0x000000010000afb5 traffic_server`Continuation::handleEvent(this=0x000000010dc35b40, event=106, data=0x000062c000006400) at I_Continuation.h:219:12
    frame #11: 0x00000001006c4cfe traffic_server`ActivityCop<Http2Stream, DLL<Http2Stream, Continuation::Link_link> >::check_activity(this=0x000000010db4ed58, (null)=2, e=0x000062c000006400) at NetTimeout.h:256:10
    frame #12: 0x000000010000afb5 traffic_server`Continuation::handleEvent(this=0x000000010db4ed58, event=2, data=0x000062c000006400) at I_Continuation.h:219:12
    frame #13: 0x0000000100fe0644 traffic_server`EThread::process_event(this=0x00000001090e5800, e=0x000062c000006400, calling_code=2) at UnixEThread.cc:127:22
    frame #14: 0x0000000100fe2058 traffic_server`EThread::execute_regular(this=0x00000001090e5800) at UnixEThread.cc:236:11
    frame #15: 0x0000000100fe3778 traffic_server`EThread::execute(this=0x00000001090e5800) at UnixEThread.cc:327:11
    frame #16: 0x0000000100fdde69 traffic_server`spawn_thread_internal(a=0x0000607000007950) at Thread.cc:92:12
    frame #17: 0x00007fff6fb33109 libsystem_pthread.dylib`_pthread_start + 148
    frame #18: 0x00007fff6fb2eb8b libsystem_pthread.dylib`thread_start + 15

Event 106 is VC_EVENT_ACTIVE_TIMEOUT.

[maskit]

(lldb) p history
(History<65>) $0 = {
  history = {
    [0] = {
      location = (file = "HttpSM.cc", func = "state_read_client_request_header", line = 667)
      event = 100
      reentrancy = 2
    }
    [1] = {
      location = (file = "HttpSM.cc", func = "state_read_client_request_header", line = 667)
      event = 102
      reentrancy = 1
    }
    [2] = {
      location = (file = "HttpSM.cc", func = "state_watch_for_client_abort", line = 934)
      event = 102
      reentrancy = 2
    }
    [3] = {
      location = (file = "HttpSM.cc", func = "state_api_callback", line = 1391)
      event = 60000
      reentrancy = 2
    }
    [4] = {
      location = (file = "HttpSM.cc", func = "state_api_callout", line = 1431)
      event = 60000
      reentrancy = 2
    }
    [5] = {
      location = (file = "HttpSM.cc", func = "set_next_state", line = 7484)
      event = 34463
      reentrancy = 2
    }
    [6] = {
      location = (file = "HttpCacheSM.cc", func = "state_cache_open_read", line = 100)
      event = 1103
      reentrancy = -31073
    }
    [7] = {
      location = (file = "HttpSM.cc", func = "state_cache_open_read", line = 2576)
      event = 1103
      reentrancy = 3
    }
    [8] = {
      location = (file = "HttpSM.cc", func = "set_next_state", line = 7444)
      event = 34463
      reentrancy = 3
    }
    [9] = {
      location = (file = "HttpSM.cc", func = "set_next_state", line = 7593)
      event = 34463
      reentrancy = 3
    }
    [10] = {
      location = (file = "HttpCacheSM.cc", func = "state_cache_open_write", line = 160)
      event = 1108
      reentrancy = -31073
    }
    [11] = {
      location = (file = "HttpSM.cc", func = "state_cache_open_write", line = 2457)
      event = 1108
      reentrancy = 4
    }
    [12] = {
      location = (file = "HttpSM.cc", func = "set_next_state", line = 7490)
      event = 34463
      reentrancy = 4
    }
    [13] = {
      location = (file = "HttpSM.cc", func = "state_http_server_open", line = 1778)
      event = 200
      reentrancy = 5
    }
    [14] = {
      location = (file = "HttpSM.cc", func = "do_cache_lookup_and_read", line = 4643)
      event = 0
      reentrancy = 2
    }
    [15] = {
      location = (file = "HttpSM.cc", func = "state_http_server_open", line = 1778)
      event = 102
      reentrancy = 1
    }
    [16] = {
      location = (file = "HttpSM.cc", func = "state_send_server_request_header", line = 2065)
      event = 103
      reentrancy = 1
    }
    [17] = {
      location = (file = "HttpSM.cc", func = "state_read_server_response_header", line = 1911)
      event = 100
      reentrancy = 1
    }
    [18] = {
      location = (file = "HttpSM.cc", func = "state_api_callback", line = 1391)
      event = 60000
      reentrancy = 2
    }
    [19] = {
      location = (file = "HttpSM.cc", func = "state_api_callout", line = 1431)
      event = 60000
      reentrancy = 2
    }
    [20] = {
      location = (file = "HttpSM.cc", func = "setup_server_transfer", line = 6734)
      event = 34463
      reentrancy = 2
    }
    [21] = {
      location = (file = "HttpSM.cc", func = "state_watch_for_client_abort", line = 934)
      event = 106
      reentrancy = 1
    }
    [22] = {
      location = (file = "HttpSM.cc", func = "tunnel_handler_ua", line = 3261)
      event = 106
      reentrancy = 1
    }
    [23] = {
      location = (file = "HttpSM.cc", func = "tunnel_handler", line = 2935)
      event = 106
      reentrancy = 1
    }
    [24] = {
      location = (file = 0x0000000000000000, func = 0x0000000000000000, line = 0)
      event = 0
      reentrancy = 0
    }

[maskit]

This happens only on H2 connections, but not H1 and H3.

[maskit]

Reverting #6494 fixed the crash. This explains why it only happens on master but not 9.0.x, because it's not backported.

[maskit]

@masaori335 I'm going to hand over this issue to you.

[masaori335]

How to reproduce this crash?

[masaori335]

 [23] = {
      location = (file = "HttpSM.cc", func = "tunnel_handler", line = 2935)
      event = 106
      reentrancy = 1
    }

It looks like the transaction is done, but the Http2Stream is still in the stream_list and active timeout is not canceled.
Probably, we need to cancel active & inactive timeouts in Http2Stream::transaction_done() or Http2Stream::do_io_close().

[masaori335]

Prior to the #6494, Http2Stream::do_io_close() had Http2Stream::clear_timers() and it canceled timeouts. I should have cancel timeouts instead of just removing.

[maskit]

I set proxy.config.http.transaction_active_timeout_in to 3, and have a remap rule / -> httpbin.org/. I have more changes on records.config, but I guess short timeout_in is enough. Then run ATS with -K and access / from a Web bowser.

[maskit]

[Aug 13 16:31:53.341] [ET_NET 1] DEBUG: <Http2ClientSession.cc:471 (do_start_frame_read)> (http2_cs) [0] receiving frame header
[Aug 13 16:31:53.341] [ET_NET 1] DEBUG: <Http2ClientSession.cc:488 (do_start_frame_read)> (http2_cs) [0] frame header length=4, type=8, flags=0x0, streamid=0
[Aug 13 16:31:53.341] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:795 (rcv_window_update_frame)> (http2_con) [0] [0] Received WINDOW_UPDATE frame - updated to: 65535 delta: 32768
[Aug 13 16:31:53.342] [ET_NET 1] DEBUG: <Http2ClientSession.cc:471 (do_start_frame_read)> (http2_cs) [0] receiving frame header
[Aug 13 16:31:53.342] [ET_NET 1] DEBUG: <Http2ClientSession.cc:488 (do_start_frame_read)> (http2_cs) [0] frame header length=4, type=8, flags=0x0, streamid=1
[Aug 13 16:31:53.342] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:829 (rcv_window_update_frame)> (http2_con) [0] [1] Received WINDOW_UPDATE frame - updated to: 65535 delta: 32768
[Aug 13 16:31:53.368] [ET_NET 1] DEBUG: <HttpSM.cc:2645 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_ACTIVE_TIMEOUT/TS_EVENT_VCONN_ACTIVE_TIMEOUT]
[Aug 13 16:31:53.368] [ET_NET 1] DEBUG: <HttpSM.cc:934 (state_watch_for_client_abort)> (http) [0] [&HttpSM::state_watch_for_client_abort, VC_EVENT_ACTIVE_TIMEOUT/TS_EVENT_VCONN_ACTIVE_TIMEOUT]
[Aug 13 16:31:53.368] [ET_NET 1] DEBUG: <HttpSM.cc:977 (state_watch_for_client_abort)> (http) [0] [watch_for_client_abort] forwarding event VC_EVENT_ACTIVE_TIMEOUT/TS_EVENT_VCONN_ACTIVE_TIMEOUT to tunnel
[Aug 13 16:31:53.368] [ET_NET 1] DEBUG: <HttpTunnel.cc:1307 (consumer_handler)> (http_tunnel) [0] consumer_handler [user agent VC_EVENT_ACTIVE_TIMEOUT/TS_EVENT_VCONN_ACTIVE_TIMEOUT]
[Aug 13 16:31:53.368] [ET_NET 1] DEBUG: <HttpSM.cc:3261 (tunnel_handler_ua)> (http) [0] [&HttpSM::tunnel_handler_ua, VC_EVENT_ACTIVE_TIMEOUT/TS_EVENT_VCONN_ACTIVE_TIMEOUT]
[Aug 13 16:31:53.368] [ET_NET 1] DEBUG: <HttpSM.cc:3280 (tunnel_handler_ua)> (http) [0] Initiating background fill
[Aug 13 16:31:53.368] [ET_NET 1] DEBUG: <ProxyTransaction.cc:63 (release)> (http_txn) [0] session released by sm [0]
[Aug 13 16:31:53.368] [ET_NET 1] DEBUG: <Http2Stream.cc:353 (do_io_close)> (http2_stream) [0] [1] do_io_close
[Aug 13 16:31:53.368] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1569 (send_a_data_frame)> (http2_con) [0] [1] No payload
[Aug 13 16:31:53.368] [ET_NET 1] DEBUG: <ProxyTransaction.cc:63 (release)> (http_txn) [0] session released by sm [0]
[Aug 13 16:31:53.529] [ET_NET 1] DEBUG: <HttpTunnel.cc:1101 (producer_handler)> (http_tunnel) [0] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Aug 13 16:31:53.529] [ET_NET 1] DEBUG: <HttpTunnel.cc:1145 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0
[Aug 13 16:31:53.530] [ET_NET 1] DEBUG: <HttpTunnel.cc:1101 (producer_handler)> (http_tunnel) [0] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Aug 13 16:31:53.530] [ET_NET 1] DEBUG: <HttpTunnel.cc:1145 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0
[Aug 13 16:31:53.530] [ET_NET 1] DEBUG: <HttpTunnel.cc:1307 (consumer_handler)> (http_tunnel) [0] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Aug 13 16:31:53.734] [ET_NET 1] DEBUG: <HttpTunnel.cc:1101 (producer_handler)> (http_tunnel) [0] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Aug 13 16:31:53.734] [ET_NET 1] DEBUG: <HttpTunnel.cc:1145 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0
[Aug 13 16:31:53.735] [ET_NET 1] DEBUG: <HttpTunnel.cc:1307 (consumer_handler)> (http_tunnel) [0] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Aug 13 16:31:53.735] [ET_NET 1] DEBUG: <HttpTunnel.cc:1101 (producer_handler)> (http_tunnel) [0] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Aug 13 16:31:53.735] [ET_NET 1] DEBUG: <HttpTunnel.cc:1145 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0
[Aug 13 16:31:53.736] [ET_NET 1] DEBUG: <HttpTunnel.cc:1307 (consumer_handler)> (http_tunnel) [0] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Aug 13 16:31:53.910] [ET_NET 1] DEBUG: <HttpTunnel.cc:1101 (producer_handler)> (http_tunnel) [0] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Aug 13 16:31:53.910] [ET_NET 1] DEBUG: <HttpTunnel.cc:1145 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0
[Aug 13 16:31:53.910] [ET_NET 1] DEBUG: <HttpTunnel.cc:1307 (consumer_handler)> (http_tunnel) [0] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Aug 13 16:31:54.085] [ET_NET 1] DEBUG: <HttpTunnel.cc:1101 (producer_handler)> (http_tunnel) [0] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Aug 13 16:31:54.086] [ET_NET 1] DEBUG: <HttpTunnel.cc:1145 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0
[Aug 13 16:31:54.086] [ET_NET 1] DEBUG: <HttpTunnel.cc:1307 (consumer_handler)> (http_tunnel) [0] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Aug 13 16:31:54.366] [ET_NET 1] DEBUG: <HttpSM.cc:2645 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_ACTIVE_TIMEOUT/TS_EVENT_VCONN_ACTIVE_TIMEOUT]
[Aug 13 16:31:54.366] [ET_NET 1] DEBUG: <HttpSM.cc:2935 (tunnel_handler)> (http) [0] [&HttpSM::tunnel_handler, VC_EVENT_ACTIVE_TIMEOUT/TS_EVENT_VCONN_ACTIVE_TIMEOUT]
Fatal: HttpSM.cc:2937: failed assertion `event == HTTP_TUNNEL_EVENT_DONE`
2020-08-13 16:31:54.366253+0900 traffic_server[27148:21841903] Fatal: HttpSM.cc:2937: failed assertion `event == HTTP_TUNNEL_EVENT_DONE`