shinrich edited a comment on pull request #7237: URL: https://github.com/apache/trafficserver/pull/7237#issuecomment-704299762
@masaori335 and I have been trying to augment h2spec to reproduce the problem I was seeing in our production. We are applying patches to https://github.com/summerwind/h2spec. And then running some variant of "./h2spec -h localhost -p 4443 -P "/post" -t -k http2/8.1.2.6/3" against our traffic_server with the appropriate remap rule for the URL. I had my config remap /post to https://httpbin.org/post. @masaori335's original patch is attached as no-eos.txt. With this patch, ATS processed the no-eos's POST request and returned a response. The Post tunnel followed the pre-complete path. All of the data had been read from the client before the tunnel run started. So the producer was marked as completed and the consumer read all the data and the server returned a response. However after a while (10-30 seconds), ATS crashes with an inactivity timeout triggers on a HttpTunnel continuation which belongs to a deleted HttpSM. But then I realized I had my config set to debug another issue. With that fixed, no crash. So I added a 2 second delay between sending the request header and sending the data. That avoided the pre-complete, so the tunnel got into the state of an active producer but a completed consumer. However the h2spec client shutdown shortly there after. So the client EOS was processed before any timeout occurred. Then I added a 10 second delay between sending the post data and processing the response. This allowed the default inactivity timeout to trigger (which I had set to 10 seconds) to trigger. The client exited after one iteration of the time out, but by that time ATS continued iterating every 10 seconds on state_send_server_request_header and handle_server_setup_error. My final version of the patch is attached in no-eos-delays.txt ``` [Oct 6 14:32:31.180] [ET_NET 14] DEBUG: <HttpSM.cc:1835 (state_http_server_open)> (http_ss) [2] TCP Handshake complete +++++++++ Proxy's Request after hooks +++++++++ -- State Machine Id: 2 POST /post HTTP/1.1 Content-Length: 4000 Host: httpbin.org Client-ip: 127.0.0.1 X-Forwarded-For: 127.0.0.1 Via: https/2 traffic_server[eaf1cc17-5d00-4e02-909d-5a20c6d923bb] (ApacheTrafficServer/10.0.0) [Oct 6 14:32:31.180] [ET_NET 14] DEBUG: <HttpSM.cc:2636 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Oct 6 14:32:31.180] [ET_NET 14] DEBUG: <HttpSM.cc:2056 (state_send_server_request_header)> (http) [2] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Oct 6 14:32:31.180] [ET_NET 14] DEBUG: <HttpTunnel.cc:595 (add_producer)> (http_tunnel) [2] adding producer 'user agent post' [Oct 6 14:32:31.180] [ET_NET 14] DEBUG: <HttpTunnel.cc:650 (add_consumer)> (http_tunnel) [2] adding consumer 'http server post' [Oct 6 14:32:31.180] [ET_NET 14] DEBUG: <HttpTunnel.cc:697 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided [Oct 6 14:32:31.180] [ET_NET 14] DEBUG: <HttpTunnel.cc:1307 (consumer_handler)> (http_tunnel) [2] consumer_handler [http server post VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Oct 6 14:32:33.035] [ET_NET 14] DEBUG: <Http2ClientSession.cc:457 (state_start_frame_read)> (http2_cs) [2] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Oct 6 14:32:33.035] [ET_NET 14] DEBUG: <Http2ClientSession.cc:471 (do_start_frame_read)> (http2_cs) [2] receiving frame header [Oct 6 14:32:33.035] [ET_NET 14] DEBUG: <Http2ClientSession.cc:488 (do_start_frame_read)> (http2_cs) [2] frame header length=1000, type=0, flags=0x0, streamid=1 [Oct 6 14:32:33.035] [ET_NET 14] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [2] [1] Received DATA frame [Oct 6 14:32:33.035] [ET_NET 14] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [2] [1] Received DATA frame: rwnd con=64535/65535 stream=64535/65535 [Oct 6 14:32:33.035] [ET_NET 14] DEBUG: <HttpTunnel.cc:1101 (producer_handler)> (http_tunnel) [2] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Oct 6 14:32:33.036] [ET_NET 14] DEBUG: <HttpTunnel.cc:1145 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0 [Oct 6 14:32:33.036] [ET_NET 14] DEBUG: <Http2ClientSession.cc:471 (do_start_frame_read)> (http2_cs) [2] receiving frame header [Oct 6 14:32:33.036] [ET_NET 14] DEBUG: <Http2ClientSession.cc:488 (do_start_frame_read)> (http2_cs) [2] frame header length=1000, type=0, flags=0x0, streamid=1 [Oct 6 14:32:33.036] [ET_NET 14] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [2] [1] Received DATA frame [Oct 6 14:32:33.036] [ET_NET 14] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [2] [1] Received DATA frame: rwnd con=63535/65535 stream=63535/65535 [Oct 6 14:32:33.036] [ET_NET 14] DEBUG: <HttpTunnel.cc:1101 (producer_handler)> (http_tunnel) [2] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Oct 6 14:32:33.036] [ET_NET 14] DEBUG: <HttpTunnel.cc:1145 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0 [Oct 6 14:32:33.036] [ET_NET 14] DEBUG: <Http2ClientSession.cc:471 (do_start_frame_read)> (http2_cs) [2] receiving frame header [Oct 6 14:32:33.036] [ET_NET 14] DEBUG: <Http2ClientSession.cc:488 (do_start_frame_read)> (http2_cs) [2] frame header length=1000, type=0, flags=0x0, streamid=1 [Oct 6 14:32:33.036] [ET_NET 14] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [2] [1] Received DATA frame [Oct 6 14:32:33.036] [ET_NET 14] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [2] [1] Received DATA frame: rwnd con=62535/65535 stream=62535/65535 [Oct 6 14:32:33.036] [ET_NET 14] DEBUG: <HttpTunnel.cc:1101 (producer_handler)> (http_tunnel) [2] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Oct 6 14:32:33.037] [ET_NET 14] DEBUG: <HttpTunnel.cc:1145 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0 [Oct 6 14:32:33.037] [ET_NET 14] DEBUG: <Http2ClientSession.cc:471 (do_start_frame_read)> (http2_cs) [2] receiving frame header [Oct 6 14:32:33.037] [ET_NET 14] DEBUG: <Http2ClientSession.cc:488 (do_start_frame_read)> (http2_cs) [2] frame header length=1000, type=0, flags=0x0, streamid=1 [Oct 6 14:32:33.037] [ET_NET 14] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [2] [1] Received DATA frame [Oct 6 14:32:33.037] [ET_NET 14] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [2] [1] Received DATA frame: rwnd con=61535/65535 stream=61535/65535 [Oct 6 14:32:33.037] [ET_NET 14] DEBUG: <HttpTunnel.cc:1101 (producer_handler)> (http_tunnel) [2] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Oct 6 14:32:33.037] [ET_NET 14] DEBUG: <HttpTunnel.cc:1145 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0 [Oct 6 14:32:33.037] [ET_NET 14] DEBUG: <HttpTunnel.cc:1307 (consumer_handler)> (http_tunnel) [2] consumer_handler [http server post VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Oct 6 14:32:33.037] [ET_NET 14] DEBUG: <HttpSM.cc:3611 (tunnel_handler_post_server)> (http) [2] [&HttpSM::tunnel_handler_post_server, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Oct 6 14:32:55.035] [ET_NET 14] DEBUG: <Http2ClientSession.cc:349 (main_event_handler)> (http2_cs) [2] Closing event 104 [Oct 6 14:32:55.036] [ET_NET 14] DEBUG: <Http2ClientSession.cc:276 (do_io_close)> (http2_cs) [2] session closed [Oct 6 14:32:55.036] [ET_NET 14] DEBUG: <Http2Stream.cc:421 (initiating_close)> (http2_stream) [2] [1] initiating_close [Oct 6 14:32:55.036] [ET_NET 14] DEBUG: <Http2Stream.cc:448 (initiating_close)> (http2_stream) [2] [1] handle write from destroy (event=103) [Oct 6 14:33:03.074] [ET_NET 14] DEBUG: <HttpSM.cc:2636 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:03.075] [ET_NET 14] DEBUG: <HttpSM.cc:2056 (state_send_server_request_header)> (http) [2] [&HttpSM::state_send_server_request_header, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:03.075] [ET_NET 14] DEBUG: <HttpSM.cc:5606 (handle_server_setup_error)> (http) [2] [&HttpSM::handle_server_setup_error, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:03.075] [ET_NET 14] DEBUG: <HttpSM.cc:5616 (handle_server_setup_error)> (http) [2] [handle_server_setup_error] forwarding event VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT to post tunnel [Oct 6 14:33:14.077] [ET_NET 14] DEBUG: <HttpSM.cc:2636 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:14.077] [ET_NET 14] DEBUG: <HttpSM.cc:2056 (state_send_server_request_header)> (http) [2] [&HttpSM::state_send_server_request_header, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:14.077] [ET_NET 14] DEBUG: <HttpSM.cc:5606 (handle_server_setup_error)> (http) [2] [&HttpSM::handle_server_setup_error, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:14.077] [ET_NET 14] DEBUG: <HttpSM.cc:5616 (handle_server_setup_error)> (http) [2] [handle_server_setup_error] forwarding event VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT to post tunnel [Oct 6 14:33:25.076] [ET_NET 14] DEBUG: <HttpSM.cc:2636 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:25.076] [ET_NET 14] DEBUG: <HttpSM.cc:2056 (state_send_server_request_header)> (http) [2] [&HttpSM::state_send_server_request_header, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:25.076] [ET_NET 14] DEBUG: <HttpSM.cc:5606 (handle_server_setup_error)> (http) [2] [&HttpSM::handle_server_setup_error, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:25.076] [ET_NET 14] DEBUG: <HttpSM.cc:5616 (handle_server_setup_error)> (http) [2] [handle_server_setup_error] forwarding event VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT to post tunnel [Oct 6 14:33:37.073] [ET_NET 14] DEBUG: <HttpSM.cc:2636 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:37.073] [ET_NET 14] DEBUG: <HttpSM.cc:2056 (state_send_server_request_header)> (http) [2] [&HttpSM::state_send_server_request_header, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:37.074] [ET_NET 14] DEBUG: <HttpSM.cc:5606 (handle_server_setup_error)> (http) [2] [&HttpSM::handle_server_setup_error, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:37.074] [ET_NET 14] DEBUG: <HttpSM.cc:5616 (handle_server_setup_error)> (http) [2] [handle_server_setup_error] forwarding event VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT to post tunnel [Oct 6 14:33:48.075] [ET_NET 14] DEBUG: <HttpSM.cc:2636 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:48.076] [ET_NET 14] DEBUG: <HttpSM.cc:2056 (state_send_server_request_header)> (http) [2] [&HttpSM::state_send_server_request_header, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:48.076] [ET_NET 14] DEBUG: <HttpSM.cc:5606 (handle_server_setup_error)> (http) [2] [&HttpSM::handle_server_setup_error, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:48.076] [ET_NET 14] DEBUG: <HttpSM.cc:5616 (handle_server_setup_error)> (http) [2] [handle_server_setup_error] forwarding event VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT to post tunnel [Oct 6 14:33:59.075] [ET_NET 14] DEBUG: <HttpSM.cc:2636 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:59.075] [ET_NET 14] DEBUG: <HttpSM.cc:2056 (state_send_server_request_header)> (http) [2] [&HttpSM::state_send_server_request_header, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:59.075] [ET_NET 14] DEBUG: <HttpSM.cc:5606 (handle_server_setup_error)> (http) [2] [&HttpSM::handle_server_setup_error, VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT] [Oct 6 14:33:59.075] [ET_NET 14] DEBUG: <HttpSM.cc:5616 (handle_server_setup_error)> (http) [2] [handle_server_setup_error] forwarding event VC_EVENT_INACTIVITY_TIMEOUT/TS_EVENT_VCONN_INACTIVITY_TIMEOUT to post tunnel ``` [no-eos.txt](https://github.com/apache/trafficserver/files/5334394/no-eos.txt) [no-eos-delays.txt](https://github.com/apache/trafficserver/files/5334396/no-eos-delays.txt) ---------------------------------------------------------------- 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. For queries about this service, please contact Infrastructure at: [email protected]
