[
https://issues.apache.org/jira/browse/TS-3404?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Sudheer Vinukonda updated TS-3404:
----------------------------------
Description:
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}
was:
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}
> 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)
