trafficserver icon indicating copy to clipboard operation
trafficserver copied to clipboard
verified publisher icon apache

Assertion failure in HttpSM::tunnel_handler_post_ua

Open maskit opened this issue 3 years ago • 2 comments

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`

maskit avatar Dec 02 '22 18:12 maskit

I've created an AuTest that seems to reproduce this issue: https://github.com/bneradt/trafficserver/tree/add_autest_for_issue_9229

The test is structured like slow_post.test.py and has an ad-hoc Python3 origin configured to act like the origin @maskit described above. That is, the origin replies "early" to a request without waiting for the full response to come in.

FWIW: the crash this test is reproducing requires the origin to close the connection before the request is finished being sent by the proxy. That is, the origin both sends an early response, and then it closes the connection early.

bneradt avatar Dec 12 '22 17:12 bneradt

This issue 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[bot] avatar Dec 13 '23 01:12 github-actions[bot]

I can't reproduce the assertion failure on the latest master. It might have been fixed by some changes.

maskit avatar Jul 02 '24 20:07 maskit