You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@trafficserver.apache.org by "Bryan Call (JIRA)" <ji...@apache.org> on 2016/01/30 19:51:39 UTC
[jira] [Comment Edited] (TS-4162) Http2ClientSession close
connection by INACTIVITY_TIMEOUT event, even if the connection is still
active
[ https://issues.apache.org/jira/browse/TS-4162?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15125013#comment-15125013 ]
Bryan Call edited comment on TS-4162 at 1/30/16 6:50 PM:
---------------------------------------------------------
The fundamental issue is ATS is closing connections with an active timeout of 0 (active_timeout_in == 0). I have opened a pull request for it:
https://github.com/apache/trafficserver/pull/447
was (Author: bcall):
The fundamental issue is ATS is closing connections with an active timeout of 0. I have opened a pull request for it:
https://github.com/apache/trafficserver/pull/447
> Http2ClientSession close connection by INACTIVITY_TIMEOUT event, even if the connection is still active
> -------------------------------------------------------------------------------------------------------
>
> Key: TS-4162
> URL: https://issues.apache.org/jira/browse/TS-4162
> Project: Traffic Server
> Issue Type: Bug
> Components: HTTP/2
> Reporter: Masaori Koshiba
> Assignee: Masaori Koshiba
> Fix For: 6.2.0
>
>
> h3. Summary
> In my investigation, {{Http2ClientSession}} close connection by {{VC_EVENT_INACTIVITY_TIMEOUT}} event.
> TS should keep "active" connection until {{VC_EVENT_ACTIVITY_TIMEOUT}} event is issued.
> h3. Investigation Details
> 1. Add debug logs to clarify what event is issued in Http2ClientSession.cc
> {code}
> diff --git a/proxy/http2/Http2ClientSession.cc b/proxy/http2/Http2ClientSession.cc
> index ccad11f..b1a5a26 100644
> --- a/proxy/http2/Http2ClientSession.cc
> +++ b/proxy/http2/Http2ClientSession.cc
> @@ -241,7 +241,13 @@ Http2ClientSession::main_event_handler(int event, void *edata)
> }
> case VC_EVENT_ACTIVE_TIMEOUT:
> + DebugHttp2Ssn0("VC_EVENT_ACTIVITY_TIMEOUT");
> + this->do_io_close();
> + return 0;
> +
> case VC_EVENT_INACTIVITY_TIMEOUT:
> + DebugHttp2Ssn0("VC_EVENT_INACTIVITY_TIMEOUT");
> + this->do_io_close();
> + return 0;
> {code}
> - Enable HTTP/2 with default HTTP/2 settings
> - Enable debug and set debug tag 'http2_cs'
> - Disable cache
> 2. Start origin server with netcat and remap every request to it.
> 3. Do HTTP/2 request on h2i to TS
> Below is debug logs.
> {noformat}
> [Jan 29 14:56:35.723] Server {0x700000ba2000} DEBUG: <Http2SessionAccept.cc:52 (accept)> (http2_seq) [HttpSessionAccept2:mainEvent 0x7fc4f424fc80] accepted connection from 127.0.0.1:56466 transport type = 4
> [Jan 29 14:56:35.724] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:127 (new_connection)> (http2_cs) [0] session born, netvc 0x7fc4f424fc80
> [Jan 29 14:56:35.724] Server {0x700000ba2000} DEBUG: <Http2ConnectionState.cc:1136 (send_window_update_frame)> (http2_cs) [0] Send WINDOW_UPDATE frame.
> [Jan 29 14:56:35.724] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:285 (state_read_connection_preface)> (http2_cs) [0] [&Http2ClientSession::state_read_connection_preface, VC_EVENT_READ_READY]
> [Jan 29 14:56:35.724] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:285 (state_read_connection_preface)> (http2_cs) [0] [&Http2ClientSession::state_read_connection_preface, VC_EVENT_READ_READY]
> [Jan 29 14:56:35.724] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:301 (state_read_connection_preface)> (http2_cs) [0] received connection preface
> [Jan 29 14:56:51.205] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:329 (state_start_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY]
> [Jan 29 14:56:51.205] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:336 (state_start_frame_read)> (http2_cs) [0] receiving frame header
> [Jan 29 14:56:51.205] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:346 (state_start_frame_read)> (http2_cs) [0] frame header length=7, type=1, flags=0x5, streamid=1
> [Jan 29 14:56:51.205] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:404 (state_complete_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY]
> [Jan 29 14:56:51.205] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:412 (state_complete_frame_read)> (http2_cs) [0] completed frame read, 7 bytes available
> [Jan 29 14:56:51.551] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:249 (main_event_handler)> (http2_cs) [0] VC_EVENT_INACTIVITY_TIMEOUT
> [Jan 29 14:56:51.551] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:203 (do_io_close)> (http2_cs) [0] session closed
> [Jan 29 14:56:51.552] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:72 (destroy)> (http2_cs) [0] session destroy
> {noformat}
> 300ms after TS requests to origin server, {{VC_EVENT_INACTIVITY_TIMEOUT}} is happen immediately and Http2ClientSession close the connection.
> It looks like origin server needs return first byte of headers in 300ms. In some cases like origin server is slow or faraway, this could be problem.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)