[
https://issues.apache.org/jira/browse/TS-3404?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14335336#comment-14335336
]
Sudheer Vinukonda edited comment on TS-3404 at 2/24/15 8:43 PM:
----------------------------------------------------------------
The key difference in the failed case is that, the tunnel sends a
{{VC_EVENT_WRITE_READY}} event first with the received bytes which are
transferred from PluginVC's PassiveSide to ActiveSide (FetchSM). The ActiveSide
only triggers a {{VC_EVENT_READ_READY}}, since the terminating chunk is not
received yet. It checks if the other_side (PassiveSide) is closed or in write
shutdown state, which it is not, since the terminating chunk is not read yet.
When the terminating chunk is subsequently received, the tunnel sends a
{{VC_EVENT_WRITE_COMPLETE}} event which triggers the client_vc's (which is the
PluginVC's PassiveSide) half close, setting the write_state for PassiveSide to
shutdown. The PassiveSide's read side is triggered with the 0 bytes
(terminating chunk), however, the current code, sends an EOS only if the
other_side of the PluginVC (which is the FetchSM) is in closed/write_shutdown
state, otherwise, simply drops that event on the floor.
In the working case, there's no {{VC_EVENT_WRITE_READY}} - Instead, the tunnel
just sends {{VC_EVENT_WRITE_COMPLETE}} directly, since it reads the terminating
chunk already. This results in the PassiveSide (PluginVC) transferring the
bytes to the ActiveSide (FetchSM). ActiveSide detects that the PassiveSide is
already in closed state (due to other_side's write_shutdown state) and sends an
EOS to the continuation (FetchSM).
Below are more logs with PluginVC debug enabled:
Working:
{code}
[Feb 24 00:37:11.044] Server {0x2b1745918700} DEBUG: (http_chunk) completed
read of chunk of 122 bytes
[Feb 24 00:37:11.044] Server {0x2b1745918700} DEBUG: (http_chunk) read chunk
size of 122 bytes
[Feb 24 00:37:11.044] Server {0x2b1745918700} DEBUG: (http_chunk) completed
read of chunk of 122 bytes
[Feb 24 00:37:11.044] Server {0x2b1745918700} DEBUG: (http_chunk) read chunk
size of 3 bytes
[Feb 24 00:37:11.044] Server {0x2b1745918700} DEBUG: (http_chunk) completed
read of chunk of 3 bytes
[Feb 24 00:37:11.044] Server {0x2b1745918700} DEBUG: (http_chunk) read chunk
size of 0 bytes
[Feb 24 00:37:11.044] Server {0x2b1745918700} DEBUG: (http_chunk) completed
read of trailers
[Feb 24 00:37:11.044] Server {0x2b1745918700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 102
[Feb 24 00:37:11.044] Server {0x2b1745918700} DEBUG: (http) [3]
[&HttpSM::tunnel_handler_server, VC_EVENT_READ_COMPLETE]
[Feb 24 00:37:11.044] Server {0x2b1745918700} DEBUG: (http_ss) [3] session
closing, netvc 0x2b17bc015600
[Feb 24 00:37:11.044] Server {0x2b1745918700} DEBUG: (pvc) [1] Passive:
reenable Write
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc_event) [1] Passive:
Received event 1
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc) [1] Passive:
process_write_side
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc) [1] Passive:
process_write_side; act_on 6379
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc) [1] Passive:
process_write_side; added 6379
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (http_tunnel) [3]
consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (http) [3]
[&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (http_cs) [3] session half
close
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc) [1] Passive:
do_io_read for 9223372036854775807 bytes
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (http) [3]
[HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (http) [3]
[&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (http) [3] calling plugin
on hook TS_HTTP_TXN_CLOSE_HOOK at hook 0x2ad0050
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (http) [3]
[&HttpSM::state_api_callback, HTTP_API_CONTINUE]
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (http) [3]
[&HttpSM::state_api_callout, HTTP_API_CONTINUE]
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (http_seq)
[HttpSM::update_stats] Logging transaction
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (http) [3] deallocating sm
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc) [1] Active:
process_read_side
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc) [1] Active:
process_read_side; act_on 6379
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc) [1] Active:
process_read_side; added 6379
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 6379
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (FetchSM)
[process_fetch_read] copied 6379 bytes
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (FetchSM)
[process_fetch_read] total copied 6379 bytes
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc) [1] Active: reenable
Read
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc) [1] Passive:
reenable Write
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc_event) [1] Passive:
Received event 1
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc) [1] Passive:
process_read_side
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc) [1] Passive:
process_read_side; act_on 0
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc_event) [1] Active:
Received event 1
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc) [1] Active:
process_read_side
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (pvc) [1] Active:
process_read_side; act_on 0
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Feb 24 00:37:11.045] Server {0x2b1745918700} DEBUG: (FetchSM)
[get_info_from_buffer] total avail 6379
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (pvc) [0] Passive:
reenable Write
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (FetchSM)
[process_fetch_read] received EOS
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (FetchSM) [cleanUp]
calling cleanup
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (pvc) [1] Active:
do_io_close
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (pvc) [1] Active:
process_close
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (pvc_event) [0] Passive:
Received event 1
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (pvc) [0] Passive:
process_write_side
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (pvc) [0] Passive:
process_write_side; act_on 6328
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (pvc) [0] Passive:
process_write_side; added 6328
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (pvc) [0] Passive:
reenable Write
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (pvc) [0] Active:
process_read_side
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (pvc) [0] Active:
process_read_side; act_on 6328
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (pvc) [0] Active:
process_read_side; added 6328
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (http_tunnel) [2]
producer_handler [http server VC_EVENT_READ_READY]
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (http_tunnel) [2]
producer_handler_dechunked [http server VC_EVENT_READ_READY]
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (http_chunk) creating a
chunk of size 4096 bytes
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (http_chunk) creating a
chunk of size 2232 bytes
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (pvc) [0] Passive:
reenable Write
[Feb 24 00:37:11.046] Server {0x2b1745918700} DEBUG: (pvc_event) [1] Passive:
Received event 1
[Feb 24 00:37:11.047] Server {0x2b1745918700} DEBUG: (pvc) [1] Passive:
process_read_side
[Feb 24 00:37:11.047] Server {0x2b1745918700} DEBUG: (pvc) [1] Passive:
process_read_side; act_on 0
[Feb 24 00:37:11.047] Server {0x2b1745918700} DEBUG: (http_cs) [3]
[&HttpClientSession::state_wait_for_close, VC_EVENT_EOS]
[Feb 24 00:37:11.047] Server {0x2b1745918700} DEBUG: (pvc) [1] Passive:
do_io_close
[Feb 24 00:37:11.047] Server {0x2b1745918700} DEBUG: (http_cs) [3] session
closed
[Feb 24 00:37:11.047] Server {0x2b1745918700} DEBUG: (http_cs) [3] session
destroy
[Feb 24 00:37:11.047] Server {0x2b1745918700} DEBUG: (pvc) [1] Passive:
process_close
{code}
Failed:
{code}
Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_chunk) completed read
of chunk of 122 bytes
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_chunk) read chunk
size of 3 bytes
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_chunk) completed
read of chunk of 3 bytes
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Passive:
reenable Write
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc_event) [15] Passive:
Received event 1
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Passive:
process_write_side
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Passive:
process_write_side; act_on 6379
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Passive:
process_write_side; added 6379
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_tunnel) [18]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Active:
process_read_side
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Active:
process_read_side; act_on 6379
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Active:
process_read_side; added 6379
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 6379
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (FetchSM)
[process_fetch_read] copied 6379 bytes
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (FetchSM)
[process_fetch_read] total copied 6379 bytes
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Active:
reenable Read
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Passive:
reenable Write
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc_event) [15] Active:
Received event 1
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Active:
process_read_side
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Active:
process_read_side; act_on 0
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc_event) [15] Passive:
Received event 1
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Passive:
process_write_side
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Passive:
process_write_side; act_on 0
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_tunnel) [18]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_tunnel) [18]
producer_handler [http server VC_EVENT_READ_READY]
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_tunnel) [18]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_chunk) read chunk
size of 0 bytes
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_chunk) completed
read of trailers
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 102
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http) [18]
[&HttpSM::tunnel_handler_server, VC_EVENT_READ_COMPLETE]
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_tunnel) [18]
consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http) [18]
[&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_cs) [18] session
half close
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Passive:
do_io_read for 9223372036854775807 bytes
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_ss) [18] session
closing, netvc 0x2b17bc014080
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http) [18]
[HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http) [18]
[&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http) [18] calling plugin
on hook TS_HTTP_TXN_CLOSE_HOOK at hook 0x2ad0050
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http) [18]
[&HttpSM::state_api_callback, HTTP_API_CONTINUE]
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http) [18]
[&HttpSM::state_api_callout, HTTP_API_CONTINUE]
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http_seq)
[HttpSM::update_stats] Logging transaction
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (http) [18] deallocating sm
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc_event) [15] Passive:
Received event 1
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Passive:
process_read_side
[Feb 24 00:37:18.535] Server {0x2b1745b1a700} DEBUG: (pvc) [15] Passive:
process_read_side; act_on 0
[Feb 24 00:37:19.508] Server {0x2b1745c1b700} DEBUG: (pvc_event) [14] Active:
Received event 2
[Feb 24 00:37:19.536] Server {0x2b1745f1e700} DEBUG: (pvc_event) [15] Passive:
Received event 2
[Feb 24 00:37:20.511] Server {0x2b1745c1b700} DEBUG: (pvc_event) [14] Active:
Received event 2
[Feb 24 00:37:20.537] Server {0x2b1745f1e700} DEBUG: (pvc_event) [15] Passive:
Received event 2
[Feb 24 00:37:21.513] Server {0x2b1745c1b700} DEBUG: (pvc_event) [14] Active:
Received event 2
[Feb 24 00:37:21.540] Server {0x2b1745f1e700} DEBUG: (pvc_event) [15] Passive:
Received event 2
[Feb 24 00:37:22.053] Server {0x2b17b07d1700} DEBUG: (pvc) [14] Passive:
reenable Write
{code}
was (Author: sudheerv):
The key difference in the failed case is that, the tunnel sends a
{{VC_EVENT_WRITE_READY}} event first with the received bytes which are
transferred from PluginVC's PassiveSide to ActiveSide (FetchSM). The ActiveSide
only triggers a {{VC_EVENT_READ_READY}}, since the terminating chunk is not
received yet. When the terminating chunk is subsequently received, the tunnel
sends a {{VC_EVENT_WRITE_COMPLETE}} event which triggers the client_vc's (which
is the PluginVC's PassiveSide) half close, setting the write_state for
PassiveSide to shutdown. However, the current code sends an EOS only if the
other_side of the PluginVC (which is the FetchSM) is in closed/write_shutdown
state.
In the working case, there's no {{VC_EVENT_WRITE_READY}} - Instead, the tunnel
just sends {{VC_EVENT_WRITE_COMPLETE}} directly, since it reads the terminating
chunk already. This results in the PassiveSide (PluginVC) transferring the
bytes to the ActiveSide (FetchSM) along with sending a
{{VC_EVENT_READ_COMPLETE}} event, since the ntodo() is 0.
> 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)
