You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@trafficserver.apache.org by "Leif Hedstrom (JIRA)" <ji...@apache.org> on 2015/03/16 16:33:38 UTC
[jira] [Updated] (TS-3404) PluginVC not notifying ActiveSide of EOS
due to race condition in handling terminating chunk.
[ https://issues.apache.org/jira/browse/TS-3404?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Leif Hedstrom updated TS-3404:
------------------------------
Backport to Version: (was: 5.2.1)
> PluginVC not notifying ActiveSide 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
> Affects Versions: 5.3.0
> Reporter: Sudheer Vinukonda
> Assignee: Sudheer Vinukonda
> Fix For: 6.0.0
>
>
> When there's a race condition in receiving the terminating chunk (of size 0), {{PluginVC}} is not notifying the ActiveSide (for e.g. {{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)