[
https://issues.apache.org/jira/browse/TS-1062?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13177909#comment-13177909
]
James Peach commented on TS-1062:
---------------------------------
This is another instance of events failing to be delivered correctly. The Http
SM layer knows that it's the end on the read, but ends up delivering
TS_EVENT_VCONN_READ_READY instead of TS_EVENT_VCONN_READ_COMPLETE.
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http) [0] State
Transition: ORIGIN_SERVER_OPEN -> SERVER_READ
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpSM::do_redirect]
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0] adding
producer 'http server'
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0] adding
consumer 'user agent'
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http) [0]
perform_cache_write_action CACHE_DO_NO_ACTION
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) tunnel_run
started, p_arg is NULL
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_cs)
tcp_init_cwnd_set 0
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_cs) desired TCP
congestion window is 0
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.chunked_reader->read_avail() =
3144
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_tunnel)
[producer_run] do_dechunking p->chunked_handler.skip_bytes = 242
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_chunk) read chunk
size of 20477 bytes
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_chunk) read 2896
bytes of an 20477 chunk
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Dec 30 23:31:05.605] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Dec 30 23:31:05.606] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 3144
[Dec 30 23:31:05.606] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.676] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.676] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.676] Server {0x7fff7b5f9960} DEBUG: (http_chunk) read 1448
bytes of an 20477 chunk
[Dec 30 23:31:05.676] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Dec 30 23:31:05.676] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.676] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.676] Server {0x7fff7b5f9960} DEBUG: (http_chunk) read 1448
bytes of an 20477 chunk
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 2896
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (http_chunk) read 1448
bytes of an 20477 chunk
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 1448
[Dec 30 23:31:05.677] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_chunk) read 1448
bytes of an 20477 chunk
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_chunk) read 1448
bytes of an 20477 chunk
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 2896
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_chunk) read 1448
bytes of an 20477 chunk
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 1448
[Dec 30 23:31:05.750] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.751] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.751] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.751] Server {0x7fff7b5f9960} DEBUG: (http_chunk) read 4344
bytes of an 20477 chunk
[Dec 30 23:31:05.751] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Dec 30 23:31:05.751] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.751] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Dec 30 23:31:05.751] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Dec 30 23:31:05.751] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 4344
[Dec 30 23:31:05.751] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.824] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.824] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.824] Server {0x7fff7b5f9960} DEBUG: (http_chunk) read 1448
bytes of an 20477 chunk
[Dec 30 23:31:05.824] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Dec 30 23:31:05.824] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.824] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Dec 30 23:31:05.824] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Dec 30 23:31:05.824] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 1448
[Dec 30 23:31:05.824] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (http_chunk) read 1448
bytes of an 20477 chunk
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 1448
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (http_chunk) read 1448
bytes of an 20477 chunk
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Dec 30 23:31:05.825] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 1448
[Dec 30 23:31:05.826] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_READY]
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
producer_handler_chunked [http server VC_EVENT_READ_READY]
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http_chunk) completed
read of chunk of 20477 bytes
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http_chunk) read chunk
size of 0 bytes
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http_chunk) completed
read of trailers
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 102
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[&HttpSM::tunnel_handler_server, VC_EVENT_READ_COMPLETE]
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http_cs) [0] attaching
server session [0] as slave
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http_tunnel) [0]
consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http_cs) [0] session
released by sm [0]
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http_cs) [0] initiating
io for next header
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http) [0]
[&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http_seq)
[HttpStateMachineGet::update_stats] Logging transaction
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (http) [0] dellocating sm
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (FetchSM) [fetch_handler]
calling fetch_plugin
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] I am here read
[Dec 30 23:31:05.830] Server {0x7fff7b5f9960} DEBUG: (FetchSM)
[process_fetch_read] number of bytes in read ready 212
[Dec 30 23:31:16.596] Server {0x7fff7b5f9960} DEBUG: (http_cs) [0]
[&HttpClientSession::state_slave_keep_alive, VC_EVENT_EOS]
[Dec 30 23:31:16.598] Server {0x7fff7b5f9960} DEBUG: (http_ss) [0] session
closed
> TSFetchUrl doesn't handle chunked encoding
> ------------------------------------------
>
> Key: TS-1062
> URL: https://issues.apache.org/jira/browse/TS-1062
> Project: Traffic Server
> Issue Type: Bug
> Components: TS API
> Reporter: James Peach
> Fix For: 3.1.2
>
>
> If you use TSFetchUrl() to fetch a resource and the response comes back with
> chunked encoding, you are basically hosed. The caller never gets the SUCCESS
> event because FetchSM does not know how to decode the body. There's no
> content-length header and the origin server doesn't drop the TCP connection,
> so we just sit there waiting for the response to finish forever (well until
> the origin server drops the connection 10s later).
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators:
https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
