Major Description
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.
Investigation Details
1. Add debug logs to clarify what event is issued in Http2ClientSession.cc
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;
- 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.
[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
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.