2025-04-30 08:48:38,946 Generated random file: ldycdbnuzg of size: 5120 2025-04-30 08:48:38,946 Generated random file: oxkwavcknr of size: 10240 2025-04-30 08:48:38,946 Requests: https://server6:443/ldycdbnuzg https://server6:443/oxkwavcknr 2025-04-30 08:48:39,009 2025-04-30 08:48:39,009 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_37eewyd9/ TESTCASE_SERVER=transfer TESTCASE_CLIENT=transfer WWW=/tmp/www_n97jb8oc/ DOWNLOADS=/tmp/download_g_ymfk40/ SERVER_LOGS=/tmp/logs_server_9mvb2eq8 CLIENT_LOGS=/tmp/logs_client_yjjrqm78 SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=ghcr.io/mozilla/neqo-qns:latest SERVER=ghcr.io/ngtcp2/ngtcp2-interop:latest REQUESTS="https://server6:443/ldycdbnuzg https://server6:443/oxkwavcknr" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-04-30 08:48:51,401 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 client | Setting up routes... 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 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 server | Endpoint's IPv4 address is 193.167.100.100 client | Endpoint's IPv4 address is 193.167.0.100 server | Endpoint's IPv6 address is fd00:cafe:cafe:100::100 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.052593255s sim | Using scenario: simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25 sim | tcpdump: listening on eth1, link-type EN10MB (Ethernet)tcpdump: , snapshot length 262144 bytes sim | listening on eth0, 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/ldycdbnuzg https://server6:443/oxkwavcknr' ']' 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/ldycdbnuzg 'https://server6:443/oxkwavcknr 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: [::]:43736 -> [fd00:cafe:cafe:100::100]:443 client | 0.001 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Client dcid=296883952319f1111155 client | 0.001 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 client | 0.001 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 client | 0.001 DEBUG Outbound interface eth0 for destination fd00:cafe:cafe:100::100 has MTU 1500 client | 0.001 DEBUG [unv-path [::]:43736->[fd00:cafe:cafe:100::100]:443] Make permanent client | 0.001 DEBUG [unv-path:296883952319f1111155 [::]:43736->[fd00:cafe:cafe:100::100]:443] set as primary path client | 0.001 DEBUG [pri-unv-path:296883952319f1111155 [::]:43736->[fd00:cafe:cafe:100::100]:443] Path validated Instant { tv_sec: 582, tv_nsec: 934525142 } client | 0.001 DEBUG [Client 296883952319f1111155] client_start client | 0.002 DEBUG Writing transport parameters, msg=1 client | 0.002 DEBUG [Agent 0x556641219ed0] state -> InProgress client | 0.002 DEBUG [Client 296883952319f1111155] State change from Init -> WaitInitial client | 0.002 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.002 DEBUG Building Initial dcid Some(CID [10]: 296883952319f1111155) scid Some(CID [0]: ) client | 0.002 DEBUG CRYPTO for in offset=0, len=1191 client | 0.002 DEBUG [Client 296883952319f1111155] pn=0 type=Initial pri-path:296883952319f1111155 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1232 client | TX -> Crypto { offset: 0, len: 1191 } client | 0.002 DEBUG packet_sent this=0x55664122d6d0, pn=0, ps=1232 client | 0.002 DEBUG ECN probing: sent 1 probes client | 0.002 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.002 DEBUG Building Initial dcid Some(CID [10]: 296883952319f1111155) scid Some(CID [0]: ) client | 0.002 DEBUG CRYPTO for in offset=1191, len=348 client | 0.002 DEBUG [Client 296883952319f1111155] pn=1 type=Initial pri-path:296883952319f1111155 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 390 client | TX -> Crypto { offset: 1191, len: 348 } client | 0.002 DEBUG [Client 296883952319f1111155] pad Initial from 390 to PLPMTU 1232 client | 0.002 DEBUG packet_sent this=0x55664122d6d0, pn=1, ps=1232 client | 0.002 DEBUG ECN probing: sent 2 probes client | 0.002 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG Building Initial dcid Some(CID [10]: 296883952319f1111155) 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 296883952319f1111155] delay duration 3.891077ms client | 0.002 DEBUG Setting timeout of 3.891077ms client | 0.002 DEBUG StateChange(WaitInitial) client | 0.002 WARN Cannot create stream ConnectionState client | 0.002 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG Building Initial dcid Some(CID [10]: 296883952319f1111155) 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 296883952319f1111155] delay duration 3.865098ms client | 0.002 DEBUG Setting timeout of 3.865098ms client | 0.007 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.007 DEBUG Building Initial dcid Some(CID [10]: 296883952319f1111155) scid Some(CID [0]: ) client | 0.007 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.007 DEBUG [Client 296883952319f1111155] delay duration 294.830171ms client | 0.007 DEBUG Setting timeout of 294.830171ms client | 0.041 DEBUG [Client 296883952319f1111155] pn=1490582792 type=Initial pri-path:296883952319f1111155 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, NotEct) len 58 client | -> RX Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } client | 0.041 DEBUG [Client 296883952319f1111155] Rx ACK space=in, ranges=[0..=0] client | 0.041 DEBUG [LossRecovery] ACK for Initial - largest_acked=0 client | 0.041 DEBUG on_packets_acked this=0x55664122d6d0, limited=1, bytes_in_flight=1232, cwnd=12320, state=SlowStart, new_acked=1232 client | 0.041 DEBUG Acked crypto frame space=in offset=0 length=1191 client | 0.041 DEBUG [Client 296883952319f1111155] Changing to use Server CID=28af54f449ac242e24b4959b521ef0a60351 client | 0.041 DEBUG [Client 296883952319f1111155] State change from WaitInitial -> WaitVersion client | 0.042 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.042 DEBUG Building Initial dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) scid Some(CID [0]: ) client | 0.042 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.042 DEBUG [Client 296883952319f1111155] delay duration 80.694172ms client | 0.042 DEBUG Setting timeout of 80.694172ms client | 0.042 WARN Unhandled event StateChange(WaitVersion) client | 0.042 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.042 DEBUG Building Initial dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) scid Some(CID [0]: ) client | 0.042 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.042 DEBUG [Client 296883952319f1111155] delay duration 80.662853ms client | 0.042 DEBUG Setting timeout of 80.662853ms client | 0.044 DEBUG [Client 296883952319f1111155] pn=1490582793 type=Initial pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 152 client | -> RX Ack { largest_acknowledged: 1, ack_delay: 0, 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.044 DEBUG [Client 296883952319f1111155] Rx ACK space=in, ranges=[0..=1] client | 0.044 DEBUG [LossRecovery] ACK for Initial - largest_acked=1 client | 0.044 DEBUG on_packets_acked this=0x55664122d6d0, limited=1, bytes_in_flight=0, cwnd=12320, state=SlowStart, new_acked=1232 client | 0.044 DEBUG Acked crypto frame space=in offset=1191 length=348 client | 0.044 DEBUG Read Ok(90) bytes client | 0.044 DEBUG Write secret available for Handshake: SymKey [32]: 35c92e93a0b30cab408b64fc6927e9e2430b505adf5e74bf6546eb15c586e800 client | 0.044 DEBUG Read secret available for Handshake: SymKey [32]: a0a383d9176f25b0b21f5d46f135970b0c8c3cfc5d7ef2898fca3c7ce863f957 client | 0.044 DEBUG [Agent 0x556641219ed0] state -> InProgress client | 0.044 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: 582, tv_nsec: 977486422 } client | 0.044 DEBUG [Client 296883952319f1111155] State change from WaitVersion -> Handshaking client | 0.044 DEBUG [Client 296883952319f1111155] pn=1490582792 type=Handshake pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 760 client | -> RX Crypto { offset: 0, len: 707 } client | 0.044 DEBUG Read Ok(707) bytes client | 0.045 DEBUG [Agent 0x556641219ed0] state -> AuthenticationPending client | 0.045 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 582, tv_nsec: 977486422 } client | 0.045 DEBUG saving datagram of 288 bytes client | 0.045 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.045 DEBUG Building Initial dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) scid Some(CID [0]: ) client | 0.045 DEBUG [Client 296883952319f1111155] pn=2 type=Initial pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 61 client | TX -> Ack { largest_acknowledged: 1490582793, ack_delay: 162, first_ack_range: 1, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } client | 0.045 DEBUG Building Handshake dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) scid Some(CID [0]: ) client | 0.045 DEBUG [Client 296883952319f1111155] pn=0 type=Handshake pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 121 client | TX -> Ack { largest_acknowledged: 1490582792, ack_delay: 162, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } client | 0.045 DEBUG [Client 296883952319f1111155] Drop packet number space in client | 0.045 DEBUG [LossRecovery] Reset loss recovery state for Initial client | 0.045 WARN [LossRecovery] ignoring in-2 from dropped space client | 0.045 DEBUG ECN probing: sent 3 probes client | 0.045 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.045 DEBUG Building Handshake dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) 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 296883952319f1111155] delay duration 102.262215ms client | 0.045 DEBUG Setting timeout of 102.262215ms client | 0.045 DEBUG StateChange(Handshaking) client | 0.045 WARN Cannot create stream ConnectionState client | 0.045 DEBUG [Client 296883952319f1111155] Authenticated Ok client | 0.045 DEBUG Write secret available for ApplicationData: SymKey [32]: 06845c70c51c58bf2dda26ae93d79b2c3b3b7666e2b4218699a0b92e7e8c219f client | 0.045 DEBUG Read secret available for ApplicationData: SymKey [32]: d52ce905f1a152992040f4b0bd7e7b10a9368cc404584fc9f31051b88b711ca4 client | 0.045 DEBUG [Agent 0x556641219ed0] SSL_AuthCertificateComplete: Ok(()) client | 0.045 DEBUG [Agent 0x556641219ed0] 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 296883952319f1111155] 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 296883952319f1111155] State change from Handshaking -> Connected client | 0.045 INFO [Client 296883952319f1111155] Connection established client | 0.045 DEBUG [Client 296883952319f1111155] process saved for epoch ApplicationData client | 0.045 DEBUG [Client 296883952319f1111155] pn=1490582792 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 288 client | -> RX NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [88, 84, 128, 180, 18, 84, 21, 73, 1, 65, 189, 112, 232, 127, 132, 117, 103, 126], stateless_reset_token: [226, 203, 89, 172, 84, 69, 88, 41, 97, 158, 116, 215, 231, 181, 34, 58] } client | -> RX NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [225, 120, 58, 16, 154, 151, 113, 239, 91, 249, 214, 65, 28, 118, 134, 136, 84, 206], stateless_reset_token: [15, 156, 5, 55, 74, 80, 168, 190, 199, 52, 14, 2, 111, 120, 10, 121] } client | -> RX NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [35, 122, 52, 121, 192, 137, 95, 116, 36, 152, 66, 211, 58, 43, 238, 44, 219, 2], stateless_reset_token: [224, 233, 68, 82, 94, 146, 19, 11, 94, 173, 156, 249, 80, 182, 195, 210] } client | -> RX NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [167, 5, 26, 247, 202, 17, 180, 71, 184, 12, 81, 109, 182, 21, 53, 209, 236, 44], stateless_reset_token: [239, 166, 186, 91, 156, 99, 23, 232, 83, 2, 192, 47, 60, 126, 45, 22] } client | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [250, 50, 29, 8, 9, 174, 62, 97, 50, 2, 0, 120, 14, 75, 89, 123, 4, 118], stateless_reset_token: [234, 90, 209, 191, 167, 3, 182, 72, 246, 38, 187, 67, 200, 127, 156, 162] } client | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [115, 186, 167, 93, 116, 67, 63, 83, 96, 159, 33, 70, 123, 85, 0, 49, 66, 148], stateless_reset_token: [129, 253, 15, 107, 33, 244, 85, 65, 30, 165, 251, 126, 113, 81, 237, 234] } client | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [123, 1, 147, 169, 214, 177, 222, 161, 114, 37, 192, 254, 63, 248, 160, 37, 148, 59], stateless_reset_token: [172, 202, 47, 18, 235, 156, 243, 51, 134, 66, 209, 12, 70, 106, 120, 80] } client | -> RX Padding { len: 1 } client | 0.045 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 582, tv_nsec: 977486422 } client | 0.045 DEBUG stream BiDi creatable client | 0.045 INFO Created stream 0 for https://server6/ldycdbnuzg client | 0.045 INFO Saving https://server6/ldycdbnuzg to "/downloads/ldycdbnuzg" client | 0.046 INFO Created stream 4 for https://server6/oxkwavcknr client | 0.046 INFO Saving https://server6/oxkwavcknr to "/downloads/oxkwavcknr" client | 0.046 DEBUG StateChange(Connected) client | 0.046 DEBUG stream 0 writable client | 0.046 DEBUG stream 4 writable client | 0.046 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.046 DEBUG Building Handshake dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) scid Some(CID [0]: ) client | 0.046 DEBUG CRYPTO for hs offset=0, len=36 client | 0.046 DEBUG [Client 296883952319f1111155] pn=1 type=Handshake pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 83 client | TX -> Crypto { offset: 0, len: 36 } client | 0.046 DEBUG packet_sent this=0x55664122d6d0, pn=1, ps=83 client | 0.046 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.046 DEBUG [Client 296883952319f1111155] pn=0 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 175 client | TX -> Ack { largest_acknowledged: 1490582792, ack_delay: 246, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } 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.046 DEBUG packet_sent this=0x55664122d6d0, pn=0, ps=92 client | 0.046 DEBUG ECN probing: sent 4 probes client | 0.046 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.046 DEBUG Building Handshake dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) scid Some(CID [0]: ) client | 0.046 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.046 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.046 DEBUG [Client 296883952319f1111155] delay duration 102.272875ms client | 0.046 DEBUG Setting timeout of 102.272875ms client | 0.078 DEBUG [Client 296883952319f1111155] pn=1490582793 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1406 client | -> RX Ping client | -> RX Padding { len: 1387 } client | 0.078 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 583, tv_nsec: 12207010 } client | 0.078 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 12207010 } client | 0.078 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.078 DEBUG Building Handshake dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) scid Some(CID [0]: ) client | 0.078 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.078 DEBUG [Client 296883952319f1111155] pn=1 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 51 client | TX -> Ack { largest_acknowledged: 1490582793, ack_delay: 8, first_ack_range: 1, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 2, Ce: 0})) } client | 0.078 DEBUG ECN probing: sent 5 probes client | 0.079 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.079 DEBUG Building Handshake dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) scid Some(CID [0]: ) client | 0.079 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.079 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.079 DEBUG [Client 296883952319f1111155] delay duration 69.459574ms client | 0.079 DEBUG Setting timeout of 69.459574ms client | 0.079 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.079 DEBUG Building Handshake dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) scid Some(CID [0]: ) client | 0.079 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.079 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.079 DEBUG [Client 296883952319f1111155] delay duration 69.42001ms client | 0.079 DEBUG Setting timeout of 69.42001ms client | 0.079 DEBUG [Client 296883952319f1111155] pn=1490582794 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1200 client | -> RX HandshakeDone client | -> RX NewToken { token: [54, 54, 108, 125, 12, 99, 70, 26, 97, 96, 76, 52, 124, 98, 194, 38, 80, 76, 215, 186, 42, 76, 30, 18, 44, 210, 137, 197, 114, 210, 206, 61, 243, 102, 81, 241, 37, 213, 208, 86, 115] } client | -> RX Crypto { offset: 0, len: 237 } client | -> RX Stream { stream_id: 0, offset: 0, len: 893, fin: false } client | 0.079 DEBUG [Client 296883952319f1111155] State change from Connected -> Confirmed client | 0.079 DEBUG PMTUD started with probe size 1380 client | 0.079 DEBUG [Client 296883952319f1111155] Drop packet number space hs client | 0.079 DEBUG [LossRecovery] Reset loss recovery state for Handshake client | 0.079 DEBUG [Client 296883952319f1111155] No preferred address to migrate to client | 0.079 DEBUG Read Ok(237) bytes client | 0.080 DEBUG [0x556641219ed0] Got resumption token [908]: 02000633fafbdd4b..0000000000000000 client | 0.080 DEBUG [Agent 0x556641219ed0] 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.080 DEBUG setting max_stream_data to 262144 client | 0.080 DEBUG setting max_stream_data to 262144 client | 0.080 DEBUG resumption token [1051]: 0000000128405e00..0000000000000000 client | 0.080 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 33147328 } client | 0.080 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.080 DEBUG Sending PMTUD probe of size 1380, count 1 client | 0.080 DEBUG [Client 296883952319f1111155] pn=2 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1332 client | TX -> Ping client | TX -> Padding { len: 1295 } client | 0.080 DEBUG packet_sent this=0x55664122d6d0, pn=2, ps=1332 client | 0.080 DEBUG ECN probing: sent 6 probes client | 0.080 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.080 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG [Client 296883952319f1111155] delay duration 19.618276ms client | 0.080 DEBUG Setting timeout of 19.618276ms client | 0.080 WARN Unhandled event StateChange(Confirmed) client | 0.080 DEBUG stream BiDi creatable client | 0.080 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.080 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG [Client 296883952319f1111155] delay duration 19.58316ms client | 0.080 DEBUG Setting timeout of 19.58316ms client | 0.080 DEBUG [Client 296883952319f1111155] pn=1490582795 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1200 client | -> RX Stream { stream_id: 0, offset: 893, len: 1176, fin: false } client | 0.080 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 14143411 } client | 0.080 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.080 DEBUG [Client 296883952319f1111155] pn=3 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 51 client | TX -> Ack { largest_acknowledged: 1490582795, ack_delay: 3, first_ack_range: 3, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 4, Ce: 0})) } client | 0.080 DEBUG ECN probing: sent 7 probes client | 0.080 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.080 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG [Client 296883952319f1111155] delay duration 126.54728ms client | 0.080 DEBUG Setting timeout of 126.54728ms client | 0.080 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.080 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.080 DEBUG [Client 296883952319f1111155] delay duration 126.518777ms client | 0.080 DEBUG Setting timeout of 126.518777ms client | 0.081 DEBUG [Client 296883952319f1111155] pn=1490582796 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1200 client | -> RX Stream { stream_id: 0, offset: 2069, len: 1176, fin: false } client | 0.081 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 35145639 } client | 0.081 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.081 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.081 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.081 DEBUG [Client 296883952319f1111155] delay duration 19.932154ms client | 0.081 DEBUG Setting timeout of 19.932154ms client | 0.081 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.081 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.081 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.081 DEBUG [Client 296883952319f1111155] delay duration 19.899783ms client | 0.081 DEBUG Setting timeout of 19.899783ms client | 0.082 DEBUG [Client 296883952319f1111155] pn=1490582797 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1200 client | -> RX Stream { stream_id: 0, offset: 3245, len: 1176, fin: false } client | 0.082 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 16143094 } client | 0.082 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.082 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.082 DEBUG [Client 296883952319f1111155] pn=4 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 51 client | TX -> Ack { largest_acknowledged: 1490582797, ack_delay: 2, first_ack_range: 5, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 6, Ce: 0})) } client | 0.082 DEBUG ECN probing: sent 8 probes client | 0.082 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.082 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.082 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.082 DEBUG [Client 296883952319f1111155] delay duration 124.584664ms client | 0.082 DEBUG Setting timeout of 124.584664ms client | 0.082 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.082 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.082 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.082 DEBUG [Client 296883952319f1111155] delay duration 124.557353ms client | 0.082 DEBUG Setting timeout of 124.557353ms client | 0.083 DEBUG [Client 296883952319f1111155] pn=1490582798 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1200 client | -> RX Stream { stream_id: 0, offset: 4421, len: 699, fin: true } client | -> RX Stream { stream_id: 4, offset: 0, len: 473, fin: false } client | 0.083 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 37138075 } client | 0.083 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.083 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.083 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.083 DEBUG [Client 296883952319f1111155] delay duration 19.974342ms client | 0.083 DEBUG Setting timeout of 19.974342ms client | 0.083 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.083 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.083 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.083 DEBUG [Client 296883952319f1111155] delay duration 19.926813ms client | 0.083 DEBUG Setting timeout of 19.926813ms client | 0.084 DEBUG [Client 296883952319f1111155] pn=1490582799 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1200 client | -> RX Stream { stream_id: 4, offset: 473, len: 1176, fin: false } client | 0.084 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 18140380 } client | 0.084 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.084 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.084 DEBUG [Client 296883952319f1111155] pn=5 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 51 client | TX -> Ack { largest_acknowledged: 1490582799, ack_delay: 2, first_ack_range: 7, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 8, Ce: 0})) } client | 0.084 DEBUG ECN probing: sent 9 probes client | 0.084 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.084 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.084 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.084 DEBUG [Client 296883952319f1111155] delay duration 122.577643ms client | 0.084 DEBUG Setting timeout of 122.577643ms client | 0.084 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.084 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.084 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.084 DEBUG [Client 296883952319f1111155] delay duration 122.54945ms client | 0.084 DEBUG Setting timeout of 122.54945ms client | 0.085 DEBUG [Client 296883952319f1111155] pn=1490582800 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1200 client | -> RX Stream { stream_id: 4, offset: 1649, len: 1176, fin: false } client | 0.085 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 39140054 } client | 0.085 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.085 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.085 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.085 DEBUG [Client 296883952319f1111155] delay duration 19.974742ms client | 0.085 DEBUG Setting timeout of 19.974742ms client | 0.085 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.085 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.085 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.085 DEBUG [Client 296883952319f1111155] delay duration 19.946229ms client | 0.085 DEBUG Setting timeout of 19.946229ms client | 0.086 DEBUG [Client 296883952319f1111155] pn=1490582801 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1200 client | -> RX Stream { stream_id: 4, offset: 2825, len: 1176, fin: false } client | 0.086 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 20136919 } client | 0.086 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.086 DEBUG [Client 296883952319f1111155] pn=6 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 51 client | TX -> Ack { largest_acknowledged: 1490582801, ack_delay: 3, first_ack_range: 9, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 10, Ce: 0})) } client | 0.086 DEBUG ECN probing: sent 10 probes client | 0.086 DEBUG ECN probing concluded with 10 probes sent client | 0.086 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.086 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG [Client 296883952319f1111155] delay duration 120.578717ms client | 0.086 DEBUG Setting timeout of 120.578717ms client | 0.086 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.086 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG [Client 296883952319f1111155] delay duration 120.550394ms client | 0.086 DEBUG Setting timeout of 120.550394ms client | 0.087 DEBUG [Client 296883952319f1111155] pn=1490582802 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1200 client | -> RX Stream { stream_id: 4, offset: 4001, len: 1176, fin: false } client | 0.087 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 41142229 } client | 0.087 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.087 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.087 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.087 DEBUG [Client 296883952319f1111155] delay duration 19.976396ms client | 0.087 DEBUG Setting timeout of 19.976396ms client | 0.087 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.087 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.087 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.087 DEBUG [Client 296883952319f1111155] delay duration 19.961138ms client | 0.087 DEBUG Setting timeout of 19.961138ms client | 0.088 DEBUG [Client 296883952319f1111155] pn=1490582803 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1200 client | -> RX Stream { stream_id: 4, offset: 5177, len: 1176, fin: false } client | 0.088 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 22141859 } client | 0.088 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.088 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.088 DEBUG [Client 296883952319f1111155] pn=7 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, NotEct) len 51 client | TX -> Ack { largest_acknowledged: 1490582803, ack_delay: 3, first_ack_range: 11, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 12, Ce: 0})) } client | 0.088 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.088 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.088 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.088 DEBUG [Client 296883952319f1111155] delay duration 118.587823ms client | 0.088 DEBUG Setting timeout of 118.587823ms client | 0.088 DEBUG [Client 296883952319f1111155] pn=1490582804 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 40 client | -> RX Ack { largest_acknowledged: 0, ack_delay: 562, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } client | -> RX Padding { len: 13 } client | 0.088 DEBUG [Client 296883952319f1111155] Rx ACK space=ap, ranges=[0..=0] client | 0.088 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=0 client | 0.088 DEBUG on_packets_acked this=0x55664122d6d0, limited=1, bytes_in_flight=1332, cwnd=12320, state=SlowStart, new_acked=92 client | 0.088 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.088 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.088 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.088 DEBUG [Client 296883952319f1111155] delay duration 105.716639ms client | 0.088 DEBUG Setting timeout of 105.716639ms client | 0.088 DEBUG stream 0 complete client | 0.088 DEBUG stream 4 complete client | 0.088 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.088 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.088 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.088 DEBUG [Client 296883952319f1111155] delay duration 105.691382ms client | 0.088 DEBUG Setting timeout of 105.691382ms client | 0.111 DEBUG [Client 296883952319f1111155] pn=1490582805 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1444 client | -> RX Ping client | -> RX Padding { len: 1425 } client | 0.111 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 583, tv_nsec: 44368501 } client | 0.111 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 44368501 } client | 0.111 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.111 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.111 DEBUG [Client 296883952319f1111155] pn=8 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, NotEct) len 51 client | TX -> Ack { largest_acknowledged: 1490582805, ack_delay: 7, first_ack_range: 13, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 14, Ce: 0})) } client | 0.111 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.111 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.111 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.111 DEBUG [Client 296883952319f1111155] delay duration 83.490989ms client | 0.111 DEBUG Setting timeout of 83.490989ms client | 0.111 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.111 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.111 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.111 DEBUG [Client 296883952319f1111155] delay duration 83.460552ms client | 0.111 DEBUG Setting timeout of 83.460552ms client | 0.112 DEBUG [Client 296883952319f1111155] pn=1490582806 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1406 client | -> RX Stream { stream_id: 4, offset: 6353, len: 1382, fin: false } client | 0.112 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 65530564 } client | 0.112 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.112 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.112 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.112 DEBUG [Client 296883952319f1111155] delay duration 19.963201ms client | 0.112 DEBUG Setting timeout of 19.963201ms client | 0.112 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.112 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.112 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.112 DEBUG [Client 296883952319f1111155] delay duration 19.932584ms client | 0.112 DEBUG Setting timeout of 19.932584ms client | 0.113 DEBUG [Client 296883952319f1111155] pn=1490582807 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1406 client | -> RX Stream { stream_id: 4, offset: 7735, len: 1382, fin: false } client | 0.113 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 46679453 } client | 0.113 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.113 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.113 DEBUG [Client 296883952319f1111155] pn=9 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, NotEct) len 51 client | TX -> Ack { largest_acknowledged: 1490582807, ack_delay: 3, first_ack_range: 15, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 16, Ce: 0})) } client | 0.113 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.113 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.113 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.113 DEBUG [Client 296883952319f1111155] delay duration 81.223398ms client | 0.113 DEBUG Setting timeout of 81.223398ms client | 0.113 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.113 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.113 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.113 DEBUG [Client 296883952319f1111155] delay duration 81.198601ms client | 0.113 DEBUG Setting timeout of 81.198601ms client | 0.114 DEBUG [Client 296883952319f1111155] pn=1490582808 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, Ect0) len 1406 client | -> RX Stream { stream_id: 4, offset: 9117, len: 1123, fin: true } client | -> RX Padding { len: 259 } client | 0.114 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 583, tv_nsec: 67835585 } client | 0.114 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.114 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.114 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.114 DEBUG [Client 296883952319f1111155] delay duration 19.967529ms client | 0.114 DEBUG Setting timeout of 19.967529ms client | 0.114 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.114 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.114 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.114 DEBUG [Client 296883952319f1111155] delay duration 19.903148ms client | 0.114 DEBUG Setting timeout of 19.903148ms client | 0.114 DEBUG [Client 296883952319f1111155] State change from Confirmed -> Closing { error: Application(0), timeout: Instant { tv_sec: 583, tv_nsec: 391673050 } } client | 0.114 WARN Unhandled event StateChange(Closing { error: Application(0), timeout: Instant { tv_sec: 583, tv_nsec: 391673050 } }) client | 0.114 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.114 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.114 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 583, tv_nsec: 47966771 } client | 0.114 DEBUG [Client 296883952319f1111155] pn=10 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, NotEct) len 62 client | TX -> Ack { largest_acknowledged: 1490582808, ack_delay: 16, first_ack_range: 16, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 17, Ce: 0})) } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 0.114 DEBUG Setting timeout of 343.607274ms client | 0.116 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.116 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.116 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 583, tv_nsec: 49875812 } client | 0.116 DEBUG [Client 296883952319f1111155] pn=11 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, NotEct) len 63 client | TX -> Ack { largest_acknowledged: 1490582808, ack_delay: 255, first_ack_range: 16, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 17, Ce: 0})) } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 0.116 DEBUG Setting timeout of 341.725655ms client | 0.116 DEBUG [Client 296883952319f1111155] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } client | 0.116 DEBUG Building Short dcid Some(CID [18]: 28af54f449ac242e24b4959b521ef0a60351) client | 0.116 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 583, tv_nsec: 49963926 } client | 0.116 DEBUG [Client 296883952319f1111155] pn=12 type=Short pri-path:28af54f449ac242e24b4959b521ef0a60351 [::]:43736->[fd00:cafe:cafe:100::100]:443 IpTos(Cs0, NotEct) len 63 client | TX -> Ack { largest_acknowledged: 1490582808, ack_delay: 266, first_ack_range: 16, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 17, Ce: 0})) } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 0.116 DEBUG Setting timeout of 341.63219ms client | 0.116 DEBUG Setting timeout of 341.621179ms client | 0.459 DEBUG [Client 296883952319f1111155] State change from Closing { error: Application(0), timeout: Instant { tv_sec: 583, tv_nsec: 391673050 } } -> Closed(Application(0)) client | 0.459 INFO Closing timer expired client | 0.459 DEBUG Output::None client | 0.459 WARN Unhandled event StateChange(Closed(Application(0))) client | 0.459 DEBUG Timer fired while closed client | 0.459 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-04-30 08:48:51,511 Using the client's key log file. 2025-04-30 08:48:51,524 2025-04-30 08:48:51,525 Using the client's key log file. 2025-04-30 08:48:51,525 Using the client's key log file. 2025-04-30 08:48:51,536 2025-04-30 08:48:51,537 Using the client's key log file. 2025-04-30 08:48:52,127 Check of downloaded files succeeded. 2025-04-30 08:48:52,723 Check of downloaded files succeeded.