You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@trafficserver.apache.org by GitBox <gi...@apache.org> on 2021/06/02 23:04:59 UTC
[GitHub] [trafficserver] bneradt opened a new issue #7915: h2spec.test.py has become flakey
bneradt opened a new issue #7915:
URL: https://github.com/apache/trafficserver/issues/7915
I've noticed that CI has started having intermittent failures with the h2spec.test.py test. I reproduced it locally, running the test 20 times, and noticing that it would fail consistently within a few runs. I did a git bisect and here's the results:
```
$ git bisect run /var/tmp/build_and_run_h2spec_test.sh
running /var/tmp/build_and_run_h2spec_test.sh
building: f80ed7354 (HEAD) Do not delete the continuation twice (#7862)
tests failed for: f80ed7354 (HEAD) Do not delete the continuation twice (#7862)
Bisecting: 5 revisions left to test after this (roughly 3 steps)
[a0c267cdc88586679ccba4ec3e394f386d52f806] Add URI Signing cdnistd Claim Implementation (#7822)
running /var/tmp/build_and_run_h2spec_test.sh
building: a0c267cdc (HEAD) Add URI Signing cdnistd Claim Implementation (#7822)
tests failed for: a0c267cdc (HEAD) Add URI Signing cdnistd Claim Implementation (#7822)
Bisecting: 2 revisions left to test after this (roughly 2 steps)
[19dfdd4753232d0b77ca555f7ef5f5ba3d2ccae1] Clean up lua plugin doc for overridable configurations (#7844)
running /var/tmp/build_and_run_h2spec_test.sh
building: 19dfdd475 (HEAD) Clean up lua plugin doc for overridable configurations (#7844)
tests failed for: 19dfdd475 (HEAD) Clean up lua plugin doc for overridable configurations (#7844)
Bisecting: 0 revisions left to test after this (roughly 1 step)
[23174f43ba543c9f56916e5d6aadb7a22f349355] Save and propagate epoll network error (#7809)
running /var/tmp/build_and_run_h2spec_test.sh
building: 23174f43b (HEAD) Save and propagate epoll network error (#7809)
tests failed for: 23174f43b (HEAD) Save and propagate epoll network error (#7809)
Bisecting: 0 revisions left to test after this (roughly 0 steps)
[fbdbb5b733c389e537d777938298219be43e619e] Add method to write an IpAddr value to a sockaddr. (#7821)
running /var/tmp/build_and_run_h2spec_test.sh
building: fbdbb5b73 (HEAD) Add method to write an IpAddr value to a sockaddr. (#7821)
tests passed for: fbdbb5b73 (HEAD) Add method to write an IpAddr value to a sockaddr. (#7821)
23174f43ba543c9f56916e5d6aadb7a22f349355 is the first bad commit
commit 23174f43ba543c9f56916e5d6aadb7a22f349355
Author: Susan Hinrichs <sh...@verizonmedia.com>
Date: Mon May 17 19:23:48 2021 -0500
Save and propagate epoll network error (#7809)
iocore/net/NetEvent.h | 17 +++++++++++++++++
iocore/net/UnixNet.cc | 19 ++++++++-----------
iocore/net/UnixNetVConnection.cc | 12 ++++++++++++
3 files changed, 37 insertions(+), 11 deletions(-)
bisect run success
```
Those results seem to indicate that this PR has made the h2spec test to pass inconsistently:
https://github.com/apache/trafficserver/pull/7809
For those trying to reproduce these results:
* Docker image: `controller.trafficserver.org/ats/centos:8`
* `./configure --prefix /var/tmp/build --with-openssl=/opt/openssl-quic --enable-experimental-plugins --enable-example-plugins --enable-werror --enable-debug --enable-wccp`
* `./autest.sh --sandbox /tmp/sb_master --ats-bin /var/tmp/build/bin/ --clean=none -f h2spec`
--
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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 removed a comment on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
masaori335 removed a comment on issue #7915:
URL: https://github.com/apache/trafficserver/issues/7915#issuecomment-853571203
I got repro on my mac (intermittent failure of 2/5, 3.9/2, and 3.10/2).
--
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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 edited a comment on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
masaori335 edited a comment on issue #7915:
URL: https://github.com/apache/trafficserver/issues/7915#issuecomment-853600232
It looks like `http2/4.2/1` hangs intermittently. Debug logs with `http2|ssl` tag is below.
<details><summary>Debug logs of good case</summary>
```
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:388 (state_read_connection_preface)> (http2_cs) [3] [&Http2ClientSession::state_read_connection_preface, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:409 (state_read_connection_preface)> (http2_cs) [3] received connection preface
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=6, type=4, flags=0x0, streamid=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:566 (rcv_settings_frame)> (http2_con) [3] [0] Received SETTINGS frame
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:638 (rcv_settings_frame)> (http2_con) [3] [0] INITIAL_WINDOW_SIZE : 65535
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4057
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:719 (net_read_io)> (ssl) read finished - would block
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:780 (load_buffer_and_write)> (ssl) towrite=30
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:836 (load_buffer_and_write)> (ssl) try_to_write=30 written=30 total_written=30
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4057
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=9
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4048
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=25
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4023
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=34
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=0, type=4, flags=0x1, streamid=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:566 (rcv_settings_frame)> (http2_con) [3] [0] Received SETTINGS frame
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=16, type=1, flags=0x4, streamid=1
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:233 (rcv_headers_frame)> (http2_con) [3] [1] Received HEADERS frame
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [3] [1] Http2StreamState::HTTP2_STREAM_STATE_OPEN
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4023
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=4023
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=1872
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=2224
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=2224
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=8119
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=16384, type=0, flags=0x1, streamid=1
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=754
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=3342
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=3342
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=82
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=82
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:514 (state_complete_frame_read)> (http2_cs) [3] completed frame read, 16384 bytes available
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [3] [1] Received DATA frame
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [3] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [3] [1] Received DATA frame: rwnd con=49151/65535 stream=49151/65535
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:719 (net_read_io)> (ssl) read finished - would block
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1756 (send_headers_frame)> (http2_con) [3] [1] Send HEADERS frame
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1700 (send_a_data_frame)> (http2_con) [3] [1] Send a DATA frame - client window con: 65357 stream: 65357 payload: 178
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1700 (send_a_data_frame)> (http2_con) [3] [1] Send a DATA frame - client window con: 65357 stream: 65357 payload: 0
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1708 (send_a_data_frame)> (http2_con) [3] [1] END_STREAM
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [3] [1] Http2StreamState::HTTP2_STREAM_STATE_CLOSED
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1741 (send_data_frames)> (http2_con) [3] [1] Shutdown stream
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:493 (initiating_close)> (http2_stream) [3] [1] initiating_close
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:520 (initiating_close)> (http2_stream) [3] [1] handle write from destroy (event=103)
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:68 (~Http2Stream)> (http2_stream) [3] [1] Destroy stream, sent 178 bytes
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1487 (delete_stream)> (http2_con) [3] [1] Delete stream
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:780 (load_buffer_and_write)> (ssl) towrite=361
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:836 (load_buffer_and_write)> (ssl) try_to_write=361 written=361 total_written=361
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffe402d070, where: 16388, ret: 256, State: SSL negotiation finished successfully
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:334 (ssl_read_from_net)> (ssl.error) SSL_ERROR_ZERO_RETURN
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:327 (main_event_handler)> (http2_cs) [3] Closing event 104
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:239 (do_io_close)> (http2_cs) [3] session closed
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:78 (destroy)> (http2_cs) [3] session destroy
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:1694 (callHooks)> (ssl) sslHandshakeHookState=7 eventID=108
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:1811 (callHooks)> (ssl) iterated to curHook=(nil)
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:905 (do_io_close)> (ssl-shutdown) previous shutdown state 0x2
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:935 (do_io_close)> (ssl-shutdown) Enable quiet shutdown
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:106 (free)> (http2_cs) [3] session free
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:739 (net_read_io)> (ssl) read finished - 0 useful bytes read, bytes used by SSL layer
```
</details>
<details><summary>Debug logs of bad case </summary>
```
[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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 edited a comment on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
masaori335 edited a comment 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 of good case</summary>
```
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:388 (state_read_connection_preface)> (http2_cs) [3] [&Http2ClientSession::state_read_connection_preface, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:409 (state_read_connection_preface)> (http2_cs) [3] received connection preface
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=6, type=4, flags=0x0, streamid=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:566 (rcv_settings_frame)> (http2_con) [3] [0] Received SETTINGS frame
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:638 (rcv_settings_frame)> (http2_con) [3] [0] INITIAL_WINDOW_SIZE : 65535
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4057
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:719 (net_read_io)> (ssl) read finished - would block
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:780 (load_buffer_and_write)> (ssl) towrite=30
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:836 (load_buffer_and_write)> (ssl) try_to_write=30 written=30 total_written=30
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4057
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=9
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4048
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=25
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4023
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=34
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=0, type=4, flags=0x1, streamid=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:566 (rcv_settings_frame)> (http2_con) [3] [0] Received SETTINGS frame
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=16, type=1, flags=0x4, streamid=1
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:233 (rcv_headers_frame)> (http2_con) [3] [1] Received HEADERS frame
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [3] [1] Http2StreamState::HTTP2_STREAM_STATE_OPEN
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4023
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=4023
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=1872
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=2224
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=2224
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=8119
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=16384, type=0, flags=0x1, streamid=1
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=754
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=3342
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=3342
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=82
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=82
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:514 (state_complete_frame_read)> (http2_cs) [3] completed frame read, 16384 bytes available
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [3] [1] Received DATA frame
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [3] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [3] [1] Received DATA frame: rwnd con=49151/65535 stream=49151/65535
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:719 (net_read_io)> (ssl) read finished - would block
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1756 (send_headers_frame)> (http2_con) [3] [1] Send HEADERS frame
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1700 (send_a_data_frame)> (http2_con) [3] [1] Send a DATA frame - client window con: 65357 stream: 65357 payload: 178
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1700 (send_a_data_frame)> (http2_con) [3] [1] Send a DATA frame - client window con: 65357 stream: 65357 payload: 0
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1708 (send_a_data_frame)> (http2_con) [3] [1] END_STREAM
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [3] [1] Http2StreamState::HTTP2_STREAM_STATE_CLOSED
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1741 (send_data_frames)> (http2_con) [3] [1] Shutdown stream
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:493 (initiating_close)> (http2_stream) [3] [1] initiating_close
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:520 (initiating_close)> (http2_stream) [3] [1] handle write from destroy (event=103)
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:68 (~Http2Stream)> (http2_stream) [3] [1] Destroy stream, sent 178 bytes
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1487 (delete_stream)> (http2_con) [3] [1] Delete stream
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:780 (load_buffer_and_write)> (ssl) towrite=361
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:836 (load_buffer_and_write)> (ssl) try_to_write=361 written=361 total_written=361
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffe402d070, where: 16388, ret: 256, State: SSL negotiation finished successfully
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:334 (ssl_read_from_net)> (ssl.error) SSL_ERROR_ZERO_RETURN
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:327 (main_event_handler)> (http2_cs) [3] Closing event 104
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:239 (do_io_close)> (http2_cs) [3] session closed
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:78 (destroy)> (http2_cs) [3] session destroy
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:1694 (callHooks)> (ssl) sslHandshakeHookState=7 eventID=108
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:1811 (callHooks)> (ssl) iterated to curHook=(nil)
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:905 (do_io_close)> (ssl-shutdown) previous shutdown state 0x2
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:935 (do_io_close)> (ssl-shutdown) Enable quiet shutdown
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:106 (free)> (http2_cs) [3] session free
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:739 (net_read_io)> (ssl) read finished - 0 useful bytes read, bytes used by SSL layer
```
</details>
<details><summary>Debug logs of bad case </summary>
```
[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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 commented on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
masaori335 commented on issue #7915:
URL: https://github.com/apache/trafficserver/issues/7915#issuecomment-853639438
Debug log with `http` shows interesting thing. It might be some bug around connect retry and dechunk. I'm not sure how #7809 is related. It's possible I'm tracking another bug.
<details><summary>Debug logs of good case</summary>
```
+++++++++ Proxy's Request +++++++++
-- State Machine Id: 0
POST / HTTP/1.1
Host: 127.0.0.1:61000
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0)
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpTransact.cc:2243 (LookupSkipOpenServer)> (http_trans) Next action next; HttpTransact::HandleResponse
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:7359 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_ORIGIN_SERVER_OPEN
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:4922 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4]
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:4943 (do_http_server_open)> (http) [0] open connection to 127.0.0.1: 127.0.0.1:61000
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:4955 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpTransact.cc:6576 (will_this_request_self_loop)> (http_transact) [0] max_proxy_cycles = 0
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpTransact.cc:6582 (will_this_request_self_loop)> (http_transact) [0] dst_port = 61000 local_port = 61003
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpTransact.cc:6633 (will_this_request_self_loop)> (http_transact) [0] count = 0 <= max_proxy_cycles = 0 : allowing loop
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSessionManager.cc:413 (_acquire_session)> (http_ss) [acquire session] thread pool search failed
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:5267 (do_http_server_open)> (http) calling netProcessor.connect_re
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http1ServerSession.cc:89 (new_connection)> (http_ss) [1] session born, netvc 0x7fffec061c40
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1864 (state_http_server_open)> (http) [0] setting handler for TCP handshake
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [0] receiving frame header
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [0] frame header length=16384, type=0, flags=0x1, streamid=1
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:514 (state_complete_frame_read)> (http2_cs) [0] completed frame read, 16384 bytes available
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [0] [1] Received DATA frame
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [0] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [0] [1] Received DATA frame: rwnd con=49151/65535 stream=49151/65535
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:971 (state_watch_for_client_abort)> (http) [0] [&HttpSM::state_watch_for_client_abort, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [0] [&HttpSM::state_http_server_open, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1890 (state_http_server_open)> (http_ss) [0] TCP Handshake complete
+++++++++ Proxy's Request after hooks +++++++++
-- State Machine Id: 0
POST / HTTP/1.1
Host: 127.0.0.1:61000
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0)
Transfer-Encoding: chunked
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:2105 (state_send_server_request_header)> (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:596 (add_producer)> (http_tunnel) [0] adding producer 'user agent post'
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [0] adding consumer 'http server post'
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:698 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [0] producer_handler_dechunked [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 9
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [0] producer_handler_dechunked [user agent post VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [0 0 0] event: 102, state: 10
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:3579 (tunnel_handler_post_ua)> (http) [0] [&HttpSM::tunnel_handler_post_ua, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:3685 (tunnel_handler_post_server)> (http) [0] [&HttpSM::tunnel_handler_post_server, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:2787 (tunnel_handler_post)> (http) [0] [&HttpSM::tunnel_handler_post, HTTP_TUNNEL_EVENT_DONE]
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpSM.cc:1959 (state_read_server_response_header)> (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpSM.cc:2067 (state_read_server_response_header)> (http_seq) Done parsing server response header
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpSM.cc:8308 (clear)> (http_redirect) [PostDataBuffers::clear]
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:3468 (HandleResponse)> (http_trans) [0] [HttpTransact::HandleResponse]
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:3469 (HandleResponse)> (http_seq) [0] [HttpTransact::HandleResponse] Response received
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:3476 (HandleResponse)> (http_trans) [0] [HandleResponse] response_received_time: 1622704296
+++++++++ Incoming O.S. Response +++++++++
-- State Machine Id: 0
HTTP/1.1 405 METHOD NOT ALLOWED
Server: gunicorn
Date: Thu, 03 Jun 2021 07:11:36 GMT
Connection: close
Content-Type: text/html; charset=utf-8
Allow: HEAD, GET, OPTIONS
Content-Length: 178
Access-Control-Allow-Origin: *
Access-Control-Allow-Credentials: true
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:334 (is_response_valid)> (http_trans) [0] [is_response_valid] No errors in response
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:3493 (HandleResponse)> (http_seq) [0] [HttpTransact::HandleResponse] Response valid
```
</details>
<details><summary>Debug logs of bad case</summary>
```
+++++++++ Proxy's Request +++++++++
-- State Machine Id: 2
POST / HTTP/1.1
Host: 127.0.0.1:61000
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0)
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpTransact.cc:2243 (LookupSkipOpenServer)> (http_trans) Next action next; HttpTransact::HandleResponse
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:7359 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_ORIGIN_SERVER_OPEN
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:4922 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4]
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:4943 (do_http_server_open)> (http) [2] open connection to 127.0.0.1: 127.0.0.1:61000
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:4955 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpTransact.cc:6576 (will_this_request_self_loop)> (http_transact) [2] max_proxy_cycles = 0
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpTransact.cc:6582 (will_this_request_self_loop)> (http_transact) [2] dst_port = 61000 local_port = 61003
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpTransact.cc:6633 (will_this_request_self_loop)> (http_transact) [2] count = 0 <= max_proxy_cycles = 0 : allowing loop
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSessionManager.cc:413 (_acquire_session)> (http_ss) [acquire session] thread pool search failed
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:5267 (do_http_server_open)> (http) calling netProcessor.connect_re
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT]
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [2] [&HttpSM::state_http_server_open, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT]
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http1ServerSession.cc:89 (new_connection)> (http_ss) [5] session born, netvc 0x7fffec0614c0
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:1864 (state_http_server_open)> (http) [2] setting handler for TCP handshake
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [4] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [4] receiving frame header
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [4] frame header length=16384, type=0, flags=0x1, streamid=1
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [4] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [4] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [4] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ClientSession.cc:514 (state_complete_frame_read)> (http2_cs) [4] completed frame read, 16384 bytes available
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [4] [1] Received DATA frame
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [4] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [4] [1] Received DATA frame: rwnd con=49151/65535 stream=49151/65535
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:971 (state_watch_for_client_abort)> (http) [2] [&HttpSM::state_watch_for_client_abort, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [2] [&HttpSM::state_http_server_open, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:1890 (state_http_server_open)> (http_ss) [2] TCP Handshake complete
+++++++++ Proxy's Request after hooks +++++++++
-- State Machine Id: 2
POST / HTTP/1.1
Host: 127.0.0.1:61000
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0)
Transfer-Encoding: chunked
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2105 (state_send_server_request_header)> (http) [2] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:596 (add_producer)> (http_tunnel) [2] adding producer 'user agent post'
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [2] adding consumer 'http server post'
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:698 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [2] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [2] producer_handler_dechunked [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 9
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [2] consumer_handler [http server post VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [2] producer_handler [user agent post VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [2] producer_handler_dechunked [user agent post VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [0 0 0] event: 102, state: 10
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:3579 (tunnel_handler_post_ua)> (http) [2] [&HttpSM::tunnel_handler_post_ua, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [2] consumer_handler [http server post VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:3685 (tunnel_handler_post_server)> (http) [2] [&HttpSM::tunnel_handler_post_server, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2787 (tunnel_handler_post)> (http) [2] [&HttpSM::tunnel_handler_post, HTTP_TUNNEL_EVENT_DONE]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1959 (state_read_server_response_header)> (http) [2] [&HttpSM::state_read_server_response_header, EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:5636 (handle_server_setup_error)> (http) [2] [&HttpSM::handle_server_setup_error, EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <Http1ServerSession.cc:138 (do_io_close)> (http_ss) [5] session close: nevtc 0x7fffec0614c0
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3468 (HandleResponse)> (http_trans) [2] [HttpTransact::HandleResponse]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3469 (HandleResponse)> (http_seq) [2] [HttpTransact::HandleResponse] Response received
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3476 (HandleResponse)> (http_trans) [2] [HandleResponse] response_received_time: 1622704426
+++++++++ Incoming O.S. Response +++++++++
-- State Machine Id: 2
HTTP/1.0 0
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3491 (HandleResponse)> (http_seq) [2] [HttpTransact::HandleResponse] Response not valid
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3760 (handle_response_from_server)> (http_trans) [2] [handle_response_from_server] (hrfs)
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3798 (handle_response_from_server)> (http_trans) [2] max_connect_retries: 3 s->current.attempts: 0
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3892 (error_log_connection_failure)> (http_trans) [2] [0] failed to connect [5] to 127.0.0.1
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3942 (retry_server_connection_not_open)> (http_trans) [2] [retry_server_connection_not_open] attempts now: 1, max: 3
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3822 (handle_response_from_server)> (http_trans) [2] [handle_response_from_server] Error. Retrying...
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:7359 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_ORIGIN_SERVER_OPEN
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:4922 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:4943 (do_http_server_open)> (http) [2] open connection to 127.0.0.1: 127.0.0.1:61000
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:4955 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:6576 (will_this_request_self_loop)> (http_transact) [2] max_proxy_cycles = 0
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:6582 (will_this_request_self_loop)> (http_transact) [2] dst_port = 61000 local_port = 61003
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:6633 (will_this_request_self_loop)> (http_transact) [2] count = 0 <= max_proxy_cycles = 0 : allowing loop
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSessionManager.cc:413 (_acquire_session)> (http_ss) [acquire session] thread pool search failed
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:5267 (do_http_server_open)> (http) calling netProcessor.connect_re
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [2] [&HttpSM::state_http_server_open, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <Http1ServerSession.cc:89 (new_connection)> (http_ss) [6] session born, netvc 0x7fffec061100
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1864 (state_http_server_open)> (http) [2] setting handler for TCP handshake
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [2] [&HttpSM::state_http_server_open, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1890 (state_http_server_open)> (http_ss) [2] TCP Handshake complete
+++++++++ Proxy's Request after hooks +++++++++
-- State Machine Id: 2
POST / HTTP/1.1
Host: 127.0.0.1:61000
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0)
Transfer-Encoding: chunked, chunked
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2105 (state_send_server_request_header)> (http) [2] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:596 (add_producer)> (http_tunnel) [2] adding producer 'user agent post'
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [2] adding consumer 'http server post'
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:698 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [2] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [2] producer_handler_dechunked [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 9
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [2] consumer_handler [http server post VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
# timeout
```
</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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 edited a comment on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
masaori335 edited a comment on issue #7915:
URL: https://github.com/apache/trafficserver/issues/7915#issuecomment-853639438
Debug log with `http` tag is more interesting. It might be some bug around connect retry and dechunk. I'm not sure how #7809 is related. It's possible I'm tracking another bug.
<details><summary>Debug logs of good case</summary>
```
+++++++++ Proxy's Request +++++++++
-- State Machine Id: 0
POST / HTTP/1.1
Host: 127.0.0.1:61000
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0)
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpTransact.cc:2243 (LookupSkipOpenServer)> (http_trans) Next action next; HttpTransact::HandleResponse
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:7359 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_ORIGIN_SERVER_OPEN
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:4922 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4]
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:4943 (do_http_server_open)> (http) [0] open connection to 127.0.0.1: 127.0.0.1:61000
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:4955 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpTransact.cc:6576 (will_this_request_self_loop)> (http_transact) [0] max_proxy_cycles = 0
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpTransact.cc:6582 (will_this_request_self_loop)> (http_transact) [0] dst_port = 61000 local_port = 61003
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpTransact.cc:6633 (will_this_request_self_loop)> (http_transact) [0] count = 0 <= max_proxy_cycles = 0 : allowing loop
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSessionManager.cc:413 (_acquire_session)> (http_ss) [acquire session] thread pool search failed
[Jun 3 07:11:36.803] [ET_NET 0] DEBUG: <HttpSM.cc:5267 (do_http_server_open)> (http) calling netProcessor.connect_re
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http1ServerSession.cc:89 (new_connection)> (http_ss) [1] session born, netvc 0x7fffec061c40
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1864 (state_http_server_open)> (http) [0] setting handler for TCP handshake
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [0] receiving frame header
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [0] frame header length=16384, type=0, flags=0x1, streamid=1
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [0] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ClientSession.cc:514 (state_complete_frame_read)> (http2_cs) [0] completed frame read, 16384 bytes available
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [0] [1] Received DATA frame
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [0] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [0] [1] Received DATA frame: rwnd con=49151/65535 stream=49151/65535
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:971 (state_watch_for_client_abort)> (http) [0] [&HttpSM::state_watch_for_client_abort, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [0] [&HttpSM::state_http_server_open, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:11:36.804] [ET_NET 0] DEBUG: <HttpSM.cc:1890 (state_http_server_open)> (http_ss) [0] TCP Handshake complete
+++++++++ Proxy's Request after hooks +++++++++
-- State Machine Id: 0
POST / HTTP/1.1
Host: 127.0.0.1:61000
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0)
Transfer-Encoding: chunked
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:2105 (state_send_server_request_header)> (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:596 (add_producer)> (http_tunnel) [0] adding producer 'user agent post'
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [0] adding consumer 'http server post'
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:698 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [0] producer_handler_dechunked [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 9
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [0] producer_handler [user agent post VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [0] producer_handler_dechunked [user agent post VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [0 0 0] event: 102, state: 10
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:3579 (tunnel_handler_post_ua)> (http) [0] [&HttpSM::tunnel_handler_post_ua, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [0] consumer_handler [http server post VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:3685 (tunnel_handler_post_server)> (http) [0] [&HttpSM::tunnel_handler_post_server, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Jun 3 07:11:36.805] [ET_NET 0] DEBUG: <HttpSM.cc:2787 (tunnel_handler_post)> (http) [0] [&HttpSM::tunnel_handler_post, HTTP_TUNNEL_EVENT_DONE]
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpSM.cc:1959 (state_read_server_response_header)> (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpSM.cc:2067 (state_read_server_response_header)> (http_seq) Done parsing server response header
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpSM.cc:8308 (clear)> (http_redirect) [PostDataBuffers::clear]
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:3468 (HandleResponse)> (http_trans) [0] [HttpTransact::HandleResponse]
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:3469 (HandleResponse)> (http_seq) [0] [HttpTransact::HandleResponse] Response received
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:3476 (HandleResponse)> (http_trans) [0] [HandleResponse] response_received_time: 1622704296
+++++++++ Incoming O.S. Response +++++++++
-- State Machine Id: 0
HTTP/1.1 405 METHOD NOT ALLOWED
Server: gunicorn
Date: Thu, 03 Jun 2021 07:11:36 GMT
Connection: close
Content-Type: text/html; charset=utf-8
Allow: HEAD, GET, OPTIONS
Content-Length: 178
Access-Control-Allow-Origin: *
Access-Control-Allow-Credentials: true
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:334 (is_response_valid)> (http_trans) [0] [is_response_valid] No errors in response
[Jun 3 07:11:36.806] [ET_NET 0] DEBUG: <HttpTransact.cc:3493 (HandleResponse)> (http_seq) [0] [HttpTransact::HandleResponse] Response valid
```
</details>
<details><summary>Debug logs of bad case</summary>
```
+++++++++ Proxy's Request +++++++++
-- State Machine Id: 2
POST / HTTP/1.1
Host: 127.0.0.1:61000
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0)
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpTransact.cc:2243 (LookupSkipOpenServer)> (http_trans) Next action next; HttpTransact::HandleResponse
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:7359 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_ORIGIN_SERVER_OPEN
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:4922 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4]
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:4943 (do_http_server_open)> (http) [2] open connection to 127.0.0.1: 127.0.0.1:61000
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:4955 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpTransact.cc:6576 (will_this_request_self_loop)> (http_transact) [2] max_proxy_cycles = 0
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpTransact.cc:6582 (will_this_request_self_loop)> (http_transact) [2] dst_port = 61000 local_port = 61003
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpTransact.cc:6633 (will_this_request_self_loop)> (http_transact) [2] count = 0 <= max_proxy_cycles = 0 : allowing loop
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSessionManager.cc:413 (_acquire_session)> (http_ss) [acquire session] thread pool search failed
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:5267 (do_http_server_open)> (http) calling netProcessor.connect_re
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT]
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [2] [&HttpSM::state_http_server_open, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT]
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http1ServerSession.cc:89 (new_connection)> (http_ss) [5] session born, netvc 0x7fffec0614c0
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <HttpSM.cc:1864 (state_http_server_open)> (http) [2] setting handler for TCP handshake
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [4] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [4] receiving frame header
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [4] frame header length=16384, type=0, flags=0x1, streamid=1
[Jun 3 07:13:46.007] [ET_NET 2] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [4] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [4] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [4] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ClientSession.cc:514 (state_complete_frame_read)> (http2_cs) [4] completed frame read, 16384 bytes available
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [4] [1] Received DATA frame
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [4] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [4] [1] Received DATA frame: rwnd con=49151/65535 stream=49151/65535
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:971 (state_watch_for_client_abort)> (http) [2] [&HttpSM::state_watch_for_client_abort, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [2] [&HttpSM::state_http_server_open, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:1890 (state_http_server_open)> (http_ss) [2] TCP Handshake complete
+++++++++ Proxy's Request after hooks +++++++++
-- State Machine Id: 2
POST / HTTP/1.1
Host: 127.0.0.1:61000
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0)
Transfer-Encoding: chunked
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2105 (state_send_server_request_header)> (http) [2] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:596 (add_producer)> (http_tunnel) [2] adding producer 'user agent post'
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [2] adding consumer 'http server post'
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:698 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [2] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [2] producer_handler_dechunked [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:335 (generate_chunked_content)> (http_chunk) creating a chunk of size 4096 bytes
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 9
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [2] consumer_handler [http server post VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [2] producer_handler [user agent post VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [2] producer_handler_dechunked [user agent post VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [0 0 0] event: 102, state: 10
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:3579 (tunnel_handler_post_ua)> (http) [2] [&HttpSM::tunnel_handler_post_ua, VC_EVENT_READ_COMPLETE/TS_EVENT_VCONN_READ_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [2] consumer_handler [http server post VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:3685 (tunnel_handler_post_server)> (http) [2] [&HttpSM::tunnel_handler_post_server, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Jun 3 07:13:46.008] [ET_NET 2] DEBUG: <HttpSM.cc:2787 (tunnel_handler_post)> (http) [2] [&HttpSM::tunnel_handler_post, HTTP_TUNNEL_EVENT_DONE]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1959 (state_read_server_response_header)> (http) [2] [&HttpSM::state_read_server_response_header, EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:5636 (handle_server_setup_error)> (http) [2] [&HttpSM::handle_server_setup_error, EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <Http1ServerSession.cc:138 (do_io_close)> (http_ss) [5] session close: nevtc 0x7fffec0614c0
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3468 (HandleResponse)> (http_trans) [2] [HttpTransact::HandleResponse]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3469 (HandleResponse)> (http_seq) [2] [HttpTransact::HandleResponse] Response received
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3476 (HandleResponse)> (http_trans) [2] [HandleResponse] response_received_time: 1622704426
+++++++++ Incoming O.S. Response +++++++++
-- State Machine Id: 2
HTTP/1.0 0
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3491 (HandleResponse)> (http_seq) [2] [HttpTransact::HandleResponse] Response not valid
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3760 (handle_response_from_server)> (http_trans) [2] [handle_response_from_server] (hrfs)
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3798 (handle_response_from_server)> (http_trans) [2] max_connect_retries: 3 s->current.attempts: 0
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3892 (error_log_connection_failure)> (http_trans) [2] [0] failed to connect [5] to 127.0.0.1
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3942 (retry_server_connection_not_open)> (http_trans) [2] [retry_server_connection_not_open] attempts now: 1, max: 3
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:3822 (handle_response_from_server)> (http_trans) [2] [handle_response_from_server] Error. Retrying...
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:7359 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_ORIGIN_SERVER_OPEN
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:4922 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:4943 (do_http_server_open)> (http) [2] open connection to 127.0.0.1: 127.0.0.1:61000
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:4955 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:6576 (will_this_request_self_loop)> (http_transact) [2] max_proxy_cycles = 0
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:6582 (will_this_request_self_loop)> (http_transact) [2] dst_port = 61000 local_port = 61003
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTransact.cc:6633 (will_this_request_self_loop)> (http_transact) [2] count = 0 <= max_proxy_cycles = 0 : allowing loop
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSessionManager.cc:413 (_acquire_session)> (http_ss) [acquire session] thread pool search failed
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:5267 (do_http_server_open)> (http) calling netProcessor.connect_re
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [2] [&HttpSM::state_http_server_open, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <Http1ServerSession.cc:89 (new_connection)> (http_ss) [6] session born, netvc 0x7fffec061100
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1864 (state_http_server_open)> (http) [2] setting handler for TCP handshake
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1812 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1813 (state_http_server_open)> (http) [2] [&HttpSM::state_http_server_open, VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:1890 (state_http_server_open)> (http_ss) [2] TCP Handshake complete
+++++++++ Proxy's Request after hooks +++++++++
-- State Machine Id: 2
POST / HTTP/1.1
Host: 127.0.0.1:61000
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
Via: https/2 traffic_server[d29ec0f7-e508-4253-8847-da0615dd3101] (ApacheTrafficServer/10.0.0)
Transfer-Encoding: chunked, chunked
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2686 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpSM.cc:2105 (state_send_server_request_header)> (http) [2] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:596 (add_producer)> (http_tunnel) [2] adding producer 'user agent post'
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [2] adding consumer 'http server post'
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:698 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [2] producer_handler [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:1000 (producer_handler_dechunked)> (http_tunnel) [2] producer_handler_dechunked [user agent post VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:1148 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 100, state: 9
[Jun 3 07:13:46.009] [ET_NET 2] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [2] consumer_handler [http server post VC_EVENT_WRITE_READY/TS_EVENT_VCONN_WRITE_READY]
# timeout
```
</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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 commented on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
masaori335 commented on issue #7915:
URL: https://github.com/apache/trafficserver/issues/7915#issuecomment-855543295
After #7809, `read_from_net` raises `VC_EVENT_ERROR` when the origin server resets the connection after sending the response.
<details><summary>`VC_EVENT_ERROR` on `HttpSM::state_read_server_response_header`</summary>
```
(gdb) bt
#0 HttpSM::state_read_server_response_header (this=0x7ffff02a03b0, event=3, data=0x7fffec1552e8) at HttpSM.cc:1981
#1 0x0000000000594768 in HttpSM::main_handler (this=0x7ffff02a03b0, event=3, data=0x7fffec1552e8) at HttpSM.cc:2703
#2 0x00000000007e052e in read_signal_and_update (event=3, vc=0x7fffec155100) at UnixNetVConnection.cc:83
#3 0x00000000007e4f41 in UnixNetVConnection::readSignalAndUpdate (event=3, this=0x7fffec155100) at UnixNetVConnection.cc:1043
#4 read_from_net (nh=0x7ffff3845180, vc=0x7fffec155100, thread=0x7ffff3841010) at UnixNetVConnection.cc:204
#5 0x00000000007d1947 in NetHandler::process_ready_list (this=this@entry=0x7ffff3845180) at UnixNet.cc:415
#6 0x00000000007d1d13 in NetHandler::waitForActivity (this=0x7ffff3845180, timeout=<optimized out>) at UnixNet.cc:546
#7 0x00000000008271aa in EThread::execute_regular (this=this@entry=0x7ffff3841010) at I_PriorityEventQueue.h:115
#8 0x0000000000827412 in EThread::execute (this=0x7ffff3841010) at UnixEThread.cc:364
#9 EThread::execute (this=0x7ffff3841010) at UnixEThread.cc:342
#10 0x00000000008257ea in spawn_thread_internal (a=0xd5e7f0) at Thread.cc:92
#11 0x00007ffff68a614a in start_thread () from /lib64/libpthread.so.0
#12 0x00007ffff5aa4f23 in clone () from /lib64/libc.so.6
(gdb) frame 4
#4 read_from_net (nh=0x7ffff3845180, vc=0x7fffec155100, thread=0x7ffff3841010) at UnixNetVConnection.cc:204
204 vc->readSignalAndUpdate(VC_EVENT_ERROR);
(gdb) p vc->error
$1 = 104
```
</details>
<details><summary>tcpdump trafficserver <-> origin server</summary>
```
1 2021-06-07 02:51:09.889582 0.000000 TCP 127.0.0.1 51260 127.0.0.1 61000 74 51260 → 61000 [SYN] Seq=0 Win=43690 Len=0 MSS=65495 SACK_PERM=1 TSval=1062468354 TSecr=0 WS=128
2 2021-06-07 02:51:09.889596 0.000014 TCP 127.0.0.1 61000 127.0.0.1 51260 74 61000 → 51260 [SYN, ACK] Seq=0 Ack=1 Win=43690 Len=0 MSS=65495 SACK_PERM=1 TSval=1062468354 TSecr=1062468354 WS=128
3 2021-06-07 02:51:09.889605 0.000023 TCP 127.0.0.1 51260 127.0.0.1 61000 66 51260 → 61000 [ACK] Seq=1 Ack=1 Win=43776 Len=0 TSval=1062468354 TSecr=1062468354
4 2021-06-07 02:51:09.889839 0.000257 TCP 127.0.0.1 51260 127.0.0.1 61000 282 POST / HTTP/1.1 [TCP segment of a reassembled PDU]
5 2021-06-07 02:51:09.889845 0.000263 TCP 127.0.0.1 61000 127.0.0.1 51260 66 61000 → 51260 [ACK] Seq=1 Ack=217 Win=44800 Len=0 TSval=1062468355 TSecr=1062468355
6 2021-06-07 02:51:09.889993 0.000411 HTTP 127.0.0.1 51260 127.0.0.1 61000 16487 POST / HTTP/1.1
7 2021-06-07 02:51:09.889999 0.000417 TCP 127.0.0.1 61000 127.0.0.1 51260 66 61000 → 51260 [ACK] Seq=1 Ack=16638 Win=175744 Len=0 TSval=1062468355 TSecr=1062468355
8 2021-06-07 02:51:09.891157 0.001575 TCP 127.0.0.1 61000 127.0.0.1 51260 335 HTTP/1.1 405 METHOD NOT ALLOWED [TCP segment of a reassembled PDU]
9 2021-06-07 02:51:09.891169 0.001587 TCP 127.0.0.1 51260 127.0.0.1 61000 66 51260 → 61000 [ACK] Seq=16638 Ack=270 Win=44800 Len=0 TSval=1062468356 TSecr=1062468356
10 2021-06-07 02:51:09.891184 0.001602 HTTP 127.0.0.1 61000 127.0.0.1 51260 244 HTTP/1.1 405 METHOD NOT ALLOWED (text/html)
11 2021-06-07 02:51:09.891189 0.001607 TCP 127.0.0.1 51260 127.0.0.1 61000 66 51260 → 61000 [ACK] Seq=16638 Ack=448 Win=45952 Len=0 TSval=1062468356 TSecr=1062468356
12 2021-06-07 02:51:09.891231 0.001649 TCP 127.0.0.1 61000 127.0.0.1 51260 66 61000 → 51260 [RST, ACK] Seq=448 Ack=16638 Win=175744 Len=0 TSval=1062468356 TSecr=1062468356
```
</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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 closed issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
masaori335 closed issue #7915:
URL: https://github.com/apache/trafficserver/issues/7915
--
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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 edited a comment on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
masaori335 edited a comment 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 of good case</summary>
```
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:388 (state_read_connection_preface)> (http2_cs) [3] [&Http2ClientSession::state_read_connection_preface, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:409 (state_read_connection_preface)> (http2_cs) [3] received connection preface
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=6, type=4, flags=0x0, streamid=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:566 (rcv_settings_frame)> (http2_con) [3] [0] Received SETTINGS frame
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:638 (rcv_settings_frame)> (http2_con) [3] [0] INITIAL_WINDOW_SIZE : 65535
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4057
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:719 (net_read_io)> (ssl) read finished - would block
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:780 (load_buffer_and_write)> (ssl) towrite=30
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:836 (load_buffer_and_write)> (ssl) try_to_write=30 written=30 total_written=30
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4057
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=9
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4048
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=25
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4023
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=34
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=0, type=4, flags=0x1, streamid=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:566 (rcv_settings_frame)> (http2_con) [3] [0] Received SETTINGS frame
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=16, type=1, flags=0x4, streamid=1
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:233 (rcv_headers_frame)> (http2_con) [3] [1] Received HEADERS frame
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [3] [1] Http2StreamState::HTTP2_STREAM_STATE_OPEN
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4023
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=4023
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=1872
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=2224
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=2224
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=8119
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=16384, type=0, flags=0x1, streamid=1
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=754
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=3342
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=3342
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=82
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=82
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:514 (state_complete_frame_read)> (http2_cs) [3] completed frame read, 16384 bytes available
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [3] [1] Received DATA frame
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [3] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [3] [1] Received DATA frame: rwnd con=49151/65535 stream=49151/65535
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:719 (net_read_io)> (ssl) read finished - would block
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1756 (send_headers_frame)> (http2_con) [3] [1] Send HEADERS frame
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1700 (send_a_data_frame)> (http2_con) [3] [1] Send a DATA frame - client window con: 65357 stream: 65357 payload: 178
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1700 (send_a_data_frame)> (http2_con) [3] [1] Send a DATA frame - client window con: 65357 stream: 65357 payload: 0
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1708 (send_a_data_frame)> (http2_con) [3] [1] END_STREAM
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [3] [1] Http2StreamState::HTTP2_STREAM_STATE_CLOSED
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1741 (send_data_frames)> (http2_con) [3] [1] Shutdown stream
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:493 (initiating_close)> (http2_stream) [3] [1] initiating_close
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:520 (initiating_close)> (http2_stream) [3] [1] handle write from destroy (event=103)
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:68 (~Http2Stream)> (http2_stream) [3] [1] Destroy stream, sent 178 bytes
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1487 (delete_stream)> (http2_con) [3] [1] Delete stream
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:780 (load_buffer_and_write)> (ssl) towrite=361
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:836 (load_buffer_and_write)> (ssl) try_to_write=361 written=361 total_written=361
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffe402d070, where: 16388, ret: 256, State: SSL negotiation finished successfully
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:334 (ssl_read_from_net)> (ssl.error) SSL_ERROR_ZERO_RETURN
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:327 (main_event_handler)> (http2_cs) [3] Closing event 104
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:239 (do_io_close)> (http2_cs) [3] session closed
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:78 (destroy)> (http2_cs) [3] session destroy
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:1694 (callHooks)> (ssl) sslHandshakeHookState=7 eventID=108
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:1811 (callHooks)> (ssl) iterated to curHook=(nil)
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:905 (do_io_close)> (ssl-shutdown) previous shutdown state 0x2
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:935 (do_io_close)> (ssl-shutdown) Enable quiet shutdown
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:106 (free)> (http2_cs) [3] session free
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:739 (net_read_io)> (ssl) read finished - 0 useful bytes read, bytes used by SSL layer
```
</details>
<details><summary>Debug logs of bad case </summary>
```
[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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 edited a comment on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
masaori335 edited a comment on issue #7915:
URL: https://github.com/apache/trafficserver/issues/7915#issuecomment-853600232
It looks like `http2/4.2/1` hangs intermittently. Debug logs with `http2|ssl` is below.
<details><summary>Debug logs of good case</summary>
```
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:388 (state_read_connection_preface)> (http2_cs) [3] [&Http2ClientSession::state_read_connection_preface, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:409 (state_read_connection_preface)> (http2_cs) [3] received connection preface
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=6, type=4, flags=0x0, streamid=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:566 (rcv_settings_frame)> (http2_con) [3] [0] Received SETTINGS frame
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:638 (rcv_settings_frame)> (http2_con) [3] [0] INITIAL_WINDOW_SIZE : 65535
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4057
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:719 (net_read_io)> (ssl) read finished - would block
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:780 (load_buffer_and_write)> (ssl) towrite=30
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:836 (load_buffer_and_write)> (ssl) try_to_write=30 written=30 total_written=30
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4057
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=9
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4048
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=25
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4023
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=34
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=0, type=4, flags=0x1, streamid=0
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:566 (rcv_settings_frame)> (http2_con) [3] [0] Received SETTINGS frame
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=16, type=1, flags=0x4, streamid=1
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:233 (rcv_headers_frame)> (http2_con) [3] [1] Received HEADERS frame
[Jun 3 06:20:45.062] [ET_NET 1] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [3] [1] Http2StreamState::HTTP2_STREAM_STATE_OPEN
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4023
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=4023
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=1872
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=2224
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=2224
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=8119
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:438 (state_start_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_start_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:452 (do_start_frame_read)> (http2_cs) [3] receiving frame header
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:469 (do_start_frame_read)> (http2_cs) [3] frame header length=16384, type=0, flags=0x1, streamid=1
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=754
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=3342
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=3342
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4096
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=82
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:349 (ssl_read_from_net)> (ssl) bytes_read=82
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:499 (state_complete_frame_read)> (http2_cs) [3] [&Http2ClientSession::state_complete_frame_read, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ClientSession.cc:514 (state_complete_frame_read)> (http2_cs) [3] completed frame read, 16384 bytes available
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:89 (rcv_data_frame)> (http2_con) [3] [1] Received DATA frame
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [3] [1] Http2StreamState::HTTP2_STREAM_STATE_HALF_CLOSED_REMOTE
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:176 (rcv_data_frame)> (http2_con) [3] [1] Received DATA frame: rwnd con=49151/65535 stream=49151/65535
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:308 (ssl_read_from_net)> (ssl.error) SSL_ERROR_WOULD_BLOCK(read)
[Jun 3 06:20:45.063] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:719 (net_read_io)> (ssl) read finished - would block
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1756 (send_headers_frame)> (http2_con) [3] [1] Send HEADERS frame
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1700 (send_a_data_frame)> (http2_con) [3] [1] Send a DATA frame - client window con: 65357 stream: 65357 payload: 178
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1700 (send_a_data_frame)> (http2_con) [3] [1] Send a DATA frame - client window con: 65357 stream: 65357 payload: 0
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1708 (send_a_data_frame)> (http2_con) [3] [1] END_STREAM
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:370 (change_state)> (http2_stream) [3] [1] Http2StreamState::HTTP2_STREAM_STATE_CLOSED
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1741 (send_data_frames)> (http2_con) [3] [1] Shutdown stream
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:493 (initiating_close)> (http2_stream) [3] [1] initiating_close
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:520 (initiating_close)> (http2_stream) [3] [1] handle write from destroy (event=103)
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2Stream.cc:68 (~Http2Stream)> (http2_stream) [3] [1] Destroy stream, sent 178 bytes
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <Http2ConnectionState.cc:1487 (delete_stream)> (http2_con) [3] [1] Delete stream
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:780 (load_buffer_and_write)> (ssl) towrite=361
[Jun 3 06:20:45.064] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:836 (load_buffer_and_write)> (ssl) try_to_write=361 written=361 total_written=361
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:282 (ssl_read_from_net)> (ssl) amount_to_read=4014
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLUtils.cc:1074 (ssl_callback_info)> (ssl) ssl_callback_info ssl: 0x7fffe402d070, where: 16388, ret: 256, State: SSL negotiation finished successfully
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:287 (ssl_read_from_net)> (ssl) nread=0
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:334 (ssl_read_from_net)> (ssl.error) SSL_ERROR_ZERO_RETURN
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:327 (main_event_handler)> (http2_cs) [3] Closing event 104
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:239 (do_io_close)> (http2_cs) [3] session closed
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:78 (destroy)> (http2_cs) [3] session destroy
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:1694 (callHooks)> (ssl) sslHandshakeHookState=7 eventID=108
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:1811 (callHooks)> (ssl) iterated to curHook=(nil)
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:905 (do_io_close)> (ssl-shutdown) previous shutdown state 0x2
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:935 (do_io_close)> (ssl-shutdown) Enable quiet shutdown
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <Http2ClientSession.cc:106 (free)> (http2_cs) [3] session free
[Jun 3 06:20:45.065] [ET_NET 1] DEBUG: <SSLNetVConnection.cc:739 (net_read_io)> (ssl) read finished - 0 useful bytes read, bytes used by SSL layer
```
</details>
<details><summary>Debug logs of bad case </summary>
```
[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:
users@infra.apache.org
[GitHub] [trafficserver] shinrich commented on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
shinrich commented on issue #7915:
URL: https://github.com/apache/trafficserver/issues/7915#issuecomment-854897410
Weird. Hitting proxy-requests after hooks 2 times seems very bad.
--
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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 commented on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 removed a comment on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
masaori335 removed a comment on issue #7915:
URL: https://github.com/apache/trafficserver/issues/7915#issuecomment-853571203
I got repro on my mac (intermittent failure of 2/5, 3.9/2, and 3.10/2).
--
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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 commented on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
masaori335 commented on issue #7915:
URL: https://github.com/apache/trafficserver/issues/7915#issuecomment-853571203
I got repro on my mac (intermittent failure of 2/5, 3.9/2, and 3.10/2).
--
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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 edited a comment on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
masaori335 edited a comment on issue #7915:
URL: https://github.com/apache/trafficserver/issues/7915#issuecomment-853600232
--
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:
users@infra.apache.org
[GitHub] [trafficserver] masaori335 commented on issue #7915: h2spec.test.py has become flakey
Posted by GitBox <gi...@apache.org>.
masaori335 commented on issue #7915:
URL: https://github.com/apache/trafficserver/issues/7915#issuecomment-853571203
--
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:
users@infra.apache.org