2025-04-30 11:47:24,311 Generated random file: vqtwssgsta of size: 10240 2025-04-30 11:47:24,311 Requests: https://server4:443/vqtwssgsta 2025-04-30 11:47:24,371 2025-04-30 11:47:24,371 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_wj6e73wi/ TESTCASE_SERVER=retry TESTCASE_CLIENT=retry WWW=/tmp/www_00id2gku/ DOWNLOADS=/tmp/download_mqcxv6k0/ SERVER_LOGS=/tmp/logs_server_9n8k84ar CLIENT_LOGS=/tmp/logs_client_mw3ojgfs SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=ghcr.io/microsoft/msquic/qns:main SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server4:443/vqtwssgsta" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-04-30 11:47:41,435 Container sim Created Container server Recreate Container client Recreate Container client Recreated Container server 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 client | Setting up routes... 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-checksumming: off client | tx-checksum-ip-generic: off client | tx-checksum-sctp: off client | tcp-segmentation-offload: off client | tx-tcp-segmentation: off [requested on] client | tx-tcp-ecn-segmentation: off [requested on] client | tx-tcp-mangleid-segmentation: off [requested on] client | tx-tcp6-segmentation: off [requested on] client | tx-udp-segmentation: off [requested on] 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 server | + export PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/neqo/bin server | + PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/neqo/bin server | + '[' -n retry ']' server | + '[' -n /logs/qlog/ ']' server | + case "$ROLE" in server | + DB=/neqo/db server | + CERT=cert server | ++ mktemp server | + P12CERT=/tmp/tmp.tYM8U5klOn server | + mkdir -p /neqo/db server | + certutil -N -d sql:/neqo/db --empty-password client | wait-for-it.sh: waiting 30 seconds for sim:57832 server | + openssl pkcs12 -export -nodes -in /certs/cert.pem -inkey /certs/priv.key -name cert -passout pass: -out /tmp/tmp.tYM8U5klOn server | Warning: output encryption option -nodes ignored with -export server | + pk12util -d sql:/neqo/db -i /tmp/tmp.tYM8U5klOn -W '' server | pk12util: PKCS12 IMPORT SUCCESSFUL server | + certutil -L -d sql:/neqo/db -n cert server | Certificate: server | Data: server | Version: 3 (0x2) server | Serial Number: server | 57:07:51:f5:90:5e:74:01:86:24:66:b9:37:e6:d0:04: server | a0:a6:be:32 server | Signature Algorithm: X9.62 ECDSA signature with SHA256 server | Issuer: "O=interop runner Root Certificate Authority" server | Validity: server | Not Before: Wed Apr 30 11:47:24 2025 server | Not After : Sat May 10 11:47:24 2025 server | Subject: "O=interop runner leaf" server | Subject Public Key Info: server | Public Key Algorithm: X9.62 elliptic curve public key server | Args: server | 06:08:2a:86:48:ce:3d:03:01:07 server | EC Public Key: server | PublicValue: server | 04:7c:02:67:cf:3b:a3:d4:11:92:e8:fe:80:f4:0b:37: server | 71:47:5e:86:dd:7d:d9:3d:c6:45:bc:75:f8:c8:51:2f: server | 13:a7:2d:7e:7d:6c:34:75:77:68:8b:a4:dd:7e:0a:c7: server | 4f:18:82:4d:ef:5b:9d:19:7c:f8:1e:82:8d:c7:09:a5: server | 27 server | Curve: ANSI X9.62 elliptic curve prime256v1 (aka secp256r1, NIST P-256) server | Signed Extensions: server | Name: Certificate Subject Alt Name server | DNS name: "server" server | DNS name: "server4" server | DNS name: "server6" server | DNS name: "server46" server | server | Name: Certificate Subject Key ID server | Data: server | 1d:87:1a:8d:17:4f:35:9f:d6:3e:1e:dc:a0:b5:83:a3: server | 13:ee:0a:1e server | server | Name: Certificate Authority Key Identifier server | Key ID: server | 58:ec:14:40:90:c4:1f:62:7a:2e:a6:fa:07:42:88:be: server | 9a:0f:ff:b5 server | server | Signature Algorithm: X9.62 ECDSA signature with SHA256 server | Signature: server | 30:45:02:20:56:38:0f:2e:b4:86:ef:25:97:ef:42:2c: server | bf:fe:28:38:58:a2:68:69:56:5f:a3:64:8a:77:3a:dc: server | 06:10:e9:8c:02:21:00:dc:b5:c2:f3:ce:ee:15:8a:70: server | 90:db:c5:10:74:36:7c:ea:e7:3e:e1:28:70:88:6e:d9: server | 1b:79:e7:98:ca:f2:0d server | Fingerprint (SHA-256): server | 5A:49:CF:C5:59:BA:13:F5:3F:B4:79:10:50:DB:3B:5D:EE:02:96:D8:49:77:AD:B7:EF:ED:D6:9A:9D:F6:B4:16 server | Fingerprint (SHA1): server | 1B:13:6A:59:C9:A0:85:27:9D:6A:36:43:9B:F7:71:D7:91:D6:C6:C6 server | server | Mozilla-CA-Policy: false (attribute missing) server | Certificate Trust Flags: server | SSL Flags: server | User server | Email Flags: server | User server | Object Signing Flags: server | User server | server | + OPTIONS=(--cc cubic --qns-test "$TESTCASE" --qlog-dir "$QLOGDIR" -d "$DB" -k "$CERT") server | + '[' retry = connectionmigration ']' server | + RUST_LOG=debug server | + RUST_BACKTRACE=1 server | + neqo-server --cc cubic --qns-test retry --qlog-dir /logs/qlog/ -d /neqo/db -k cert '[::]:443' server | ++ tee -i -a /logs/server.log server | 0.000 DEBUG Logging initialized server | 0.002 DEBUG Default socket send buffer size is 212992 server | 0.002 DEBUG Default socket receive buffer size is 1048576, not changing server | 0.002 INFO Server waiting for connection on: [::]:443 server | 0.776 DEBUG [Server] Unsupported version: 57414954 server | 0.776 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:52251 IpTos(Cs0, NotEct) len 15 server | 0.776 DEBUG [Server] Unsupported version: 57414954 server | 0.776 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:52251 IpTos(Cs0, NotEct) len 15 server | 0.776 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" }) sim | server:443 is available after 1.030243127s server | 0.776 DEBUG [Server] Unsupported version: 57414954 server | 0.776 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:52251 IpTos(Cs0, NotEct) len 15 server | 0.776 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" }) sim | Using scenario: simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25 sim | tcpdump: listening on eth1, link-type EN10MB (Ethernet), snapshot length 262144 bytes sim | tcpdump: listening on eth0, link-type EN10MB (Ethernet), snapshot length 262144 bytes client | wait-for-it.sh: sim:57832 is available after 1 seconds client | Connecting to server4 client | Client params (before files):-test:D -sslkeylogfile:/logs/keys.log client | Sending request: GET /vqtwssgsta server | 1.007 DEBUG [Server] Handle initial server | 1.007 INFO AddressValidation: no token; validating server | 1.007 INFO [Server] Send retry for CID [8]: f4dda274f2489785 server | 1.008 DEBUG [Server] type=Retry path:f4dda274f2489785 [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 84 server | 1.039 DEBUG [Server] Handle initial server | 1.039 INFO AddressValidation: valid Retry token for f4dda274f2489785 server | 1.040 INFO [Server] Accept connection CID [8]: f4dda274f2489785 server | 1.040 DEBUG Overwrite initial version Version1 ==> Version1 server | 1.041 DEBUG Outbound interface eth0 for destination ::ffff:193.167.0.100 has MTU 1500 server | 1.041 INFO [Server ...] Received valid Initial packet with scid CID [0]: dcid CID [10]: 0e0745f571f880abaab2 server | 1.041 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=0e0745f571f880abaab2 server | 1.041 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 server | 1.041 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 server | 1.041 DEBUG [Server 0e0745f571f880abaab2] State change from Init -> WaitInitial server | 1.041 DEBUG [Server 0e0745f571f880abaab2] pn=1 type=Initial unv-path [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 1220 server | -> RX Crypto { offset: 0, len: 288 } server | -> RX Padding { len: 837 } server | 1.041 DEBUG Read Ok(288) bytes server | 1.041 DEBUG 0-RTT: no token, no 0-RTT server | 1.042 DEBUG Read secret available for Handshake: SymKey [32]: 0065ebd5fbed6680f2cce95914711ed5f2bc02111457b8f60dded9d876eae964 server | 1.042 DEBUG Write secret available for Handshake: SymKey [32]: 69a5086f278bb95836a10389ff9b3e3d35f7aff5ba4bfaa40f23e72f91fb5e51 server | 1.042 DEBUG Writing transport parameters, msg=8 server | 1.042 DEBUG Read secret available for ApplicationData: SymKey [32]: 34b2b86df9eb7138799eaa7656af38bd531a9071fcf9d9b1b59b82499cdd08c7 server | 1.042 DEBUG Write secret available for ApplicationData: SymKey [32]: cec1488b7575a86ed76eb643a5dfc947250ed986be0535cc5ea0ec1822795be9 server | 1.042 DEBUG [Agent 0x55c16d5f4710] state -> InProgress server | 1.042 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865 server | 1.042 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865 server | 1.042 DEBUG [Crypto] Handshake keys installed server | 1.042 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 1.042 DEBUG [Crypto] Application write key installed server | 1.042 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 358, tv_nsec: 765734516 } server | 1.042 DEBUG [unv-path [::]:443->[::ffff:193.167.0.100]:57529] Make permanent server | 1.042 DEBUG [unv-path: [::]:443->[::ffff:193.167.0.100]:57529] set as primary path server | 1.042 DEBUG [Server 0e0745f571f880abaab2] State change from WaitInitial -> Handshaking server | 1.042 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.042 DEBUG Building Initial dcid Some(CID [0]: ) scid Some(CID [10]: 487f517c8b2960fa7009) server | 1.042 DEBUG CRYPTO for in offset=0, len=90 server | 1.042 DEBUG [Server 0e0745f571f880abaab2] pn=0 type=Initial pri-unv-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 136 server | TX -> Ack { largest_acknowledged: 1, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | TX -> Crypto { offset: 0, len: 90 } server | 1.042 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: 487f517c8b2960fa7009) server | 1.042 DEBUG CRYPTO for hs offset=0, len=737 server | 1.042 DEBUG [Server 0e0745f571f880abaab2] pn=0 type=Handshake pri-unv-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 913 server | TX -> Crypto { offset: 0, len: 737 } server | 1.042 DEBUG packet_sent this=0x55c16d63bb40, pn=0, ps=777 server | 1.042 DEBUG Building Short dcid Some(CID [0]: ) server | 1.042 DEBUG [Server 0e0745f571f880abaab2] pad Initial from 913 to PLPMTU 1232 server | 1.042 DEBUG packet_sent this=0x55c16d63bb40, pn=0, ps=455 server | 1.042 DEBUG ECN probing: sent 1 probes server | 1.042 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.042 DEBUG Building Initial dcid Some(CID [0]: ) scid Some(CID [10]: 487f517c8b2960fa7009) server | 1.042 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: 487f517c8b2960fa7009) server | 1.042 DEBUG Building Short dcid Some(CID [0]: ) server | 1.042 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.042 DEBUG [Server 0e0745f571f880abaab2] delay duration 296.922268ms server | 1.042 DEBUG Setting timeout of 296.922268ms server | 1.043 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.043 DEBUG Building Initial dcid Some(CID [0]: ) scid Some(CID [10]: 487f517c8b2960fa7009) server | 1.043 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: 487f517c8b2960fa7009) server | 1.043 DEBUG Building Short dcid Some(CID [0]: ) server | 1.043 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.043 DEBUG [Server 0e0745f571f880abaab2] delay duration 296.884106ms server | 1.043 DEBUG Setting timeout of 296.884106ms server | 1.075 DEBUG [Server 0e0745f571f880abaab2] Drop packet number space in server | 1.075 DEBUG [LossRecovery] Reset loss recovery state for Initial server | 1.075 INFO [pri-unv-path: [::]:443->[::ffff:193.167.0.100]:57529] discarding a packet without an RTT estimate; guessing RTT=35.476307ms server | 1.075 DEBUG [Server 0e0745f571f880abaab2] pn=2 type=Handshake pri-unv-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 86 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 2, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } server | -> RX Crypto { offset: 0, len: 36 } server | 1.075 DEBUG [Server 0e0745f571f880abaab2] Rx ACK space=hs, ranges=[0..=0] server | 1.075 DEBUG [LossRecovery] ACK for Handshake - largest_acked=0 server | 1.075 DEBUG on_packets_acked this=0x55c16d63bb40, limited=1, bytes_in_flight=0, cwnd=12320, state=SlowStart, new_acked=777 server | 1.075 DEBUG Acked crypto frame space=hs offset=0 length=737 server | 1.075 DEBUG Read Ok(36) bytes server | 1.075 DEBUG [Agent 0x55c16d5f4710] state -> Complete(SecretAgentInfo { version: 772, cipher: 4865, group: 29, resumed: false, early_data: false, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 }) server | 1.075 DEBUG [Server 0e0745f571f880abaab2] TLS connection complete server | 1.075 DEBUG [pri-unv-path: [::]:443->[::ffff:193.167.0.100]:57529] Path validated Instant { tv_sec: 358, tv_nsec: 801210823 } server | 1.075 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 1.075 DEBUG [Crypto] application read keys installed server | 1.075 DEBUG [Server 0e0745f571f880abaab2] State change from Handshaking -> Connected server | 1.075 DEBUG [Server 0e0745f571f880abaab2] State change from Connected -> Confirmed server | 1.075 DEBUG PMTUD started with probe size 1380 server | 1.075 INFO [Server 0e0745f571f880abaab2] Connection established server | 1.075 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 358, tv_nsec: 801210823 } server | 1.075 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.075 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: 487f517c8b2960fa7009) server | 1.075 DEBUG [Server 0e0745f571f880abaab2] pn=1 type=Handshake pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 41 server | TX -> Ack { largest_acknowledged: 2, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | 1.075 DEBUG [Server 0e0745f571f880abaab2] Drop packet number space hs server | 1.075 DEBUG [LossRecovery] Reset loss recovery state for Handshake server | 1.075 DEBUG Building Short dcid Some(CID [0]: ) server | 1.075 DEBUG [Server 0e0745f571f880abaab2] pn=0 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 1332 server | TX -> HandshakeDone server | TX -> NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [17, 203, 72, 54, 0, 186, 207, 96, 160, 90], stateless_reset_token: [123, 160, 187, 22, 122, 234, 206, 69, 52, 130, 68, 237, 26, 26, 10, 105] } server | TX -> NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [26, 163, 14, 50, 69, 53, 71, 156, 188, 178], stateless_reset_token: [90, 93, 95, 189, 103, 100, 193, 182, 191, 213, 32, 21, 76, 218, 255, 219] } server | TX -> NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [38, 72, 84, 198, 183, 103, 190, 167, 205, 211], stateless_reset_token: [231, 73, 170, 178, 203, 10, 70, 195, 38, 255, 172, 234, 29, 186, 56, 205] } server | TX -> Padding { len: 1182 } server | 1.075 DEBUG packet_sent this=0x55c16d63bb40, pn=0, ps=1291 server | 1.075 DEBUG ECN probing: sent 2 probes server | 1.075 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.075 DEBUG Building Short dcid Some(CID [0]: ) server | 1.075 DEBUG Sending PMTUD probe of size 1380, count 1 server | 1.075 DEBUG [Server 0e0745f571f880abaab2] pn=1 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 1332 server | TX -> Ping server | TX -> Padding { len: 1313 } server | 1.075 DEBUG packet_sent this=0x55c16d63bb40, pn=1, ps=1332 server | 1.075 DEBUG ECN probing: sent 3 probes server | 1.076 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.076 DEBUG Building Short dcid Some(CID [0]: ) server | 1.076 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.076 DEBUG [Server 0e0745f571f880abaab2] delay duration 1.338336ms server | 1.076 DEBUG Setting timeout of 1.338336ms server | 1.077 DEBUG [Server 0e0745f571f880abaab2] send session ticket 406f0008f4dda274f24897850104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0a487f517c8b2960fa7009100a0e0745f571f880abaab2110c000000019a9a9aea000000016ab200c0000000ff02de1a0243e8200100686921 server | 1.077 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.077 DEBUG Building Short dcid Some(CID [0]: ) server | 1.077 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.077 DEBUG [Server 0e0745f571f880abaab2] delay duration 269.755µs server | 1.077 DEBUG Setting timeout of 269.755µs server | 1.077 DEBUG [Server 0e0745f571f880abaab2] pn=3 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 1252 server | -> RX Ping server | -> RX Stream { stream_id: 0, offset: 0, len: 17, fin: true } server | -> RX Padding { len: 1199 } server | 1.077 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 358, tv_nsec: 802985336 } server | 1.077 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 358, tv_nsec: 802985336 } server | 1.077 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.077 DEBUG Building Short dcid Some(CID [0]: ) server | 1.077 DEBUG [Server 0e0745f571f880abaab2] pn=2 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 23 server | TX -> Ack { largest_acknowledged: 3, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | 1.077 DEBUG ECN probing: sent 4 probes server | 1.077 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.077 DEBUG Building Short dcid Some(CID [0]: ) server | 1.077 DEBUG CRYPTO for ap offset=0, len=321 server | 1.077 DEBUG [Server 0e0745f571f880abaab2] pn=3 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 388 server | TX -> Crypto { offset: 0, len: 321 } server | TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 133, 202, 234, 175, 39, 242, 164, 68, 245, 70, 30, 149, 192, 78, 131, 59, 141, 116, 170, 68, 221, 105, 19, 167, 5, 153, 80, 41, 83, 252, 152, 99, 58, 173, 190, 10] } server | 1.077 DEBUG packet_sent this=0x55c16d63bb40, pn=3, ps=388 server | 1.077 DEBUG ECN probing: sent 5 probes server | 1.077 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.077 DEBUG Building Short dcid Some(CID [0]: ) server | 1.077 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.077 DEBUG [Server 0e0745f571f880abaab2] delay duration 114.618648ms server | 1.077 DEBUG Setting timeout of 114.618648ms server | 1.077 DEBUG Path = 'vqtwssgsta' server | 1.077 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.077 DEBUG Building Short dcid Some(CID [0]: ) server | 1.077 DEBUG [Server 0e0745f571f880abaab2] pn=4 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 0, offset: 0, len: >>1212, fin: false } server | 1.077 DEBUG packet_sent this=0x55c16d63bb40, pn=4, ps=1232 server | 1.077 DEBUG ECN probing: sent 6 probes server | 1.077 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.077 DEBUG Building Short dcid Some(CID [0]: ) server | 1.077 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.077 DEBUG [Server 0e0745f571f880abaab2] delay duration 1.716878ms server | 1.077 DEBUG Setting timeout of 1.716878ms server | 1.080 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.080 DEBUG Building Short dcid Some(CID [0]: ) server | 1.080 DEBUG [Server 0e0745f571f880abaab2] pn=5 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 0, offset: 1212, len: >>1210, fin: false } server | 1.080 DEBUG packet_sent this=0x55c16d63bb40, pn=5, ps=1232 server | 1.080 DEBUG ECN probing: sent 7 probes server | 1.080 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.080 DEBUG Building Short dcid Some(CID [0]: ) server | 1.080 DEBUG [Server 0e0745f571f880abaab2] pn=6 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 0, offset: 2422, len: >>1210, fin: false } server | 1.080 DEBUG packet_sent this=0x55c16d63bb40, pn=6, ps=1232 server | 1.080 DEBUG ECN probing: sent 8 probes server | 1.080 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.080 DEBUG Building Short dcid Some(CID [0]: ) server | 1.080 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.080 DEBUG [Server 0e0745f571f880abaab2] delay duration 1.696671ms server | 1.080 DEBUG Setting timeout of 1.696671ms server | 1.080 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.080 DEBUG Building Short dcid Some(CID [0]: ) server | 1.080 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.080 DEBUG [Server 0e0745f571f880abaab2] delay duration 1.679228ms server | 1.080 DEBUG Setting timeout of 1.679228ms server | 1.083 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.083 DEBUG Building Short dcid Some(CID [0]: ) server | 1.083 DEBUG [Server 0e0745f571f880abaab2] pn=7 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 0, offset: 3632, len: >>1210, fin: false } server | 1.083 DEBUG packet_sent this=0x55c16d63bb40, pn=7, ps=1232 server | 1.083 DEBUG ECN probing: sent 9 probes server | 1.083 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.083 DEBUG Building Short dcid Some(CID [0]: ) server | 1.083 DEBUG [Server 0e0745f571f880abaab2] pn=8 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 0, offset: 4842, len: >>1210, fin: false } server | 1.083 DEBUG packet_sent this=0x55c16d63bb40, pn=8, ps=1232 server | 1.083 DEBUG ECN probing: sent 10 probes server | 1.083 DEBUG ECN probing concluded with 10 probes sent server | 1.083 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.083 DEBUG Building Short dcid Some(CID [0]: ) server | 1.083 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.083 DEBUG [Server 0e0745f571f880abaab2] delay duration 1.683897ms server | 1.083 DEBUG Setting timeout of 1.683897ms server | 1.083 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.083 DEBUG Building Short dcid Some(CID [0]: ) server | 1.083 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.083 DEBUG [Server 0e0745f571f880abaab2] delay duration 1.661455ms server | 1.083 DEBUG Setting timeout of 1.661455ms server | 1.086 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.086 DEBUG Building Short dcid Some(CID [0]: ) server | 1.086 DEBUG [Server 0e0745f571f880abaab2] pn=9 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 1232 server | TX -> Stream { stream_id: 0, offset: 6052, len: >>1210, fin: false } server | 1.086 DEBUG packet_sent this=0x55c16d63bb40, pn=9, ps=1232 server | 1.086 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.086 DEBUG Building Short dcid Some(CID [0]: ) server | 1.086 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.086 DEBUG [Server 0e0745f571f880abaab2] delay duration 1.285171ms server | 1.086 DEBUG Setting timeout of 1.285171ms server | 1.086 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.086 DEBUG Building Short dcid Some(CID [0]: ) server | 1.086 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.086 DEBUG [Server 0e0745f571f880abaab2] delay duration 1.262518ms server | 1.086 DEBUG Setting timeout of 1.262518ms server | 1.088 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.088 DEBUG Building Short dcid Some(CID [0]: ) server | 1.088 DEBUG [Server 0e0745f571f880abaab2] pn=10 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 1232 server | TX -> Stream { stream_id: 0, offset: 7262, len: >>1210, fin: false } server | 1.088 DEBUG packet_sent this=0x55c16d63bb40, pn=10, ps=1232 server | 1.088 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 685, pto: None, probe: EnumSet(), paced: false } server | 1.088 DEBUG Building Short dcid Some(CID [0]: ) server | 1.088 DEBUG [Server 0e0745f571f880abaab2] pn=11 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 685 server | TX -> Stream { stream_id: 0, offset: 8472, len: >>663, fin: false } server | 1.088 DEBUG packet_sent this=0x55c16d63bb40, pn=11, ps=685 server | 1.088 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false } server | 1.088 DEBUG Building Short dcid Some(CID [0]: ) server | 1.088 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false } server | 1.088 DEBUG [Server 0e0745f571f880abaab2] delay duration 114.612566ms server | 1.088 DEBUG Setting timeout of 114.612566ms server | 1.088 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false } server | 1.088 DEBUG Building Short dcid Some(CID [0]: ) server | 1.088 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false } server | 1.088 DEBUG [Server 0e0745f571f880abaab2] delay duration 114.590034ms server | 1.088 DEBUG Setting timeout of 114.590034ms client | vqtwssgsta: Wrote 1212 bytes.(0 ms/0 ms/0 ms) client | vqtwssgsta: Wrote 1210 bytes.(2 ms/2 ms/2 ms) client | vqtwssgsta: Wrote 1210 bytes.(3 ms/1 ms/-1 ms) client | vqtwssgsta: Wrote 1210 bytes.(5 ms/2 ms/1 ms) client | vqtwssgsta: Wrote 1210 bytes.(6 ms/1 ms/-1 ms) client | vqtwssgsta: Wrote 1210 bytes.(8 ms/2 ms/1 ms) client | vqtwssgsta: Wrote 1210 bytes.(10 ms/2 ms/0 ms) client | vqtwssgsta: Wrote 663 bytes.(10 ms/0 ms/-2 ms) server | 1.108 DEBUG [Server 0e0745f571f880abaab2] pn=4 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 39 server | -> 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})) } server | 1.108 DEBUG [Server 0e0745f571f880abaab2] Rx ACK space=ap, ranges=[0..=1] server | 1.108 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=1 server | 1.108 INFO ECN validation succeeded, path is capable server | 1.108 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 9697/14943 ssthresh 18446744073709551615] slow start += 2623 server | 1.108 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 9697/14943 ssthresh 18446744073709551615] on_packets_acked this=0x55c16d63bb40, limited=0, bytes_in_flight=9697, cwnd=14943, state=SlowStart, new_acked=2623 server | 1.108 DEBUG PMTUD probe of size 1380 succeeded server | 1.108 DEBUG PMTUD started with probe size 1420 server | 1.108 DEBUG PLPMTU changed from 1232 to 1332, updating pacer server | 1.108 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.108 DEBUG Building Short dcid Some(CID [0]: ) server | 1.108 DEBUG Sending PMTUD probe of size 1420, count 1 server | 1.108 DEBUG [Server 0e0745f571f880abaab2] pn=12 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 1372 server | TX -> Ping server | TX -> Stream { stream_id: 0, offset: 9135, len: 1105, fin: true } server | TX -> Padding { len: 242 } server | 1.108 DEBUG packet_sent this=0x55c16d63bb40, pn=12, ps=1372 server | 1.108 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.108 DEBUG Building Short dcid Some(CID [0]: ) server | 1.108 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.108 DEBUG [Server 0e0745f571f880abaab2] delay duration 103.713927ms server | 1.108 DEBUG Setting timeout of 103.713927ms server | 1.108 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.108 DEBUG Building Short dcid Some(CID [0]: ) server | 1.108 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.108 DEBUG [Server 0e0745f571f880abaab2] delay duration 103.678781ms server | 1.108 DEBUG Setting timeout of 103.678781ms server | 1.109 DEBUG [Server 0e0745f571f880abaab2] pn=5 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 1332 server | -> RX Ping server | -> RX Padding { len: 1300 } server | 1.109 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 358, tv_nsec: 835421851 } server | 1.109 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 358, tv_nsec: 835421851 } server | 1.109 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.109 DEBUG Building Short dcid Some(CID [0]: ) server | 1.109 DEBUG [Server 0e0745f571f880abaab2] pn=13 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 23 server | TX -> Ack { largest_acknowledged: 5, ack_delay: 0, first_ack_range: 2, ack_ranges: [], ecn_count: None } server | 1.109 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.109 DEBUG Building Short dcid Some(CID [0]: ) server | 1.109 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.109 DEBUG [Server 0e0745f571f880abaab2] delay duration 102.734804ms server | 1.109 DEBUG Setting timeout of 102.734804ms server | 1.109 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.109 DEBUG Building Short dcid Some(CID [0]: ) server | 1.109 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.109 DEBUG [Server 0e0745f571f880abaab2] delay duration 102.709947ms server | 1.109 DEBUG Setting timeout of 102.709947ms server | 1.109 DEBUG [Server 0e0745f571f880abaab2] pn=6 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 50 server | -> RX Ack { largest_acknowledged: 4, ack_delay: 0, first_ack_range: 4, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 5, Ce: 0})) } server | -> RX MaxData { maximum_data: 16778428 } server | -> RX MaxStreamData { stream_id: StreamId(0), maximum_stream_data: 66748 } server | 1.110 DEBUG [Server 0e0745f571f880abaab2] Rx ACK space=ap, ranges=[0..=4] server | 1.110 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=4 server | 1.110 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 9449/16563 ssthresh 18446744073709551615] slow start += 1620 server | 1.110 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 9449/16563 ssthresh 18446744073709551615] on_packets_acked this=0x55c16d63bb40, limited=0, bytes_in_flight=9449, cwnd=16563, state=SlowStart, new_acked=1620 server | 1.110 DEBUG Acked crypto frame space=ap offset=0 length=321 server | 1.110 DEBUG setting max_stream_data to 66748 server | 1.110 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 358, tv_nsec: 855820478 } server | 1.110 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.110 DEBUG Building Short dcid Some(CID [0]: ) server | 1.110 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.110 DEBUG [Server 0e0745f571f880abaab2] delay duration 20ms server | 1.110 DEBUG Setting timeout of 20ms server | 1.110 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.110 DEBUG Building Short dcid Some(CID [0]: ) server | 1.110 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.110 DEBUG [Server 0e0745f571f880abaab2] delay duration 19.900854ms server | 1.110 DEBUG Setting timeout of 19.900854ms server | 1.113 DEBUG [Server 0e0745f571f880abaab2] pn=7 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 50 server | -> RX Ack { largest_acknowledged: 6, ack_delay: 0, first_ack_range: 6, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 7, Ce: 0})) } server | -> RX MaxData { maximum_data: 16780848 } server | -> RX MaxStreamData { stream_id: StreamId(0), maximum_stream_data: 69168 } server | 1.113 DEBUG [Server 0e0745f571f880abaab2] Rx ACK space=ap, ranges=[0..=6] server | 1.113 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=6 server | 1.113 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 6985/19027 ssthresh 18446744073709551615] slow start += 2464 server | 1.113 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 6985/19027 ssthresh 18446744073709551615] on_packets_acked this=0x55c16d63bb40, limited=0, bytes_in_flight=6985, cwnd=19027, state=SlowStart, new_acked=2464 server | 1.113 DEBUG setting max_stream_data to 69168 server | 1.113 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 358, tv_nsec: 838854949 } server | 1.113 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.113 DEBUG Building Short dcid Some(CID [0]: ) server | 1.113 DEBUG [Server 0e0745f571f880abaab2] pn=14 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, Ect0) len 23 server | TX -> Ack { largest_acknowledged: 7, ack_delay: 0, first_ack_range: 4, ack_ranges: [], ecn_count: None } server | 1.113 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.113 DEBUG Building Short dcid Some(CID [0]: ) server | 1.113 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.113 DEBUG [Server 0e0745f571f880abaab2] delay duration 84.256542ms server | 1.113 DEBUG Setting timeout of 84.256542ms server | 1.113 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.113 DEBUG Building Short dcid Some(CID [0]: ) server | 1.113 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.113 DEBUG [Server 0e0745f571f880abaab2] delay duration 84.233819ms server | 1.113 DEBUG Setting timeout of 84.233819ms server | 1.116 DEBUG [Server 0e0745f571f880abaab2] pn=8 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 50 server | -> RX Ack { largest_acknowledged: 8, ack_delay: 0, first_ack_range: 8, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 9, Ce: 0})) } server | -> RX MaxData { maximum_data: 16783268 } server | -> RX MaxStreamData { stream_id: StreamId(0), maximum_stream_data: 71588 } server | 1.116 DEBUG [Server 0e0745f571f880abaab2] Rx ACK space=ap, ranges=[0..=8] server | 1.116 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=8 server | 1.116 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 4521/21491 ssthresh 18446744073709551615] slow start += 2464 server | 1.116 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 4521/21491 ssthresh 18446744073709551615] on_packets_acked this=0x55c16d63bb40, limited=0, bytes_in_flight=4521, cwnd=21491, state=SlowStart, new_acked=2464 server | 1.116 DEBUG setting max_stream_data to 71588 server | 1.116 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 358, tv_nsec: 862109814 } server | 1.116 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.116 DEBUG Building Short dcid Some(CID [0]: ) server | 1.116 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.116 DEBUG [Server 0e0745f571f880abaab2] delay duration 20ms server | 1.116 DEBUG Setting timeout of 20ms server | 1.116 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.116 DEBUG Building Short dcid Some(CID [0]: ) server | 1.116 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.116 DEBUG [Server 0e0745f571f880abaab2] delay duration 19.928617ms server | 1.116 DEBUG Setting timeout of 19.928617ms server | 1.119 DEBUG [Server 0e0745f571f880abaab2] pn=9 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 50 server | -> RX Ack { largest_acknowledged: 10, ack_delay: 0, first_ack_range: 10, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 9, Ce: 0})) } server | -> RX MaxData { maximum_data: 16785688 } server | -> RX MaxStreamData { stream_id: StreamId(0), maximum_stream_data: 74008 } server | 1.119 DEBUG [Server 0e0745f571f880abaab2] Rx ACK space=ap, ranges=[0..=10] server | 1.119 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=10 server | 1.119 WARN ECN validation failed, no ECT(0) packets were newly acked server | 1.119 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 2057/23955 ssthresh 18446744073709551615] slow start += 2464 server | 1.119 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 2057/23955 ssthresh 18446744073709551615] on_packets_acked this=0x55c16d63bb40, limited=0, bytes_in_flight=2057, cwnd=23955, state=SlowStart, new_acked=2464 server | 1.119 DEBUG setting max_stream_data to 74008 server | 1.119 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 358, tv_nsec: 845560715 } server | 1.119 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.119 DEBUG Building Short dcid Some(CID [0]: ) server | 1.119 DEBUG [Server 0e0745f571f880abaab2] pn=15 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 23 server | TX -> Ack { largest_acknowledged: 9, ack_delay: 0, first_ack_range: 6, ack_ranges: [], ecn_count: None } server | 1.119 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.119 DEBUG Building Short dcid Some(CID [0]: ) server | 1.119 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.119 DEBUG [Server 0e0745f571f880abaab2] delay duration 68.85698ms server | 1.119 DEBUG Setting timeout of 68.85698ms server | 1.119 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.119 DEBUG Building Short dcid Some(CID [0]: ) server | 1.119 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.119 DEBUG [Server 0e0745f571f880abaab2] delay duration 68.823738ms server | 1.119 DEBUG Setting timeout of 68.823738ms client | vqtwssgsta: Wrote 1105 bytes.(30 ms/20 ms/20 ms) client | vqtwssgsta: Completed download! (30 ms) server | 1.140 DEBUG [Server 0e0745f571f880abaab2] pn=10 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 44 server | -> RX Ack { largest_acknowledged: 13, ack_delay: 0, first_ack_range: 11, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 11, Ce: 0})) } server | -> RX MaxData { maximum_data: 16787456 } server | 1.140 DEBUG [Server 0e0745f571f880abaab2] Rx ACK space=ap, ranges=[2..=13] server | 1.140 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=13 server | 1.140 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 0/26012 ssthresh 18446744073709551615] slow start += 2057 server | 1.140 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 0/26012 ssthresh 18446744073709551615] on_packets_acked this=0x55c16d63bb40, limited=0, bytes_in_flight=0, cwnd=26012, state=SlowStart, new_acked=2057 server | 1.140 DEBUG PMTUD probe of size 1420 succeeded server | 1.140 DEBUG PMTUD started with probe size 1470 server | 1.140 DEBUG PLPMTU changed from 1332 to 1372, updating pacer server | 1.140 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 358, tv_nsec: 886260093 } server | 1.140 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.140 DEBUG Building Short dcid Some(CID [0]: ) server | 1.140 DEBUG Sending PMTUD probe of size 1470, count 1 server | 1.140 DEBUG [Server 0e0745f571f880abaab2] pn=16 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 1422 server | TX -> Ping server | TX -> MaxStreams { stream_type: BiDi, maximum_streams: 17 } server | TX -> Padding { len: 1401 } server | 1.140 DEBUG packet_sent this=0x55c16d63bb40, pn=16, ps=1422 server | 1.140 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.140 DEBUG Building Short dcid Some(CID [0]: ) server | 1.140 DEBUG TX blocked, profile=SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.140 DEBUG [Server 0e0745f571f880abaab2] delay duration 19.788123ms server | 1.140 DEBUG Setting timeout of 19.788123ms server | 1.140 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.140 DEBUG Building Short dcid Some(CID [0]: ) server | 1.140 DEBUG TX blocked, profile=SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.140 DEBUG [Server 0e0745f571f880abaab2] delay duration 19.752216ms server | 1.140 DEBUG Setting timeout of 19.752216ms server | 1.141 DEBUG [Server 0e0745f571f880abaab2] pn=11 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 1412 server | -> RX Ping server | -> RX Padding { len: 1380 } server | 1.141 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 358, tv_nsec: 867406810 } server | 1.141 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 358, tv_nsec: 867406810 } server | 1.141 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.141 DEBUG Building Short dcid Some(CID [0]: ) server | 1.141 DEBUG [Server 0e0745f571f880abaab2] pn=17 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 23 server | TX -> Ack { largest_acknowledged: 11, ack_delay: 0, first_ack_range: 8, ack_ranges: [], ecn_count: None } server | 1.141 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.141 DEBUG Building Short dcid Some(CID [0]: ) server | 1.141 DEBUG TX blocked, profile=SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.141 DEBUG [Server 0e0745f571f880abaab2] delay duration 76.503887ms server | 1.141 DEBUG Setting timeout of 76.503887ms server | 1.141 DEBUG [Server 0e0745f571f880abaab2] pn=12 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 34 server | -> RX ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "" } server | 1.141 INFO [Server 0e0745f571f880abaab2] ConnectionClose received. Error code: Application(0) frame type 0 reason server | 1.141 DEBUG [Server 0e0745f571f880abaab2] State change from Confirmed -> Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 359, tv_nsec: 100942845 } } server | 1.141 DEBUG [pri-path: [::]:443->[::ffff:193.167.0.100]:57529] Path validated Instant { tv_sec: 358, tv_nsec: 867576460 } server | 1.141 DEBUG [Server 0e0745f571f880abaab2] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.141 DEBUG Building Short dcid Some(CID [0]: ) server | 1.141 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 358, tv_nsec: 867576460 } server | 1.141 DEBUG [Server 0e0745f571f880abaab2] pn=18 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:57529 IpTos(Cs0, NotEct) len 27 server | TX -> Ack { largest_acknowledged: 12, ack_delay: 0, first_ack_range: 9, ack_ranges: [], ecn_count: None } server | TX -> ConnectionClose { error_code: Transport(0), frame_type: 29, reason_phrase: "" } server | 1.141 DEBUG Setting timeout of 233.261429ms server | 1.141 DEBUG Setting timeout of 233.248755ms client | client | TARGET VHDCRZSQUMBGA2E VERSION ALPN client | ============================================ client | server4 --D------------ 0x00000001 hq-interop client | client | Total execution time: 0.172s client | server | 1.376 DEBUG [Server 0e0745f571f880abaab2] State change from Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 359, tv_nsec: 100942845 } } -> Closed(Transport(PeerApplicationError(0))) server | 1.376 INFO Closing timer expired client | Client complete. client | Script complete. 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 11:47:41,535 Using the client's key log file. 2025-04-30 11:47:41,544 2025-04-30 11:47:41,545 Using the client's key log file. 2025-04-30 11:47:41,545 Using the client's key log file. 2025-04-30 11:47:41,553 2025-04-30 11:47:41,554 Using the client's key log file. 2025-04-30 11:47:42,144 Check of downloaded files succeeded. 2025-04-30 11:47:42,724 Check of Retry succeeded. Token used: 52657472790100dff120024831b179a4354f47e3cc66aea20c26bc2d51a1de9b0c7a3cceb379933d035e2e3b21e94484e5a8ae