Sudheer Vinukonda created TS-3404:
-------------------------------------
Summary: PluginVC not notifying ActiveSide (FetchSM) of EOS due to
race condition in handling terminating chunk.
Key: TS-3404
URL: https://issues.apache.org/jira/browse/TS-3404
Project: Traffic Server
Issue Type: Bug
Components: Core
Reporter: Sudheer Vinukonda
When there's a race condition in receiving the terminating chunk (of size 0),
{{PluginVC}} is not notifying the ActiveSide {{FetchSM}} of EOS, causing it to
hang until an eventual timeout occurs.
The code below checks if the {{other_side}} is closed or in write shutdown
state to send the EOS,
https://github.com/apache/trafficserver/blob/master/proxy/PluginVC.cc#L638
but, in the race condition observed in our environment, the {{PassiveSide}}'s
write_state is in shutdown (set via consumer_handler handling the event
{{VC_EVENT_WRITE_COMPLETE}} at the final terminating chunk and HttpSM calling
{{do_io_close} with {{IO_SHUTDOWN_WRITE}} on the passive side.
The below simple fix resolves the issue:
{code}
if (act_on <= 0) {
if (other_side->closed || other_side->write_state.shutdown ||
write_state.shutdown) {
read_state.vio._cont->handleEvent(VC_EVENT_EOS, &read_state.vio);
}
return;
}
{code}
Below are the debug logs that indicate the failed and working cases due to the
race condition:
Working Case:
{code}
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [205] adding
producer 'http server'
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [205] adding
consumer 'user agent'
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http) [205]
perform_cache_write_action CACHE_DO_NO_ACTION
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) tunnel_run
started, p_arg is NULL
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() =
368
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel)
[producer_run] do_dechunking::Copied header of size 179
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_cs)
tcp_init_cwnd_set 0
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_cs) desired TCP
congestion window is 0
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() =
368
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.skip_bytes = 179
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [205]
producer_handler [http server VC_EVENT_READ_READY]
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [205]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) read chunk
size of 57 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) completed
read of chunk of 57 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) read chunk
size of 120 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) completed
read of chunk of 120 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [205]
producer_handler [http server VC_EVENT_READ_READY]
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_tunnel) [205]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) read chunk
size of 3 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) completed
read of chunk of 3 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) read chunk
size of 0 bytes
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_chunk) completed
read of trailers
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 102
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http) [205]
[&HttpSM::tunnel_handler_server, VC_EVENT_READ_COMPLETE]
[Feb 22 22:03:16.551] Server {0x7f865d664700} DEBUG: (http_ss) [205] session
closing, netvc 0x7f85ec0158b0
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http_tunnel) [205]
consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205]
[&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http_cs) [205] session
half close
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205]
[HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205]
[&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205] calling
plugin on hook TS_HTTP_TXN_CLOSE_HOOK at hook 0x220a210
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205]
[&HttpSM::state_api_callback, HTTP_API_CONTINUE]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205]
[&HttpSM::state_api_callout, HTTP_API_CONTINUE]
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http_seq)
[HttpSM::update_stats] Logging transaction
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (http) [205] deallocating
sm
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 359
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM)
[process_fetch_read] copied 359 bytes
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM)
[process_fetch_read] total copied 359 bytes
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Feb 22 22:03:16.552] Server {0x7f865d664700} DEBUG: (FetchSM)
[get_info_from_buffer] total avail 359
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (FetchSM)
[process_fetch_read] received EOS
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (FetchSM) [cleanUp]
calling cleanup
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_tunnel) [204]
producer_handler [http server VC_EVENT_READ_READY]
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_tunnel) [204]
producer_handler_dechunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_chunk) creating a
chunk of size 267 bytes
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_cs) [205]
[&HttpClientSession::state_wait_for_close, VC_EVENT_EOS]
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_cs) [205] session
closed
[Feb 22 22:03:16.554] Server {0x7f865d664700} DEBUG: (http_cs) [205] session
destroy
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_tunnel) [204]
producer_handler [http server VC_EVENT_EOS]
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_tunnel) [204]
producer_handler_dechunked [http server VC_EVENT_EOS]
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 104
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http) [204]
[&HttpSM::tunnel_handler_server, VC_EVENT_EOS]
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http) [204]
[HttpSM::tunnel_handler_server] finishing HTTP tunnel
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_ss) [204] session
closing, netvc 0x7f85f0002770
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_tunnel) [204]
consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http) [204]
[&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_cs) [204] session
released by sm [204]
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http_cs) [204] initiating
io for next header
[Feb 22 22:03:16.555] Server {0x7f865d664700} DEBUG: (http) [204]
[HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 22 22:03:16.556] Server {0x7f865d664700} DEBUG: (http) [204]
[&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 22 22:03:16.556] Server {0x7f865d664700} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
{code}
Failed Case:
{code}
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207] adding
producer 'http server'
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207] adding
consumer 'user agent'
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207]
perform_cache_write_action CACHE_DO_NO_ACTION
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) tunnel_run
started, p_arg is NULL
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() =
368
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel)
[producer_run] do_dechunking::Copied header of size 179
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_cs)
tcp_init_cwnd_set 0
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_cs) desired TCP
congestion window is 0
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() =
368
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.skip_bytes = 179
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207]
producer_handler [http server VC_EVENT_READ_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) read chunk
size of 57 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) completed
read of chunk of 57 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) read chunk
size of 120 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) completed
read of chunk of 120 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207]
producer_handler [http server VC_EVENT_READ_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) read chunk
size of 3 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) completed
read of chunk of 3 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 359
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (FetchSM)
[process_fetch_read] copied 359 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (FetchSM)
[process_fetch_read] total copied 359 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207]
producer_handler [http server VC_EVENT_READ_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) read chunk
size of 0 bytes
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_chunk) completed
read of trailers
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 102
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207]
[&HttpSM::tunnel_handler_server, VC_EVENT_READ_COMPLETE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_tunnel) [207]
consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207]
[&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_cs) [207] session
half close
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_ss) [207] session
closing, netvc 0x7f85ec015600
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207]
[HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207]
[&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207] calling
plugin on hook TS_HTTP_TXN_CLOSE_HOOK at hook 0x220a210
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207]
[&HttpSM::state_api_callback, HTTP_API_CONTINUE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207]
[&HttpSM::state_api_callout, HTTP_API_CONTINUE]
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http_seq)
[HttpSM::update_stats] Logging transaction
[Feb 22 22:03:17.096] Server {0x7f865d563700} DEBUG: (http) [207] deallocating
sm
[Feb 22 22:03:22.140] Server {0x7f85f7330700} DEBUG: (http_tunnel) [206]
producer_handler [http server VC_EVENT_READ_READY]
[Feb 22 22:03:22.140] Server {0x7f85f7330700} DEBUG: (http_tunnel) [206]
producer_handler_dechunked [http server VC_EVENT_READ_READY]
[Feb 22 22:03:22.140] Server {0x7f85f7330700} DEBUG: (http_chunk) creating a
chunk of size 190 bytes
[Feb 22 22:03:22.140] Server {0x7f85f7330700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Feb 22 22:03:22.140] Server {0x7f865d563700} DEBUG: (http_tunnel) [206]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Feb 22 22:03:22.140] Server {0x7f865d563700} DEBUG: (http_tunnel) [206]
producer_handler [http server VC_EVENT_EOS]
[Feb 22 22:03:22.140] Server {0x7f865d563700} DEBUG: (http_tunnel) [206]
producer_handler_dechunked [http server VC_EVENT_EOS]
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
