James Peach created TS-2506:
-------------------------------
Summary: active request timeout leaves client hanging
Key: TS-2506
URL: https://issues.apache.org/jira/browse/TS-2506
Project: Traffic Server
Issue Type: Bug
Components: Core, HTTP
Reporter: James Peach
If you set {{proxy.config.http.transaction_active_timeout_out}} and the origin
response takes too long, the origin end of the HTTP tunnel will get shut down,
but the user agent will never get notified. The user agent just keeps waiting
for a response that will never come.
The HTTP debug log looks like this:
{code}
+++++++++ Proxy's Response 2 +++++++++
-- State Machine Id: 1
HTTP/1.1 200 OK
Content-Type: text/plain
Date: Thu, 16 Jan 2014 01:06:06 GMT
Age: 0
Transfer-Encoding: chunked
Connection: keep-alive
Server: ATS/4.2.0
[Jan 15 17:06:06.612] Server {0x109267000} DEBUG: <HttpSM.cc:6769
(call_transact_and_set_next_state)> (http) [1] State Transition:
ORIGIN_SERVER_OPEN -> SERVER_READ
[Jan 15 17:06:06.612] Server {0x109267000} DEBUG: <HttpSM.cc:7278
(do_redirect)> (http_redirect) [HttpSM::do_redirect]
[Jan 15 17:06:06.612] Server {0x109267000} DEBUG: <HttpTunnel.cc:1583
(deallocate_redirect_postdata_buffers)> (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Jan 15 17:06:06.612] Server {0x109267000} DEBUG: <HttpTunnel.cc:584
(add_producer)> (http_tunnel) [1] adding producer 'http server'
[Jan 15 17:06:06.613] Server {0x109267000} DEBUG: <HttpTunnel.cc:640
(add_consumer)> (http_tunnel) [1] adding consumer 'user agent'
[Jan 15 17:06:06.613] Server {0x109267000} DEBUG: <HttpSM.cc:5345
(perform_cache_write_action)> (http) [1] perform_cache_write_action
CACHE_DO_NO_ACTION
[Jan 15 17:06:06.613] Server {0x109267000} DEBUG: <HttpTunnel.cc:686
(tunnel_run)> (http_tunnel) tunnel_run started, p_arg is NULL
[Jan 15 17:06:06.613] Server {0x109267000} DEBUG: <HttpClientSession.cc:253
(do_io_write)> (http_cs) tcp_init_cwnd_set 0
[Jan 15 17:06:06.613] Server {0x109267000} DEBUG: <HttpClientSession.cc:265
(set_tcp_init_cwnd)> (http_cs) desired TCP congestion window is 0
[Jan 15 17:06:06.613] Server {0x109267000} DEBUG: <HttpTunnel.cc:905
(producer_run)> (http_tunnel) [producer_run] do_dechunking
p->chunked_handler.chunked_reader->read_avail() = 184
[Jan 15 17:06:06.613] Server {0x109267000} DEBUG: <HttpTunnel.cc:909
(producer_run)> (http_tunnel) [producer_run] do_dechunking
p->chunked_handler.skip_bytes = 161
[Jan 15 17:06:06.614] Server {0x109267000} DEBUG: <HttpTunnel.cc:1052
(producer_handler)> (http_tunnel) [1] producer_handler [http server
VC_EVENT_READ_READY]
[Jan 15 17:06:06.614] Server {0x109267000} DEBUG: <HttpTunnel.cc:989
(producer_handler_chunked)> (http_tunnel) [1] producer_handler_chunked [http
server VC_EVENT_READ_READY]
[Jan 15 17:06:06.614] Server {0x109267000} DEBUG: <HttpTunnel.cc:142
(read_size)> (http_chunk) read chunk size of 17 bytes
[Jan 15 17:06:06.614] Server {0x109267000} DEBUG: <HttpTunnel.cc:217
(read_chunk)> (http_chunk) completed read of chunk of 17 bytes
[Jan 15 17:06:06.614] Server {0x109267000} DEBUG: <HttpTunnel.cc:1093
(producer_handler)> (http_redirect) [HttpTunnel::producer_handler]
enable_redirection: [1 0 0] event: 100
[Jan 15 17:06:06.614] Server {0x109267000} DEBUG: <HttpTunnel.cc:1240
(consumer_handler)> (http_tunnel) [1] consumer_handler [user agent
VC_EVENT_WRITE_READY]
[Jan 15 17:06:08.610] Server {0x109267000} DEBUG: <HttpTunnel.cc:1052
(producer_handler)> (http_tunnel) [1] producer_handler [http server
VC_EVENT_ACTIVE_TIMEOUT]
[Jan 15 17:06:08.610] Server {0x109267000} DEBUG: <HttpTunnel.cc:989
(producer_handler_chunked)> (http_tunnel) [1] producer_handler_chunked [http
server VC_EVENT_ACTIVE_TIMEOUT]
[Jan 15 17:06:08.610] Server {0x109267000} DEBUG: <HttpTunnel.cc:1093
(producer_handler)> (http_redirect) [HttpTunnel::producer_handler]
enable_redirection: [1 0 0] event: 106
[Jan 15 17:06:08.612] Server {0x109267000} DEBUG: <HttpSM.cc:2791
(tunnel_handler_server)> (http) [1] [&HttpSM::tunnel_handler_server,
VC_EVENT_ACTIVE_TIMEOUT]
[Jan 15 17:06:08.612] Server {0x109267000} DEBUG: <HttpTunnel.cc:1240
(consumer_handler)> (http_tunnel) [1] consumer_handler [user agent
VC_EVENT_WRITE_COMPLETE]
[Jan 15 17:06:08.612] Server {0x109267000} DEBUG: <HttpSM.cc:3029
(tunnel_handler_ua)> (http) [1] [&HttpSM::tunnel_handler_ua,
VC_EVENT_WRITE_COMPLETE]
[Jan 15 17:06:08.612] Server {0x109267000} DEBUG: <HttpClientSession.cc:592
(release)> (http_cs) [1] session released by sm [1]
[Jan 15 17:06:08.612] Server {0x109267000} DEBUG: <HttpClientSession.cc:618
(release)> (http_cs) [1] initiating io for next header
[Jan 15 17:06:08.612] Server {0x109267000} DEBUG: <HttpServerSession.cc:123
(do_io_close)> (http_ss) [1] session closed
[Jan 15 17:06:08.612] Server {0x109267000} DEBUG: <HttpSM.cc:2505
(main_handler)> (http) [1] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Jan 15 17:06:08.612] Server {0x109267000} DEBUG: <HttpSM.cc:2736
(tunnel_handler)> (http) [1] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Jan 15 17:06:08.612] Server {0x109267000} DEBUG: <HttpTunnel.cc:1583
(deallocate_redirect_postdata_buffers)> (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Jan 15 17:06:08.612] Server {0x109267000} DEBUG: <HttpSM.cc:6505
(update_stats)> (http_seq) [HttpSM::update_stats] Logging transaction
[Jan 15 17:06:08.612] Server {0x109267000} DEBUG: <HttpSM.cc:6486 (kill_this)>
(http) [1] deallocating sm
{code}
Here is where I kill the user agent, and Traffic Server notices that TCP
session shut down ...
{code}
[Jan 15 17:06:43.717] Server {0x109267000} DEBUG: <HttpClientSession.cc:414
(state_keep_alive)> (http_cs) [1] [&HttpClientSession::state_keep_alive,
VC_EVENT_EOS]
[Jan 15 17:06:43.717] Server {0x109267000} DEBUG: <HttpClientSession.cc:327
(do_io_close)> (http_cs) [1] session closed
[Jan 15 17:06:43.717] Server {0x109267000} DEBUG: <HttpClientSession.cc:79
(cleanup)> (http_cs) [1] session destroy
{code}
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
