maskit opened a new issue, #9229: URL: https://github.com/apache/trafficserver/issues/9229
We saw crashes (assertion failures) while we test 9.2.0 on our production and we think #8301 is the cause (or it made things worse at a minimum). The change made it possible to handle POST data and response data in parallel, but it also introduced a race. As you can see on the error log, ATS setup a tunnel to send POST data after sending a 502 response to the client. Obviously the tunnel is unnecessary, and this out of order setup messes up internal state and causes the assertion failure. I was able to reproduce the abort on 9.2.x and master, on my laptop with the setup below: Origin server (this immediately sends a broken response right after connection establishment) ``` $ echo HTTP | openssl s_server -accept 12345 -cert server.crt -key server.key ``` Remap ``` map / https://127.0.0.1:12345/ ``` Client (just sends a POST request) ``` $ curl -vk --limit-rate 1 --data-binary @file https://localhost:8443/ ``` Backtrace ``` (lldb) bt * thread #2, name = '[ET_NET 0]', stop reason = signal SIGABRT * frame #0: 0x000000018ea3ad98 libsystem_kernel.dylib`__pthread_kill + 8 frame #1: 0x000000018ea6fee0 libsystem_pthread.dylib`pthread_kill + 288 frame #2: 0x000000018e9aa340 libsystem_c.dylib`abort + 168 frame #3: 0x000000010518a938 libtscore.10.dylib`ink_abort(message_format="%s:%d: failed assertion `%s`") at ink_error.cc:99:3 frame #4: 0x000000010517fe4c libtscore.10.dylib`::_ink_assert(expression="ua_entry->in_tunnel == true", file="HttpSM.cc", line=3609) at ink_assert.cc:37:3 frame #5: 0x00000001003024c4 traffic_server`HttpSM::tunnel_handler_post_ua(this=0x0000000113eec800, event=105, p=0x0000000113eedad8) at HttpSM.cc:3609:5 frame #6: 0x00000001004e982c traffic_server`HttpTunnel::producer_handler(this=0x0000000113eed7b0, event=105, p=0x0000000113eedad8) at HttpTunnel.cc:1250:7 frame #7: 0x00000001004df7f4 traffic_server`HttpTunnel::main_handler(this=0x0000000113eed7b0, event=105, data=0x0000000113d8aaf0) at HttpTunnel.cc:1664:19 frame #8: 0x0000000100009538 traffic_server`Continuation::handleEvent(this=0x0000000113eed7b0, event=105, data=0x0000000113d8aaf0) at I_Continuation.h:227:12 frame #9: 0x00000001007b1abc traffic_server`Http2Stream::signal_read_event(this=0x0000000113d8a840, event=105) at Http2Stream.cc:726:26 frame #10: 0x00000001007af0e0 traffic_server`Http2Stream::main_event_handler(this=0x0000000113d8a840, event=105, edata=0x0000000109d0afc0) at Http2Stream.cc:175:13 frame #11: 0x0000000100009538 traffic_server`Continuation::handleEvent(this=0x0000000113d8a840, event=105, data=0x0000000109d0afc0) at I_Continuation.h:227:12 frame #12: 0x00000001007a7a2c traffic_server`ActivityCop<Http2Stream, DLL<Http2Stream, Continuation::Link_link> >::check_activity(this=0x0000000113483570, (null)=2, e=0x0000000109d0afc0) at NetTimeout.h:254:10 frame #13: 0x0000000100009538 traffic_server`Continuation::handleEvent(this=0x0000000113483570, event=2, data=0x0000000109d0afc0) at I_Continuation.h:227:12 frame #14: 0x00000001014b8f58 traffic_server`EThread::process_event(this=0x0000000109f04800, e=0x0000000109d0afc0, calling_code=2) at UnixEThread.cc:152:22 frame #15: 0x00000001014ba564 traffic_server`EThread::execute_regular(this=0x0000000109f04800) at UnixEThread.cc:258:11 frame #16: 0x00000001014bb93c traffic_server`EThread::execute(this=0x0000000109f04800) at UnixEThread.cc:337:11 frame #17: 0x00000001014b63e4 traffic_server`spawn_thread_internal(a=0x000000010782e040) at Thread.cc:79:12 frame #18: 0x000000018ea7026c libsystem_pthread.dylib`_pthread_start + 148 ``` Error log ``` [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:2617 (CallOSDNSLookup)> (http) [0] 127.0.0.1 [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:2631 (CallOSDNSLookup)> (http_trans) Next action SM_ACTION_DNS_LOOKUP; OSDNSLookup [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpSM.cc:7480 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_DNS_LOOKUP [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:1880 (OSDNSLookup)> (http_trans) [0] Entering HttpTransact::OSDNSLookup [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:1923 (OSDNSLookup)> (http_seq) [0] DNS Lookup successful [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:1962 (OSDNSLookup)> (http_trans) [0] DNS lookup for O.S. successful IP: 127.0.0.1 [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:2069 (HandleRequestAuthorized)> (http_trans) Next action SM_ACTION_API_OS_DNS; HttpTransact::DecideCacheLookup [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpSM.cc:7480 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:2148 (DecideCacheLookup)> (http_trans) [0] Will NOT do cache lookup. [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:2149 (DecideCacheLookup)> (http_seq) [0] Will NOT do cache lookup [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:2173 (DecideCacheLookup)> (http_trans) Next action SM_ACTION_API_CACHE_LOOKUP_COMPLETE; LookupSkipOpenServer [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpSM.cc:7480 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_OS_DNS -> SM_ACTION_API_CACHE_LOOKUP_COMPLETE [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:576 (find_server_and_update_current_info)> (http_trans) [0] request is from localhost, so bypass parent [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:5272 (add_client_ip_to_outgoing_request)> (http_trans) [0] client_ip_set = 0 [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:5282 (add_client_ip_to_outgoing_request)> (http_trans) [0] inserted request header 'Client-ip: 127.0.0.1' [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:5293 (add_client_ip_to_outgoing_request)> (http_trans) [0] Appended connecting client's (127.0.0.1) to the X-Forwards header [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:7750 (build_request)> (http_trans) [0] removing host name from url [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:7789 (build_request)> (http_trans) [0] request_sent_time: 1669963309 +++++++++ Proxy's Request +++++++++ -- State Machine Id: 0 POST / HTTP/1.1 User-Agent: curl/7.84.0-DEV Accept: */* Content-Length: 8388608 Content-Type: application/x-www-form-urlencoded Host: 127.0.0.1:12345 Client-ip: 127.0.0.1 X-Forwarded-For: 127.0.0.1 Via: https/2 traffic_server[7a87efcd-ab7a-49e2-b055-dcaeea5ee89e] (ApacheTrafficServer/10.0.0 [uSc ]) [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.cc:2206 (LookupSkipOpenServer)> (http_trans) Next action next; HttpTransact::HandleResponse [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpSM.cc:7480 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_ORIGIN_SERVER_OPEN [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpTransact.h:938 (set_connect_fail)> (http) Setting upstream connection failure 5 to 5 [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpSM.cc:4941 (do_http_server_open)> (http_track) [0] entered inside do_http_server_open ][ipv4] [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpSM.cc:4969 (do_http_server_open)> (http) [0] open connection to 127.0.0.1: 127.0.0.1:12345 [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpSM.cc:4971 (do_http_server_open)> (http_seq) [0] Sending request to server [Dec 1 23:41:49.400] [ET_NET 0] DEBUG: <HttpSessionManager.cc:403 (_acquire_session)> (http_ss) [acquire session] thread pool search failed [Dec 1 23:41:49.401] [ET_NET 0] DEBUG: <HttpSM.cc:5347 (do_http_server_open)> (http) [0] calling sslNetProcessor.connect_re [Dec 1 23:41:49.401] [ET_NET 0] DEBUG: <HttpSM.cc:2685 (main_handler)> (http) [0] NET_EVENT_OPEN/TS_EVENT_NET_CONNECT, 200 [Dec 1 23:41:49.401] [ET_NET 0] DEBUG: <HttpSM.cc:1880 (state_http_server_open)> (http_track) [0] entered inside state_http_server_open: NET_EVENT_OPEN/TS_EVENT_NET_CONNECT [Dec 1 23:41:49.401] [ET_NET 0] DEBUG: <HttpSM.cc:1881 (state_http_server_open)> (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT] [Dec 1 23:41:49.401] [ET_NET 0] DEBUG: <Http1ServerSession.cc:94 (new_connection)> (http_ss) [1] session born, netvc 0x1132db1f0 [Dec 1 23:41:49.401] [ET_NET 0] DEBUG: <HttpSM.cc:1910 (state_http_server_open)> (http) [0] setting handler for TCP handshake [Dec 1 23:41:49.401] [ET_NET 0] DEBUG: <Http2CommonSession.cc:250 (do_start_frame_read)> (http2_cs) [0] receiving frame header [Dec 1 23:41:49.401] [ET_NET 0] DEBUG: <Http2CommonSession.cc:267 (do_start_frame_read)> (http2_cs) [0] frame header length=1, type=0, flags=0x0, streamid=1 [Dec 1 23:41:49.401] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:88 (rcv_data_frame)> (http2_con) [0] [1] Received DATA frame [Dec 1 23:41:49.401] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:175 (rcv_data_frame)> (http2_con) [0] [1] Received DATA frame: rwnd con=65534/65535 stream=65534/65535 [Dec 1 23:41:49.401] [ET_NET 0] DEBUG: <HttpSM.cc:2685 (main_handler)> (http) [0] VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY, 100 [Dec 1 23:41:49.401] [ET_NET 0] DEBUG: <HttpSM.cc:995 (state_watch_for_client_abort)> (http) [0] [&HttpSM::state_watch_for_client_abort, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Dec 1 23:41:49.406] [ET_NET 0] WARNING: Core server certificate verification failed for (127.0.0.1). Action=Continue Error=self signed certificate server=127.0.0.1(127.0.0.1) depth=0 [Dec 1 23:41:49.406] [ET_NET 0] WARNING: SNI (127.0.0.1) not in certificate. Action=Continue server=127.0.0.1(127.0.0.1) [Dec 1 23:41:49.407] [ET_NET 0] DEBUG: <HttpSM.cc:2685 (main_handler)> (http) [0] VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE, 102 [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpSM.cc:1880 (state_http_server_open)> (http_track) [0] entered inside state_http_server_open: VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpSM.cc:1881 (state_http_server_open)> (http) [0] [&HttpSM::state_http_server_open, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE] [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpSM.cc:1934 (state_http_server_open)> (http_ss) [0] TCP Handshake complete +++++++++ Proxy's Request after hooks +++++++++ -- State Machine Id: 0 POST / HTTP/1.1 User-Agent: curl/7.84.0-DEV Accept: */* Content-Length: 8388608 Content-Type: application/x-www-form-urlencoded Host: 127.0.0.1:12345 Client-ip: 127.0.0.1 X-Forwarded-For: 127.0.0.1 Via: https/2 traffic_server[7a87efcd-ab7a-49e2-b055-dcaeea5ee89e] (ApacheTrafficServer/10.0.0 [uSc ]) [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpSM.cc:6340 (setup_server_read_response_header)> (http) [0] Setting up the header read [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpSM.cc:2685 (main_handler)> (http) [0] VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY, 100 [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpSM.cc:2003 (state_read_server_response_header)> (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpSM.cc:2102 (state_read_server_response_header)> (http_seq) [0] Error parsing server response header [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTransact.cc:3411 (HandleResponse)> (http_trans) [0] Entering HttpTransact::HandleResponse [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTransact.cc:3412 (HandleResponse)> (http_seq) [0] Response received [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTransact.cc:3419 (HandleResponse)> (http_trans) [0] response_received_time: 1669963309 +++++++++ Incoming O.S. Response +++++++++ -- State Machine Id: 0 HTTP/1.0 0 [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTransact.cc:3434 (HandleResponse)> (http_seq) [0] Response not valid [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTransact.cc:3724 (handle_response_from_server)> (http_trans) [0] (hrfs) [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTransact.cc:3762 (handle_response_from_server)> (http_trans) [0] max_connect_retries: 0 s->current.attempts: 0 [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTransact.cc:3813 (error_log_connection_failure)> (http_trans) [0] [0] failed to connect [8] to 127.0.0.1 [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTransact.cc:3789 (handle_response_from_server)> (http_trans) [0] Error. No more retries. [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTransact.cc:3883 (handle_server_connection_not_open)> (http_trans) [0] (hscno) [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTransact.cc:3884 (handle_server_connection_not_open)> (http_seq) [0] Entering HttpTransact::handle_server_connection_not_open [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTransactHeaders.cc:1165 (add_server_header_to_response)> (http_trans) Adding Server: ATS/10.0.0 +++++++++ Proxy's Response 2 +++++++++ -- State Machine Id: 0 HTTP/1.1 502 Invalid HTTP Response Date: Fri, 02 Dec 2022 06:41:49 GMT Via: https/1.1 traffic_server (ApacheTrafficServer/10.0.0 [c sEf ]) Server: ATS/10.0.0 [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpSM.cc:7480 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_SEND_ERROR_CACHE_NOOP [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTunnel.cc:626 (add_producer)> (http_tunnel) [0] adding producer 'internal msg' [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTunnel.cc:681 (add_consumer)> (http_tunnel) [0] adding consumer 'user agent' [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <HttpTunnel.cc:728 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided [Dec 1 23:41:49.408] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1765 (send_headers_frame)> (http2_con) [0] [1] Send HEADERS frame [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <Http2Stream.cc:380 (change_state)> (http2_stream) [0] [1] Http2StreamState::HTTP2_STREAM_STATE_OPEN -> Http2StreamState::HTTP2_STREAM_STATE_OPEN [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1711 (send_a_data_frame)> (http2_con) [0] [1] Send a DATA frame - client window con: 33554177 stream: 33554177 payload: 255 [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1717 (send_a_data_frame)> (http2_con) [0] [1] END_STREAM [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <Http2Stream.cc:380 (change_state)> (http2_stream) [0] [1] Http2StreamState::HTTP2_STREAM_STATE_OPEN -> Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_LOCAL [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1750 (send_data_frames)> (http2_con) [0] [1] Shutdown stream [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <Http2Stream.cc:503 (initiating_close)> (http2_stream) [0] [1] initiating_close [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <Http2Stream.cc:530 (initiating_close)> (http2_stream) [0] [1] handle write from destroy (event=103) [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <HttpSM.cc:2685 (main_handler)> (http) [0] VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE, 103 [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <HttpSM.cc:2175 (state_send_server_request_header)> (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <HttpTunnel.cc:626 (add_producer)> (http_tunnel) [0] adding producer 'user agent post' [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <HttpTunnel.cc:681 (add_consumer)> (http_tunnel) [0] adding consumer 'http server post' [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <HttpTunnel.cc:728 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <HttpTunnel.cc:1344 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <HttpTunnel.cc:1344 (consumer_handler)> (http_tunnel) [0] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Dec 1 23:41:49.409] [ET_NET 0] DEBUG: <HttpSM.cc:3310 (tunnel_handler_ua)> (http) [0] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Dec 1 23:41:50.392] [ET_NET 0] DEBUG: <Http2CommonSession.cc:236 (state_start_frame_read)> (http2_cs) [0] [&Http2CommonSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Dec 1 23:41:50.393] [ET_NET 0] DEBUG: <Http2CommonSession.cc:250 (do_start_frame_read)> (http2_cs) [0] receiving frame header [Dec 1 23:41:50.393] [ET_NET 0] DEBUG: <Http2CommonSession.cc:267 (do_start_frame_read)> (http2_cs) [0] frame header length=0, type=4, flags=0x1, streamid=0 [Dec 1 23:41:50.393] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:570 (rcv_settings_frame)> (http2_con) [0] [0] Received SETTINGS frame [Dec 1 23:41:50.393] [ET_NET 0] DEBUG: <Http2CommonSession.cc:250 (do_start_frame_read)> (http2_cs) [0] receiving frame header [Dec 1 23:41:50.394] [ET_NET 0] DEBUG: <Http2CommonSession.cc:267 (do_start_frame_read)> (http2_cs) [0] frame header length=1, type=0, flags=0x0, streamid=1 [Dec 1 23:41:50.394] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:88 (rcv_data_frame)> (http2_con) [0] [1] Received DATA frame [Dec 1 23:41:50.394] [ET_NET 0] ERROR: HTTP/2 stream error code=0x05 client_ip=127.0.0.1 session_id=0 stream_id=1 recv data stream closed [Dec 1 23:41:50.394] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1936 (send_rst_stream_frame)> (http2_con) [0] [1] Send RST_STREAM frame [Dec 1 23:41:51.392] [ET_NET 0] DEBUG: <Http2CommonSession.cc:236 (state_start_frame_read)> (http2_cs) [0] [&Http2CommonSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Dec 1 23:41:51.392] [ET_NET 0] DEBUG: <Http2CommonSession.cc:250 (do_start_frame_read)> (http2_cs) [0] receiving frame header [Dec 1 23:41:51.392] [ET_NET 0] DEBUG: <Http2CommonSession.cc:267 (do_start_frame_read)> (http2_cs) [0] frame header length=0, type=0, flags=0x1, streamid=1 [Dec 1 23:41:51.393] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:88 (rcv_data_frame)> (http2_con) [0] [1] Received DATA frame [Dec 1 23:41:51.393] [ET_NET 0] ERROR: HTTP/2 stream error code=0x05 client_ip=127.0.0.1 session_id=0 stream_id=1 recv data stream closed [Dec 1 23:41:51.393] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1936 (send_rst_stream_frame)> (http2_con) [0] [1] Send RST_STREAM frame [Dec 1 23:41:51.394] [ET_NET 0] DEBUG: <Http2ClientSession.cc:196 (main_event_handler)> (http2_cs) [0] Closing event 104 [Dec 1 23:41:51.394] [ET_NET 0] DEBUG: <Http2ClientSession.cc:148 (do_io_close)> (http2_cs) [0] session closed [Dec 1 23:42:20.345] [ET_NET 0] DEBUG: <HttpTunnel.cc:1134 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Dec 1 23:42:20.346] [ET_NET 0] DEBUG: <HttpTunnel.cc:1178 (producer_handler)> (http_redirect) [0] enable_redirection: [1 0 0] event: 105, state: 0 [Dec 1 23:42:20.346] [ET_NET 0] DEBUG: <HttpSM.cc:3575 (tunnel_handler_post_ua)> (http) [0] [&HttpSM::tunnel_handler_post_ua, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Dec 1 23:42:20.346] [ET_NET 0] DEBUG: <Http1ServerSession.cc:121 (do_io_close)> (http_ss) [1] session close: nevtc 0x1132db1f0 [Dec 1 23:42:20.346] [ET_NET 0] ERROR: [0] ------- begin http state dump ------- [Dec 1 23:42:20.346] [ET_NET 0] ERROR: 100 2 HttpSM.cc:696 (state_read_client_request_header) [Dec 1 23:42:20.346] [ET_NET 0] ERROR: 100 1 HttpSM.cc:696 (state_read_client_request_header) [Dec 1 23:42:20.347] [ET_NET 0] ERROR: 60000 2 HttpSM.cc:1453 (state_api_callback) [Dec 1 23:42:20.347] [ET_NET 0] ERROR: 60000 2 HttpSM.cc:1493 (state_api_callout) [Dec 1 23:42:20.347] [ET_NET 0] ERROR: 60000 3 HttpSM.cc:1453 (state_api_callback) [Dec 1 23:42:20.347] [ET_NET 0] ERROR: 60000 3 HttpSM.cc:1493 (state_api_callout) [Dec 1 23:42:20.347] [ET_NET 0] ERROR: 34463 3 HttpSM.cc:7630 (set_next_state) [Dec 1 23:42:20.348] [ET_NET 0] ERROR: 200 4 HttpSM.cc:1881 (state_http_server_open) [Dec 1 23:42:20.348] [ET_NET 0] ERROR: 100 1 HttpSM.cc:995 (state_watch_for_client_abort) [Dec 1 23:42:20.349] [ET_NET 0] ERROR: 102 1 HttpSM.cc:1881 (state_http_server_open) [Dec 1 23:42:20.349] [ET_NET 0] ERROR: 100 1 HttpSM.cc:2003 (state_read_server_response_header) [Dec 1 23:42:20.349] [ET_NET 0] ERROR: 34463 1 HttpSM.cc:6619 (setup_internal_transfer) [Dec 1 23:42:20.349] [ET_NET 0] ERROR: 103 1 HttpSM.cc:2175 (state_send_server_request_header) [Dec 1 23:42:20.349] [ET_NET 0] ERROR: 34463 1 HttpSM.cc:5991 (do_setup_post_tunnel) [Dec 1 23:42:20.349] [ET_NET 0] ERROR: 103 0 HttpSM.cc:3310 (tunnel_handler_ua) [Dec 1 23:42:20.350] [ET_NET 0] ERROR: 105 0 HttpSM.cc:3575 (tunnel_handler_post_ua) [Dec 1 23:42:20.350] [ET_NET 0] ERROR: Via String: [uSc sEf p eC:tOc p sF] [Dec 1 23:42:20.350] [ET_NET 0] ERROR: ---- Client Request [0] ---- POST https://127.0.0.1:12345/ HTTP/1.1 User-Agent: curl/7.84.0-DEV Accept: */* Content-Length: 8388608 Content-Type: application/x-www-form-urlencoded Host: 127.0.0.1:12345 [Dec 1 23:42:20.350] [ET_NET 0] ERROR: ---- Server Request [0] ---- POST / HTTP/1.1 User-Agent: curl/7.84.0-DEV Accept: */* Content-Length: 8388608 Content-Type: application/x-www-form-urlencoded Host: 127.0.0.1:12345 Client-ip: 127.0.0.1 X-Forwarded-For: 127.0.0.1 Via: https/2 traffic_server[7a87efcd-ab7a-49e2-b055-dcaeea5ee89e] (ApacheTrafficServer/10.0.0 [uSc ]) [Dec 1 23:42:20.350] [ET_NET 0] ERROR: ---- Server Response [0] ---- HTTP/1.0 0 ?? [Dec 1 23:42:20.350] [ET_NET 0] ERROR: ---- Client Response [0] ---- HTTP/1.1 502 Invalid HTTP Response Date: Fri, 02 Dec 2022 06:41:49 GMT Via: https/1.1 traffic_server (ApacheTrafficServer/10.0.0 [c sEf ]) Server: ATS/10.0.0 Cache-Control: no-store Content-Type: text/html Content-Language: en Content-Length: 255 [Dec 1 23:42:20.350] [ET_NET 0] ERROR: [0] ------- end http state dump --------- Fatal: HttpSM.cc:3609: failed assertion `ua_entry->in_tunnel == true` 2022-12-01 23:42:20.350593-0700 traffic_server[19811:1520381] Fatal: HttpSM.cc:3609: failed assertion `ua_entry->in_tunnel == true` ``` -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
