[
https://issues.apache.org/jira/browse/TS-4162?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Masaori Koshiba reassigned TS-4162:
-----------------------------------
Assignee: Masaori Koshiba
> 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
>
>
> 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.
> # 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)
