background_fill is broken with HTTP/1.1 over TLS

[masaori335]

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.

ATS Debug Log with HTTP/1.1

...
[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

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. )

ATS Debug Log with HTTP/2

...
[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

Affected version

• HTTP/1.1 over TLS: 7.1.5+
• HTTP/1.1 over TCP: 8.0.0+ (with setting CONFIG proxy.config.http.allow_half_open INT 0)

[masaori335]

I found the background fill works on HTTP/1.1 over TCP with the default config, but it stops filling cache if I set CONFIG proxy.config.http.allow_half_open INT 0.

For HTTP/1.1, ua_txn->allow_half_open() is the knob of killing tunnel (background fill) or not.

• HTTP/1.1 over TCP: configured by the proxy.config.http.allow_half_open
• HTTP/1.1 over TLS: it always returns false
  

  trafficserver/proxy/http/HttpSM.cc

  Lines 975 to 993 in 42db8bb

  	case VC_EVENT_EOS: {
  	// We got an early EOS.
  	NetVConnection *netvc = ua_txn->get_netvc();
  	if (ua_txn->allow_half_open()) {
  	if (netvc) {
  	netvc->do_io_shutdown(IO_SHUTDOWN_READ);
  	}
  	ua_entry->eos = true;
  	} else {
  	ua_txn->do_io_close();
  	ua_buffer_reader = nullptr;
  	vc_table.cleanup_entry(ua_entry);
  	ua_entry = nullptr;
  	tunnel.kill_tunnel();
  	terminate_sm = true; // Just die already, the requester is gone
  	set_ua_abort(HttpTransact::ABORTED, event);
  	}
  	break;
  	}

Below commits are related to this issue.

• 3164c00 Adding proxy.config.http.allow_half_open (Adding proxy.config.http.allow_half_open #3325)
• 422e810 Disable the HttpSM half open logic if the underlying transport is TLS (Disable the HttpSM half open logic if the underlying transport is TLS #4213)

[masaori335]

proxy.process.http.background_fill_bytes_aborted_stat and proxy.process.http.background_fill_bytes_completed_stat might also be broken. Both of them keep saying 0 even if proxy.process.http.background_fill_current_count is more than 1.

[SolidWallOfCode]

There is a more subtle issue here, which also involves #7629. If the destruction of the HttpSM is delayed because of the cache write, so is the next transaction on that inbound connection. Currently I/O completion for the cache write is decoupled from transaction finish, which means a new transaction can start before that I/O completes. Clearly this isn't an issue for a client abort, but I don't think that information is retained in a way useful in this situation. This is related to the original reason for the response data sink support, to be able to keep a tunnel up even if the user agent drops.