[ https://issues.apache.org/jira/browse/TS-2506?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Leif Hedstrom updated TS-2506: ------------------------------ Summary: Active request timeout leaves client hanging (was: active request timeout leaves client hanging) > 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 > Assignee: James Peach > Fix For: 5.2.0 > > > 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.3.4#6332)