2025-04-30 10:29:33,436 Generated random file: unisqxgrqc of size: 5120 2025-04-30 10:29:33,436 Generated random file: heaksezpzn of size: 10240 2025-04-30 10:29:33,436 Requests: https://server6:443/unisqxgrqc https://server6:443/heaksezpzn 2025-04-30 10:29:33,502 2025-04-30 10:29:33,503 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_2qzamo4b/ TESTCASE_SERVER=transfer TESTCASE_CLIENT=transfer WWW=/tmp/www__ampnwky/ DOWNLOADS=/tmp/download_jbx8qekj/ SERVER_LOGS=/tmp/logs_server_ng1_hqic CLIENT_LOGS=/tmp/logs_client__zjua6ok SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=ghcr.io/ngtcp2/ngtcp2-interop:latest SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server6:443/unisqxgrqc https://server6:443/heaksezpzn" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-04-30 10:29:45,606 Container sim Recreate Container sim Recreated Container client Recreate Container server Recreate Container client Recreated Container server Recreated Attaching to client, server, sim sim | waiting 10s for server:443 client | Setting up routes... server | Setting up routes... client | Actual changes: client | tx-checksum-ip-generic: off client | tx-tcp-segmentation: off [not requested] client | tx-tcp-ecn-segmentation: off [not requested] client | tx-tcp-mangleid-segmentation: off [not requested] client | tx-tcp6-segmentation: off [not requested] client | tx-udp-segmentation: off [not requested] client | tx-checksum-sctp: off 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 | Endpoint's IPv4 address is 193.167.0.100 server | Endpoint's IPv4 address is 193.167.100.100 client | Endpoint's IPv6 address is fd00:cafe:cafe::100 server | Endpoint's IPv6 address is fd00:cafe:cafe:100::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 transfer ']' server | + '[' -n /logs/qlog/ ']' server | + case "$ROLE" in server | + DB=/neqo/db server | + CERT=cert server | ++ mktemp server | + P12CERT=/tmp/tmp.V5ybJXjlfJ 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.V5ybJXjlfJ server | Warning: output encryption option -nodes ignored with -export server | + pk12util -d sql:/neqo/db -i /tmp/tmp.V5ybJXjlfJ -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 | 51:76:0e:33:85:b7:7c:10:da:2f:17:d2:9f:98:3e:90: server | b9:c2:5a:24 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 10:29:33 2025 server | Not After : Sat May 10 10:29:33 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:bf:97:73:2f:43:84:0b:7d:11:95:17:86:e7:7a:cc: server | 1e:5c:51:f4:ae:cc:83:bf:cd:dd:6d:00:5b:74:b2:d7: server | 60:ee:30:07:dc:85:50:16:b4:a1:cd:3d:93:1b:4e:ea: server | fd:20:80:53:99:96:3f:69:b5:c3:50:65:af:73:3c:ca: server | 73 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 | 36:a6:7b:c8:d6:ec:1a:f6:ee:16:aa:07:13:ef:24:29: server | 1b:54:f9:11 server | server | Name: Certificate Authority Key Identifier server | Key ID: server | c4:8e:12:04:8a:2d:dd:bb:19:a6:d9:b7:29:2c:c2:0d: server | 15:6f:8f:25 server | server | Signature Algorithm: X9.62 ECDSA signature with SHA256 server | Signature: server | 30:44:02:20:69:05:c0:b3:8c:55:2c:ea:1e:6d:db:c2: server | f9:be:cc:f7:71:c0:b2:fe:52:74:b5:24:50:46:9b:9f: server | 3e:60:0e:ce:02:20:63:bd:64:ab:8b:8a:c2:1f:8b:2b: server | ad:86:b6:55:8c:da:a6:fa:f5:6f:8f:a0:25:eb:88:fe: server | 46:68:d0:52:f9:75 server | Fingerprint (SHA-256): server | 06:F6:E4:B9:A0:39:24:F0:B0:92:7F:4A:59:71:41:9D:92:1A:85:B4:47:4D:34:8F:B0:A0:11:9A:02:EA:A6:CA server | Fingerprint (SHA1): server | 4B:94:25:C0:05:81:5F:03:92:F1:F6:91:55:97:83:2E:13:39:46:BC 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 | + '[' transfer = connectionmigration ']' server | + RUST_LOG=debug server | + RUST_BACKTRACE=1 server | + neqo-server --cc cubic --qns-test transfer --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 sim | server:443 is available after 1.064003145s server | 0.801 DEBUG [Server] Unsupported version: 57414954 server | 0.801 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:56234 IpTos(Cs0, NotEct) len 15 server | 0.801 DEBUG [Server] Unsupported version: 57414954 server | 0.801 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:56234 IpTos(Cs0, NotEct) len 15 server | 0.801 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" }) server | 0.801 DEBUG [Server] Unsupported version: 57414954 server | 0.801 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:56234 IpTos(Cs0, NotEct) len 15 server | 0.801 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: tcpdump: listening on eth0listening on eth1, link-type EN10MB (Ethernet), link-type EN10MB (Ethernet), snapshot length 262144 bytes sim | , snapshot length 262144 bytes client | wait-for-it.sh: sim:57832 is available after 1 seconds server | 1.056 DEBUG [Server] Handle initial server | 1.056 INFO AddressValidation: no token; accepting server | 1.056 INFO [Server] Accept connection CID [18]: da18260341f2ae075f1398a9ccbb1f979b07 server | 1.056 DEBUG Overwrite initial version Version1 ==> Version1 server | 1.058 DEBUG Outbound interface eth0 for destination fd00:cafe:cafe::100 has MTU 1500 server | 1.058 INFO [Server ...] Received valid Initial packet with scid CID [17]: e92f01f2231e0b9ec8023f267b41070e48 dcid CID [18]: da18260341f2ae075f1398a9ccbb1f979b07 server | 1.058 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=da18260341f2ae075f1398a9ccbb1f979b07 server | 1.058 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 server | 1.058 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 server | 1.058 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] State change from Init -> WaitInitial server | 1.058 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584835 type=Initial unv-path [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1200 server | -> RX Crypto { offset: 0, len: 263 } server | -> RX Padding { len: 866 } server | 1.058 DEBUG Read Ok(263) bytes server | 1.058 DEBUG 0-RTT: no token, no 0-RTT server | 1.058 DEBUG Read secret available for Handshake: SymKey [32]: 7a1d4ec8190600fc8f1fee79432adcd5835148df4fae11776e66bff3e50247d6 server | 1.058 DEBUG Write secret available for Handshake: SymKey [32]: 0e3e440ee562ce931d294245346c49d84123fb8ff4992e01d2a92db3bfca2ef8 server | 1.058 DEBUG Writing transport parameters, msg=8 server | 1.059 DEBUG Read secret available for ApplicationData: SymKey [32]: e55e77dede08baf2b47a1f214d60682d668693a45df13c510ef29fb7f6ba7bc2 server | 1.059 DEBUG Write secret available for ApplicationData: SymKey [32]: 624f9e1a805c06967434c7b0c90abf236253d5ecd0aebda11337e7209b1c492e server | 1.059 DEBUG [Agent 0x56137256e1d0] state -> InProgress server | 1.059 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865 server | 1.059 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865 server | 1.059 DEBUG [Crypto] Handshake keys installed server | 1.059 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 1.059 DEBUG [Crypto] Application write key installed server | 1.059 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 598, tv_nsec: 954046897 } server | 1.059 DEBUG [unv-path [::]:443->[fd00:cafe:cafe::100]:47046] Make permanent server | 1.059 DEBUG [unv-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046] set as primary path server | 1.059 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] State change from WaitInitial -> Handshaking server | 1.059 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.059 DEBUG Building Initial dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) scid Some(CID [10]: 7384a61bd12b980fb09c) server | 1.059 DEBUG CRYPTO for in offset=0, len=90 server | 1.059 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=0 type=Initial pri-unv-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 163 server | TX -> Ack { largest_acknowledged: 2017584835, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } server | TX -> Crypto { offset: 0, len: 90 } server | 1.059 DEBUG Building Handshake dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) scid Some(CID [10]: 7384a61bd12b980fb09c) server | 1.059 DEBUG CRYPTO for hs offset=0, len=733 server | 1.059 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=0 type=Handshake pri-unv-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 953 server | TX -> Crypto { offset: 0, len: 733 } server | 1.059 DEBUG packet_sent this=0x56137256db40, pn=0, ps=790 server | 1.059 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.059 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pad Initial from 953 to PLPMTU 1232 server | 1.059 DEBUG packet_sent this=0x56137256db40, pn=0, ps=442 server | 1.059 DEBUG ECN probing: sent 1 probes server | 1.059 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.059 DEBUG Building Initial dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) scid Some(CID [10]: 7384a61bd12b980fb09c) server | 1.059 DEBUG Building Handshake dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) scid Some(CID [10]: 7384a61bd12b980fb09c) server | 1.059 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.059 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.059 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 296.729905ms server | 1.059 DEBUG Setting timeout of 296.729905ms server | 1.059 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.059 DEBUG Building Initial dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) scid Some(CID [10]: 7384a61bd12b980fb09c) server | 1.059 DEBUG Building Handshake dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) scid Some(CID [10]: 7384a61bd12b980fb09c) server | 1.059 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.059 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.059 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 296.691643ms server | 1.059 DEBUG Setting timeout of 296.691643ms server | 1.093 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584836 type=Initial pri-unv-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 64 server | -> 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})) } server | 1.093 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] Rx ACK space=in, ranges=[0..=0] server | 1.093 DEBUG [LossRecovery] ACK for Initial - largest_acked=0 server | 1.093 DEBUG on_packets_acked this=0x56137256db40, limited=1, bytes_in_flight=790, cwnd=12320, state=SlowStart, new_acked=442 server | 1.093 DEBUG Acked crypto frame space=in offset=0 length=90 server | 1.093 DEBUG [pri-unv-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046] Path validated Instant { tv_sec: 598, tv_nsec: 991634631 } server | 1.093 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] Drop packet number space in server | 1.093 DEBUG [LossRecovery] Reset loss recovery state for Initial server | 1.093 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584835 type=Handshake pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 105 server | -> 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})) } server | -> RX Crypto { offset: 0, len: 36 } server | 1.093 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] Rx ACK space=hs, ranges=[0..=0] server | 1.093 DEBUG [LossRecovery] ACK for Handshake - largest_acked=0 server | 1.093 DEBUG on_packets_acked this=0x56137256db40, limited=1, bytes_in_flight=0, cwnd=12320, state=SlowStart, new_acked=790 server | 1.093 DEBUG Acked crypto frame space=hs offset=0 length=733 server | 1.093 DEBUG Read Ok(36) bytes server | 1.093 DEBUG [Agent 0x56137256e1d0] 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.093 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] TLS connection complete server | 1.093 DEBUG [pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046] Path validated Instant { tv_sec: 598, tv_nsec: 991634631 } server | 1.093 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 1.093 DEBUG [Crypto] application read keys installed server | 1.094 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] State change from Handshaking -> Connected server | 1.094 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] State change from Connected -> Confirmed server | 1.094 DEBUG PMTUD started with probe size 1380 server | 1.094 INFO [Server da18260341f2ae075f1398a9ccbb1f979b07] Connection established server | 1.094 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 598, tv_nsec: 991634631 } server | 1.094 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584835 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1031 server | -> RX NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [160, 1, 46, 78, 97, 132, 213, 64, 220, 173, 247, 55, 209, 197, 173, 177, 142], stateless_reset_token: [247, 123, 183, 10, 120, 35, 5, 100, 1, 95, 213, 109, 205, 191, 34, 85] } server | -> RX NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [37, 90, 45, 51, 219, 206, 9, 171, 120, 70, 253, 114, 91, 239, 106, 224, 160], stateless_reset_token: [168, 223, 231, 159, 23, 12, 18, 85, 96, 105, 205, 8, 28, 190, 170, 241] } server | -> RX NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [162, 152, 147, 189, 186, 161, 134, 251, 136, 32, 192, 220, 98, 244, 231, 26, 89], stateless_reset_token: [42, 155, 20, 55, 196, 172, 255, 45, 33, 49, 68, 59, 80, 173, 122, 124] } server | -> RX NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [0, 136, 182, 202, 56, 83, 69, 150, 76, 128, 54, 79, 250, 149, 38, 87, 183], stateless_reset_token: [228, 182, 250, 88, 179, 195, 31, 223, 49, 239, 49, 70, 34, 216, 124, 81] } server | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [169, 123, 90, 227, 79, 41, 91, 1, 185, 205, 132, 165, 81, 199, 168, 122, 72], stateless_reset_token: [105, 106, 80, 233, 238, 8, 54, 144, 8, 53, 28, 253, 77, 87, 96, 209] } server | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [21, 145, 253, 193, 4, 33, 41, 122, 82, 165, 131, 58, 45, 182, 188, 179, 1], stateless_reset_token: [172, 35, 185, 100, 48, 76, 64, 121, 179, 221, 6, 196, 77, 46, 73, 127] } server | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [221, 81, 139, 28, 142, 84, 140, 113, 7, 203, 94, 12, 247, 226, 101, 237, 177], stateless_reset_token: [183, 205, 67, 5, 253, 7, 1, 115, 16, 51, 64, 144, 93, 170, 251, 122] } server | -> RX Stream { stream_id: 0, offset: 0, len: 17, fin: true } server | -> RX Stream { stream_id: 4, offset: 0, len: 17, fin: true } server | -> RX Padding { len: 701 } server | 1.094 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 598, tv_nsec: 991634631 } server | 1.094 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.094 DEBUG Building Handshake dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) scid Some(CID [10]: 7384a61bd12b980fb09c) server | 1.094 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=1 type=Handshake pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 68 server | TX -> Ack { largest_acknowledged: 2017584835, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } server | 1.094 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] Drop packet number space hs server | 1.094 DEBUG [LossRecovery] Reset loss recovery state for Handshake server | 1.094 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.094 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=0 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1332 server | TX -> Ack { largest_acknowledged: 2017584835, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } server | TX -> HandshakeDone server | TX -> NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [148, 194, 171, 151, 44, 41, 222, 193, 214, 40], stateless_reset_token: [21, 168, 166, 33, 209, 124, 126, 253, 90, 130, 177, 20, 193, 239, 136, 42] } server | TX -> NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [247, 77, 132, 221, 215, 37, 76, 136, 142, 78], stateless_reset_token: [230, 250, 80, 107, 248, 83, 103, 239, 202, 237, 199, 15, 44, 0, 227, 28] } server | TX -> NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [206, 255, 0, 118, 134, 214, 47, 128, 68, 146], stateless_reset_token: [69, 34, 195, 206, 17, 10, 160, 75, 107, 160, 11, 213, 138, 252, 233, 215] } server | TX -> NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [39, 120, 251, 203, 113, 39, 130, 207, 11, 129], stateless_reset_token: [169, 182, 57, 90, 242, 161, 82, 225, 208, 56, 237, 77, 195, 13, 204, 91] } server | TX -> NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [35, 179, 164, 3, 50, 34, 98, 200, 119, 168], stateless_reset_token: [57, 136, 207, 156, 122, 113, 82, 162, 60, 172, 121, 161, 116, 106, 210, 3] } server | TX -> NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [103, 52, 17, 70, 191, 33, 89, 7, 96, 30], stateless_reset_token: [106, 55, 102, 189, 179, 153, 59, 43, 244, 135, 2, 52, 155, 86, 51, 217] } server | TX -> Padding { len: 1033 } server | 1.094 DEBUG packet_sent this=0x56137256db40, pn=0, ps=1264 server | 1.094 DEBUG ECN probing: sent 2 probes server | 1.094 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.094 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.094 DEBUG Sending PMTUD probe of size 1380, count 1 server | 1.094 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=1 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1332 server | TX -> Ping server | TX -> Padding { len: 1296 } server | 1.094 DEBUG packet_sent this=0x56137256db40, pn=1, ps=1332 server | 1.094 DEBUG ECN probing: sent 3 probes server | 1.094 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.094 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.094 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.094 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 1.480952ms server | 1.094 DEBUG Setting timeout of 1.480952ms server | 1.095 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] send session ticket 406d0012da18260341f2ae075f1398a9ccbb1f979b070104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0a7384a61bd12b980fb09c110c000000018a8aaa8a000000016ab200c0000000ff02de1a0243e8200100686921 server | 1.095 DEBUG Path = 'unisqxgrqc' server | 1.095 DEBUG Path = 'heaksezpzn' server | 1.095 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.095 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.095 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.095 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 490.614µs server | 1.095 DEBUG Setting timeout of 490.614µs server | 1.095 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584836 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1406 server | -> RX Ping server | -> RX Padding { len: 1374 } server | 1.095 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 598, tv_nsec: 993257415 } server | 1.095 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 598, tv_nsec: 993257415 } server | 1.095 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.095 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.095 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 50 server | TX -> Ack { largest_acknowledged: 2017584836, ack_delay: 0, first_ack_range: 1, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 2, Ce: 0})) } server | 1.095 DEBUG ECN probing: sent 4 probes server | 1.095 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.095 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.095 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=3 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 0, offset: 0, len: >>1195, fin: false } server | 1.095 DEBUG packet_sent this=0x56137256db40, pn=3, ps=1232 server | 1.095 DEBUG ECN probing: sent 5 probes server | 1.095 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.095 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.095 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.095 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 1.797422ms server | 1.095 DEBUG Setting timeout of 1.797422ms server | 1.095 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.095 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.095 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.095 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 1.776834ms server | 1.095 DEBUG Setting timeout of 1.776834ms server | 1.098 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.098 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.098 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=4 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 0, offset: 1195, len: >>1193, fin: false } server | 1.098 DEBUG packet_sent this=0x56137256db40, pn=4, ps=1232 server | 1.098 DEBUG ECN probing: sent 6 probes server | 1.098 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.098 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.098 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=5 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 0, offset: 2388, len: >>1193, fin: false } server | 1.098 DEBUG packet_sent this=0x56137256db40, pn=5, ps=1232 server | 1.098 DEBUG ECN probing: sent 7 probes server | 1.098 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.098 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.098 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.098 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 1.765523ms server | 1.098 DEBUG Setting timeout of 1.765523ms server | 1.098 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.098 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.098 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.098 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 1.746978ms server | 1.098 DEBUG Setting timeout of 1.746978ms server | 1.101 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.101 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.101 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=6 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 0, offset: 3581, len: >>1193, fin: false } server | 1.101 DEBUG packet_sent this=0x56137256db40, pn=6, ps=1232 server | 1.101 DEBUG ECN probing: sent 8 probes server | 1.101 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.101 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.101 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.101 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 1.488821ms server | 1.101 DEBUG Setting timeout of 1.488821ms server | 1.101 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.101 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.101 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.101 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 1.467491ms server | 1.101 DEBUG Setting timeout of 1.467491ms server | 1.103 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.103 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.103 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=7 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 0, offset: 4774, len: 346, fin: true } server | TX -> Stream { stream_id: 4, offset: 0, len: >>843, fin: false } server | 1.103 DEBUG packet_sent this=0x56137256db40, pn=7, ps=1232 server | 1.103 DEBUG ECN probing: sent 9 probes server | 1.103 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.103 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.103 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.103 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 1.126689ms server | 1.103 DEBUG Setting timeout of 1.126689ms server | 1.103 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.103 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.103 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.103 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 1.104307ms server | 1.103 DEBUG Setting timeout of 1.104307ms server | 1.105 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.105 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.105 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=8 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 4, offset: 843, len: >>1193, fin: false } server | 1.105 DEBUG packet_sent this=0x56137256db40, pn=8, ps=1232 server | 1.105 DEBUG ECN probing: sent 10 probes server | 1.105 DEBUG ECN probing concluded with 10 probes sent server | 1.105 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.105 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.105 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=9 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, NotEct) len 1232 server | TX -> Stream { stream_id: 4, offset: 2036, len: >>1193, fin: false } server | 1.105 DEBUG packet_sent this=0x56137256db40, pn=9, ps=1232 server | 1.105 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1100, pto: None, probe: EnumSet(), paced: false } server | 1.105 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.105 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=10 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, NotEct) len 1100 server | TX -> Stream { stream_id: 4, offset: 3229, len: >>1061, fin: false } server | 1.105 DEBUG packet_sent this=0x56137256db40, pn=10, ps=1100 server | 1.105 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false } server | 1.105 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.105 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false } server | 1.105 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 118.928497ms server | 1.105 DEBUG Setting timeout of 118.928497ms server | 1.105 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false } server | 1.105 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.105 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false } server | 1.105 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 118.907087ms server | 1.105 DEBUG Setting timeout of 118.907087ms server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584837 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1444 server | -> RX Ping server | -> RX Padding { len: 1415 } server | 1.128 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 599, tv_nsec: 26036040 } server | 1.128 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 599, tv_nsec: 26036040 } server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false } server | 1.128 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=11 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, NotEct) len 50 server | TX -> Ack { largest_acknowledged: 2017584837, ack_delay: 0, first_ack_range: 2, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 3, Ce: 0})) } server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false } server | 1.128 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.128 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false } server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 96.231446ms server | 1.128 DEBUG Setting timeout of 96.231446ms server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584838 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 39 server | -> RX Ack { largest_acknowledged: 2, ack_delay: 5, first_ack_range: 2, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 3, Ce: 0})) } server | -> RX Padding { len: 3 } server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] Rx ACK space=ap, ranges=[0..=2] server | 1.128 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=2 server | 1.128 INFO ECN validation succeeded, path is capable server | 1.128 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 9724/14916 ssthresh 18446744073709551615] slow start += 2596 server | 1.128 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 9724/14916 ssthresh 18446744073709551615] on_packets_acked this=0x56137256db40, limited=0, bytes_in_flight=9724, cwnd=14916, state=SlowStart, new_acked=2596 server | 1.128 DEBUG PMTUD probe of size 1380 succeeded server | 1.128 DEBUG PMTUD started with probe size 1420 server | 1.128 DEBUG PLPMTU changed from 1232 to 1332, updating pacer server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.128 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.128 DEBUG Sending PMTUD probe of size 1420, count 1 server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=12 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1372 server | TX -> Ping server | TX -> Stream { stream_id: 4, offset: 4290, len: >>1332, fin: false } server | 1.128 DEBUG packet_sent this=0x56137256db40, pn=12, ps=1372 server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.128 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=13 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1332 server | TX -> Stream { stream_id: 4, offset: 5622, len: >>1293, fin: false } server | 1.128 DEBUG packet_sent this=0x56137256db40, pn=13, ps=1332 server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.128 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.128 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 1.593742ms server | 1.128 DEBUG Setting timeout of 1.593742ms server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.128 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.128 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.128 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 1.570809ms server | 1.128 DEBUG Setting timeout of 1.570809ms server | 1.130 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584839 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 39 server | -> RX Ack { largest_acknowledged: 4, ack_delay: 4, first_ack_range: 4, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 5, Ce: 0})) } server | -> RX Padding { len: 3 } server | 1.130 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] Rx ACK space=ap, ranges=[0..=4] server | 1.130 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=4 server | 1.130 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 9964/17380 ssthresh 18446744073709551615] slow start += 2464 server | 1.130 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 9964/17380 ssthresh 18446744073709551615] on_packets_acked this=0x56137256db40, limited=0, bytes_in_flight=9964, cwnd=17380, state=SlowStart, new_acked=2464 server | 1.130 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.130 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.130 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=14 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1332 server | TX -> Stream { stream_id: 4, offset: 6915, len: >>1293, fin: false } server | 1.130 DEBUG packet_sent this=0x56137256db40, pn=14, ps=1332 server | 1.130 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.130 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.130 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=15 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1332 server | TX -> Stream { stream_id: 4, offset: 8208, len: >>1293, fin: false } server | 1.130 DEBUG packet_sent this=0x56137256db40, pn=15, ps=1332 server | 1.130 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.130 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.130 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.130 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 1.348724ms server | 1.130 DEBUG Setting timeout of 1.348724ms server | 1.130 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.130 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.130 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.130 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 1.323717ms server | 1.130 DEBUG Setting timeout of 1.323717ms server | 1.132 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584840 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 39 server | -> RX Ack { largest_acknowledged: 6, ack_delay: 5, first_ack_range: 6, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 7, Ce: 0})) } server | -> RX Padding { len: 3 } server | 1.132 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] Rx ACK space=ap, ranges=[0..=6] server | 1.132 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=6 server | 1.132 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 10164/19844 ssthresh 18446744073709551615] slow start += 2464 server | 1.132 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 10164/19844 ssthresh 18446744073709551615] on_packets_acked this=0x56137256db40, limited=0, bytes_in_flight=10164, cwnd=19844, state=SlowStart, new_acked=2464 server | 1.132 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.132 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.132 DEBUG CRYPTO for ap offset=0, len=321 server | 1.132 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=16 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 1150 server | TX -> Stream { stream_id: 4, offset: 9501, len: 739, fin: true } server | TX -> Crypto { offset: 0, len: 321 } server | TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 48, 130, 139, 209, 236, 207, 53, 228, 221, 247, 85, 34, 240, 175, 69, 69, 21, 253, 165, 121, 225, 180, 201, 142, 95, 166, 94, 157, 210, 46, 237, 190, 76, 133, 106, 70] } server | 1.132 DEBUG packet_sent this=0x56137256db40, pn=16, ps=1150 server | 1.132 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.132 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.132 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.132 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 95.94113ms server | 1.132 DEBUG Setting timeout of 95.94113ms server | 1.132 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.132 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.132 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.132 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 95.895244ms server | 1.132 DEBUG Setting timeout of 95.895244ms server | 1.136 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584841 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 39 server | -> RX Ack { largest_acknowledged: 8, ack_delay: 5, first_ack_range: 8, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 9, Ce: 0})) } server | -> RX Padding { len: 3 } server | 1.136 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] Rx ACK space=ap, ranges=[0..=8] server | 1.136 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=8 server | 1.136 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 8850/22308 ssthresh 18446744073709551615] slow start += 2464 server | 1.136 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 8850/22308 ssthresh 18446744073709551615] on_packets_acked this=0x56137256db40, limited=0, bytes_in_flight=8850, cwnd=22308, state=SlowStart, new_acked=2464 server | 1.136 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.136 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.136 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=17 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 37 server | TX -> MaxStreams { stream_type: BiDi, maximum_streams: 17 } server | 1.137 DEBUG packet_sent this=0x56137256db40, pn=17, ps=38 server | 1.137 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.137 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.137 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.137 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 90.764189ms server | 1.137 DEBUG Setting timeout of 90.764189ms server | 1.137 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.137 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.137 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.137 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 90.733581ms server | 1.137 DEBUG Setting timeout of 90.733581ms server | 1.138 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584842 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 39 server | -> RX Ack { largest_acknowledged: 10, ack_delay: 5, first_ack_range: 10, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 9, Ce: 0})) } server | -> RX Padding { len: 3 } server | 1.138 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] Rx ACK space=ap, ranges=[0..=10] server | 1.138 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=10 server | 1.138 WARN ECN validation failed, no ECT(0) packets were newly acked server | 1.138 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 6556/24640 ssthresh 18446744073709551615] slow start += 2332 server | 1.138 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 6556/24640 ssthresh 18446744073709551615] on_packets_acked this=0x56137256db40, limited=0, bytes_in_flight=6556, cwnd=24640, state=SlowStart, new_acked=2332 server | 1.138 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.138 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.138 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.138 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 82.966441ms server | 1.138 DEBUG Setting timeout of 82.966441ms server | 1.138 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.138 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.138 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.138 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 82.902972ms server | 1.138 DEBUG Setting timeout of 82.902972ms server | 1.161 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584843 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 39 server | -> RX Ack { largest_acknowledged: 13, ack_delay: 5, first_ack_range: 13, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 11, Ce: 0})) } server | -> RX Padding { len: 3 } server | 1.161 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] Rx ACK space=ap, ranges=[0..=13] server | 1.161 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=13 server | 1.161 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 3852/27344 ssthresh 18446744073709551615] slow start += 2704 server | 1.161 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 3852/27344 ssthresh 18446744073709551615] on_packets_acked this=0x56137256db40, limited=0, bytes_in_flight=3852, cwnd=27344, state=SlowStart, new_acked=2704 server | 1.161 DEBUG PMTUD probe of size 1420 succeeded server | 1.161 DEBUG PMTUD started with probe size 1470 server | 1.161 DEBUG PLPMTU changed from 1332 to 1372, updating pacer server | 1.161 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.161 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.161 DEBUG Sending PMTUD probe of size 1470, count 1 server | 1.161 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=18 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, NotEct) len 1422 server | TX -> Ping server | TX -> Padding { len: 1386 } server | 1.161 DEBUG packet_sent this=0x56137256db40, pn=18, ps=1422 server | 1.161 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.161 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.161 DEBUG TX blocked, profile=SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.161 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 80.402774ms server | 1.161 DEBUG Setting timeout of 80.402774ms server | 1.161 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.161 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.161 DEBUG TX blocked, profile=SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.161 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 80.378449ms server | 1.161 DEBUG Setting timeout of 80.378449ms server | 1.163 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584844 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 39 server | -> RX Ack { largest_acknowledged: 15, ack_delay: 5, first_ack_range: 15, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 13, Ce: 0})) } server | -> RX Padding { len: 3 } server | 1.163 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] Rx ACK space=ap, ranges=[0..=15] server | 1.163 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=15 server | 1.163 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 2610/30008 ssthresh 18446744073709551615] slow start += 2664 server | 1.163 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 2610/30008 ssthresh 18446744073709551615] on_packets_acked this=0x56137256db40, limited=0, bytes_in_flight=2610, cwnd=30008, state=SlowStart, new_acked=2664 server | 1.163 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.163 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.163 DEBUG TX blocked, profile=SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.163 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 74.178263ms server | 1.163 DEBUG Setting timeout of 74.178263ms server | 1.163 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.163 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.163 DEBUG TX blocked, profile=SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.163 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] delay duration 74.083214ms server | 1.163 DEBUG Setting timeout of 74.083214ms server | 1.164 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=2017584845 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, Ect0) len 39 server | -> RX ConnectionClose { error_code: Transport(0), frame_type: 0, reason_phrase: "" } server | -> RX Padding { len: 7 } server | 1.164 INFO [Server da18260341f2ae075f1398a9ccbb1f979b07] ConnectionClose received. Error code: Transport(0) frame type 0 reason server | 1.164 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] State change from Confirmed -> Draining { error: Transport(PeerError(0)), timeout: Instant { tv_sec: 599, tv_nsec: 292037323 } } server | 1.164 DEBUG [pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046] Path validated Instant { tv_sec: 599, tv_nsec: 62309392 } server | 1.164 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false } server | 1.164 DEBUG Building Short dcid Some(CID [17]: e92f01f2231e0b9ec8023f267b41070e48) server | 1.164 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 599, tv_nsec: 62309392 } server | 1.164 DEBUG [Server da18260341f2ae075f1398a9ccbb1f979b07] pn=19 type=Short pri-path:e92f01f2231e0b9ec8023f267b41070e48 [::]:443->[fd00:cafe:cafe::100]:47046 IpTos(Cs0, NotEct) len 54 server | TX -> Ack { largest_acknowledged: 2017584845, ack_delay: 0, first_ack_range: 10, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 11, Ce: 0})) } server | TX -> ConnectionClose { error_code: Transport(0), frame_type: 28, reason_phrase: "" } server | 1.164 DEBUG Setting timeout of 229.613736ms server | 1.164 DEBUG Setting timeout of 229.606282ms 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 10:29:45,711 Using the client's key log file. 2025-04-30 10:29:45,723 2025-04-30 10:29:45,724 Using the client's key log file. 2025-04-30 10:29:45,724 Using the client's key log file. 2025-04-30 10:29:45,737 2025-04-30 10:29:45,738 Using the client's key log file. 2025-04-30 10:29:46,335 Check of downloaded files succeeded. 2025-04-30 10:29:46,934 Check of downloaded files succeeded.