[
https://issues.apache.org/jira/browse/TS-3404?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14335949#comment-14335949
]
Sudheer Vinukonda commented on TS-3404:
---------------------------------------
The new commit seems less riskier than the original commit, but, it is limited
to POST and internal (plugin) requests. Whereas, the race condition in handling
the terminating chunk (from the origin), seems like it could affect other kinds
of transactions as well including spdy transactions (which are not marked
internal).
> 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.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)
