[
https://issues.apache.org/jira/browse/TS-3404?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Leif Hedstrom closed TS-3404.
-----------------------------
Resolution: Fixed
> 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: 5.2.1, 5.3.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)
