[
https://issues.apache.org/jira/browse/TS-4162?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15123212#comment-15123212
]
Masaori Koshiba commented on TS-4162:
-------------------------------------
Added "net_queue" to debug tags and picked up some logs.
{noformat}
[Jan 29 16:58:56.441] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:127
(new_connection)> (http2_cs) [0] session born, netvc 0x7fac4c094c80
...
[Jan 29 16:58:56.565] Server {0x700000693000} DEBUG: <UnixNet.cc:578
(manage_active_queue)> (net_queue) max_connections_per_thread_in: 2500
max_connections_active_per_thread_in: 833 total_connections_in: 0
active_queue_size: 0 keep_alive_queue_size: 0
[Jan 29 16:58:56.565] Server {0x700000693000} DEBUG: <UnixNet.cc:630
(manage_keep_alive_queue)> (net_queue) max_connections_per_thread_in: 2500
total_connections_in: 0 active_queue_size: 0 keep_alive_queue_size: 0
...
[Jan 29 16:59:09.824] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:329
(state_start_frame_read)> (http2_cs) [0]
[&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY]
[Jan 29 16:59:09.824] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:336
(state_start_frame_read)> (http2_cs) [0] receiving frame header
[Jan 29 16:59:09.824] 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 16:59:09.824] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:404
(state_complete_frame_read)> (http2_cs) [0]
[&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY]
[Jan 29 16:59:09.824] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:412
(state_complete_frame_read)> (http2_cs) [0] completed frame read, 7 bytes
available
[Jan 29 16:59:09.824] Server {0x700000ba2000} DEBUG:
<Http2ConnectionState.cc:176 (rcv_headers_frame)> (http2_cs) [0] Received
HEADERS frame.
[Jan 29 16:59:09.824] Server {0x700000ba2000} DEBUG: <UnixNet.cc:725
(add_to_active_queue)> (net_queue) NetVC: 0x7fac4c094c80
[Jan 29 16:59:09.824] Server {0x700000ba2000} DEBUG: <UnixNet.cc:727
(add_to_active_queue)> (net_queue) max_connections_per_thread_in: 2500
active_queue_size: 0 keep_alive_queue_size: 0
[Jan 29 16:59:09.824] Server {0x700000ba2000} DEBUG: <UnixNet.cc:578
(manage_active_queue)> (net_queue) max_connections_per_thread_in: 2500
max_connections_active_per_thread_in: 833 total_connections_in: 0
active_queue_size: 0 keep_alive_queue_size: 0
[Jan 29 16:59:09.824] Server {0x700000ba2000} DEBUG: <UnixNet.cc:715
(remove_from_keep_alive_queue)> (net_queue) NetVC: 0x7fac4c094c80
...
[Jan 29 16:59:10.593] Server {0x700000ba2000} DEBUG: <UnixNet.cc:578
(manage_active_queue)> (net_queue) max_connections_per_thread_in: 2500
max_connections_active_per_thread_in: 833 total_connections_in: 1
active_queue_size: 1 keep_alive_queue_size: 0
[Jan 29 16:59:10.593] Server {0x700000287000} DEBUG: <UnixNet.cc:630
(manage_keep_alive_queue)> (net_queue) max_connections_per_thread_in: 2500
total_connections_in: 0 active_queue_size: 0 keep_alive_queue_size: 0
[Jan 29 16:59:10.594] Server {0x700000ba2000} DEBUG: <UnixNet.cc:679
(_close_vc)> (net_queue) closing connection NetVC=0x7fac4c094c80 idle: 0 now:
1454054350 at: 1454054464 in: 115 diff: 0
[Jan 29 16:59:10.594] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:249
(main_event_handler)> (http2_cs) [0] VC_EVENT_INACTIVITY_TIMEOUT
[Jan 29 16:59:10.594] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:203
(do_io_close)> (http2_cs) [0] session closed
[Jan 29 16:59:10.595] Server {0x700000ba2000} DEBUG: <Http2ClientSession.cc:72
(destroy)> (http2_cs) [0] session destroy
[Jan 29 16:59:10.595] Server {0x700000ba2000} DEBUG: <UnixNet.cc:715
(remove_from_keep_alive_queue)> (net_queue) NetVC: 0x7fac4c094c80
[Jan 29 16:59:10.604] Server {0x700000ba2000} DEBUG: <UnixNet.cc:751
(remove_from_active_queue)> (net_queue) NetVC: 0x7fac4c094c80
...
[Jan 29 16:59:10.604] Server {0x700000ba2000} DEBUG: <UnixNet.cc:630
(manage_keep_alive_queue)> (net_queue) max_connections_per_thread_in: 2500
total_connections_in: 0 active_queue_size: 0 keep_alive_queue_size: 0
[Jan 29 16:59:11.558] Server {0x700000184000} DEBUG: <UnixNet.cc:578
(manage_active_queue)> (net_queue) max_connections_per_thread_in: 2500
max_connections_active_per_thread_in: 833 total_connections_in: 0
active_queue_size: 0 keep_alive_queue_size: 0
{noformat}
> 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)
