You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@trafficserver.apache.org by "Leif Hedstrom (JIRA)" <ji...@apache.org> on 2014/12/16 19:02:13 UTC
[jira] [Updated] (TS-2506) Active request timeout leaves client
hanging
[ 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)