2025-09-12 05:46:27,822 Generated random file: tquvwiydji of size: 5120 2025-09-12 05:46:27,822 Generated random file: terwuvwwps of size: 10240 2025-09-12 05:46:27,822 Requests: https://server4:443/tquvwiydji https://server4:443/terwuvwwps 2025-09-12 05:46:27,880 2025-09-12 05:46:27,880 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_ro1qzdkx/ TESTCASE_SERVER=resumption TESTCASE_CLIENT=resumption WWW=/tmp/www_nn26iaxd/ DOWNLOADS=/tmp/download_t6dicibj/ SERVER_LOGS=/tmp/logs_server_1znxjznj CLIENT_LOGS=/tmp/logs_client__hcbprhz SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=ghcr.io/mozilla/neqo-qns:latest SERVER=haproxytech/haproxy-qns:latest REQUESTS="https://server4:443/tquvwiydji https://server4:443/terwuvwwps" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-09-12 05:46:40,527 Container server Recreate Container client Recreate Container client Recreated Container server Recreated Attaching to client, server, sim sim | waiting 10s for server:443 client | Setting up routes... client | Actual changes: client | tx-checksum-ip-generic: off client | tx-tcp-segmentation: off [not requested] client | tx-tcp-ecn-segmentation: off [not requested] client | tx-tcp-mangleid-segmentation: off [not requested] client | tx-tcp6-segmentation: off [not requested] client | tx-udp-segmentation: off [not requested] client | tx-checksum-sctp: off client | Endpoint's IPv4 address is 193.167.0.100 client | Endpoint's IPv6 address is fd00:cafe:cafe::100 server | Setting up routes... server | Actual changes: server | tx-checksum-ip-generic: off server | tx-tcp-segmentation: off [not requested] server | tx-tcp-ecn-segmentation: off [not requested] server | tx-tcp-mangleid-segmentation: off [not requested] server | tx-tcp6-segmentation: off [not requested] server | tx-udp-segmentation: off [not requested] server | tx-checksum-sctp: off server | Endpoint's IPv4 address is 193.167.100.100 client | + export PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/neqo/bin client | + PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/neqo/bin client | + '[' -n resumption ']' client | + '[' -n /logs/qlog/ ']' client | + case "$ROLE" in client | + /wait-for-it.sh sim:57832 -s -t 30 server | Endpoint's IPv6 address is fd00:cafe:cafe:100::100 server | starting lighttpd server client | wait-for-it.sh: waiting 30 seconds for sim:57832 server | haproxy version HAProxy version 0678d0a69b1a2a903781e33153630ae203a72aa7 2025/09/05 - https://haproxy.org/ server | Status: development branch - not safe for use in production. server | Known bugs: https://github.com/haproxy/haproxy/issues?q=is:issue+is:open server | Running on: Linux 6.11.0-1018-azure #18~24.04.1-Ubuntu SMP Sat Jun 28 04:46:03 UTC 2025 x86_64 server | starting haproxy... sim | server:443 is available after 501.326861ms sim | Using scenario: simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25 sim | tcpdump: listening on eth0, link-type EN10MB (Ethernet), snapshot length 262144 bytes sim | tcpdump: listening on eth1, link-type EN10MB (Ethernet), snapshot length 262144 bytes client | wait-for-it.sh: sim:57832 is available after 1 seconds client | + OPTIONS=(--cc cubic --qns-test "$TESTCASE" --qlog-dir "$QLOGDIR" --output-dir /downloads) client | + '[' 'https://server4:443/tquvwiydji https://server4:443/terwuvwwps' ']' client | + mapfile -d ' ' -t URLS client | + OPTIONS+=("${URLS[@]}") client | + RUST_LOG=debug client | + RUST_BACKTRACE=1 client | + neqo-client --cc cubic --qns-test resumption --qlog-dir /logs/qlog/ --output-dir /downloads https://server4:443/tquvwiydji 'https://server4:443/terwuvwwps client | ' client | ++ tee -i -a /logs/client.log client | 0.000 DEBUG Logging initialized client | 0.001 DEBUG Default socket send buffer size is Ok(212992) client | 0.001 DEBUG Default socket receive buffer size is 1048576, not changing client | 0.001 INFO hq-interop Client connecting: 0.0.0.0:49514 -> 193.167.100.100:443 client | 0.001 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Client dcid=a1d965024df3e3208edc1444a495 client | 0.001 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 min_pn=647 client | 0.001 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 min_pn=0 client | 0.001 DEBUG Outbound interface eth0 for destination 193.167.100.100 has MTU 1500 client | 0.001 DEBUG [unv-path 0.0.0.0:49514->193.167.100.100:443] Make permanent client | 0.001 DEBUG [unv-path:a1d965024df3e3208edc1444a495 0.0.0.0:49514->193.167.100.100:443] set as primary path client | 0.001 DEBUG [pri-unv-path:a1d965024df3e3208edc1444a495 0.0.0.0:49514->193.167.100.100:443] Path validated Instant { tv_sec: 335, tv_nsec: 295356113 } client | 0.001 DEBUG [Client a1d965024df3e3208edc1444a495] client_start client | 0.002 DEBUG Writing transport parameters, msg=1 client | 0.002 DEBUG [Agent 0x563a16a2c420] state -> InProgress client | 0.002 DEBUG [Client a1d965024df3e3208edc1444a495] State change from Init -> WaitInitial client | 0.002 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.002 DEBUG Building Initial dcid Some(CID [14]: a1d965024df3e3208edc1444a495) scid Some(CID [0]: ) client | 0.002 DEBUG CRYPTO for in offset=0, len=1206 client | 0.002 DEBUG [Client a1d965024df3e3208edc1444a495] pn=647 type=Initial pri-path:a1d965024df3e3208edc1444a495 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | TX -> Crypto { offset: 0, len: 1206 } client | 0.002 DEBUG packet_sent this=0x563a16a3fbe0, pn=647, ps=1252 client | 0.002 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.002 DEBUG Building Initial dcid Some(CID [14]: a1d965024df3e3208edc1444a495) scid Some(CID [0]: ) client | 0.002 DEBUG CRYPTO for in offset=1206, len=334 client | 0.002 DEBUG [Client a1d965024df3e3208edc1444a495] pn=648 type=Initial pri-path:a1d965024df3e3208edc1444a495 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 381 client | TX -> Crypto { offset: 1206, len: 334 } client | 0.002 DEBUG [Client a1d965024df3e3208edc1444a495] pad Initial from 381 to PLPMTU 1252 client | 0.002 DEBUG packet_sent this=0x563a16a3fbe0, pn=648, ps=1252 client | 0.002 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG Building Initial dcid Some(CID [14]: a1d965024df3e3208edc1444a495) scid Some(CID [0]: ) client | 0.002 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG Building Initial dcid Some(CID [14]: a1d965024df3e3208edc1444a495) scid Some(CID [0]: ) client | 0.002 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 3.915327ms client | 0.002 DEBUG Setting timeout of 3.915327ms client | 0.002 DEBUG StateChange(WaitInitial) client | 0.002 WARN Cannot create stream ConnectionState client | 0.002 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG Building Initial dcid Some(CID [14]: a1d965024df3e3208edc1444a495) scid Some(CID [0]: ) client | 0.002 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 3.881894ms client | 0.002 DEBUG Setting timeout of 3.881894ms client | 0.007 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.007 DEBUG Building Initial dcid Some(CID [14]: a1d965024df3e3208edc1444a495) scid Some(CID [0]: ) client | 0.007 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.007 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 294.352007ms client | 0.007 DEBUG Setting timeout of 294.352007ms client | 0.042 DEBUG [Client a1d965024df3e3208edc1444a495] pn=0 type=Initial pri-path:a1d965024df3e3208edc1444a495 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 136 client | -> RX Ack { largest_acknowledged: 648, ack_delay: 250, first_ack_range: 1, ack_ranges: [], ecn_count: None } client | -> RX Crypto { offset: 0, len: 90 } client | 0.042 DEBUG [Client a1d965024df3e3208edc1444a495] Rx ACK space=in, ranges=[647..=648] client | 0.042 DEBUG [recovery::Loss] ACK for Initial - largest_acked=648 client | 0.042 DEBUG on_packets_acked this=0x563a16a3fbe0, limited=1, bytes_in_flight=0, cwnd=12520, state=SlowStart, new_acked=2504 client | 0.042 DEBUG Acked crypto frame space=in offset=1206 length=334 client | 0.042 DEBUG Acked crypto frame space=in offset=0 length=1206 client | 0.042 DEBUG Write secret available for Handshake: SymKey [48]: d74238abf1391df80b3cd656aec9fbb1893b66eb1d6b55448c6de0de6bb2c2b059de9980b1f6fb1428e4bed7f8b7b21d client | 0.042 DEBUG Read secret available for Handshake: SymKey [48]: 2e8bae8b868473f8e003656d5f3f7e5ef30d56538882e1d13c4c8333ca565f2af205d903c186c909cf9116705a6639c8 client | 0.042 DEBUG [Agent 0x563a16a2c420] state -> InProgress client | 0.042 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4866 min_pn=0 client | 0.042 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4866 min_pn=0 client | 0.042 DEBUG [Crypto] Handshake keys installed client | 0.043 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 336615569 } client | 0.043 DEBUG [Client a1d965024df3e3208edc1444a495] Changing to use Server CID=520f1082fdc36220 client | 0.043 DEBUG [Client a1d965024df3e3208edc1444a495] State change from WaitInitial -> Handshaking client | 0.043 DEBUG [Client a1d965024df3e3208edc1444a495] pn=0 type=Handshake pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1064 client | -> RX Crypto { offset: 0, len: 737 } client | -> RX Padding { len: 289 } client | 0.043 DEBUG [Agent 0x563a16a2c420] state -> AuthenticationPending client | 0.043 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 336615569 } client | 0.043 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.043 DEBUG Building Initial dcid Some(CID [8]: 520f1082fdc36220) scid Some(CID [0]: ) client | 0.043 DEBUG [Client a1d965024df3e3208edc1444a495] pn=649 type=Initial pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 41 client | TX -> Ack { largest_acknowledged: 0, ack_delay: 154, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | 0.043 DEBUG Building Handshake dcid Some(CID [8]: 520f1082fdc36220) scid Some(CID [0]: ) client | 0.043 DEBUG [Client a1d965024df3e3208edc1444a495] pn=0 type=Handshake pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 81 client | TX -> Ack { largest_acknowledged: 0, ack_delay: 154, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | 0.043 DEBUG [Client a1d965024df3e3208edc1444a495] Drop packet number space in client | 0.043 DEBUG [recovery::Loss] Reset loss recovery state for Initial client | 0.043 INFO [recovery::Loss] ignoring in-649 from dropped space client | 0.043 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.043 DEBUG Building Handshake dcid Some(CID [8]: 520f1082fdc36220) scid Some(CID [0]: ) client | 0.043 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.043 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 122.018174ms client | 0.043 DEBUG Setting timeout of 122.018174ms client | 0.043 DEBUG StateChange(Handshaking) client | 0.043 WARN Cannot create stream ConnectionState client | 0.043 DEBUG [Client a1d965024df3e3208edc1444a495] Authenticated Ok client | 0.043 DEBUG Write secret available for ApplicationData: SymKey [48]: d445c058d87386af2b198ce306a8a56eef14ce883a44267a2e0976fb6f3d222d5c3567fa009fd03dbd2145734241ecca client | 0.043 DEBUG Read secret available for ApplicationData: SymKey [48]: 34c6e6e1599f57c661df287688afe91e39849b183453412c92f80b540ae643910c0cdde35972d91f7a64cfce01811db7 client | 0.044 DEBUG [Agent 0x563a16a2c420] SSL_AuthCertificateComplete: Ok(()) client | 0.044 DEBUG [Agent 0x563a16a2c420] state -> Complete(SecretAgentInfo { version: 772, cipher: 4866, group: 29, resumed: false, early_data: false, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 }) client | 0.044 DEBUG [Client a1d965024df3e3208edc1444a495] TLS connection complete client | 0.044 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4866 min_pn=0 client | 0.044 DEBUG [Crypto] Application write key installed client | 0.044 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4866 min_pn=0 client | 0.044 DEBUG [Crypto] application read keys installed client | 0.044 DEBUG [Client a1d965024df3e3208edc1444a495] State change from Handshaking -> Connected client | 0.044 INFO [Client a1d965024df3e3208edc1444a495] Connection established client | 0.044 DEBUG stream BiDi creatable client | 0.044 INFO Created stream 0 for https://server4/tquvwiydji client | 0.044 INFO Saving https://server4/tquvwiydji to "/downloads/tquvwiydji" client | 0.044 DEBUG stream UniDi creatable client | 0.044 DEBUG StateChange(Connected) client | 0.044 DEBUG stream 0 writable client | 0.044 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.044 DEBUG Building Handshake dcid Some(CID [8]: 520f1082fdc36220) scid Some(CID [0]: ) client | 0.044 DEBUG CRYPTO for hs offset=0, len=52 client | 0.044 DEBUG [Client a1d965024df3e3208edc1444a495] pn=1 type=Handshake pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 89 client | TX -> Crypto { offset: 0, len: 52 } client | 0.044 DEBUG packet_sent this=0x563a16a3fbe0, pn=1, ps=89 client | 0.044 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.044 DEBUG [Client a1d965024df3e3208edc1444a495] pn=0 type=Short pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 135 client | TX -> Stream { stream_id: 0, offset: 0, len: 17, fin: true } client | 0.044 DEBUG packet_sent this=0x563a16a3fbe0, pn=0, ps=46 client | 0.044 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.044 DEBUG Building Handshake dcid Some(CID [8]: 520f1082fdc36220) scid Some(CID [0]: ) client | 0.044 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.044 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.044 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 122.037578ms client | 0.044 DEBUG Setting timeout of 122.037578ms client | 0.076 DEBUG [Client a1d965024df3e3208edc1444a495] pn=1 type=Handshake pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 38 client | -> RX Ack { largest_acknowledged: 1, ack_delay: 0, first_ack_range: 1, ack_ranges: [], ecn_count: None } client | 0.076 DEBUG [Client a1d965024df3e3208edc1444a495] Rx ACK space=hs, ranges=[0..=1] client | 0.076 DEBUG [recovery::Loss] ACK for Handshake - largest_acked=1 client | 0.076 DEBUG on_packets_acked this=0x563a16a3fbe0, limited=1, bytes_in_flight=46, cwnd=12520, state=SlowStart, new_acked=89 client | 0.076 DEBUG Acked crypto frame space=hs offset=0 length=52 client | 0.076 DEBUG [Client a1d965024df3e3208edc1444a495] pn=0 type=Short pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 568 client | -> RX Crypto { offset: 0, len: 546 } client | 0.076 DEBUG [0x563a16a2c420] Got resumption token [936]: 0200063e942ce2c0..55e4c3f07bd191fe client | 0.076 DEBUG [0x563a16a2c420] Got resumption token [936]: 0200063e942ce2c0..d60c0fb5c494dd59 client | 0.076 DEBUG [Agent 0x563a16a2c420] state -> Complete(SecretAgentInfo { version: 772, cipher: 4866, group: 29, resumed: false, early_data: false, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 }) client | 0.076 DEBUG setting max_stream_data to 1474200 client | 0.076 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 390606837 } client | 0.076 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.076 DEBUG Building Handshake dcid Some(CID [8]: 520f1082fdc36220) scid Some(CID [0]: ) client | 0.076 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.076 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.076 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 19.738479ms client | 0.076 DEBUG Setting timeout of 19.738479ms client | 0.076 DEBUG stream BiDi creatable client | 0.076 DEBUG stream UniDi creatable client | 0.076 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.076 DEBUG Building Handshake dcid Some(CID [8]: 520f1082fdc36220) scid Some(CID [0]: ) client | 0.076 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.076 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.076 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 19.699176ms client | 0.076 DEBUG Setting timeout of 19.699176ms client | 0.077 DEBUG [Client a1d965024df3e3208edc1444a495] pn=1 type=Short pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 147 client | -> RX Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | -> RX HandshakeDone client | -> RX NewToken { token: [183, 44, 147, 32, 239, 25, 9, 138, 161, 144, 216, 36, 224, 197, 3, 35, 73, 163, 23, 43, 129, 14, 77, 177, 5, 1, 103, 35, 80, 109, 130, 15, 112, 228, 245, 152, 95] } client | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [179, 93, 153, 81, 78, 229, 93, 52], stateless_reset_token: [172, 241, 130, 159, 174, 121, 216, 119, 229, 45, 255, 182, 67, 4, 69, 227] } client | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [63, 62, 138, 174, 210, 254, 3, 5], stateless_reset_token: [235, 11, 134, 71, 141, 9, 80, 43, 241, 46, 188, 119, 74, 75, 227, 238] } client | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [157, 91, 76, 84, 87, 242, 157, 217], stateless_reset_token: [75, 18, 144, 239, 176, 192, 209, 157, 22, 187, 88, 125, 209, 187, 95, 113] } client | 0.077 DEBUG [Client a1d965024df3e3208edc1444a495] Rx ACK space=ap, ranges=[0..=0] client | 0.077 DEBUG [recovery::Loss] ACK for ApplicationData - largest_acked=0 client | 0.077 DEBUG on_packets_acked this=0x563a16a3fbe0, limited=1, bytes_in_flight=0, cwnd=12520, state=SlowStart, new_acked=46 client | 0.077 DEBUG [Client a1d965024df3e3208edc1444a495] State change from Connected -> Confirmed client | 0.077 DEBUG PMTUD started with probe size 1380 client | 0.077 DEBUG [Client a1d965024df3e3208edc1444a495] Drop packet number space hs client | 0.077 DEBUG [recovery::Loss] Reset loss recovery state for Handshake client | 0.077 DEBUG [Client a1d965024df3e3208edc1444a495] No preferred address to migrate to client | 0.077 DEBUG resumption token [1085]: 0000000126406800..d60c0fb5c494dd59 client | 0.077 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 371431505 } client | 0.077 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.077 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.077 DEBUG Sending PMTUD probe of size 1380, count 1 client | 0.077 DEBUG [Client a1d965024df3e3208edc1444a495] pn=1 type=Short pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, Ect0) len 1352 client | TX -> Ack { largest_acknowledged: 1, ack_delay: 12, first_ack_range: 1, ack_ranges: [], ecn_count: None } client | TX -> Ping client | TX -> Padding { len: 1320 } client | 0.077 DEBUG packet_sent this=0x563a16a3fbe0, pn=1, ps=1352 client | 0.077 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.077 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.077 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.077 DEBUG ECN probing: sent 1 probes client | 0.077 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.077 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.077 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.077 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 122.585367ms client | 0.077 DEBUG Setting timeout of 122.585367ms client | 0.077 DEBUG stream 0 complete client | 0.077 WARN Unhandled event StateChange(Confirmed) client | 0.077 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.077 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.077 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.077 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 122.487606ms client | 0.077 DEBUG Setting timeout of 122.487606ms client | 0.079 DEBUG [Client a1d965024df3e3208edc1444a495] pn=2 type=Short pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | -> RX Stream { stream_id: 0, offset: 0, len: 1230, fin: false } client | 0.079 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 393638106 } client | 0.079 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.079 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.079 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.079 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 19.974282ms client | 0.079 DEBUG Setting timeout of 19.974282ms client | 0.079 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.079 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.079 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.079 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 19.942572ms client | 0.079 DEBUG Setting timeout of 19.942572ms client | 0.080 DEBUG [Client a1d965024df3e3208edc1444a495] pn=3 type=Short pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | -> RX Stream { stream_id: 0, offset: 1230, len: 1228, fin: false } client | 0.080 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 374664563 } client | 0.080 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.080 DEBUG [Client a1d965024df3e3208edc1444a495] pn=2 type=Short pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, Ect0) len 31 client | TX -> Ack { largest_acknowledged: 3, ack_delay: 3, first_ack_range: 3, ack_ranges: [], ecn_count: None } client | 0.080 DEBUG ECN probing: sent 2 probes client | 0.080 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.080 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 119.471854ms client | 0.080 DEBUG Setting timeout of 119.471854ms client | 0.080 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.080 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 119.44876ms client | 0.080 DEBUG Setting timeout of 119.44876ms client | 0.085 DEBUG [Client a1d965024df3e3208edc1444a495] pn=4 type=Short pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | -> RX Stream { stream_id: 0, offset: 2458, len: 1228, fin: false } client | 0.085 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 399288581 } client | 0.085 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.085 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.085 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.085 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 19.971016ms client | 0.085 DEBUG Setting timeout of 19.971016ms client | 0.085 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.085 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.085 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.085 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 19.953222ms client | 0.085 DEBUG Setting timeout of 19.953222ms client | 0.086 DEBUG [Client a1d965024df3e3208edc1444a495] pn=5 type=Short pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | -> RX Stream { stream_id: 0, offset: 3686, len: 1228, fin: false } client | 0.086 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 380294188 } client | 0.086 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.086 DEBUG [Client a1d965024df3e3208edc1444a495] pn=3 type=Short pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, Ect0) len 31 client | TX -> Ack { largest_acknowledged: 5, ack_delay: 2, first_ack_range: 5, ack_ranges: [], ecn_count: None } client | 0.086 DEBUG ECN probing: sent 3 probes client | 0.086 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.086 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 113.850143ms client | 0.086 DEBUG Setting timeout of 113.850143ms client | 0.086 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.086 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 113.82729ms client | 0.086 DEBUG Setting timeout of 113.82729ms client | 0.088 DEBUG [Client a1d965024df3e3208edc1444a495] pn=6 type=Short pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 230 client | -> RX Stream { stream_id: 0, offset: 4914, len: 206, fin: true } client | 0.088 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 402965692 } client | 0.088 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.088 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.088 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.088 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 19.968922ms client | 0.088 DEBUG Setting timeout of 19.968922ms client | 0.088 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.088 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.088 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.088 DEBUG [Client a1d965024df3e3208edc1444a495] delay duration 19.885004ms client | 0.088 DEBUG Setting timeout of 19.885004ms client | 0.088 DEBUG [Client a1d965024df3e3208edc1444a495] State change from Confirmed -> Closing { error: Application(0), timeout: Instant { tv_sec: 335, tv_nsec: 751173651 } } client | 0.088 WARN Unhandled event StateChange(Closing { error: Application(0), timeout: Instant { tv_sec: 335, tv_nsec: 751173651 } }) client | 0.088 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.088 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.088 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 335, tv_nsec: 383138166 } client | 0.088 DEBUG [Client a1d965024df3e3208edc1444a495] pn=4 type=Short pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, Ect0) len 42 client | TX -> Ack { largest_acknowledged: 6, ack_delay: 21, first_ack_range: 6, ack_ranges: [], ecn_count: None } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 0.088 DEBUG ECN probing: sent 4 probes client | 0.089 DEBUG Setting timeout of 367.903498ms client | 0.120 DEBUG [Client a1d965024df3e3208edc1444a495] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.120 DEBUG Building Short dcid Some(CID [8]: 520f1082fdc36220) client | 0.120 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 335, tv_nsec: 414341549 } client | 0.120 DEBUG [Client a1d965024df3e3208edc1444a495] pn=5 type=Short pri-path:520f1082fdc36220 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, Ect0) len 43 client | TX -> Ack { largest_acknowledged: 6, ack_delay: 3921, first_ack_range: 6, ack_ranges: [], ecn_count: None } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 0.120 DEBUG ECN probing: sent 5 probes client | 0.120 DEBUG Setting timeout of 336.707048ms client | 0.120 DEBUG Setting timeout of 336.695115ms client | 0.458 DEBUG [Client a1d965024df3e3208edc1444a495] State change from Closing { error: Application(0), timeout: Instant { tv_sec: 335, tv_nsec: 751173651 } } -> Closed(Application(0)) client | 0.458 INFO Closing timer expired client | 0.458 DEBUG Output::None client | 0.458 WARN Unhandled event StateChange(Closed(Application(0))) client | 0.458 DEBUG Timer fired while closed client | 0.458 DEBUG Output::None client | 0.458 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Client dcid=fa92b1616872ed08 client | 0.459 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 min_pn=16 client | 0.459 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 min_pn=0 client | 0.459 DEBUG Outbound interface eth0 for destination 193.167.100.100 has MTU 1500 client | 0.459 DEBUG [unv-path 0.0.0.0:49514->193.167.100.100:443] Make permanent client | 0.459 DEBUG [unv-path:fa92b1616872ed08 0.0.0.0:49514->193.167.100.100:443] set as primary path client | 0.459 DEBUG [pri-unv-path:fa92b1616872ed08 0.0.0.0:49514->193.167.100.100:443] Path validated Instant { tv_sec: 335, tv_nsec: 753130574 } client | 0.459 INFO [Client fa92b1616872ed08] resumption token [1085]: 0000000126406800..d60c0fb5c494dd59 client | 0.459 DEBUG Overwrite initial version Version1 ==> Version1 client | 0.459 DEBUG Overwrite initial version Version1 ==> Version1 client | 0.459 DEBUG [Client fa92b1616872ed08] client_start client | 0.459 DEBUG Writing transport parameters, msg=1 client | 0.459 DEBUG Write secret available for ZeroRtt: SymKey [48]: 835d747bd49a33db64c30f1847fa9fa5a92e2172118ca480f8d66835a1e638db4230ba2fd16f5120f684bafa9a538722 client | 0.459 DEBUG [Agent 0x563a16a2c330] state -> InProgress client | 0.459 DEBUG [Client fa92b1616872ed08] State change from Init -> WaitInitial client | 0.459 DEBUG Making Write ZeroRtt CryptoDxState, v=Version1 cipher=4866 min_pn=0 client | 0.459 DEBUG [Client fa92b1616872ed08] Enabled 0-RTT client | 0.460 DEBUG stream BiDi creatable client | 0.460 INFO Created stream 0 for https://server4/terwuvwwps client | 0.460 INFO Saving https://server4/terwuvwwps to "/downloads/terwuvwwps" client | 0.460 DEBUG stream UniDi creatable client | 0.460 DEBUG StateChange(WaitInitial) client | 0.460 DEBUG stream 0 writable client | 0.460 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.460 DEBUG Building Initial dcid Some(CID [8]: fa92b1616872ed08) scid Some(CID [0]: ) client | 0.460 DEBUG CRYPTO for in offset=0, len=1176 client | 0.460 DEBUG [Client fa92b1616872ed08] pn=16 type=Initial pri-path:fa92b1616872ed08 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | TX -> Crypto { offset: 0, len: 1176 } client | 0.460 DEBUG packet_sent this=0x563a16a3fbe0, pn=16, ps=1252 client | 0.460 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.460 DEBUG Building Initial dcid Some(CID [8]: fa92b1616872ed08) scid Some(CID [0]: ) client | 0.460 DEBUG CRYPTO for in offset=1176, len=671 client | 0.460 DEBUG [Client fa92b1616872ed08] pn=17 type=Initial pri-path:fa92b1616872ed08 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 748 client | TX -> Crypto { offset: 1176, len: 671 } client | 0.460 DEBUG Building ZeroRtt dcid Some(CID [8]: fa92b1616872ed08) scid Some(CID [0]: ) client | 0.460 DEBUG [Client fa92b1616872ed08] pn=0 type=ZeroRtt pri-path:fa92b1616872ed08 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 802 client | TX -> Stream { stream_id: 0, offset: 0, len: 17, fin: true } client | 0.460 DEBUG packet_sent this=0x563a16a3fbe0, pn=0, ps=54 client | 0.460 DEBUG [Client fa92b1616872ed08] pad Initial from 802 to PLPMTU 1252 client | 0.460 DEBUG packet_sent this=0x563a16a3fbe0, pn=17, ps=1198 client | 0.460 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.460 DEBUG Building Initial dcid Some(CID [8]: fa92b1616872ed08) scid Some(CID [0]: ) client | 0.460 DEBUG Building ZeroRtt dcid Some(CID [8]: fa92b1616872ed08) scid Some(CID [0]: ) client | 0.460 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.460 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.460 DEBUG Building Initial dcid Some(CID [8]: fa92b1616872ed08) scid Some(CID [0]: ) client | 0.460 DEBUG Building ZeroRtt dcid Some(CID [8]: fa92b1616872ed08) scid Some(CID [0]: ) client | 0.460 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.460 DEBUG [Client fa92b1616872ed08] delay duration 113.823118ms client | 0.460 DEBUG Setting timeout of 113.823118ms client | 0.492 DEBUG [Client fa92b1616872ed08] pn=0 type=Initial pri-path:fa92b1616872ed08 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 40 client | -> RX Ack { largest_acknowledged: 16, ack_delay: 1000, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | 0.492 DEBUG [Client fa92b1616872ed08] Rx ACK space=in, ranges=[16..=16] client | 0.492 DEBUG [recovery::Loss] ACK for Initial - largest_acked=16 client | 0.492 DEBUG on_packets_acked this=0x563a16a3fbe0, limited=1, bytes_in_flight=1252, cwnd=12520, state=SlowStart, new_acked=1252 client | 0.492 DEBUG Acked crypto frame space=in offset=0 length=1176 client | 0.492 DEBUG [Client fa92b1616872ed08] Changing to use Server CID=c3205d718e5ffba4 client | 0.492 DEBUG [Client fa92b1616872ed08] State change from WaitInitial -> WaitVersion client | 0.492 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.492 DEBUG Building Initial dcid Some(CID [8]: c3205d718e5ffba4) scid Some(CID [0]: ) client | 0.492 DEBUG Building ZeroRtt dcid Some(CID [8]: c3205d718e5ffba4) scid Some(CID [0]: ) client | 0.492 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.492 DEBUG [Client fa92b1616872ed08] delay duration 65.294007ms client | 0.492 DEBUG Setting timeout of 65.294007ms client | 0.492 WARN Unhandled event StateChange(WaitVersion) client | 0.492 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.492 DEBUG Building Initial dcid Some(CID [8]: c3205d718e5ffba4) scid Some(CID [0]: ) client | 0.492 DEBUG Building ZeroRtt dcid Some(CID [8]: c3205d718e5ffba4) scid Some(CID [0]: ) client | 0.492 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.492 DEBUG [Client fa92b1616872ed08] delay duration 65.266054ms client | 0.492 DEBUG Setting timeout of 65.266054ms client | 0.495 DEBUG [Client fa92b1616872ed08] pn=1 type=Initial pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 140 client | -> RX Ack { largest_acknowledged: 17, ack_delay: 0, first_ack_range: 1, ack_ranges: [], ecn_count: None } client | -> RX Crypto { offset: 0, len: 96 } client | 0.495 DEBUG [Client fa92b1616872ed08] Rx ACK space=in, ranges=[16..=17] client | 0.495 DEBUG [recovery::Loss] ACK for Initial - largest_acked=17 client | 0.495 DEBUG on_packets_acked this=0x563a16a3fbe0, limited=1, bytes_in_flight=54, cwnd=12520, state=SlowStart, new_acked=1198 client | 0.495 DEBUG Acked crypto frame space=in offset=1176 length=671 client | 0.495 DEBUG Write secret available for Handshake: SymKey [48]: 9f5dff0874c1b79cf58c7f67a5cb0c429f8a9f8ddba9e7b47fe527971053b97e7964b1d097dd0fc96656ba6f46c8f4f5 client | 0.495 DEBUG Read secret available for Handshake: SymKey [48]: ec6d42b3d06b057adcc1a5690c9ac37964836cd16f94a34c03a073d4d5c7b30d0c9d697728f172a2a588447c554e0d85 client | 0.495 DEBUG [Agent 0x563a16a2c330] state -> InProgress client | 0.495 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4866 min_pn=0 client | 0.495 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4866 min_pn=0 client | 0.495 DEBUG [Crypto] Handshake keys installed client | 0.495 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 789601302 } client | 0.495 DEBUG [Client fa92b1616872ed08] State change from WaitVersion -> Handshaking client | 0.495 DEBUG [Client fa92b1616872ed08] pn=0 type=Handshake pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1060 client | -> RX Crypto { offset: 0, len: 185 } client | -> RX Padding { len: 837 } client | 0.495 DEBUG Write secret available for ApplicationData: SymKey [48]: ab06f360086840f220f4f25a7abc40002148633a3a63724046942b9cb49f30992ea59769b311b6e9c8a2014014144ba4 client | 0.495 DEBUG Read secret available for ApplicationData: SymKey [48]: 8280161569a598ae79736e04f6c2cf909332245e7f7d3b3aa8941c87500fd7fbb44497fda64942c82c0e233bb86d5900 client | 0.496 DEBUG [Agent 0x563a16a2c330] state -> Complete(SecretAgentInfo { version: 772, cipher: 4866, group: 29, resumed: true, early_data: true, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 }) client | 0.496 DEBUG [Client fa92b1616872ed08] TLS connection complete client | 0.496 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4866 min_pn=0 client | 0.496 DEBUG [Crypto] Application write key installed client | 0.496 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4866 min_pn=0 client | 0.496 DEBUG [Crypto] application read keys installed client | 0.496 DEBUG setting max_stream_data to 1474200 client | 0.496 DEBUG [Client fa92b1616872ed08] State change from Handshaking -> Connected client | 0.496 INFO [Client fa92b1616872ed08] Connection established client | 0.496 DEBUG setting max_stream_data to 1474200 client | 0.496 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 789601302 } client | 0.496 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.496 DEBUG Building Initial dcid Some(CID [8]: c3205d718e5ffba4) scid Some(CID [0]: ) client | 0.496 DEBUG [Client fa92b1616872ed08] pn=18 type=Initial pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 78 client | TX -> Ack { largest_acknowledged: 1, ack_delay: 109, first_ack_range: 1, ack_ranges: [], ecn_count: None } client | 0.496 DEBUG Building Handshake dcid Some(CID [8]: c3205d718e5ffba4) scid Some(CID [0]: ) client | 0.496 DEBUG CRYPTO for hs offset=0, len=52 client | 0.496 DEBUG [Client fa92b1616872ed08] pn=0 type=Handshake pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 173 client | TX -> Ack { largest_acknowledged: 0, ack_delay: 109, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | TX -> Crypto { offset: 0, len: 52 } client | 0.496 DEBUG packet_sent this=0x563a16a3fbe0, pn=0, ps=95 client | 0.496 DEBUG [Client fa92b1616872ed08] Drop packet number space in client | 0.496 DEBUG [recovery::Loss] Reset loss recovery state for Initial client | 0.496 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.496 INFO [recovery::Loss] ignoring in-18 from dropped space client | 0.496 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.496 DEBUG Building Handshake dcid Some(CID [8]: c3205d718e5ffba4) scid Some(CID [0]: ) client | 0.496 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.496 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.496 DEBUG [Client fa92b1616872ed08] delay duration 84.447165ms client | 0.496 DEBUG Setting timeout of 84.447165ms client | 0.496 DEBUG StateChange(Handshaking) client | 0.496 DEBUG stream BiDi creatable client | 0.496 DEBUG stream UniDi creatable client | 0.496 DEBUG StateChange(Connected) client | 0.496 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.496 DEBUG Building Handshake dcid Some(CID [8]: c3205d718e5ffba4) scid Some(CID [0]: ) client | 0.496 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.496 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.496 DEBUG [Client fa92b1616872ed08] delay duration 84.419683ms client | 0.496 DEBUG Setting timeout of 84.419683ms client | 0.529 DEBUG [Client fa92b1616872ed08] pn=1 type=Handshake pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 38 client | -> RX Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | 0.529 DEBUG [Client fa92b1616872ed08] Rx ACK space=hs, ranges=[0..=0] client | 0.529 DEBUG [recovery::Loss] ACK for Handshake - largest_acked=0 client | 0.529 DEBUG on_packets_acked this=0x563a16a3fbe0, limited=1, bytes_in_flight=54, cwnd=12520, state=SlowStart, new_acked=95 client | 0.529 DEBUG Acked crypto frame space=hs offset=0 length=52 client | 0.529 DEBUG [Client fa92b1616872ed08] pn=0 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 301 client | -> RX Ack { largest_acknowledged: 0, ack_delay: 4250, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | -> RX Crypto { offset: 0, len: 273 } client | 0.529 DEBUG [Client fa92b1616872ed08] Rx ACK space=ap, ranges=[0..=0] client | 0.529 DEBUG [recovery::Loss] ACK for ApplicationData - largest_acked=0 client | 0.529 DEBUG on_packets_acked this=0x563a16a3fbe0, limited=1, bytes_in_flight=0, cwnd=12520, state=SlowStart, new_acked=54 client | 0.529 DEBUG [0x563a16a2c330] Got resumption token [936]: 0200063e942ce9a9..e58edfc4c33bc60c client | 0.529 DEBUG [Agent 0x563a16a2c330] state -> Complete(SecretAgentInfo { version: 772, cipher: 4866, group: 29, resumed: true, early_data: true, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 }) client | 0.529 DEBUG setting max_stream_data to 1474200 client | 0.529 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 843333561 } client | 0.529 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.529 DEBUG Building Handshake dcid Some(CID [8]: c3205d718e5ffba4) scid Some(CID [0]: ) client | 0.529 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.529 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.529 DEBUG [Client fa92b1616872ed08] delay duration 19.869334ms client | 0.529 DEBUG Setting timeout of 19.869334ms client | 0.529 DEBUG stream 0 complete client | 0.529 DEBUG stream BiDi creatable client | 0.529 DEBUG stream UniDi creatable client | 0.529 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.529 DEBUG Building Handshake dcid Some(CID [8]: c3205d718e5ffba4) scid Some(CID [0]: ) client | 0.529 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.529 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.529 DEBUG [Client fa92b1616872ed08] delay duration 19.838406ms client | 0.529 DEBUG Setting timeout of 19.838406ms client | 0.529 DEBUG [Client fa92b1616872ed08] pn=1 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 142 client | -> RX HandshakeDone client | -> RX NewToken { token: [183, 200, 130, 94, 29, 167, 92, 70, 23, 150, 17, 147, 116, 129, 170, 131, 86, 58, 149, 7, 38, 216, 44, 82, 175, 164, 35, 0, 166, 93, 214, 201, 207, 178, 70, 23, 24] } client | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [120, 254, 168, 102, 85, 106, 82, 60], stateless_reset_token: [185, 64, 83, 12, 89, 184, 63, 215, 111, 121, 235, 90, 103, 144, 129, 229] } client | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [144, 165, 135, 111, 215, 133, 226, 200], stateless_reset_token: [89, 93, 62, 49, 226, 154, 6, 64, 102, 230, 12, 221, 128, 179, 110, 1] } client | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [58, 107, 164, 96, 29, 22, 215, 58], stateless_reset_token: [207, 178, 22, 53, 158, 37, 134, 251, 2, 146, 165, 249, 94, 192, 166, 238] } client | 0.529 DEBUG [Client fa92b1616872ed08] State change from Connected -> Confirmed client | 0.529 DEBUG PMTUD started with probe size 1380 client | 0.529 DEBUG [Client fa92b1616872ed08] Drop packet number space hs client | 0.529 DEBUG [recovery::Loss] Reset loss recovery state for Handshake client | 0.529 DEBUG [Client fa92b1616872ed08] No preferred address to migrate to client | 0.529 DEBUG resumption token [1079]: 0000000121406200..e58edfc4c33bc60c client | 0.529 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 823814534 } client | 0.529 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.529 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.529 DEBUG Sending PMTUD probe of size 1380, count 1 client | 0.529 DEBUG [Client fa92b1616872ed08] pn=1 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, Ect0) len 1352 client | TX -> Ack { largest_acknowledged: 1, ack_delay: 9, first_ack_range: 1, ack_ranges: [], ecn_count: None } client | TX -> Ping client | TX -> Padding { len: 1320 } client | 0.529 DEBUG packet_sent this=0x563a16a3fbe0, pn=1, ps=1352 client | 0.529 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.529 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.529 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.529 DEBUG ECN probing: sent 1 probes client | 0.529 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.529 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.529 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.529 DEBUG [Client fa92b1616872ed08] delay duration 89.202674ms client | 0.529 DEBUG Setting timeout of 89.202674ms client | 0.529 WARN Unhandled event StateChange(Confirmed) client | 0.529 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.529 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.529 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.529 DEBUG [Client fa92b1616872ed08] delay duration 89.088998ms client | 0.529 DEBUG Setting timeout of 89.088998ms client | 0.531 DEBUG [Client fa92b1616872ed08] pn=2 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | -> RX Stream { stream_id: 0, offset: 0, len: 1230, fin: false } client | 0.531 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 845348871 } client | 0.531 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.531 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.531 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.531 DEBUG [Client fa92b1616872ed08] delay duration 19.975133ms client | 0.531 DEBUG Setting timeout of 19.975133ms client | 0.531 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.531 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.531 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.531 DEBUG [Client fa92b1616872ed08] delay duration 19.953552ms client | 0.531 DEBUG Setting timeout of 19.953552ms client | 0.532 DEBUG [Client fa92b1616872ed08] pn=3 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | -> RX Stream { stream_id: 0, offset: 1230, len: 1228, fin: false } client | 0.532 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 826369276 } client | 0.532 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.532 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.532 DEBUG [Client fa92b1616872ed08] pn=2 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, Ect0) len 31 client | TX -> Ack { largest_acknowledged: 3, ack_delay: 2, first_ack_range: 3, ack_ranges: [], ecn_count: None } client | 0.532 DEBUG ECN probing: sent 2 probes client | 0.532 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.532 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.532 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.532 DEBUG [Client fa92b1616872ed08] delay duration 86.721637ms client | 0.532 DEBUG Setting timeout of 86.721637ms client | 0.532 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.532 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.532 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.532 DEBUG [Client fa92b1616872ed08] delay duration 86.697993ms client | 0.532 DEBUG Setting timeout of 86.697993ms client | 0.536 DEBUG [Client fa92b1616872ed08] pn=4 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | -> RX Stream { stream_id: 0, offset: 2458, len: 1228, fin: false } client | 0.536 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 850928383 } client | 0.536 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.536 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.536 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.536 DEBUG [Client fa92b1616872ed08] delay duration 19.971446ms client | 0.536 DEBUG Setting timeout of 19.971446ms client | 0.536 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.536 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.536 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.536 DEBUG [Client fa92b1616872ed08] delay duration 19.947772ms client | 0.536 DEBUG Setting timeout of 19.947772ms client | 0.537 DEBUG [Client fa92b1616872ed08] pn=5 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | -> RX Stream { stream_id: 0, offset: 3686, len: 1228, fin: false } client | 0.537 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 831947325 } client | 0.537 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.537 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.537 DEBUG [Client fa92b1616872ed08] pn=3 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, Ect0) len 31 client | TX -> Ack { largest_acknowledged: 5, ack_delay: 2, first_ack_range: 5, ack_ranges: [], ecn_count: None } client | 0.537 DEBUG ECN probing: sent 3 probes client | 0.537 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.537 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.537 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.537 DEBUG [Client fa92b1616872ed08] delay duration 81.150461ms client | 0.537 DEBUG Setting timeout of 81.150461ms client | 0.537 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.537 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.537 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.537 DEBUG [Client fa92b1616872ed08] delay duration 81.125464ms client | 0.537 DEBUG Setting timeout of 81.125464ms client | 0.542 DEBUG [Client fa92b1616872ed08] pn=6 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | -> RX Stream { stream_id: 0, offset: 4914, len: 1228, fin: false } client | 0.542 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 856510750 } client | 0.542 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.542 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.542 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.542 DEBUG [Client fa92b1616872ed08] delay duration 19.973631ms client | 0.542 DEBUG Setting timeout of 19.973631ms client | 0.542 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.542 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.542 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.542 DEBUG [Client fa92b1616872ed08] delay duration 19.956689ms client | 0.542 DEBUG Setting timeout of 19.956689ms client | 0.543 DEBUG [Client fa92b1616872ed08] pn=7 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | -> RX Stream { stream_id: 0, offset: 6142, len: 1228, fin: false } client | 0.543 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 837524523 } client | 0.543 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.543 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.543 DEBUG [Client fa92b1616872ed08] pn=4 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, Ect0) len 31 client | TX -> Ack { largest_acknowledged: 7, ack_delay: 2, first_ack_range: 7, ack_ranges: [], ecn_count: None } client | 0.543 DEBUG ECN probing: sent 4 probes client | 0.543 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.543 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.543 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.543 DEBUG [Client fa92b1616872ed08] delay duration 75.585287ms client | 0.543 DEBUG Setting timeout of 75.585287ms client | 0.543 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.543 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.543 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.543 DEBUG [Client fa92b1616872ed08] delay duration 75.555961ms client | 0.543 DEBUG Setting timeout of 75.555961ms client | 0.548 DEBUG [Client fa92b1616872ed08] pn=8 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | -> RX Stream { stream_id: 0, offset: 7370, len: 1228, fin: false } client | 0.548 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 862194247 } client | 0.548 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.548 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.548 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.548 DEBUG [Client fa92b1616872ed08] delay duration 19.976556ms client | 0.548 DEBUG Setting timeout of 19.976556ms client | 0.548 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.548 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.548 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.548 DEBUG [Client fa92b1616872ed08] delay duration 19.96282ms client | 0.548 DEBUG Setting timeout of 19.96282ms client | 0.549 DEBUG [Client fa92b1616872ed08] pn=9 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 1252 client | -> RX Stream { stream_id: 0, offset: 8598, len: 1228, fin: false } client | 0.549 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 843226705 } client | 0.549 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.549 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.549 DEBUG [Client fa92b1616872ed08] pn=5 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, Ect0) len 31 client | TX -> Ack { largest_acknowledged: 9, ack_delay: 6, first_ack_range: 9, ack_ranges: [], ecn_count: None } client | 0.549 DEBUG ECN probing: sent 5 probes client | 0.549 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.549 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.549 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.549 DEBUG [Client fa92b1616872ed08] delay duration 69.845985ms client | 0.549 DEBUG Setting timeout of 69.845985ms client | 0.549 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.549 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.549 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.549 DEBUG [Client fa92b1616872ed08] delay duration 69.8063ms client | 0.549 DEBUG Setting timeout of 69.8063ms client | 0.551 DEBUG [Client fa92b1616872ed08] pn=10 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, NotEct) len 438 client | -> RX Stream { stream_id: 0, offset: 9826, len: 414, fin: true } client | 0.551 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 335, tv_nsec: 866141816 } client | 0.551 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.551 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.552 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.552 DEBUG [Client fa92b1616872ed08] delay duration 19.969182ms client | 0.552 DEBUG Setting timeout of 19.969182ms client | 0.552 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.552 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.552 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.552 DEBUG [Client fa92b1616872ed08] delay duration 19.910412ms client | 0.552 DEBUG Setting timeout of 19.910412ms client | 0.552 DEBUG [Client fa92b1616872ed08] State change from Confirmed -> Closing { error: Application(0), timeout: Instant { tv_sec: 336, tv_nsec: 114118381 } } client | 0.552 WARN Unhandled event StateChange(Closing { error: Application(0), timeout: Instant { tv_sec: 336, tv_nsec: 114118381 } }) client | 0.552 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.552 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.552 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 335, tv_nsec: 846270478 } client | 0.552 DEBUG [Client fa92b1616872ed08] pn=6 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, Ect0) len 42 client | TX -> Ack { largest_acknowledged: 10, ack_delay: 16, first_ack_range: 10, ack_ranges: [], ecn_count: None } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 0.552 DEBUG ECN probing: sent 6 probes client | 0.552 DEBUG Setting timeout of 267.753326ms client | 0.583 DEBUG [Client fa92b1616872ed08] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.583 DEBUG Building Short dcid Some(CID [8]: c3205d718e5ffba4) client | 0.583 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 335, tv_nsec: 877428997 } client | 0.583 DEBUG [Client fa92b1616872ed08] pn=7 type=Short pri-path:c3205d718e5ffba4 0.0.0.0:49514->193.167.100.100:443 Tos(Cs0, Ect0) len 43 client | TX -> Ack { largest_acknowledged: 10, ack_delay: 3910, first_ack_range: 10, ack_ranges: [], ecn_count: None } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 0.583 DEBUG ECN probing: sent 7 probes client | 0.583 DEBUG Setting timeout of 236.621577ms client | 0.583 DEBUG Setting timeout of 236.608823ms client | 0.821 DEBUG [Client fa92b1616872ed08] State change from Closing { error: Application(0), timeout: Instant { tv_sec: 336, tv_nsec: 114118381 } } -> Closed(Application(0)) client | 0.821 INFO Closing timer expired client | 0.821 DEBUG Output::None client | 0.821 WARN Unhandled event StateChange(Closed(Application(0))) client | 0.821 DEBUG Timer fired while closed client | 0.821 DEBUG Output::None client exited with code 0 Aborting on container exit... Container server Stopping Container client Stopping Container client Stopped Container server Stopped Container sim Stopping Container sim Stopped 2025-09-12 05:46:40,613 Using the client's key log file. 2025-09-12 05:46:40,622 2025-09-12 05:46:40,622 Using the client's key log file. 2025-09-12 05:46:40,622 Using the client's key log file. 2025-09-12 05:46:40,630 2025-09-12 05:46:40,630 Using the client's key log file. 2025-09-12 05:46:40,630 Using the client's key log file. 2025-09-12 05:46:41,281 Check of downloaded files succeeded.