ATS/9.0.x : asserting on "event == HTTP_TUNNEL_EVENT_DONE" #6368
Description
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpTunnel.cc:1084 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [15/3755]
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpTunnel.cc:1128 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpTunnel.cc:1084 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT]
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpTunnel.cc:1128 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 105
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpSM.cc:3436 (tunnel_handler_post_ua)> (http) [0] [&HttpSM::tunnel_handler_post_ua, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT]
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpSM.cc:3446 (tunnel_handler_post_ua)> (http_tunnel) send 408 response to client to vc 0x401d400, tunnel vc 0x1825000
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <Http1ServerSession.cc:149 (do_io_close)> (http_ss) [0] session close: nevtc 0x9302c0
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpSM.cc:2575 (main_handler)> (http) [0] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpSM.cc:2676 (tunnel_handler_post)> (http) [0] [&HttpSM::tunnel_handler_post, HTTP_TUNNEL_EVENT_DONE]
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpTransact.cc:752 (PostInactiveTimeoutResponse)> (http_trans) [0] [PostInactiveTimeoutResponse]post inactive timeout
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpTransactHeaders.cc:1180 (add_server_header_to_response)> (http_trans) Adding Server: ATS/9.0.0
+++++++++ Proxy's Response 2 +++++++++
-- State Machine Id: 0
HTTP/1.1 408 Inactive Timeout
Date: Wed, 29 Jan 2020 06:57:58 GMT
Connection: close
Via: http/1.1 traffic_server (ApacheTrafficServer/9.0.0 [cMs f ])
Server: ATS/9.0.0
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpTransact.cc:755 (PostInactiveTimeoutResponse)> (http_trans) Next action SM_ACTION_SEND_ERROR_CACHE_NOOP; nullptr
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpSM.cc:7161 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_SEND_ERROR_CACHE_NOOP
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpTunnel.cc:595 (add_producer)> (http_tunnel) [0] adding producer 'internal msg'
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpTunnel.cc:650 (add_consumer)> (http_tunnel) [0] adding consumer 'user agent'
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <HttpTunnel.cc:697 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <Http2Stream.cc:594 (update_write_request)> (http2_stream) [0] [1] write_vio.nbytes=533, write_vio.ndone=0, write_vio.write_avail=0, reader.read_avail=533
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1594 (send_headers_frame)> (http2_con) [0] [1] Send HEADERS frame
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1905 (send_goaway_frame)> (http2_con) [0] Send GOAWAY frame, last_stream_id: 2147483647
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1527 (send_a_data_frame)> (http2_con) [0] [1] Send a DATA frame - client window con: 65270 stream: 65270 payload: 265
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1527 (send_a_data_frame)> (http2_con) [0] [1] Send a DATA frame - client window con: 65270 stream: 65270 payload: 0
[Jan 29 15:57:58.492] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1541 (send_a_data_frame)> (http2_con) [0] [1] END_STREAM
[Jan 29 15:57:58.493] [ET_NET 0] DEBUG: <Http2Stream.cc:321 (change_state)> (http2_stream) [0] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_LOCAL
[Jan 29 15:57:58.493] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1574 (send_data_frames)> (http2_con) [0] [1] Shutdown stream
[Jan 29 15:57:58.493] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1317 (delete_stream)> (http2_con) [0] [1] Delete stream
[Jan 29 15:57:58.493] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1802 (send_rst_stream_frame)> (http2_con) [0] [1] Send RST_STREAM frame
[Jan 29 15:57:58.493] [ET_NET 0] DEBUG: <Http2Stream.cc:321 (change_state)> (http2_stream) [0] [1] Http2StreamState::HTTP2_STREAM_STATE_CLOSED
[Jan 29 15:57:58.493] [ET_NET 0] DEBUG: <Http2Stream.cc:444 (initiating_close)> (http2_stream) [0] [1] initiating_close
[Jan 29 15:57:58.493] [ET_NET 0] DEBUG: <Http2Stream.cc:472 (initiating_close)> (http2_stream) [0] [1] handle write from destroy (event=103)
[Jan 29 15:57:58.493] [ET_NET 0] DEBUG: <HttpSM.cc:2575 (main_handler)> (http) [0] [HttpSM::main_handler, EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR]
[Jan 29 15:57:58.493] [ET_NET 0] DEBUG: <HttpSM.cc:2864 (tunnel_handler)> (http) [0] [&HttpSM::tunnel_handler, EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR]
Fatal: HttpSM.cc:2866: failed assertion `event == HTTP_TUNNEL_EVENT_DONE`
2020-01-29 15:57:58.493449+0900 traffic_server[84607:22856376] Fatal: HttpSM.cc:2866: failed assertion `event == HTTP_TUNNEL_EVENT_DONE`
Process 84607 stopped
* thread #2, name = '[ET_NET 0]', stop reason = signal SIGABRT
frame #0: 0x00007fff663167fa libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
-> 0x7fff663167fa <+10>: jae 0x7fff66316804 ; <+20>
0x7fff663167fc <+12>: movq %rax, %rdi
0x7fff663167ff <+15>: jmp 0x7fff66310a89 ; cerror_nocancel
0x7fff66316804 <+20>: retq
(lldb) bt
* thread #2, name = '[ET_NET 0]', stop reason = signal SIGABRT
* frame #0: 0x00007fff663167fa libsystem_kernel.dylib`__pthread_kill + 10
frame #1: 0x00007fff663d3bc1 libsystem_pthread.dylib`pthread_kill + 432
frame #2: 0x00007fff6629da1c libsystem_c.dylib`abort + 120
frame #3: 0x000000000006eb1e libtscore.9.dylib`ink_abort(message_format="%s:%d: failed assertion `%s`") at ink_error.cc:99:3
frame #4: 0x000000000006bbb2 libtscore.9.dylib`::_ink_assert(expression="event == HTTP_TUNNEL_EVENT_DONE", file="HttpSM.cc", line=2866) at ink_assert.cc:37:3
frame #5: 0x000000010010eb1f traffic_server`HttpSM::tunnel_handler(this=0x000000000182c400, event=3, data=0x0000000000000000) at HttpSM.cc:2866:3
frame #6: 0x0000000100104a75 traffic_server`HttpSM::main_handler(this=0x000000000182c400, event=3, data=0x0000000000000000) at HttpSM.cc:2595:5
frame #7: 0x0000000100010ac1 traffic_server`Continuation::handleEvent(this=0x000000000182c400, event=3, data=0x0000000000000000) at I_Continuation.h:190:12
frame #8: 0x0000000100253b1f traffic_server`Http2Stream::initiating_close(this=0x0000000001825000) at Http2Stream.cc:491:12
frame #9: 0x000000010023d34a traffic_server`Http2ConnectionState::delete_stream(this=0x000000000182f540, stream=0x0000000001825000) at Http2ConnectionState.cc:1352:11
frame #10: 0x000000010023f42e traffic_server`Http2ConnectionState::send_data_frames(this=0x000000000182f540, stream=0x0000000001825000) at Http2ConnectionState.cc:1575:13
frame #11: 0x0000000100253f7b traffic_server`Http2Stream::send_response_body(this=0x0000000001825000, call_update=false) at Http2Stream.cc:725:36
frame #12: 0x0000000100251590 traffic_server`Http2Stream::update_write_request(this=0x0000000001825000, buf_reader=0x0000000000e03e00, write_len=533, call_update=false) at Http2Stream.cc:644:15
frame #13: 0x000000010025279a traffic_server`Http2Stream::do_io_write(this=0x0000000001825000, c=0x000000000182d348, nbytes=533, abuffer=0x0000000000e03e00, owner=false) at Http2Stream.cc:363:3
frame #14: 0x0000000100195829 traffic_server`HttpTunnel::producer_run(this=0x000000000182d348, p=0x000000000182d558) at HttpTunnel.cc:882:29
frame #15: 0x0000000100194f30 traffic_server`HttpTunnel::tunnel_run(this=0x000000000182d348, p_arg=0x000000000182d558) at HttpTunnel.cc:699:5
frame #16: 0x0000000100113a67 traffic_server`HttpSM::setup_internal_transfer(this=0x000000000182c400, handler_arg=70 e9 10 00 01 00 00 00 00 00 00 00 00 00 00 00)(int, void*)) at HttpSM.cc:6331:10
frame #17: 0x0000000100110e41 traffic_server`HttpSM::handle_api_return(this=0x000000000182c400) at HttpSM.cc:1677:5
frame #18: 0x0000000100104fbc traffic_server`HttpSM::do_api_callout(this=0x000000000182c400) at HttpSM.cc:353:5
frame #19: 0x000000010012797e traffic_server`HttpSM::setup_error_transfer(this=0x000000000182c400) at HttpSM.cc:6230:5
frame #20: 0x000000010012afa7 traffic_server`HttpSM::set_next_state(this=0x000000000182c400) at HttpSM.cc:7492:5
frame #21: 0x00000001001089c7 traffic_server`HttpSM::call_transact_and_set_next_state(this=0x000000000182c400, f=(traffic_server`HttpTransact::PostInactiveTimeoutResponse(HttpTransact::State*) at HttpTransact.cc:750))(HttpTransact::State*)) at HttpSM.cc:7163:3
frame #22: 0x00000001001099f4 traffic_server`HttpSM::tunnel_handler_post(this=0x000000000182c400, event=2301, data=0x000000000182d348) at HttpSM.cc:2692:9
frame #23: 0x0000000100104a75 traffic_server`HttpSM::main_handler(this=0x000000000182c400, event=2301, data=0x000000000182d348) at HttpSM.cc:2595:5
frame #24: 0x0000000100010ac1 traffic_server`Continuation::handleEvent(this=0x000000000182c400, event=2301, data=0x000000000182d348) at I_Continuation.h:190:12
frame #25: 0x0000000100193e25 traffic_server`HttpTunnel::main_handler(this=0x000000000182d348, event=105, data=0x00000000018252a0) at HttpTunnel.cc:1579:11
frame #26: 0x0000000100010ac1 traffic_server`Continuation::handleEvent(this=0x000000000182d348, event=105, data=0x00000000018252a0) at I_Continuation.h:190:12
frame #27: 0x000000010024fe1d traffic_server`Http2Stream::main_event_handler(this=0x0000000001825000, event=105, edata=0x0000000000c3cd00) at Http2Stream.cc:100:24
frame #28: 0x0000000100010ac1 traffic_server`Continuation::handleEvent(this=0x0000000001825000, event=2, data=0x0000000000c3cd00) at I_Continuation.h:190:12
frame #29: 0x0000000100519dac traffic_server`EThread::process_event(this=0x0000000004800000, e=0x0000000000c3cd00, calling_code=2) at UnixEThread.cc:136:22
frame #30: 0x000000010051a6dd traffic_server`EThread::execute_regular(this=0x0000000004800000) at UnixEThread.cc:249:11
frame #31: 0x000000010051acf8 traffic_server`EThread::execute(this=0x0000000004800000) at UnixEThread.cc:344:11
frame #32: 0x0000000100518d92 traffic_server`spawn_thread_internal(a=0x000000000090b900) at Thread.cc:92:12
frame #33: 0x00007fff663d3e65 libsystem_pthread.dylib`_pthread_start + 148
frame #34: 0x00007fff663cf83b libsystem_pthread.dylib`thread_start + 15
Conditions
- 9.0.x branch
- set
proxy.config.http.transaction_no_activity_timeout_insmall
CONFIG proxy.config.http.transaction_no_activity_timeout_in INT 3
- send large post request over HTTP/2�