masaori335 commented on issue #7915: URL: https://github.com/apache/trafficserver/issues/7915#issuecomment-853600232
It looks like `http2/4.2/1` hangs intermittently. <details><summary>Debug logs</summary> ``` [Jun 3 06:14:04.940] [ET_NET 0] DEBUG: <ALPNSupport.cc:105 (select_next_protocol)> (ssl) selected ALPN protocol h2 [Jun 3 06:14:04.940] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 8193, ret: 1, State: SSLv3/TLS read client hello [Jun 3 06:14:04.940] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 8193, ret: 1, State: SSLv3/TLS write server hello [Jun 3 06:14:04.940] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 8193, ret: 1, State: SSLv3/TLS write certificate [Jun 3 06:14:04.941] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 8193, ret: 1, State: SSLv3/TLS write key exchange [Jun 3 06:14:04.941] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 8193, ret: 1, State: SSLv3/TLS write server done [Jun 3 06:14:04.941] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 8194, ret: -1, State: SSLv3/TLS write server done [Jun 3 06:14:04.941] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:1297 (sslServerHandShakeEvent)> (ssl-diag) SSL handshake error: SSL_ERROR_WANT_READ (2), errno=0 [Jun 3 06:14:04.941] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:626 (net_read_io)> (ssl) ssl handshake for vc 0x7ffff0426800, took 0.000 seconds, configured handshake_timer: 30 [Jun 3 06:14:04.941] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:1227 (sslServerHandShakeEvent)> (ssl) Go on with the handshake state=7 [Jun 3 06:14:04.941] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 8193, ret: 1, State: SSLv3/TLS write server done [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 8193, ret: 1, State: SSLv3/TLS read client key exchange [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 8193, ret: 1, State: SSLv3/TLS read change cipher spec [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 8193, ret: 1, State: SSLv3/TLS read finished [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 8193, ret: 1, State: SSLv3/TLS write change cipher spec [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 8193, ret: 1, State: SSLv3/TLS write finished [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLUtils.cc:210 (ssl_new_cached_session)> (ssl.session_cache.insert) ssl_new_cached_session session '45874F8E9DFE0544C6A6FE6D84B3E1C96B24A1D389EA9AA876A30D504E1E783C' and context 0xde7950 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLSessionCache.cc:110 (insertSession)> (ssl.session_cache.insert) SessionCache using bucket 18 (0xdde668): Inserting session '45874F8E9DFE0544C6A6FE6D84B3E1C96B24A1D389EA9AA876A30D504E1E783C' (hash: 4867EDCB9446BD12). [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLSessionCache.cc:147 (insertSession)> (ssl.session_cache) Inserting session '45874F8E9DFE0544C6A6FE6D84B3E1C96B24A1D389EA9AA876A30D504E1E783C' to bucket 0xdde668. [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 32, ret: 1, State: SSL negotiation finished successfully [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffec028f40, where: 8194, ret: 1, State: SSL negotiation finished successfully [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:1314 (sslServerHandShakeEvent)> (ssl) SSL server handshake completed successfully [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <TLSBasicSupport.cc:132 (_record_tls_handshake_end_time)> (ssl) ssl handshake time:1130199 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:1358 (sslServerHandShakeEvent)> (ssl) client selected next protocol 'h2' [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:650 (net_read_io)> (ssl) ssl handshake EVENT_DONE ntodo=0 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2SessionAccept.cc:53 (accept)> (http2_seq) [HttpSessionAccept2:mainEvent 0x7ffff0426800] accepted connection from 127.0.0.1:43010 transport type = 4 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ClientSession.cc:209 (new_connection)> (ssl_early_data) read_from_early_data = 0 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ClientSession.cc:212 (new_connection)> (http2_cs) [8] session born, netvc 0x7ffff0426800 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1959 (send_settings_frame)> (http2_con) [8] [0] Send SETTINGS frame [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1970 (send_settings_frame)> (http2_con) [8] [0] MAX_CONCURRENT_STREAMS : 100 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:1970 (send_settings_frame)> (http2_con) [8] [0] MAX_HEADER_LIST_SIZE : 131072 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read) [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:719 (net_read_io)> (ssl) read finished - would block [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:780 (load_buffer_and_write)> (ssl) towrite=21 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:836 (load_buffer_and_write)> (ssl) try_to_write=21 written=21 total_written=21 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=24 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4072 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=15 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4057 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=9 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4048 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read) [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=48 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ClientSession.cc:388 (state_read_connection_preface)> (http2_cs) [8] [&Http2ClientSession::state_read_connection_preface, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ClientSession.cc:409 (state_read_connection_preface)> (http2_cs) [8] received connection preface [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [8] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [8] receiving frame header [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [8] frame header length=6, type=4, flags=0x0, streamid=0 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:566 (rcv_settings_frame)> (http2_con) [8] [0] Received SETTINGS frame [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:638 (rcv_settings_frame)> (http2_con) [8] [0] INITIAL_WINDOW_SIZE : 65535 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [8] receiving frame header [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [8] frame header length=0, type=4, flags=0x1, streamid=0 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:566 (rcv_settings_frame)> (http2_con) [8] [0] Received SETTINGS frame [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4048 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read) [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:719 (net_read_io)> (ssl) read finished - would block [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:780 (load_buffer_and_write)> (ssl) towrite=9 [Jun 3 06:14:04.942] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:836 (load_buffer_and_write)> (ssl) try_to_write=9 written=9 total_written=9 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4048 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=25 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4023 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read) [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=25 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [8] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [8] receiving frame header [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [8] frame header length=16, type=1, flags=0x4, streamid=1 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:233 (rcv_headers_frame)> (http2_con) [8] [1] Received HEADERS frame [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [8] [1] Http2StreamState::HTTP2_STREAM_STATE_OPEN [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4023 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=4023 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=1872 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=2224 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=2224 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=8119 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [8] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [8] receiving frame header [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [8] frame header length=16384, type=0, flags=0x1, streamid=1 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=4096 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=4096 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [8] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=754 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=3342 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=3342 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=4096 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [8] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=82 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read) [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=82 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [8] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY] [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2ClientSession.cc:514 (state_complete_frame_read)> (http2_cs) [8] completed frame read, 16384 bytes available [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [8] [1] Received DATA frame [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [8] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [8] [1] Received DATA frame: rwnd con=49151/65535 stream=49151/65535 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0 [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read) [Jun 3 06:14:04.943] [ET_NET 0] DEBUG: <SSLNetVConnection.cc:719 (net_read_io)> (ssl) read finished - would block ### got timeout after 10 seconds ``` </details> -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: [email protected]
