2025-04-30 13:01:39,972 Generated random file: xwmbeuumit of size: 5120 2025-04-30 13:01:39,972 Generated random file: htbpvzggzj of size: 10240 2025-04-30 13:01:39,972 Requests: https://server6:443/xwmbeuumit https://server6:443/htbpvzggzj 2025-04-30 13:01:40,039 2025-04-30 13:01:40,039 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_ztdpkowk/ TESTCASE_SERVER=transfer TESTCASE_CLIENT=transfer WWW=/tmp/www_9rlqly14/ DOWNLOADS=/tmp/download_uxaehi0n/ SERVER_LOGS=/tmp/logs_server_jhn9qkae CLIENT_LOGS=/tmp/logs_client_gggogn2c SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=ghcr.io/mozilla/neqo-qns:latest SERVER=stammw/quinn-interop:latest REQUESTS="https://server6:443/xwmbeuumit https://server6:443/htbpvzggzj" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-04-30 13:01:52,533 Container sim Recreate Container sim Recreated Container client Recreate Container server Recreate Container server Recreated Container client Recreated Attaching to client, server, sim sim | waiting 10s for server:443 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 server | Endpoint's IPv6 address is fd00:cafe:cafe:100::100 server | Executing server 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 server | 2025-04-30T13:01:40.644103Z INFO server: Listening on port 443 client | Endpoint's IPv6 address is fd00:cafe:cafe::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 transfer ']' client | + '[' -n /logs/qlog/ ']' client | + case "$ROLE" in client | + /wait-for-it.sh sim:57832 -s -t 30 client | wait-for-it.sh: waiting 30 seconds for sim:57832 sim | server:443 is available after 1.006969535s 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://server6:443/xwmbeuumit https://server6:443/htbpvzggzj' ']' client | + mapfile -d ' ' -t URLS client | + OPTIONS+=("${URLS[@]}") client | + RUST_LOG=debug client | + RUST_BACKTRACE=1 client | + neqo-client --cc cubic --qns-test transfer --qlog-dir /logs/qlog/ --output-dir /downloads https://server6:443/xwmbeuumit 'https://server6:443/htbpvzggzj client | ' client | ++ tee -i -a /logs/client.log client | 0.000 DEBUG Logging initialized client | 0.001 DEBUG Default socket send buffer size is 212992 client | 0.001 DEBUG Default socket receive buffer size is 1048576, not changing client | 0.001 INFO hq-interop Client connecting: [::]:41724 -> [fd00:cafe:cafe:100::100]:443 client | 0.001 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Client dcid=0b8b41b0058d1b5c client | 0.002 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 client | 0.002 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 client | 0.002 DEBUG Outbound interface eth0 for destination fd00:cafe:cafe:100::100 has MTU 1500 client | 0.002 DEBUG [unv-path [::]:41724->[fd00:cafe:cafe:100::100]:443] Make permanent client | 0.002 DEBUG [unv-path:0b8b41b0058d1b5c [::]:41724->[fd00:cafe:cafe:100::100]:443] set as primary path client | 0.002 DEBUG [pri-unv-path:0b8b41b0058d1b5c [::]:41724->[fd00:cafe:cafe:100::100]:443] Path validated Instant { tv_sec: 1030, tv_nsec: 679618759 } client | 0.002 DEBUG [Client 0b8b41b0058d1b5c] client_start client | 0.002 DEBUG Writing transport parameters, msg=1 client | 0.002 DEBUG [Agent 0x55ae30245ed0] state -> InProgress client | 0.002 DEBUG [Client 0b8b41b0058d1b5c] State change from Init -> WaitInitial client | 0.002 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.002 DEBUG Building Initial dcid Some(CID [8]: 0b8b41b0058d1b5c) scid Some(CID [0]: ) client | 0.002 DEBUG CRYPTO for in offset=0, len=1193 client | 0.002 DEBUG [Client 0b8b41b0058d1b5c] pn=0 type=Initial pri-path:0b8b41b0058d1b5c [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1232 client | TX -> Crypto { offset: 0, len: 1193 } client | 0.003 DEBUG packet_sent this=0x55ae302596d0, pn=0, ps=1232 client | 0.003 DEBUG ECN probing: sent 1 probes client | 0.003 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.003 DEBUG Building Initial dcid Some(CID [8]: 0b8b41b0058d1b5c) scid Some(CID [0]: ) client | 0.003 DEBUG CRYPTO for in offset=1193, len=346 client | 0.003 DEBUG [Client 0b8b41b0058d1b5c] pn=1 type=Initial pri-path:0b8b41b0058d1b5c [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 386 client | TX -> Crypto { offset: 1193, len: 346 } client | 0.003 DEBUG [Client 0b8b41b0058d1b5c] pad Initial from 386 to PLPMTU 1232 client | 0.003 DEBUG packet_sent this=0x55ae302596d0, pn=1, ps=1232 client | 0.003 DEBUG ECN probing: sent 2 probes client | 0.003 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.003 DEBUG Building Initial dcid Some(CID [8]: 0b8b41b0058d1b5c) scid Some(CID [0]: ) client | 0.003 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.003 DEBUG [Client 0b8b41b0058d1b5c] delay duration 3.641438ms client | 0.003 DEBUG Setting timeout of 3.641438ms client | 0.003 DEBUG StateChange(WaitInitial) client | 0.003 WARN Cannot create stream ConnectionState client | 0.003 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.003 DEBUG Building Initial dcid Some(CID [8]: 0b8b41b0058d1b5c) scid Some(CID [0]: ) client | 0.003 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.003 DEBUG [Client 0b8b41b0058d1b5c] delay duration 3.431956ms client | 0.003 DEBUG Setting timeout of 3.431956ms client | 0.008 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.008 DEBUG Building Initial dcid Some(CID [8]: 0b8b41b0058d1b5c) scid Some(CID [0]: ) client | 0.008 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.008 DEBUG [Client 0b8b41b0058d1b5c] delay duration 294.573043ms client | 0.008 DEBUG Setting timeout of 294.573043ms client | 0.043 DEBUG [Client 0b8b41b0058d1b5c] pn=0 type=Initial pri-path:0b8b41b0058d1b5c [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 137 client | -> RX Ack { largest_acknowledged: 1, ack_delay: 62, first_ack_range: 1, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 2, Ce: 0})) } client | -> RX Crypto { offset: 0, len: 90 } client | 0.043 DEBUG [Client 0b8b41b0058d1b5c] Rx ACK space=in, ranges=[0..=1] client | 0.043 DEBUG [LossRecovery] ACK for Initial - largest_acked=1 client | 0.043 DEBUG on_packets_acked this=0x55ae302596d0, limited=1, bytes_in_flight=0, cwnd=12320, state=SlowStart, new_acked=2464 client | 0.043 DEBUG Acked crypto frame space=in offset=1193 length=346 client | 0.043 DEBUG Acked crypto frame space=in offset=0 length=1193 client | 0.043 DEBUG Read Ok(90) bytes client | 0.043 DEBUG Write secret available for Handshake: SymKey [32]: c587eea20d74163d399fd2bfcb89272bd64501a2b3ec804b28760ae4fd3ecdec client | 0.043 DEBUG Read secret available for Handshake: SymKey [32]: 2358419317a670338647bcd7856ee9f4eabd2a81ddb8cab78a6ba22473d579a3 client | 0.043 DEBUG [Agent 0x55ae30245ed0] state -> InProgress client | 0.043 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865 client | 0.044 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865 client | 0.044 DEBUG [Crypto] Handshake keys installed client | 0.044 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 721230057 } client | 0.044 DEBUG [Client 0b8b41b0058d1b5c] Changing to use Server CID=a34c5bb3f13c9a2d client | 0.044 DEBUG [Client 0b8b41b0058d1b5c] State change from WaitInitial -> Handshaking client | 0.044 DEBUG [Client 0b8b41b0058d1b5c] pn=0 type=Handshake pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1063 client | -> RX Crypto { offset: 0, len: 725 } client | -> RX Padding { len: 300 } client | 0.044 DEBUG Read Ok(725) bytes client | 0.044 DEBUG [Agent 0x55ae30245ed0] state -> AuthenticationPending client | 0.044 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 721230057 } client | 0.044 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.044 DEBUG Building Initial dcid Some(CID [8]: a34c5bb3f13c9a2d) scid Some(CID [0]: ) client | 0.044 DEBUG [Client 0b8b41b0058d1b5c] pn=2 type=Initial pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 44 client | TX -> Ack { largest_acknowledged: 0, ack_delay: 181, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } client | 0.044 DEBUG Building Handshake dcid Some(CID [8]: a34c5bb3f13c9a2d) scid Some(CID [0]: ) client | 0.044 DEBUG [Client 0b8b41b0058d1b5c] pn=0 type=Handshake pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 87 client | TX -> Ack { largest_acknowledged: 0, ack_delay: 181, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } client | 0.044 DEBUG [Client 0b8b41b0058d1b5c] Drop packet number space in client | 0.044 DEBUG [LossRecovery] Reset loss recovery state for Initial client | 0.044 WARN [LossRecovery] ignoring in-2 from dropped space client | 0.044 DEBUG ECN probing: sent 3 probes client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.045 DEBUG Building Handshake dcid Some(CID [8]: a34c5bb3f13c9a2d) scid Some(CID [0]: ) client | 0.045 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] delay duration 120.787879ms client | 0.045 DEBUG Setting timeout of 120.787879ms client | 0.045 DEBUG saving datagram of 214 bytes client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.045 DEBUG Building Handshake dcid Some(CID [8]: a34c5bb3f13c9a2d) scid Some(CID [0]: ) client | 0.045 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] delay duration 120.746882ms client | 0.045 DEBUG Setting timeout of 120.746882ms client | 0.045 DEBUG StateChange(Handshaking) client | 0.045 WARN Cannot create stream ConnectionState client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] Authenticated Ok client | 0.045 DEBUG Write secret available for ApplicationData: SymKey [32]: 9dc1941d09dc2e0d6b56f3477446359154b7b35d1adbf3afa2f4886cbee274fb client | 0.045 DEBUG Read secret available for ApplicationData: SymKey [32]: 0fd1232b656992028d44b6b51df247c2e4bb3b61578b8b5aea8fc89b9281d1c2 client | 0.045 DEBUG [Agent 0x55ae30245ed0] SSL_AuthCertificateComplete: Ok(()) client | 0.045 DEBUG [Agent 0x55ae30245ed0] state -> Complete(SecretAgentInfo { version: 772, cipher: 4865, group: 29, resumed: false, early_data: false, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 }) client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] TLS connection complete client | 0.045 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865 client | 0.045 DEBUG [Crypto] Application write key installed client | 0.045 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865 client | 0.045 DEBUG [Crypto] application read keys installed client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] State change from Handshaking -> Connected client | 0.045 INFO [Client 0b8b41b0058d1b5c] Connection established client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] process saved for epoch ApplicationData client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] pn=0 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 214 client | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [116, 57, 120, 240, 153, 112, 59, 127], stateless_reset_token: [69, 108, 115, 120, 202, 38, 85, 108, 179, 156, 160, 125, 144, 101, 1, 141] } client | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [60, 166, 26, 74, 174, 92, 226, 106], stateless_reset_token: [0, 110, 106, 169, 234, 202, 239, 212, 110, 88, 133, 75, 69, 100, 189, 222] } client | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [52, 131, 21, 141, 146, 248, 174, 14], stateless_reset_token: [208, 146, 183, 127, 206, 225, 66, 177, 148, 167, 189, 162, 108, 244, 188, 111] } client | -> RX NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [150, 69, 31, 81, 185, 136, 220, 184], stateless_reset_token: [27, 200, 2, 39, 172, 14, 153, 78, 74, 68, 158, 80, 59, 56, 15, 227] } client | -> RX NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [140, 51, 114, 209, 44, 25, 163, 213], stateless_reset_token: [22, 225, 125, 183, 215, 180, 118, 142, 178, 34, 25, 155, 105, 35, 232, 208] } client | -> RX NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [87, 190, 119, 55, 89, 198, 162, 173], stateless_reset_token: [60, 130, 251, 167, 53, 89, 108, 227, 6, 113, 173, 224, 235, 114, 6, 113] } client | -> RX NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [161, 105, 205, 55, 4, 245, 196, 19], stateless_reset_token: [235, 54, 86, 50, 248, 37, 112, 237, 0, 60, 252, 99, 216, 127, 121, 18] } client | 0.045 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 742874787 } client | 0.045 DEBUG stream BiDi creatable client | 0.045 INFO Created stream 0 for https://server6/xwmbeuumit client | 0.045 INFO Saving https://server6/xwmbeuumit to "/downloads/xwmbeuumit" client | 0.045 INFO Created stream 4 for https://server6/htbpvzggzj client | 0.045 INFO Saving https://server6/htbpvzggzj to "/downloads/htbpvzggzj" client | 0.045 DEBUG stream UniDi creatable client | 0.045 DEBUG StateChange(Connected) client | 0.045 DEBUG stream 0 writable client | 0.045 DEBUG stream 4 writable client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.045 DEBUG Building Handshake dcid Some(CID [8]: a34c5bb3f13c9a2d) scid Some(CID [0]: ) client | 0.045 DEBUG CRYPTO for hs offset=0, len=36 client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] pn=1 type=Handshake pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 73 client | TX -> Crypto { offset: 0, len: 36 } client | 0.045 DEBUG packet_sent this=0x55ae302596d0, pn=1, ps=73 client | 0.045 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] pn=0 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 139 client | TX -> Stream { stream_id: 0, offset: 0, len: 17, fin: true } client | TX -> Stream { stream_id: 4, offset: 0, len: 17, fin: true } client | 0.045 DEBUG packet_sent this=0x55ae302596d0, pn=0, ps=66 client | 0.045 DEBUG ECN probing: sent 4 probes client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.045 DEBUG Building Handshake dcid Some(CID [8]: a34c5bb3f13c9a2d) scid Some(CID [0]: ) client | 0.045 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.045 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.045 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.254755ms client | 0.045 DEBUG Setting timeout of 19.254755ms server | 2025-04-30T13:01:41.732835Z INFO server: serving /www/htbpvzggzj server | 2025-04-30T13:01:41.732842Z INFO server: serving /www/xwmbeuumit client | 0.066 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.066 DEBUG Building Handshake dcid Some(CID [8]: a34c5bb3f13c9a2d) scid Some(CID [0]: ) client | 0.066 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.066 DEBUG [Client 0b8b41b0058d1b5c] pn=1 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 35 client | TX -> Ack { largest_acknowledged: 0, ack_delay: 2618, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } client | 0.066 DEBUG ECN probing: sent 5 probes client | 0.066 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.066 DEBUG Building Handshake dcid Some(CID [8]: a34c5bb3f13c9a2d) scid Some(CID [0]: ) client | 0.066 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.066 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.066 DEBUG [Client 0b8b41b0058d1b5c] delay duration 100.462159ms client | 0.066 DEBUG Setting timeout of 100.462159ms client | 0.076 DEBUG [Client 0b8b41b0058d1b5c] pn=1 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 379 client | -> RX HandshakeDone client | -> RX Crypto { offset: 0, len: 356 } client | 0.076 DEBUG [Client 0b8b41b0058d1b5c] State change from Connected -> Confirmed client | 0.076 DEBUG PMTUD started with probe size 1380 client | 0.076 DEBUG [Client 0b8b41b0058d1b5c] Drop packet number space hs client | 0.076 DEBUG [LossRecovery] Reset loss recovery state for Handshake client | 0.076 DEBUG [Client 0b8b41b0058d1b5c] No preferred address to migrate to client | 0.076 DEBUG Read Ok(356) bytes client | 0.077 DEBUG [0x55ae30245ed0] Got resumption token [728]: 02000633fe84b9e2..d43397ce57a1aa79 client | 0.077 DEBUG [0x55ae30245ed0] Got resumption token [728]: 02000633fe84b9e2..d0efbed1ed95f77a client | 0.077 DEBUG [0x55ae30245ed0] Got resumption token [728]: 02000633fe84b9e2..4c727914cb7a1be5 client | 0.077 DEBUG [0x55ae30245ed0] Got resumption token [728]: 02000633fe84b9e2..29bf0d6217a20286 client | 0.077 DEBUG [Agent 0x55ae30245ed0] state -> Complete(SecretAgentInfo { version: 772, cipher: 4865, group: 29, resumed: false, early_data: false, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 }) client | 0.077 DEBUG setting max_stream_data to 1250000 client | 0.077 DEBUG setting max_stream_data to 1250000 client | 0.077 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 774666461 } client | 0.077 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.077 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.077 DEBUG Sending PMTUD probe of size 1380, count 1 client | 0.077 DEBUG [Client 0b8b41b0058d1b5c] pn=2 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1332 client | TX -> Ping client | TX -> Padding { len: 1305 } client | 0.077 DEBUG packet_sent this=0x55ae302596d0, pn=2, ps=1332 client | 0.077 DEBUG ECN probing: sent 6 probes client | 0.077 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.077 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.077 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.077 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.528718ms client | 0.077 DEBUG Setting timeout of 19.528718ms client | 0.077 WARN Unhandled event StateChange(Confirmed) client | 0.077 DEBUG stream BiDi creatable client | 0.077 DEBUG stream UniDi creatable client | 0.077 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.077 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.077 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.077 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.491478ms client | 0.077 DEBUG Setting timeout of 19.491478ms client | 0.078 DEBUG [Client 0b8b41b0058d1b5c] pn=2 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1452 client | -> RX Stream { stream_id: 0, offset: 0, len: >>1432, fin: false } client | 0.078 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 755871898 } client | 0.078 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.078 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.078 DEBUG [Client 0b8b41b0058d1b5c] pn=3 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 34 client | TX -> Ack { largest_acknowledged: 2, ack_delay: 4, first_ack_range: 2, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 3, Ce: 0})) } client | 0.078 DEBUG ECN probing: sent 7 probes client | 0.078 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.078 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.078 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.078 DEBUG [Client 0b8b41b0058d1b5c] delay duration 144.94446ms client | 0.078 DEBUG Setting timeout of 144.94446ms client | 0.078 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.078 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.078 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.078 DEBUG [Client 0b8b41b0058d1b5c] delay duration 144.89658ms client | 0.078 DEBUG Setting timeout of 144.89658ms client | 0.079 DEBUG [Client 0b8b41b0058d1b5c] pn=3 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1452 client | -> RX Stream { stream_id: 0, offset: 1432, len: >>1430, fin: false } client | 0.079 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 777067466 } client | 0.079 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.079 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.079 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.079 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.969773ms client | 0.079 DEBUG Setting timeout of 19.969773ms client | 0.079 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.079 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.079 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.079 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.938945ms client | 0.079 DEBUG Setting timeout of 19.938945ms client | 0.080 DEBUG [Client 0b8b41b0058d1b5c] pn=4 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1452 client | -> RX Stream { stream_id: 0, offset: 2862, len: >>1430, fin: false } client | 0.080 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 758260050 } client | 0.080 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.080 DEBUG [Client 0b8b41b0058d1b5c] pn=4 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 34 client | TX -> Ack { largest_acknowledged: 4, ack_delay: 3, first_ack_range: 4, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 5, Ce: 0})) } client | 0.080 DEBUG ECN probing: sent 8 probes client | 0.080 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.080 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG [Client 0b8b41b0058d1b5c] delay duration 142.600992ms client | 0.080 DEBUG Setting timeout of 142.600992ms client | 0.080 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.080 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG [Client 0b8b41b0058d1b5c] delay duration 142.580333ms client | 0.080 DEBUG Setting timeout of 142.580333ms client | 0.081 DEBUG [Client 0b8b41b0058d1b5c] pn=5 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 852 client | -> RX Stream { stream_id: 0, offset: 4292, len: 828, fin: false } client | 0.081 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 778976571 } client | 0.081 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.081 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.081 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.081 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.953072ms client | 0.081 DEBUG Setting timeout of 19.953072ms client | 0.081 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.081 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.081 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.081 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.93075ms client | 0.081 DEBUG Setting timeout of 19.93075ms client | 0.082 DEBUG [Client 0b8b41b0058d1b5c] pn=6 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1452 client | -> RX Stream { stream_id: 4, offset: 0, len: >>1432, fin: false } client | 0.082 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 760177209 } client | 0.082 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.082 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.082 DEBUG [Client 0b8b41b0058d1b5c] pn=5 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 34 client | TX -> Ack { largest_acknowledged: 6, ack_delay: 3, first_ack_range: 6, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 7, Ce: 0})) } client | 0.082 DEBUG ECN probing: sent 9 probes client | 0.082 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.082 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.082 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.082 DEBUG [Client 0b8b41b0058d1b5c] delay duration 140.687549ms client | 0.082 DEBUG Setting timeout of 140.687549ms client | 0.082 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.082 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.082 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.082 DEBUG [Client 0b8b41b0058d1b5c] delay duration 140.668573ms client | 0.082 DEBUG Setting timeout of 140.668573ms client | 0.083 DEBUG [Client 0b8b41b0058d1b5c] pn=7 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1452 client | -> RX Stream { stream_id: 4, offset: 1432, len: >>1430, fin: false } client | 0.083 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 781374424 } client | 0.083 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.083 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.083 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.083 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.934036ms client | 0.083 DEBUG Setting timeout of 19.934036ms client | 0.083 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.083 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.083 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.083 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.906114ms client | 0.083 DEBUG Setting timeout of 19.906114ms client | 0.084 DEBUG [Client 0b8b41b0058d1b5c] pn=8 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1452 client | -> RX Stream { stream_id: 4, offset: 2862, len: >>1430, fin: false } client | 0.084 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 762576736 } client | 0.084 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.084 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.084 DEBUG [Client 0b8b41b0058d1b5c] pn=6 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 34 client | TX -> Ack { largest_acknowledged: 8, ack_delay: 3, first_ack_range: 8, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 9, Ce: 0})) } client | 0.084 DEBUG ECN probing: sent 10 probes client | 0.084 DEBUG ECN probing concluded with 10 probes sent client | 0.084 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.084 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.084 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.084 DEBUG [Client 0b8b41b0058d1b5c] delay duration 138.299063ms client | 0.084 DEBUG Setting timeout of 138.299063ms client | 0.084 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.084 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.084 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.084 DEBUG [Client 0b8b41b0058d1b5c] delay duration 138.271832ms client | 0.084 DEBUG Setting timeout of 138.271832ms client | 0.085 DEBUG [Client 0b8b41b0058d1b5c] pn=9 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1452 client | -> RX Stream { stream_id: 4, offset: 4292, len: >>1430, fin: false } client | 0.086 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 783806208 } client | 0.086 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.086 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.9678ms client | 0.086 DEBUG Setting timeout of 19.9678ms client | 0.086 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.086 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.943695ms client | 0.086 DEBUG Setting timeout of 19.943695ms client | 0.107 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.107 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.107 DEBUG [Client 0b8b41b0058d1b5c] pn=7 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, NotEct) len 35 client | TX -> Ack { largest_acknowledged: 9, ack_delay: 2648, first_ack_range: 9, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 10, Ce: 0})) } client | 0.107 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.107 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.107 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.107 DEBUG [Client 0b8b41b0058d1b5c] delay duration 115.755489ms client | 0.107 DEBUG Setting timeout of 115.755489ms client | 0.110 DEBUG [Client 0b8b41b0058d1b5c] pn=10 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1452 client | -> RX Ack { largest_acknowledged: 3, ack_delay: 11, first_ack_range: 3, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 4, Ce: 0})) } client | -> RX Stream { stream_id: 4, offset: 5722, len: >>1422, fin: false } client | 0.110 DEBUG [Client 0b8b41b0058d1b5c] Rx ACK space=ap, ranges=[0..=3] client | 0.110 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=3 client | 0.110 INFO ECN validation succeeded, path is capable client | 0.110 DEBUG on_packets_acked this=0x55ae302596d0, limited=1, bytes_in_flight=0, cwnd=12320, state=SlowStart, new_acked=1398 client | 0.110 DEBUG PMTUD probe of size 1380 succeeded client | 0.110 DEBUG PMTUD started with probe size 1420 client | 0.110 DEBUG PLPMTU changed from 1232 to 1332, updating pacer client | 0.110 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 808099578 } client | 0.110 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.110 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.110 DEBUG Sending PMTUD probe of size 1420, count 1 client | 0.110 DEBUG [Client 0b8b41b0058d1b5c] pn=8 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1372 client | TX -> Ping client | TX -> Padding { len: 1345 } client | 0.110 DEBUG packet_sent this=0x55ae302596d0, pn=8, ps=1372 client | 0.110 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.110 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.110 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.110 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.843697ms client | 0.110 DEBUG Setting timeout of 19.843697ms client | 0.110 DEBUG stream 0 complete client | 0.110 DEBUG stream 4 complete client | 0.110 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.110 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.110 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.110 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.798452ms client | 0.110 DEBUG Setting timeout of 19.798452ms client | 0.111 DEBUG [Client 0b8b41b0058d1b5c] pn=11 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1452 client | -> RX Stream { stream_id: 0, offset: 5120, len: 0, fin: true } client | -> RX Stream { stream_id: 4, offset: 7144, len: >>1425, fin: false } client | 0.111 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 789210451 } client | 0.111 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.111 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.111 DEBUG [Client 0b8b41b0058d1b5c] pn=9 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 34 client | TX -> Ack { largest_acknowledged: 11, ack_delay: 4, first_ack_range: 11, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 12, Ce: 0})) } client | 0.111 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.111 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.111 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.111 DEBUG [Client 0b8b41b0058d1b5c] delay duration 131.781378ms client | 0.111 DEBUG Setting timeout of 131.781378ms client | 0.111 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.111 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.111 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.111 DEBUG [Client 0b8b41b0058d1b5c] delay duration 131.710475ms client | 0.111 DEBUG Setting timeout of 131.710475ms client | 0.112 DEBUG [Client 0b8b41b0058d1b5c] pn=12 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1452 client | -> RX Stream { stream_id: 4, offset: 8569, len: >>1430, fin: false } client | 0.112 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 810407928 } client | 0.112 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.112 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.112 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.112 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.969834ms client | 0.112 DEBUG Setting timeout of 19.969834ms client | 0.112 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.112 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.112 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.112 DEBUG [Client 0b8b41b0058d1b5c] delay duration 19.952992ms client | 0.112 DEBUG Setting timeout of 19.952992ms client | 0.112 DEBUG [Client 0b8b41b0058d1b5c] pn=13 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 265 client | -> RX Stream { stream_id: 4, offset: 9999, len: 241, fin: true } client | 0.112 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 1030, tv_nsec: 790695221 } client | 0.112 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.112 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.112 DEBUG [Client 0b8b41b0058d1b5c] pn=10 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 34 client | TX -> Ack { largest_acknowledged: 13, ack_delay: 3, first_ack_range: 13, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 14, Ce: 0})) } client | 0.112 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.112 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.112 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.112 DEBUG [Client 0b8b41b0058d1b5c] delay duration 130.278474ms client | 0.112 DEBUG Setting timeout of 130.278474ms client | 0.113 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.113 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.113 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.113 DEBUG [Client 0b8b41b0058d1b5c] delay duration 130.172515ms client | 0.113 DEBUG Setting timeout of 130.172515ms client | 0.113 DEBUG [Client 0b8b41b0058d1b5c] State change from Confirmed -> Closing { error: Application(0), timeout: Instant { tv_sec: 1031, tv_nsec: 189606151 } } client | 0.113 WARN Unhandled event StateChange(Closing { error: Application(0), timeout: Instant { tv_sec: 1031, tv_nsec: 189606151 } }) client | 0.113 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.113 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.113 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 1030, tv_nsec: 790942675 } client | 0.113 DEBUG [Client 0b8b41b0058d1b5c] pn=11 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 45 client | TX -> Ack { largest_acknowledged: 13, ack_delay: 30, first_ack_range: 13, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 14, Ce: 0})) } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 0.113 DEBUG Setting timeout of 398.576173ms client | 0.143 DEBUG [Client 0b8b41b0058d1b5c] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } client | 0.143 DEBUG Building Short dcid Some(CID [8]: a34c5bb3f13c9a2d) client | 0.143 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 1030, tv_nsec: 821717493 } client | 0.143 DEBUG [Client 0b8b41b0058d1b5c] pn=12 type=Short pri-path:a34c5bb3f13c9a2d [::]:41724->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 46 client | TX -> Ack { largest_acknowledged: 13, ack_delay: 3877, first_ack_range: 13, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 14, Ce: 0})) } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 0.144 DEBUG Setting timeout of 367.711917ms client | 0.144 DEBUG Setting timeout of 367.701377ms client | 0.513 DEBUG [Client 0b8b41b0058d1b5c] State change from Closing { error: Application(0), timeout: Instant { tv_sec: 1031, tv_nsec: 189606151 } } -> Closed(Application(0)) client | 0.513 INFO Closing timer expired client | 0.513 DEBUG Output::None client | 0.513 WARN Unhandled event StateChange(Closed(Application(0))) client | 0.513 DEBUG Timer fired while closed client | 0.513 DEBUG Output::None client exited with code 0 Aborting on container exit... Container client Stopping Container server Stopping Container client Stopped Container server Stopped Container sim Stopping Container sim Stopped 2025-04-30 13:01:52,647 Using the client's key log file. 2025-04-30 13:01:52,660 2025-04-30 13:01:52,661 Using the client's key log file. 2025-04-30 13:01:52,661 Using the client's key log file. 2025-04-30 13:01:52,675 2025-04-30 13:01:52,676 Using the client's key log file. 2025-04-30 13:01:53,315 Check of downloaded files succeeded. 2025-04-30 13:01:53,943 Check of downloaded files succeeded.