Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

http3+ngtcp2: Transfer hangs with default libcurl receive buffer size #4525

Closed
jblazquez opened this issue Oct 26, 2019 · 21 comments
Labels

Comments

@jblazquez
Copy link
Contributor

@jblazquez jblazquez commented Oct 26, 2019

I did this

I used curl built against ngtcp2 to download a small 37KB file over HTTP/3 using the default libcurl CURLOPT_BUFFERSIZE value of 16KB:

curl --http3 --limit-rate 16384 \
https://http3.dyn.test.riotcdn.net/channels/public/releases/89D5A1AB60F28C21.manifest \
>/dev/null

Note that since the curl tool overrides CURLOPT_BUFFERSIZE with a 100KB buffer by default, I had to pass --limit-rate 16384 to make it use the 16KB value that users of libcurl that leave CURLOPT_BUFFERSIZE untouched would get. The problem is not related to speed limits, but rather download buffer sizes.

I expected the following

I expected the transfer to complete successfully, but at least half of the time it hangs after downloading most of the file. For example, here it is after 30 seconds of no progress at 37433 of 37708 bytes downloaded:

99 37708   99 37433    0     0   1113      0  0:00:30  0:00:30 --:--:--     0

The lower the download buffer size, the more likely it is for the transfer to hang. With large buffer sizes it's still possible to make it hang, but it's much less likely.

curl/libcurl version

curl 7.67.0-DEV (x86_64-pc-linux-gnu) libcurl/7.67.0-DEV OpenSSL/3.0.0 ngtcp2/0.1.0-DEV nghttp3/0.1.0-DEV
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: AsynchDNS HTTP3 HTTPS-proxy IPv6 Largefile NTLM NTLM_WB SSL TLS-SRP UnixSockets

This was built as follows:

$ git clone --depth 1 -b openssl-quic-draft-23 https://github.com/tatsuhiro-t/openssl
$ cd openssl
$ ./config enable-tls1_3 --prefix=$PWD/out
$ make -j$(nproc) && make install_sw
$ cd ..
$ git clone https://github.com/ngtcp2/nghttp3
$ cd nghttp3
$ autoreconf -i
$ ./configure --prefix=$PWD/out --enable-lib-only --enable-debug
$ make -j$(nproc) install
$ cd ..
$ git clone https://github.com/ngtcp2/ngtcp2
$ cd ngtcp2
$ autoreconf -i
$ ./configure PKG_CONFIG_PATH=$PWD/../openssl/out/lib/pkgconfig:$PWD/../nghttp3/out/lib/pkgconfig LDFLAGS="-Wl,-rpath,$PWD/../openssl/out/lib" --prefix=$PWD/out --enable-debug
$ make -j$(nproc) install
$ cd ..
$ git clone https://github.com/curl/curl
$ cd curl
$ ./buildconf
$ CPPFLAGS="-DDEBUG_NGTCP2" LDFLAGS="-Wl,-rpath,$PWD/../openssl/out/lib" ./configure --with-ssl=$PWD/../openssl/out --with-nghttp3=$PWD/../nghttp3/out --with-ngtcp2=$PWD/../ngtcp2/out
$ make -j$(nproc)

Git commits per repo:

OpenSSL: tatsuhiro-t/openssl@0685fe7
nghttp3: ngtcp2/nghttp3@723c125
ngtcp2: ngtcp2/ngtcp2@365ae24
curl: a030d48

Note that this hang doesn't occur nearly as often when building against quiche, but it can still occur there.

operating system

$ uname -a
Linux 4.19.67-microsoft-standard #1 SMP Sun Aug 18 13:37:54 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
$ cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=18.04
DISTRIB_CODENAME=bionic
DISTRIB_DESCRIPTION="Ubuntu 18.04.3 LTS"

debugging output

Here's the full debugging output, including nghttp3 and ngtcp2 logs:

$ curl --http3 --limit-rate 16384 --trace-ascii - https://http3.dyn.test.riotcdn.net/channels/public/releases/89D5A1AB60F28C21.manifest -o /dev/null
   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
== Info:   Trying 104.18.208.94:443...
== Info: Connect socket 3 over QUIC to 104.18.208.94:443
I00000000 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt tx pkn=0 dcid=0x300115fa8ee6ca00930a5fc36cc4a0c81f5ea008 scid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 type=Initial(0x00) len=0 k=0
I00000000 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 0 Initial(0x00) CRYPTO(0x06) offset=0 len=311
I00000000 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 0 Initial(0x00) PADDING(0x00) len=870
I00000000 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235042451937000 last_tx_pkt_ts=235041451937000 timeout=1000
I00000008 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=72
I00000008 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=0 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x5217953a9f637a7819068d6cd19bbea741862ea1 type=Initial(0x00) len=23 k=0
I00000008 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 0 Initial(0x00) ACK(0x02) largest_ack=0 ack_delay=0(0) ack_block_count=0
I00000008 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 0 Initial(0x00) ACK(0x02) block=[0..0] block_count=0
I00000008 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv pkn=0 acked, slow start cwnd=13252
I00000008 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235041500883000 last_tx_pkt_ts=235041451937000 timeout=48
I00000008 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 72 left 0
I00000008 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=126
I00000008 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=1 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x5217953a9f637a7819068d6cd19bbea741862ea1 type=Initial(0x00) len=76 k=0
I00000008 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 1 Initial(0x00) CRYPTO(0x06) offset=0 len=56
I00000008 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 126 left 0
I00000013 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt tx pkn=1 dcid=0x5217953a9f637a7819068d6cd19bbea741862ea1 scid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 type=Initial(0x00) len=0 k=0
I00000013 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 1 Initial(0x00) CRYPTO(0x06) offset=311 len=278
I00000013 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 1 Initial(0x00) ACK(0x02) largest_ack=1 ack_delay=0(0) ack_block_count=0
I00000013 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 1 Initial(0x00) ACK(0x02) block=[1..0] block_count=1
I00000013 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 1 Initial(0x00) PADDING(0x00) len=897
I00000013 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235041514299000 last_tx_pkt_ts=235041465353000 timeout=48
I00000023 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=167
I00000023 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=2 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x5217953a9f637a7819068d6cd19bbea741862ea1 type=Initial(0x00) len=117 k=0
I00000023 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 2 Initial(0x00) ACK(0x02) largest_ack=1 ack_delay=0(0) ack_block_count=0
I00000023 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 2 Initial(0x00) ACK(0x02) block=[1..1] block_count=0
I00000023 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv latest_rtt=9 min_rtt=7 smoothed_rtt=8.155 rttvar=3.339 ack_delay=0
I00000023 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv pkn=1 acked, slow start cwnd=14504
I00000023 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235041511862750 last_tx_pkt_ts=235041465353000 timeout=46
I00000023 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 2 Initial(0x00) CRYPTO(0x06) offset=56 len=90
I00000023 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 167 left 0
I00000023 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con processing buffered handshake packet
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1196
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=0 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x5217953a9f637a7819068d6cd19bbea741862ea1 type=Handshake(0x02) len=1147 k=0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 0 Handshake(0x02) CRYPTO(0x06) offset=0 len=1126
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1196 left 0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con processing buffered handshake packet
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1197
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=1 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x5217953a9f637a7819068d6cd19bbea741862ea1 type=Handshake(0x02) len=1148 k=0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 1 Handshake(0x02) CRYPTO(0x06) offset=1126 len=1126
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1197 left 0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con processing buffered handshake packet
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1197
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=2 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x5217953a9f637a7819068d6cd19bbea741862ea1 type=Handshake(0x02) len=1148 k=0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 2 Handshake(0x02) CRYPTO(0x06) offset=2252 len=1126
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1197 left 0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con processing buffered handshake packet
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=75
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=3 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x5217953a9f637a7819068d6cd19bbea741862ea1 type=Handshake(0x02) len=27 k=0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 3 Handshake(0x02) CRYPTO(0x06) offset=3378 len=6
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 cry remote transport_parameters initial_max_stream_data_bidi_local=0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 cry remote transport_parameters initial_max_stream_data_bidi_remote=1048576
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 cry remote transport_parameters initial_max_stream_data_uni=1048576
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 cry remote transport_parameters initial_max_data=10485760
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 cry remote transport_parameters initial_max_bidi_streams=256
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 cry remote transport_parameters initial_max_uni_streams=3
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 cry remote transport_parameters idle_timeout=180000
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 cry remote transport_parameters max_packet_size=65527
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 cry remote transport_parameters ack_delay_exponent=3
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 cry remote transport_parameters max_ack_delay=25
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 cry remote transport_parameters active_connection_id_limit=0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 cry remote transport_parameters disable_active_migration=0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 75 left 0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con processing buffered handshake packet
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=167
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt Initial packet is discarded because keys have been discarded
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 167 left 0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con processing buffered handshake packet
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1196
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=4 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x5217953a9f637a7819068d6cd19bbea741862ea1 type=Handshake(0x02) len=1147 k=0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 4 Handshake(0x02) CRYPTO(0x06) offset=0 len=1126
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1196 left 0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con processing buffered handshake packet
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1197
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=5 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x5217953a9f637a7819068d6cd19bbea741862ea1 type=Handshake(0x02) len=1148 k=0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 5 Handshake(0x02) CRYPTO(0x06) offset=1126 len=1126
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1197 left 0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con processing buffered handshake packet
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=919
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=6 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x5217953a9f637a7819068d6cd19bbea741862ea1 type=Handshake(0x02) len=870 k=0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 6 Handshake(0x02) CRYPTO(0x06) offset=2252 len=848
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 919 left 0
I00000047 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con processing buffered handshake packet
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss detection timer fired
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv pto_count=1
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235041558372500 last_tx_pkt_ts=235041465353000 timeout=93
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt tx pkn=0 dcid=0x5217953a9f637a7819068d6cd19bbea741862ea1 scid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 type=Handshake(0x02) len=0 k=0
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 0 Handshake(0x02) CRYPTO(0x06) offset=0 len=36
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 0 Handshake(0x02) ACK(0x02) largest_ack=6 ack_delay=0(0) ack_block_count=0
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 0 Handshake(0x02) ACK(0x02) block=[6..0] block_count=6
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235041620122500 last_tx_pkt_ts=235041527103000 timeout=93
== Info: QUIC handshake is completed
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con processing buffered protected packet
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con transmit probe pkt left=1
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt tx pkn=0 dcid=0x5217953a9f637a7819068d6cd19bbea741862ea1 scid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 type=Short(0x70) len=0 k=0
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 0 Short(0x70) STREAM(0x0a) id=0x2 fin=0 offset=0 len=16 uni=1
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235041620122500 last_tx_pkt_ts=235041527103000 timeout=93
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con probe pkt size=57
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt tx pkn=1 dcid=0x5217953a9f637a7819068d6cd19bbea741862ea1 scid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 type=Short(0x70) len=0 k=0
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 1 Short(0x70) STREAM(0x0a) id=0xa fin=0 offset=0 len=1 uni=1
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 1 Short(0x70) STREAM(0x0a) id=0x6 fin=0 offset=0 len=1 uni=1
I00000075 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235041620122500 last_tx_pkt_ts=235041527103000 timeout=93
== Info: Using HTTP/3 Stream ID: 0 (easy handle 0x55d82f30d9c0)
qpack::encode: stream 0 blocked=0 allow_blocking=0
qpack::encode: Indexed Header Field (static) absidx=17
qpack::encode: Literal Header Field With Name Reference (static) absidx=1 never=0
qpack::encode: Indexed Header Field (static) absidx=23
qpack::encode: Literal Header Field With Name Reference (static) absidx=0 never=0
qpack::encode: Literal Header Field With Name Reference (static) absidx=95 never=0
qpack::encode: Indexed Header Field (static) absidx=29
qpack::encode: ricnt=0 base=0 icnt=0
I00000085 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt tx pkn=2 dcid=0x5217953a9f637a7819068d6cd19bbea741862ea1 scid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 type=Short(0x70) len=0 k=0
I00000085 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 2 Short(0x70) STREAM(0x0b) id=0x0 fin=1 offset=0 len=82 uni=0
I00000085 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235041630314500 last_tx_pkt_ts=235041537295000 timeout=93
=> Send header, 142 bytes (0x8e)
0000: GET /channels/public/releases/89D5A1AB60F28C21.manifest HTTP/3
0040: Host: http3.dyn.test.riotcdn.net
0062: user-agent: curl/7.67.0-DEV
007f: accept: */*
008c:
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=499
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=0 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 0 Short(0x70) PING(0x01)
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 0 Short(0x70) CRYPTO(0x06) offset=0 len=428
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 0 Short(0x70) STREAM(0x0e) id=0x3 fin=0 offset=0 len=24 uni=1
== Info: Received 24 bytes data on stream 3
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 499 left 0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=44
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=1 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 1 Short(0x70) PING(0x01)
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 1 Short(0x70) STREAM(0x0e) id=0x7 fin=0 offset=0 len=1 uni=1
== Info: Received 1 bytes data on stream 7
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 44 left 0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=360
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=7 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x5217953a9f637a7819068d6cd19bbea741862ea1 type=Handshake(0x02) len=311 k=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 7 Handshake(0x02) ACK(0x02) largest_ack=0 ack_delay=0(0) ack_block_count=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 7 Handshake(0x02) ACK(0x02) block=[0..0] block_count=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv latest_rtt=12 min_rtt=7 smoothed_rtt=8.712 rttvar=3.618 ack_delay=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv pkn=0 acked, slow start cwnd=14614
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235041585477031 last_tx_pkt_ts=235041537295000 timeout=48
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 7 Handshake(0x02) CRYPTO(0x06) offset=3100 len=284
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 360 left 0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=43
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=2 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 2 Short(0x70) STREAM(0x0e) id=0xb fin=0 offset=0 len=1 uni=1
== Info: Received 1 bytes data on stream 11
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 43 left 0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=43
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=3 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 3 Short(0x70) ACK(0x02) largest_ack=0 ack_delay=0(5) ack_block_count=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 3 Short(0x70) ACK(0x02) block=[0..0] block_count=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv latest_rtt=12 min_rtt=7 smoothed_rtt=9.194 rttvar=3.678 ack_delay=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv pkn=0 acked, slow start cwnd=14671
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235041586199058 last_tx_pkt_ts=235041537295000 timeout=48
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 43 left 0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=43
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=4 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 4 Short(0x70) ACK(0x02) largest_ack=1 ack_delay=0(6) ack_block_count=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 4 Short(0x70) ACK(0x02) block=[1..0] block_count=1
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv latest_rtt=12 min_rtt=7 smoothed_rtt=9.615 rttvar=3.600 ack_delay=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv pkn=1 acked, slow start cwnd=14717
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235041586309668 last_tx_pkt_ts=235041537295000 timeout=49
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 43 left 0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=44
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=5 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 5 Short(0x70) ACK(0x02) largest_ack=2 ack_delay=1(145) ack_block_count=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 5 Short(0x70) ACK(0x02) block=[2..0] block_count=2
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv latest_rtt=2 min_rtt=2 smoothed_rtt=8.715 rttvar=4.499 ack_delay=1
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv pkn=2 acked, slow start cwnd=14841
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss detection timer canceled
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 44 left 0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=71
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=8 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x5217953a9f637a7819068d6cd19bbea741862ea1 type=Handshake(0x02) len=23 k=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 8 Handshake(0x02) ACK(0x02) largest_ack=0 ack_delay=0(0) ack_block_count=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 8 Handshake(0x02) ACK(0x02) block=[0..0] block_count=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 71 left 0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=498
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=6 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 6 Short(0x70) CRYPTO(0x06) offset=0 len=428
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 6 Short(0x70) STREAM(0x0e) id=0x3 fin=0 offset=0 len=24 uni=1
I00000088 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 498 left 0
I00000123 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt tx pkn=1 dcid=0x5217953a9f637a7819068d6cd19bbea741862ea1 scid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 type=Handshake(0x02) len=0 k=0
I00000123 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 1 Handshake(0x02) ACK(0x02) largest_ack=8 ack_delay=0(0) ack_block_count=0
I00000123 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 1 Handshake(0x02) ACK(0x02) block=[8..7] block_count=1
I00000123 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt tx pkn=3 dcid=0x5217953a9f637a7819068d6cd19bbea741862ea1 scid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 type=Short(0x70) len=0 k=0
I00000123 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 3 Short(0x70) ACK(0x02) largest_ack=6 ack_delay=35(4377) ack_block_count=0
I00000123 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 3 Short(0x70) ACK(0x02) block=[6..0] block_count=6
== Info: ngh3_stream_recv returns 0 bytes and EAGAIN
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1191
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=7 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 7 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=0 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
qpack::decode: ricnt=0 base=0 icnt=0
qpack::decode: OPCODE_INDEXED
qpack::decode: dynamic=0 relidx=25 base=0 icnt=0
qpack::decode: Indexed (static) absidx=25
qpack::decode: OPCODE_INDEXED_NAME
qpack::decode: dynamic=0 relidx=6 base=0 icnt=0
qpack::decode: Indexed name (static) absidx=6 value=Sat, 26 Oct 2019 18:15:58 GMT
qpack::decode: OPCODE_INDEXED_NAME
qpack::decode: dynamic=0 relidx=44 base=0 icnt=0
qpack::decode: Indexed name (static) absidx=44 value=binary/octet-stream
qpack::decode: OPCODE_INDEXED_NAME
qpack::decode: dynamic=0 relidx=4 base=0 icnt=0
qpack::decode: Indexed name (static) absidx=4 value=37708
qpack::decode: OPCODE_INDEXED_NAME
qpack::decode: dynamic=0 relidx=14 base=0 icnt=0
qpack::decode: Indexed name (static) absidx=14 value=__cfduid=db3208d6005df0b1e0e7c1ebac93dbe331572113758; expires=Sun, 25-Oct-20 18:15:58 GMT; path=/; domain=.test.riotcdn.net; HttpOnly
qpack::decode: OPCODE_LITERAL
qpack::decode: Emit literal name=cf-cache-status value=DYNAMIC
qpack::decode: OPCODE_INDEXED_NAME
qpack::decode: dynamic=0 relidx=36 base=0 icnt=0
qpack::decode: Indexed name (static) absidx=36 value=max-age=28800
qpack::decode: OPCODE_LITERAL
qpack::decode: Emit literal name=cf-ray value=52be6b2f8a70eb8d-LAX
qpack::decode: OPCODE_INDEXED
qpack::decode: dynamic=0 relidx=32 base=0 icnt=0
qpack::decode: Indexed (static) absidx=32
qpack::decode: OPCODE_INDEXED_NAME
qpack::decode: dynamic=0 relidx=2 base=0 icnt=0
qpack::decode: Indexed name (static) absidx=2 value=6249
qpack::decode: OPCODE_INDEXED_NAME
qpack::decode: dynamic=0 relidx=7 base=0 icnt=0
qpack::decode: Indexed name (static) absidx=7 value="6fb491b5e686df43b7bf64155434f77b"
qpack::decode: OPCODE_INDEXED_NAME
qpack::decode: dynamic=0 relidx=87 base=0 icnt=0
qpack::decode: Indexed name (static) absidx=87 value=max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
qpack::decode: OPCODE_INDEXED_NAME
qpack::decode: dynamic=0 relidx=10 base=0 icnt=0
qpack::decode: Indexed name (static) absidx=10 value=Sat, 26 Oct 2019 02:05:28 GMT
qpack::decode: OPCODE_LITERAL
qpack::decode: Emit literal name=via value=1.1 43212819cc3a9a484732ccf0a1968dd8.cloudfront.net (CloudFront)
qpack::decode: OPCODE_LITERAL
qpack::decode: Emit literal name=x-amz-cf-id value=vqmHw7c7tnnSxP5n4k9rt4_nhrtAl6vfdcO_CnpItqMd-FhgIdPpjw==
qpack::decode: OPCODE_LITERAL
qpack::decode: Emit literal name=x-amz-cf-pop value=LAX3-C2
qpack::decode: OPCODE_LITERAL
qpack::decode: Emit literal name=x-amz-replication-status value=COMPLETED
qpack::decode: OPCODE_LITERAL
qpack::decode: Emit literal name=x-amz-server-side-encryption value=AES256
qpack::decode: OPCODE_LITERAL
qpack::decode: Emit literal name=x-amz-version-id value=iy6Xm3gOpB1xvduS90_BrvlbopASoph0
qpack::decode: OPCODE_LITERAL
qpack::decode: Emit literal name=x-cache value=Hit from cloudfront
qpack::decode: OPCODE_LITERAL
qpack::decode: Emit literal name=x-riot-cdn value=Cloudflare
qpack::decode: OPCODE_INDEXED_NAME
qpack::decode: dynamic=0 relidx=83 base=0 icnt=0
qpack::decode: Indexed name (static) absidx=83 value=h3-23=":443"; ma=86400
qpack::decode: OPCODE_INDEXED_NAME
qpack::decode: dynamic=0 relidx=92 base=0 icnt=0
qpack::decode: Indexed name (static) absidx=92 value=cloudflare
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1191 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=8 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 8 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=1148 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=9 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 9 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=2296 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=10 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 10 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=3444 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=11 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 11 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=4592 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=12 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 12 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=5740 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=13 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 13 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=6888 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=14 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 14 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=8036 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=15 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 15 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=9184 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=16 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 16 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=10332 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=17 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 17 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=11480 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=18 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 18 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=12628 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=19 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 19 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=13776 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=20 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 20 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=14924 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=354
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=21 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 21 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=16072 len=310 uni=0
== Info: Received 310 bytes data on stream 0
I00000192 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 354 left 0
I00000229 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt tx pkn=4 dcid=0x5217953a9f637a7819068d6cd19bbea741862ea1 scid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 type=Short(0x70) len=0 k=0
I00000229 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 4 Short(0x70) ACK(0x02) largest_ack=21 ack_delay=37(4664) ack_block_count=0
I00000229 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 4 Short(0x70) ACK(0x02) block=[21..0] block_count=21
I00000229 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 4 Short(0x70) MAX_DATA(0x10) max_data=1064984
I00000229 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 4 Short(0x70) MAX_STREAM_DATA(0x11) id=0x0 max_stream_data=32766
I00000229 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235041733233580 last_tx_pkt_ts=235041681521000 timeout=51
<= Recv header, 13 bytes (0xd)
0000: HTTP/3 200
<= Recv header, 36 bytes (0x24)
0000: date: Sat, 26 Oct 2019 18:15:58 GMT.
<= Recv header, 34 bytes (0x22)
0000: content-type: binary/octet-stream.
<= Recv header, 22 bytes (0x16)
0000: content-length: 37708.
<= Recv header, 146 bytes (0x92)
0000: set-cookie: __cfduid=db3208d6005df0b1e0e7c1ebac93dbe331572113758
0040: ; expires=Sun, 25-Oct-20 18:15:58 GMT; path=/; domain=.test.riot
0080: cdn.net; HttpOnly.
<= Recv header, 25 bytes (0x19)
0000: cf-cache-status: DYNAMIC.
<= Recv header, 29 bytes (0x1d)
0000: cache-control: max-age=28800.
<= Recv header, 29 bytes (0x1d)
0000: cf-ray: 52be6b2f8a70eb8d-LAX.
<= Recv header, 21 bytes (0x15)
0000: accept-ranges: bytes.
<= Recv header, 10 bytes (0xa)
0000: age: 6249.
<= Recv header, 41 bytes (0x29)
0000: etag: "6fb491b5e686df43b7bf64155434f77b".
<= Recv header, 99 bytes (0x63)
0000: expect-ct: max-age=604800, report-uri="https://report-uri.cloudf
0040: lare.com/cdn-cgi/beacon/expect-ct".
<= Recv header, 45 bytes (0x2d)
0000: last-modified: Sat, 26 Oct 2019 02:05:28 GMT.
<= Recv header, 70 bytes (0x46)
0000: via: 1.1 43212819cc3a9a484732ccf0a1968dd8.cloudfront.net (CloudF
0040: ront).
<= Recv header, 70 bytes (0x46)
0000: x-amz-cf-id: vqmHw7c7tnnSxP5n4k9rt4_nhrtAl6vfdcO_CnpItqMd-FhgIdP
0040: pjw==.
<= Recv header, 22 bytes (0x16)
0000: x-amz-cf-pop: LAX3-C2.
<= Recv header, 36 bytes (0x24)
0000: x-amz-replication-status: COMPLETED.
<= Recv header, 37 bytes (0x25)
0000: x-amz-server-side-encryption: AES256.
<= Recv header, 51 bytes (0x33)
0000: x-amz-version-id: iy6Xm3gOpB1xvduS90_BrvlbopASoph0.
<= Recv header, 29 bytes (0x1d)
0000: x-cache: Hit from cloudfront.
<= Recv header, 23 bytes (0x17)
0000: x-riot-cdn: Cloudflare.
<= Recv header, 32 bytes (0x20)
0000: alt-svc: h3-23=":443"; ma=86400.
<= Recv header, 19 bytes (0x13)
0000: server: cloudflare.
<= Recv header, 2 bytes (0x2)
0000:
<= Recv data, 15443 bytes (0x3c53)
0000: RMAN........0...!..`........(./......%.....%.$.H........J.u.K..%
<snip>
3c21: .j*5...w...<...#.T......>.dQ0.....G.....b..r...WH.
 40 37708   40 15443    0     0  16341      0  0:00:02 --:--:--  0:00:02 16324I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1192
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=22 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 22 Short(0x70) ACK(0x02) largest_ack=4 ack_delay=0(31) ack_block_count=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 22 Short(0x70) ACK(0x02) block=[4..3] block_count=1
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv latest_rtt=629 min_rtt=2 smoothed_rtt=86.229 rttvar=158.403 ack_delay=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv pkn=4 acked, slow start cwnd=14896
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss detection timer canceled
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 22 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=16382 len=1143 uni=0
== Info: Received 1143 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1192 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=23 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 23 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=17525 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=24 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 24 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=18673 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=25 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 25 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=19821 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=26 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 26 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=20969 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=27 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 27 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=22117 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=28 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 28 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=23265 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=29 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 29 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=24413 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=30 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 30 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=25561 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=31 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 31 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=26709 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=32 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 32 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=27857 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=33 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 33 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=29005 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=34 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 34 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=30153 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=35 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 35 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=31301 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=363
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=36 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 36 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=32449 len=317 uni=0
== Info: Received 317 bytes data on stream 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 363 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=42
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=37 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 37 Short(0x70) PING(0x01)
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 37 Short(0x70) PADDING(0x00) len=3
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 42 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=42
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=38 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 38 Short(0x70) PING(0x01)
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 38 Short(0x70) PADDING(0x00) len=3
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 42 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=42
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=39 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 39 Short(0x70) PING(0x01)
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 39 Short(0x70) PADDING(0x00) len=3
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 42 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=42
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=40 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 40 Short(0x70) PING(0x01)
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 40 Short(0x70) PADDING(0x00) len=3
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 42 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=42
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=41 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 41 Short(0x70) PING(0x01)
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 41 Short(0x70) PADDING(0x00) len=3
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 42 left 0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=42
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=42 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 42 Short(0x70) PING(0x01)
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 42 Short(0x70) PADDING(0x00) len=3
I00000858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 42 left 0
I00000906 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt tx pkn=5 dcid=0x5217953a9f637a7819068d6cd19bbea741862ea1 scid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 type=Short(0x70) len=0 k=0
I00000906 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 5 Short(0x70) ACK(0x02) largest_ack=42 ack_delay=47(5933) ack_block_count=0
I00000906 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 5 Short(0x70) ACK(0x02) block=[42..22] block_count=20
I00000906 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 5 Short(0x70) MAX_DATA(0x10) max_data=1081368
I00000906 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 5 Short(0x70) MAX_STREAM_DATA(0x11) id=0x0 max_stream_data=49150
I00000906 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss_detection_timer=235043102911627 last_tx_pkt_ts=235042358069000 timeout=744
<= Recv data, 16378 bytes (0x3ffa)
0000: .C.KC.Q.L....7.....jU....Nb.9........-@.�.......J.6.........h...
<snip>
3fc0: ...^........s...q....+....Y.a.q......?3t.......$...C'.....
 84 37708   84 31821    0     0  18235      0  0:00:02  0:00:01  0:00:01 18235I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=43 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 43 Short(0x70) ACK(0x02) largest_ack=5 ack_delay=0(76) ack_block_count=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 43 Short(0x70) ACK(0x02) block=[5..5] block_count=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv latest_rtt=952 min_rtt=2 smoothed_rtt=194.393 rttvar=335.131 ack_delay=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv pkn=5 acked, slow start cwnd=14951
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 rcv loss detection timer canceled
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 43 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=32766 len=1142 uni=0
== Info: Received 1142 bytes data on stream 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=44 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 44 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=33908 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=45 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 45 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=35056 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1194
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=46 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 46 Short(0x70) STREAM(0x0e) id=0x0 fin=0 offset=36204 len=1148 uni=0
== Info: Received 1148 bytes data on stream 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1194 left 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=1075
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=47 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 47 Short(0x70) STREAM(0x0f) id=0x0 fin=1 offset=37352 len=1029 uni=0
== Info: Received 1029 bytes data on stream 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 1075 left 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=42
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=48 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 48 Short(0x70) PING(0x01)
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 48 Short(0x70) PADDING(0x00) len=3
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 42 left 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=42
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=49 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 49 Short(0x70) PING(0x01)
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 49 Short(0x70) PADDING(0x00) len=3
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 42 left 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=42
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=50 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 50 Short(0x70) PING(0x01)
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 50 Short(0x70) PADDING(0x00) len=3
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 42 left 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=42
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=51 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 51 Short(0x70) PING(0x01)
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 51 Short(0x70) PADDING(0x00) len=3
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 42 left 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=42
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=52 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 52 Short(0x70) PING(0x01)
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 52 Short(0x70) PADDING(0x00) len=3
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 42 left 0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 con recv packet len=42
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt rx pkn=53 dcid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 scid=0x type=Short(0x70) len=0 k=0
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 53 Short(0x70) PING(0x01)
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm rx 53 Short(0x70) PADDING(0x00) len=3
I00001858 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt read packet 42 left 0
I00001883 0x9d1098dc47ba208da4c73af06fe5828a4a878863 pkt tx pkn=6 dcid=0x5217953a9f637a7819068d6cd19bbea741862ea1 scid=0x9d1098dc47ba208da4c73af06fe5828a4a878863 type=Short(0x70) len=0 k=0
I00001883 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 6 Short(0x70) ACK(0x02) largest_ack=53 ack_delay=25(3168) ack_block_count=0
I00001883 0x9d1098dc47ba208da4c73af06fe5828a4a878863 frm tx 6 Short(0x70) ACK(0x02) block=[53..43] block_count=10
<= Recv data, 5610 bytes (0x15ea)
0000: L..SE.c'....6.?._c+...~TMW.\.X?#.!.&..1r2......WGu..&?v..P.a.P6.
<snip>
15c0: M...y..."..ZVG-...HW..N%`.UWd.k..@.....r`.
 99 37708   99 37431    0     0   2428      0  0:00:15  0:00:15 --:--:--     0^C
@bagder bagder added the HTTP/3 label Oct 26, 2019
@bagder

This comment has been minimized.

Copy link
Member

@bagder bagder commented Oct 27, 2019

I created 4525.c trying to reproduce, but on my dev machine this worked fine in 20 consecutive runs just now and I've not seen it hang even once... Does this hang for you or do we need to do something else to make the issue trigger?

@jblazquez

This comment has been minimized.

Copy link
Contributor Author

@jblazquez jblazquez commented Oct 27, 2019

My initial tests were done on Windows Subsystem for Linux.

I just tested on a real Linux machine on EC2 and was able to trigger the issue there as well. This is what I did:

  1. Launched a new t2.medium instance on EC2 using this AMI: Amazon Linux 2 AMI (HVM), SSD Volume Type (ami-0b69ea66ff7391e80)
  2. Connected to the instance via SSH.
  3. Ran the following commands:
$ sudo yum groupinstall "Development Tools"
$ git clone --depth 1 -b openssl-quic-draft-23 https://github.com/tatsuhiro-t/openssl
$ cd openssl/
$ ./config enable-tls1_3 --prefix=$PWD/out
$ make -j8
$ make install_sw
$ cd ..
$ git clone https://github.com/ngtcp2/nghttp3
$ cd nghttp3
$ ./configure --prefix=$PWD/out --enable-lib-only --enable-debug
$ make -j8 install
$ cd ..
$ cd ngtcp2
$ ./configure PKG_CONFIG_PATH=$PWD/../openssl/out/lib/pkgconfig:$PWD/../nghttp3/out/lib/pkgconfig LDFLAGS="-Wl,-rpath,$PWD/../openssl/out/lib" --prefix=$PWD/out --enable-debug
$ make -j12 install
$ cd ..
$ git clone https://github.com/curl/curl
$ cd curl
$ ./buildconf
$ CPPFLAGS="-DDEBUG_NGTCP2" LDFLAGS="-Wl,-rpath,$PWD/../openssl/out/lib" ./configure --with-ssl=$PWD/../openssl/out --with-nghttp3=$PWD/../nghttp3/out --with-ngtcp2=$PWD/../ngtcp2/out
$ make -j8
$ LD_LIBRARY_PATH=$PWD/lib/.libs src/.libs/curl --http3 --limit-rate 4096 https://http3.dyn.test.riotcdn.net/channels/public/releases/89D5A1AB60F28C21.manifest >/dev/null

This hung 2 out of 5 times.

I will test your libcurl test case now.

@jblazquez

This comment has been minimized.

Copy link
Contributor Author

@jblazquez jblazquez commented Oct 27, 2019

I tested your 4525.c test case and it hung 3 out of 4 times on this EC2 machine:

$ gcc -o 4525 4525.c -Iinclude -Llib/.libs/ -lcurl
$ LD_LIBRARY_PATH=$PWD/lib/.libs ./4525 >out.txt

The first time I ran it I forgot LD_LIBRARY_PATH so it was using the system's libcurl.so.4 and using HTTP/1.1 instead of HTTP/3. Maybe that's what happened when you were testing?

@jblazquez

This comment has been minimized.

Copy link
Contributor Author

@jblazquez jblazquez commented Oct 28, 2019

It looks like the ngtcp2 backend does not support small buffer sizes. I get this assert and curld dies in Debug builds:

Assertion failed: buflen <= stream->len, file lib\vquic\ngtcp2.c, line 722

That line is:

  /* TODO: this needs to be handled properly */
  DEBUGASSERT(buflen <= stream->len);
@jblazquez

This comment has been minimized.

Copy link
Contributor Author

@jblazquez jblazquez commented Oct 28, 2019

OK, I see what's happening.

The reason why HTTP/3 downloads are sometimes hanging is because the ngtcp2 backend might retrieve a QUIC datagram from the socket when there isn't enough space in the receive buffer of the target stream for the chunk of data contained in the packet. The code in cb_h3_recv_data is truncating the data in this scenario and writing less than needed to the receive buffer, resulting in a download that never reaches the expected content length, even though the server has sent all the data correctly.

The main issue is that ng_process_ingress has no idea whether it's safe to retrieve a new QUIC datagram from the socket or not. It can't possibly know at that point which streams the QUIC packets are carrying data for, and whether those streams have sufficient buffer space remaining for the incoming chunks of data. Since a given QUIC datagram could be carrying data for any stream, not just the one for the request we're currently processing, we can't just look at the current transfer and stop when its buffer is getting full, since we could be filling up other streams' buffers. Also, even if we knew the remaining buffer space for all streams in the connection, nghttp3 could be passing us data that is much larger than the actual datagram, since QPACK can expand header data quite a bit, so we can't possibly know just how much buffer space is needed to fully process a QUIC datagram from the socket.

This was probably an issue with HTTP/2 as well when using multiplexing over a single TCP connection. How is it solved there?

@bagder

This comment has been minimized.

Copy link
Member

@bagder bagder commented Oct 28, 2019

If we ignore the QPACK problem for a moment, the "standard" way do deal with this problem should probably be to only announce a flow control window that is as large as a stream is able to read into its buffer. However, I fear that might make it very slow (since updating this to the peer is half an RTT away) so we might need something more clever.

The HTTP/2 model isn't very optimal either so I'm not sure that will provide a good example to guide us: with nghttp2 we can return a special return code from the callback that says pause when the buffer is full and then there won't be any more data delivered until we unpause it again (after that buffer as been drained). I believe this systems punishes all streams when one of the stream buffers go full.

Ideally we want to stop getting data for the stream of which the buffer is full and allow the others to go on but I don't think nghttp3/ngtcp2 will allow this...

This said, I'm also willing to land a fix now to make this first work correctly and then work on optimizing it in a second/later step.

@jblazquez

This comment has been minimized.

Copy link
Contributor Author

@jblazquez jblazquez commented Oct 28, 2019

I agree that flow control is probably part of the solution, but I don't think we can rely solely on that, mainly because of header compression (both HPACK and QPACK).

From what I can see in quic_settings, curl is already limiting the flow control credits at the QUIC level to the size of the receive buffer. But that doesn't appropriately limit the amount of header data received from the server, because on HTTP/3 the flow control credits used by the compressed HEADERS frames are potentially much smaller than the size of the uncompressed headers. Since curl writes out HTTP/3 headers to the receive buffer directly it can run out of space there before the server reaches the flow control limits, which are mainly for DATA frames.

I think header compression is what's triggering the hang issue here. With the default buffer size of 16KB we are telling the server to send at most 16KB of unacknowledged QUIC data. It will probably do that very quickly in a burst that arrives at about the same time on the client, which means that curl will find all those packets waiting for it on the socket. Because it's dequeueing all those QUIC packets in one loop and writing out both HTTP/3 headers and data to the receive buffer - and headers will consume more receive buffer than they did flow control credits - we end up chopping off some of the response body from this initial burst, and end up never completing the transfer when the rest of the data arrives from the server.

It looks like on HTTP/2 curl uses a separate buffer for headers, but since it then writes those headers to the receive buffer as well I assume it has the same potential problem. In HTTP/2 it might be worse since HEADERS frames don't participate in flow control at all.

If we kept headers in a separate buffer from the response body then we would be able to rely on HTTP/2 and HTTP/3 flow control mechanisms to ensure that we never try to write too much data to the receive buffer. This would require changes to Curl_http_readwrite_headers to read headers from that separate buffer instead of the receive buffer. This seems like a big change, so not sure how feasible it is.

Assuming that we can safely rely on flow control, we would then have the issue that you mention where we'd be blocking the sender very frequently since it would only be able to send 16KB of data (by default when using libcurl) per RTT period. With an RTT of 20ms we're talking less than 10Mbps, which is very slow. We would need a significantly larger buffer, but at least the application can control that.

What do you think we can do to help solve this issue, both in the short term and the longer term?

@jblazquez

This comment has been minimized.

Copy link
Contributor Author

@jblazquez jblazquez commented Nov 2, 2019

@bagder, how should we move forward? I’d love to help if possible.

@bagder

This comment has been minimized.

Copy link
Member

@bagder bagder commented Nov 2, 2019

I don't know exactly. I haven't had much time to think about this problem. We need to work out a way to allow us to drain the buffer for the (almost) full stream buffers before we get more data to add to them from the socket - it doesn't scale to have buffers sized to hold a whole RTT full of data for each stream. Maybe it will work good enough if we stop that loop if any stream buffer is full, then "expire" that stream and rely on it draining the buffer soon enough.

I'm a little buried other under issues and duties right now but I hope to get back to this soon. I'll of course still welcome and appreciate whatever work and progress you can do here!

@jblazquez

This comment has been minimized.

Copy link
Contributor Author

@jblazquez jblazquez commented Nov 2, 2019

Thanks Daniel. I can try some things but given how new I am to the curl codebase I wanted to make sure I ran ideas by you so I don’t go down a rabbit hole that changes too many things.

Your idea of draining the buffer for a given stream before it gets full is something that I was considering, since we could invoke the write function for that easy handle to let it process the buffer and allow us to receive more data for that stream. Unfortunately write functions can request a pause and I don’t have a solution for how to handle that yet.

I’ll spend some time thinking about this.

@bagder

This comment has been minimized.

Copy link
Member

@bagder bagder commented Nov 3, 2019

I think maybe we should ask our friends in the nghttp3 project to allow us to just accept a piece of the buffer passed to us in the nghttp3_recv_data callback - and use that as a signal that one of the stream buffers is full and we can't drain more data from the socket until that buffer has been drained.

Without that ability, we need to implement our own "backup buffer" to store the part of the data that doesn't fit in the stream buffer. Uglier. Plus I suspect we're not going to be the only user of nghttp3 that will run into this problem.

@bagder

This comment has been minimized.

Copy link
Member

@bagder bagder commented Nov 12, 2019

Status update:

We need to make sure that the window size is the same as the buffer size. Which the code already does.

We then need to make sure to only extend the window when the buffer is consumed and not like the code does now, where it extends the window immediately when the data is stored in the buffer.

I first filed this as an issue with nghttp3 but I believe @tatsuhiro-t is right when he points out we need to use the windowing for this.

While working on fix for this (live on twitch! 😁) I ran into this new ngtcp2 issue that is currently blocking me.

@jblazquez

This comment has been minimized.

Copy link
Contributor Author

@jblazquez jblazquez commented Nov 12, 2019

Hey @bagder, that was a fun stream to watch! I missed it but I watched it after the fact. I'd love to be around the next time you stream so we can run ideas past each other.

I think your plan of attack is a good start, but even if you do the two things you mentioned I believe you can still encounter the issue. This is what I mentioned on a previous comment:

I think header compression is what's triggering the hang issue here. With the default buffer size of 16KB we are telling the server to send at most 16KB of unacknowledged QUIC data. It will probably do that very quickly in a burst that arrives at about the same time on the client, which means that curl will find all those packets waiting for it on the socket. Because it's dequeueing all those QUIC packets in one loop and writing out both HTTP/3 headers and data to the receive buffer - and headers will consume more receive buffer than they did flow control credits - we end up chopping off some of the response body from this initial burst, and end up never completing the transfer when the rest of the data arrives from the server.

In short: yes, libcurl is setting the QUIC window size to be the same as the buffer size, but that doesn't prevent your cb_h3_recv_header or cb_h3_recv_data callbacks from exhausting the buffer. That's because you're also writing HTTP/3 header data to the buffer, and header data on the buffer consumes more space than it consumes flow control credits, due to QPACK.

Extreme example:

  • You have a 1KB receive buffer.
  • You set QUIC flow control to 1KB.
  • The server sends you 1KB worth of QUIC data for the stream.
  • That 1KB of QUIC data is composed of 900 bytes of QPACK-compressed HTTP/3 headers with a compression ratio of 10:1, and 100 bytes of response body.
  • Your cb_h3_recv_header callback starts writing out the received headers, which uncompressed take 9KB, and they exhaust the buffer, truncating the headers in the process.
  • Your cb_h3_recv_data callback is called with 100 bytes of data you have nowhere to place.

In other words, flow control is a QUIC layer concept, not an HTTP/3 layer concept. Because the HTTP/3 layer compresses header data, you can't use the QUIC layer's flow control to control how much application-level data you will receive. You will always get more application-level data than the flow control credits you configured.

@bagder

This comment has been minimized.

Copy link
Member

@bagder bagder commented Nov 12, 2019

Hm, yes very good points indeed. I didn't account much for the headers because in my case here they're not very big and will be drained by the time we get the problems.

But in my modified approach that adds window size when we consume it, we need to add window data when the header data is consumed too (which I didn't do in this day's stream session) and then of course our current code doesn't know how much to add since we don't keep that info around!

The problem is also as you say that we consume HTTP/3 data, and that serves as the signal where we want to add flow control to the QUIC stream, on another layer. Sort of complicated this!

A modified approach could be to do this:

Whenever the libcurl API consumer drains the buffer completely, we make sure that we add enough window so that it again goes up to BUFFER_SIZE. Just need to figure out how to do that... 😀

Regarding the stream: I'm in GMT+1, which I presume is about 9 hours ahead of you so maybe an early morning for you and an early evening for me could work... Or possibly even use a more duplex method!

@jblazquez

This comment has been minimized.

Copy link
Contributor Author

@jblazquez jblazquez commented Nov 12, 2019

What kind of duplex method are you thinking of?

Yes, I'm in GMT-8, so it's a big difference :) I'm not available weekday mornings because of work, but I can be available late at night (past midnight here, so your morning) which is when you started streaming last time. I just didn't know you were going to live stream this morning or I would have been around :)

@bagder

This comment has been minimized.

Copy link
Member

@bagder bagder commented Nov 12, 2019

Ah, so then 09:00 am my time could work. I was thinking either stick to the stream, or that we do a video call or something to see if we can work out something together. But let's first make sure that we get the current ngtcp2 version of the build to work again so that we have a "stable" base to work with!

@jblazquez

This comment has been minimized.

Copy link
Contributor Author

@jblazquez jblazquez commented Nov 12, 2019

I would be up for that! We can figure out the details elsewhere so we don't add a lot of churn to this GitHub issue :)

Do you think it would make sense to revert back to the ngtcp2 version that I was using to reproduce this problem (commits on my first message above)? That would also bring us back to draft-23 so we can more easily test against Cloudflare, including the site I've been using for all my testing (http3.test.dyn.riotcdn.net).

@bagder

This comment has been minimized.

Copy link
Member

@bagder bagder commented Nov 13, 2019

Do you think it would make sense to revert back

Sure! It's easy enough so if we just agree on which commits for ngtcp2 + nghttp3 we revert back to and then we can debug curl with ngtcp2/nghttp3 in state while the @ngtcp2 team works on that -24 issue. Let's use the ones you mention at the top of this issue.

bagder added a commit that referenced this issue Nov 15, 2019
Assisted-by: Javier Blazquez
Ref #4525 (partial fix)
@jblazquez

This comment has been minimized.

Copy link
Contributor Author

@jblazquez jblazquez commented Nov 15, 2019

Thanks for fixing the QUIC window size extension logic, Daniel!

I think the next step should be dealing with those pesky QPACK-compressed HTTP/3 headers.

It's very easy to repro the issue with a tiny receive buffer. For example, here are some logs that I got when running the following command:

$ curl -v --http3 --limit-rate 4096 \
https://http3.dyn.test.riotcdn.net/channels/public/releases/89D5A1AB60F28C21.manifest \
>/dev/null
* Received 1148 bytes data on stream 0
...
* cb_h3_recv_header WROTE 19 bytes (total = 939 bytes)
* cb_h3_recv_data CALLED with 486 bytes
* Received 1148 bytes data on stream 0
* cb_h3_recv_data CALLED with 1148 bytes
* Received 1148 bytes data on stream 0
* cb_h3_recv_data CALLED with 1148 bytes
* Received 652 bytes data on stream 0
* cb_h3_recv_data CALLED with 652 bytes
  • The "Received N bytes data on stream 0" messages come from cb_recv_stream_data. This represents QUIC stream data, i.e. the one that maps 1:1 to flow control credits.
  • The "cb_h3_recv_header WROTE N bytes (total = M bytes)" is a new message I added locally to the cb_h3_recv_header callback to know how much header data we're writing to the receive buffer. The total value just tells you how much header data has been written so far.
  • The "cb_h3_recv_data CALLED with N bytes" message shows how much HTTP/3-level response body data we're writing to the receive buffer.

If you add up all the values, you get exactly 4096 bytes of QUIC-level stream data (because that's our initial flow control value) but you get 4373 bytes of HTTP/3-level data, which clearly shows the problem happening.

Clearly the QUIC flow control system can't be used to avoid running out of receive buffer if we write HTTP/3 headers (in HTTP/1.1 form) to that buffer. I think we need to use a separate buffer for headers. This buffer would store all the headers that we have received during a single call to Curl_read, because Curl_http_readwrite_headers can consume all of that before we read from the socket again. The buffer would need to be resizable since we don't know how much header data we will receive during a single socket read. We would probably want to enforce a reasonable upper limit though, like we do with the size of a single header in CURL_MAX_HTTP_HEADER. The cb_h3_recv_header callback would then write HTTP/3 headers to this new buffer instead of the receive buffer.

I think the rest of the code would be able to work fine with no changes. For example, the Curl_http_readwrite_headers function, which seems to be what parses all the headers, doesn't seem to actually need to use the receive buffer itself. If we pass it pointers into the new header buffer in k->str and friends I think it would work the same way.

Is my analysis correct?

bagder added a commit that referenced this issue Nov 15, 2019
Assisted-by: Javier Blazquez
Ref #4525 (partial fix)
Closes #4600
@jblazquez

This comment has been minimized.

Copy link
Contributor Author

@jblazquez jblazquez commented Nov 16, 2019

Using a separate buffer for headers turned out to be a pretty complicated change. Instead, I have a potential solution where we dynamically grow the receive buffer: #4602

@jblazquez

This comment has been minimized.

Copy link
Contributor Author

@jblazquez jblazquez commented Nov 16, 2019

Here's another potential solution that I like a bit better: #4603

@bagder bagder closed this in e0363a4 Nov 18, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
2 participants
You can’t perform that action at this time.