[jira] [Created] (TS-4162) Http2ClientSession close connection by INACTIVITY_TIMEOUT event, even if the connection is still active

["Masaori Koshiba (JIRA)" <ji...@apache.org>]

Masaori Koshiba created TS-4162:
-----------------------------------

             Summary: 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


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)