[
https://issues.apache.org/jira/browse/TS-2506?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Leif Hedstrom updated TS-2506:
------------------------------
Fix Version/s: (was: 5.2.0)
> 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
>
> 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)
