masaori335 opened a new issue #7603: URL: https://github.com/apache/trafficserver/issues/7603
It looks like when an HTTP/1.1 client aborts, HttpTunnel stops working. OTOH, if the client uses HTTP/2, the cache is filled. # HTTP/1.1 ## Client Origin server tasks 10 seconds to send the whole response body, but the client aborts after 2 seconds. ``` timeout 2 curl --http1.1 -vk -o /dev/null https://127.0.0.1:4443/httpbin/drip\?duration\=10 ``` ## ATS It looks like the `EOS` event is signaled to HttpSM directly and HttpTunnel is killed. <details> <summary>ATS Debug Log with HTTP/1.1</summary> ``` ... [Mar 16 10:33:55.338] [ET_NET 6] DEBUG: <HttpSM.cc:6725 (setup_server_transfer)> (http) Setup Server Transfer [Mar 16 10:33:55.338] [ET_NET 6] DEBUG: <HttpTunnel.cc:596 (add_producer)> (http_tunnel) [9] adding producer 'http server' [Mar 16 10:33:55.338] [ET_NET 6] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [9] adding consumer 'user agent' [Mar 16 10:33:55.338] [ET_NET 6] DEBUG: <HttpSM.cc:5971 (perform_cache_write_action)> (http) [9] perform_cache_write_action CACHE_DO_WRITE [Mar 16 10:33:55.338] [ET_NET 6] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [9] adding consumer 'cache write' [Mar 16 10:33:55.338] [ET_NET 6] DEBUG: <HttpTunnel.cc:698 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided [Mar 16 10:33:55.338] [ET_NET 6] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [9] consumer_handler [user agent VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:33:55.338] [ET_NET 6] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [9] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:33:56.408] [ET_NET 6] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [9] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Mar 16 10:33:56.408] [ET_NET 6] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0 [Mar 16 10:33:56.409] [ET_NET 6] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [9] consumer_handler [user agent VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:33:56.409] [ET_NET 6] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [9] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:33:57.308] [ET_NET 6] DEBUG: <HttpSM.cc:2669 (main_handler)> (http) [9] [HttpSM::main_handler, VC_EVENT_EOS/TS_EVENT_VCONN_EOS] [Mar 16 10:33:57.308] [ET_NET 6] DEBUG: <HttpSM.cc:964 (state_watch_for_client_abort)> (http) [9] [&HttpSM::state_watch_for_client_abort, VC_EVENT_EOS/TS_EVENT_VCONN_EOS] [Mar 16 10:33:57.308] [ET_NET 6] DEBUG: <Http1ClientSession.cc:255 (do_io_close)> (http_cs) [17] session closed [Mar 16 10:33:57.308] [ET_NET 6] DEBUG: <Http1ServerSession.cc:138 (do_io_close)> (http_ss) [18] session close: nevtc 0x7ff038494d50 [Mar 16 10:33:57.308] [ET_NET 6] DEBUG: <HttpSM.cc:8318 (clear)> (http_redirect) [PostDataBuffers::clear] [Mar 16 10:33:57.308] [ET_NET 6] DEBUG: <HttpSM.cc:7066 (kill_this)> (http_seq) [HttpSM::update_stats] Logging transaction [Mar 16 10:33:57.308] [ET_NET 6] DEBUG: <Http1ClientSession.cc:73 (destroy)> (http_cs) [17] session destroy [Mar 16 10:33:57.308] [ET_NET 6] DEBUG: <HttpSM.cc:7110 (kill_this)> (http) [9] deallocating sm ``` </details> # HTTP/2 ## Client ``` timeout 2 curl --http2 -vk -o /dev/null https://127.0.0.1:4443/httpbin/drip\?duration\=10 ``` ## ATS HttpTunnel keeps filling cache after Http2Stream sent the `EOS` event. ( HTTP/2 connection and stream are destroyed after filling the cache, this is another issue. ) <details> <summary>ATS Debug Log with HTTP/2</summary> ``` ... [Mar 16 10:48:13.668] [ET_NET 15] DEBUG: <HttpSM.cc:6725 (setup_server_transfer)> (http) Setup Server Transfer [Mar 16 10:48:13.668] [ET_NET 15] DEBUG: <HttpTunnel.cc:596 (add_producer)> (http_tunnel) [18] adding producer 'http server' [Mar 16 10:48:13.668] [ET_NET 15] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [18] adding consumer 'user agent' [Mar 16 10:48:13.668] [ET_NET 15] DEBUG: <HttpSM.cc:5971 (perform_cache_write_action)> (http) [18] perform_cache_write_action CACHE_DO_WRITE [Mar 16 10:48:13.668] [ET_NET 15] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [18] adding consumer 'cache write' [Mar 16 10:48:13.668] [ET_NET 15] DEBUG: <HttpTunnel.cc:698 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided [Mar 16 10:48:13.668] [ET_NET 15] DEBUG: <Http2ConnectionState.cc:1640 (send_headers_frame)> (http2_con) [31] [1] Send HEADERS frame [Mar 16 10:48:13.668] [ET_NET 15] DEBUG: <Http2ConnectionState.cc:1584 (send_a_data_frame)> (http2_con) [31] [1] Send a DATA frame - client window con: 1073741823 stream: 1073741823 payload: 1 [Mar 16 10:48:13.668] [ET_NET 15] DEBUG: <Http2ConnectionState.cc:1569 (send_a_data_frame)> (http2_con) [31] [1] No payload [Mar 16 10:48:13.668] [ET_NET 15] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [18] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:48:13.668] [ET_NET 15] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [18] consumer_handler [user agent VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:48:14.740] [ET_NET 15] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [18] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Mar 16 10:48:14.740] [ET_NET 15] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0 [Mar 16 10:48:14.740] [ET_NET 15] DEBUG: <Http2ConnectionState.cc:1584 (send_a_data_frame)> (http2_con) [31] [1] Send a DATA frame - client window con: 1073741822 stream: 1073741822 payload: 1 [Mar 16 10:48:14.740] [ET_NET 15] DEBUG: <Http2ConnectionState.cc:1569 (send_a_data_frame)> (http2_con) [31] [1] No payload [Mar 16 10:48:14.740] [ET_NET 15] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [18] consumer_handler [user agent VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:48:14.740] [ET_NET 15] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [18] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:48:15.647] [ET_NET 15] DEBUG: <Http2ClientSession.cc:330 (main_event_handler)> (http2_cs) [31] Closing event 104 [Mar 16 10:48:15.647] [ET_NET 15] DEBUG: <Http2ClientSession.cc:239 (do_io_close)> (http2_cs) [31] session closed [Mar 16 10:48:15.647] [ET_NET 15] DEBUG: <Http2Stream.cc:496 (initiating_close)> (http2_stream) [31] [1] initiating_close [Mar 16 10:48:15.647] [ET_NET 15] DEBUG: <Http2Stream.cc:527 (initiating_close)> (http2_stream) [31] [1] handle write from destroy (event=104) [Mar 16 10:48:15.647] [ET_NET 15] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [18] consumer_handler [user agent VC_EVENT_EOS/TS_EVENT_VCONN_EOS] [Mar 16 10:48:15.647] [ET_NET 15] DEBUG: <HttpSM.cc:3294 (tunnel_handler_ua)> (http) [18] [&HttpSM::tunnel_handler_ua, VC_EVENT_EOS/TS_EVENT_VCONN_EOS] [Mar 16 10:48:15.647] [ET_NET 15] DEBUG: <HttpSM.cc:3313 (tunnel_handler_ua)> (http) [18] Initiating background fill [Mar 16 10:48:15.813] [ET_NET 15] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [18] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Mar 16 10:48:15.813] [ET_NET 15] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0 [Mar 16 10:48:15.813] [ET_NET 15] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [18] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:48:16.888] [ET_NET 15] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [18] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Mar 16 10:48:16.888] [ET_NET 15] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0 [Mar 16 10:48:16.888] [ET_NET 15] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [18] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:48:17.961] [ET_NET 15] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [18] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Mar 16 10:48:17.961] [ET_NET 15] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0 [Mar 16 10:48:17.961] [ET_NET 15] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [18] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:48:19.035] [ET_NET 15] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [18] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Mar 16 10:48:19.035] [ET_NET 15] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0 [Mar 16 10:48:19.035] [ET_NET 15] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [18] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:48:20.106] [ET_NET 15] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [18] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Mar 16 10:48:20.106] [ET_NET 15] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0 [Mar 16 10:48:20.106] [ET_NET 15] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [18] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:48:21.179] [ET_NET 15] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [18] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Mar 16 10:48:21.179] [ET_NET 15] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0 [Mar 16 10:48:21.179] [ET_NET 15] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [18] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:48:22.253] [ET_NET 15] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [18] producer_handler [http server VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Mar 16 10:48:22.253] [ET_NET 15] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 0 [Mar 16 10:48:22.253] [ET_NET 15] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [18] consumer_handler [cache write VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY] [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [18] producer_handler [http server VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE] [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 102, state: 0 [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <HttpSM.cc:3010 (tunnel_handler_server)> (http) [18] [&HttpSM::tunnel_handler_server, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE] [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <Http1ServerSession.cc:138 (do_io_close)> (http_ss) [32] session close: nevtc 0x7ff038496430 [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [18] consumer_handler [cache write VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <HttpSM.cc:3504 (tunnel_handler_cache_write)> (http) [18] [&HttpSM::tunnel_handler_cache_write, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE] [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <HttpSM.cc:2669 (main_handler)> (http) [18] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE] [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <HttpSM.cc:2959 (tunnel_handler)> (http) [18] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE] [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <HttpSM.cc:8318 (clear)> (http_redirect) [PostDataBuffers::clear] [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <HttpSM.cc:7066 (kill_this)> (http_seq) [HttpSM::update_stats] Logging transaction [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <Http2Stream.cc:68 (~Http2Stream)> (http2_stream) [31] [1] Destroy stream, sent 2 bytes [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <Http2ConnectionState.cc:1371 (delete_stream)> (http2_con) [31] [1] Delete stream [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <Http2ClientSession.cc:78 (destroy)> (http2_cs) [31] session destroy [Mar 16 10:48:23.327] [ET_NET 15] DEBUG: <Http2ClientSession.cc:106 (free)> (http2_cs) [31] session free [Mar 16 10:48:23.329] [ET_NET 15] DEBUG: <HttpSM.cc:7110 (kill_this)> (http) [18] deallocating sm ``` </details> # Affected version I saw this behavior with 8.1.x and master. ---------------------------------------------------------------- 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]
