2025-04-30 09:15:02,353 Generated random file: geuavmluqs of size: 1024 2025-04-30 09:15:02,353 Requests: https://server4:443/geuavmluqs 2025-04-30 09:15:02,416 2025-04-30 09:15:02,417 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_eli_rn94/ TESTCASE_SERVER=ecn TESTCASE_CLIENT=ecn WWW=/tmp/www_icr1ntx6/ DOWNLOADS=/tmp/download_8tap5okj/ SERVER_LOGS=/tmp/logs_server_1nsjj68r CLIENT_LOGS=/tmp/logs_client_ya9pm00m SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=stammw/quinn-interop:latest SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server4:443/geuavmluqs" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-04-30 09:15:17,742 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... client | Setting up routes... server | Actual changes: 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 | 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 client | Executing client 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 ecn ']' server | + '[' -n /logs/qlog/ ']' server | + case "$ROLE" in server | + DB=/neqo/db server | + CERT=cert server | ++ mktemp server | + P12CERT=/tmp/tmp.L093VHxrsp 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.L093VHxrsp server | Warning: output encryption option -nodes ignored with -export server | + pk12util -d sql:/neqo/db -i /tmp/tmp.L093VHxrsp -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 | 23:57:16:c0:ff:92:8d:de:ac:9c:ba:45:3b:67:cd:a7: server | 82:30:9a:62 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 09:15:02 2025 server | Not After : Sat May 10 09:15:02 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:ca:5a:27:f0:3d:a5:4e:9e:e3:00:3f:85:8d:dc:e2: server | 89:3c:e6:a4:2d:b5:c2:68:ee:28:fb:0e:3d:4b:3b:1e: server | c7:9b:59:c5:04:73:9a:f1:eb:2c:da:a3:d4:c4:ef:8d: server | ef:bd:38:e9:0c:0b:f5:74:79:25:bc:5f:45:1b:8a:c9: server | f8 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 | 57:cb:aa:76:5e:34:8c:b8:28:3c:97:94:0e:4e:31:a2: server | 87:9c:7c:d3 server | server | Name: Certificate Authority Key Identifier server | Key ID: server | b9:b4:c5:25:1e:5f:36:75:a5:4e:b4:6c:6e:aa:1e:03: server | bb:d2:ff:b4 server | server | Signature Algorithm: X9.62 ECDSA signature with SHA256 server | Signature: server | 30:45:02:20:4b:9a:b0:a9:b0:00:b0:a3:43:25:02:48: server | 51:db:65:7a:7c:06:f2:19:25:1d:90:93:cd:57:6e:5b: server | de:4c:b8:1f:02:21:00:a9:34:f7:09:f6:b7:bf:48:14: server | ce:87:26:2a:7d:b2:4c:e2:57:c9:75:fc:8b:28:61:22: server | f4:11:a1:37:cf:ef:f0 server | Fingerprint (SHA-256): server | C4:ED:4C:01:48:97:8C:51:7F:71:34:56:F2:0D:17:B0:E3:82:8B:73:76:15:89:D1:61:30:3D:C8:06:0A:CE:7C server | Fingerprint (SHA1): server | 12:00:24:FF:CA:81:14:22:91:44:2F:BC:F5:FE:B8:F8:6C:9E:71:F2 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 | + '[' ecn = connectionmigration ']' server | + RUST_LOG=debug server | + RUST_BACKTRACE=1 server | + neqo-server --cc cubic --qns-test ecn --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.784 DEBUG [Server] Unsupported version: 57414954 server | 0.784 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:51553 IpTos(Cs0, NotEct) len 15 server | 0.784 DEBUG [Server] Unsupported version: 57414954 sim | server:443 is available after 1.040945828s server | 0.784 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:51553 IpTos(Cs0, NotEct) len 15 server | 0.784 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" }) server | 0.784 DEBUG [Server] Unsupported version: 57414954 server | 0.784 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:51553 IpTos(Cs0, NotEct) len 15 server | 0.784 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 eth0, link-type EN10MB (Ethernet), snapshot length 262144 bytes sim | tcpdump: listening on eth1, link-type EN10MB (Ethernet), snapshot length 262144 bytes client | wait-for-it.sh: sim:57832 is available after 1 seconds server | 3.994 DEBUG [Server] Handle initial server | 3.994 INFO AddressValidation: no token; accepting server | 3.994 INFO [Server] Accept connection CID [20]: c298c342094a0d403c9b8102735d2419d1a02b13 server | 3.994 DEBUG Overwrite initial version Version1 ==> Version1 server | 3.996 DEBUG Outbound interface eth0 for destination ::ffff:193.167.0.100 has MTU 1500 server | 3.996 INFO [Server ...] Received valid Initial packet with scid CID [8]: 7cc1b47fabea095f dcid CID [20]: c298c342094a0d403c9b8102735d2419d1a02b13 server | 3.996 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=c298c342094a0d403c9b8102735d2419d1a02b13 server | 3.996 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 server | 3.996 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 server | 3.996 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] State change from Init -> WaitInitial server | 3.996 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=0 type=Initial unv-path [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 1200 server | -> RX Crypto { offset: 0, len: 286 } server | -> RX Padding { len: 855 } server | 3.996 DEBUG Read Ok(286) bytes server | 3.996 DEBUG 0-RTT: no token, no 0-RTT server | 3.997 DEBUG Read secret available for Handshake: SymKey [32]: f50dacd8515368a106c6759e611832d4c20c1243143b55bb9b129e43b9d291f1 server | 3.997 DEBUG Write secret available for Handshake: SymKey [32]: 287c2208a4b88d90d166b038af6d54ce765c42794268a38a83c4ced7e7dc3b74 server | 3.997 DEBUG Writing transport parameters, msg=8 server | 3.997 DEBUG Read secret available for ApplicationData: SymKey [32]: fdfa9155b5f92e27ee3be7a0b0f0f716e65463a83bb425096b9c07340a7d3e72 server | 3.997 DEBUG Write secret available for ApplicationData: SymKey [32]: 866b11389fdeff27ed7d27832a640a412eef97d937d8e74d2c62af652ba1ccf9 server | 3.997 DEBUG [Agent 0x55c9ae82b1d0] state -> InProgress server | 3.997 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865 server | 3.997 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865 server | 3.997 DEBUG [Crypto] Handshake keys installed server | 3.997 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 3.997 DEBUG [Crypto] Application write key installed server | 3.997 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 434, tv_nsec: 215733952 } server | 3.997 DEBUG [unv-path [::]:443->[::ffff:193.167.0.100]:59294] Make permanent server | 3.997 DEBUG [unv-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294] set as primary path server | 3.997 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] State change from WaitInitial -> Handshaking server | 3.997 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.997 DEBUG Building Initial dcid Some(CID [8]: 7cc1b47fabea095f) scid Some(CID [10]: 5c3cb3bdd3f6afd13684) server | 3.997 DEBUG CRYPTO for in offset=0, len=90 server | 3.997 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=0 type=Initial pri-unv-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 147 server | TX -> 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 | TX -> Crypto { offset: 0, len: 90 } server | 3.997 DEBUG Building Handshake dcid Some(CID [8]: 7cc1b47fabea095f) scid Some(CID [10]: 5c3cb3bdd3f6afd13684) server | 3.997 DEBUG CRYPTO for hs offset=0, len=734 server | 3.997 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=0 type=Handshake pri-unv-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 929 server | TX -> Crypto { offset: 0, len: 734 } server | 3.997 DEBUG packet_sent this=0x55c9ae82ab40, pn=0, ps=782 server | 3.997 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 3.997 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pad Initial from 929 to PLPMTU 1232 server | 3.997 DEBUG packet_sent this=0x55c9ae82ab40, pn=0, ps=450 server | 3.997 DEBUG ECN probing: sent 1 probes server | 3.997 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.997 DEBUG Building Initial dcid Some(CID [8]: 7cc1b47fabea095f) scid Some(CID [10]: 5c3cb3bdd3f6afd13684) server | 3.997 DEBUG Building Handshake dcid Some(CID [8]: 7cc1b47fabea095f) scid Some(CID [10]: 5c3cb3bdd3f6afd13684) server | 3.997 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 3.997 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.997 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] delay duration 297.005781ms server | 3.997 DEBUG Setting timeout of 297.005781ms server | 3.997 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.997 DEBUG Building Initial dcid Some(CID [8]: 7cc1b47fabea095f) scid Some(CID [10]: 5c3cb3bdd3f6afd13684) server | 3.997 DEBUG Building Handshake dcid Some(CID [8]: 7cc1b47fabea095f) scid Some(CID [10]: 5c3cb3bdd3f6afd13684) server | 3.997 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 3.997 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.997 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] delay duration 296.96806ms server | 3.997 DEBUG Setting timeout of 296.96806ms server | 4.030 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=1 type=Initial pri-unv-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 53 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 47, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } server | 4.030 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] Rx ACK space=in, ranges=[0..=0] server | 4.030 DEBUG [LossRecovery] ACK for Initial - largest_acked=0 server | 4.030 DEBUG on_packets_acked this=0x55c9ae82ab40, limited=1, bytes_in_flight=782, cwnd=12320, state=SlowStart, new_acked=450 server | 4.030 DEBUG Acked crypto frame space=in offset=0 length=90 server | 4.030 DEBUG [pri-unv-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294] Path validated Instant { tv_sec: 434, tv_nsec: 251511362 } server | 4.030 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] Drop packet number space in server | 4.030 DEBUG [LossRecovery] Reset loss recovery state for Initial server | 4.030 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=0 type=Handshake pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 1147 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 47, 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 | -> RX Padding { len: 1056 } server | 4.030 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] Rx ACK space=hs, ranges=[0..=0] server | 4.030 DEBUG [LossRecovery] ACK for Handshake - largest_acked=0 server | 4.030 DEBUG on_packets_acked this=0x55c9ae82ab40, limited=1, bytes_in_flight=0, cwnd=12320, state=SlowStart, new_acked=782 server | 4.030 DEBUG Acked crypto frame space=hs offset=0 length=734 server | 4.030 DEBUG Read Ok(36) bytes server | 4.030 DEBUG [Agent 0x55c9ae82b1d0] 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 | 4.030 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] TLS connection complete server | 4.030 DEBUG [pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294] Path validated Instant { tv_sec: 434, tv_nsec: 251511362 } server | 4.030 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 4.030 DEBUG [Crypto] application read keys installed server | 4.030 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] State change from Handshaking -> Connected server | 4.030 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] State change from Connected -> Confirmed server | 4.030 DEBUG PMTUD started with probe size 1380 server | 4.030 INFO [Server c298c342094a0d403c9b8102735d2419d1a02b13] Connection established server | 4.030 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 434, tv_nsec: 251511362 } server | 4.030 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.030 DEBUG Building Handshake dcid Some(CID [8]: 7cc1b47fabea095f) scid Some(CID [10]: 5c3cb3bdd3f6afd13684) server | 4.030 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=1 type=Handshake pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 52 server | TX -> 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 | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] Drop packet number space hs server | 4.031 DEBUG [LossRecovery] Reset loss recovery state for Handshake server | 4.031 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=0 type=Short pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 1332 server | TX -> HandshakeDone server | TX -> NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [254, 167, 185, 226, 212, 19, 245, 139, 40, 84], stateless_reset_token: [55, 142, 114, 63, 113, 105, 78, 67, 217, 8, 4, 238, 124, 43, 116, 123] } server | TX -> NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [190, 148, 62, 80, 231, 84, 47, 33, 218, 172], stateless_reset_token: [51, 225, 154, 191, 100, 184, 32, 118, 33, 156, 90, 37, 129, 226, 152, 185] } server | TX -> NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [98, 39, 164, 97, 243, 165, 227, 40, 34, 193], stateless_reset_token: [118, 87, 82, 141, 68, 138, 158, 204, 189, 57, 134, 44, 239, 25, 231, 149] } server | TX -> NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [122, 101, 7, 118, 225, 3, 170, 61, 212, 181], stateless_reset_token: [99, 90, 235, 124, 39, 86, 73, 247, 41, 117, 158, 144, 44, 98, 187, 149] } server | TX -> Padding { len: 1133 } server | 4.031 DEBUG packet_sent this=0x55c9ae82ab40, pn=0, ps=1280 server | 4.031 DEBUG ECN probing: sent 2 probes server | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.031 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.031 DEBUG Sending PMTUD probe of size 1380, count 1 server | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=1 type=Short pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 1332 server | TX -> Ping server | TX -> Padding { len: 1305 } server | 4.031 DEBUG packet_sent this=0x55c9ae82ab40, pn=1, ps=1332 server | 4.031 DEBUG ECN probing: sent 3 probes server | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.031 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.031 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] delay duration 1.525869ms server | 4.031 DEBUG Setting timeout of 1.525869ms server | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=0 type=Short pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 224 server | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [91, 149, 201, 89, 211, 53, 203, 62], stateless_reset_token: [55, 85, 156, 41, 207, 241, 145, 94, 95, 30, 153, 125, 1, 171, 181, 129] } server | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [36, 51, 68, 108, 40, 181, 92, 155], stateless_reset_token: [232, 150, 136, 213, 211, 222, 170, 159, 32, 84, 13, 195, 219, 161, 40, 59] } server | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [171, 12, 61, 18, 28, 101, 186, 34], stateless_reset_token: [206, 57, 243, 24, 52, 134, 153, 222, 51, 224, 14, 223, 236, 199, 249, 142] } server | -> RX NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [56, 42, 69, 249, 192, 9, 194, 165], stateless_reset_token: [208, 180, 237, 55, 74, 95, 21, 118, 35, 44, 217, 150, 58, 69, 255, 74] } server | -> RX NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [6, 22, 126, 109, 66, 194, 90, 172], stateless_reset_token: [193, 35, 17, 201, 168, 154, 92, 167, 70, 136, 214, 17, 204, 182, 81, 23] } server | -> RX NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [52, 226, 82, 174, 114, 99, 249, 225], stateless_reset_token: [168, 191, 42, 185, 60, 97, 129, 193, 70, 194, 125, 26, 57, 133, 75, 145] } server | -> RX NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [79, 141, 72, 230, 1, 236, 247, 95], stateless_reset_token: [234, 200, 165, 252, 165, 90, 1, 131, 96, 54, 246, 154, 201, 196, 130, 45] } server | 4.031 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 434, tv_nsec: 272029127 } server | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.031 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.031 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] delay duration 1.486025ms server | 4.031 DEBUG Setting timeout of 1.486025ms server | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=1 type=Short pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 48 server | -> RX Stream { stream_id: 0, offset: 0, len: 17, fin: true } server | 4.031 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 434, tv_nsec: 252104036 } server | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.031 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=2 type=Short pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 34 server | TX -> 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 | 4.031 DEBUG ECN probing: sent 4 probes server | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.031 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.031 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.031 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] delay duration 1.396357ms server | 4.031 DEBUG Setting timeout of 1.396357ms server | 4.032 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] send session ticket 406f0014c298c342094a0d403c9b8102735d2419d1a02b130104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0a5c3cb3bdd3f6afd13684110c00000001ea9aeaaa000000016ab200c0000000ff02de1a0243e8200100686921 server | 4.032 DEBUG Path = 'geuavmluqs' server | 4.032 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.032 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.032 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.032 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] delay duration 387.467µs server | 4.032 DEBUG Setting timeout of 387.467µs server | 4.033 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.033 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.033 DEBUG CRYPTO for ap offset=0, len=174 server | 4.033 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=3 type=Short pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 0, offset: 0, len: 1024, fin: true } server | TX -> Crypto { offset: 0, len: 174 } server | 4.033 DEBUG packet_sent this=0x55c9ae82ab40, pn=3, ps=1232 server | 4.033 DEBUG ECN probing: sent 5 probes server | 4.033 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.033 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.033 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.033 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] delay duration 982.431µs server | 4.033 DEBUG Setting timeout of 982.431µs server | 4.033 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.033 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.033 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.033 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] delay duration 959.127µs server | 4.033 DEBUG Setting timeout of 959.127µs server | 4.035 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.035 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.035 DEBUG CRYPTO for ap offset=174, len=147 server | 4.035 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=4 type=Short pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 223 server | TX -> Crypto { offset: 174, len: 147 } server | TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 66, 225, 34, 120, 128, 107, 122, 191, 87, 157, 113, 241, 54, 21, 60, 186, 50, 142, 114, 194, 17, 117, 173, 249, 79, 132, 46, 151, 105, 107, 201, 114, 55, 141, 112, 215] } server | 4.035 DEBUG packet_sent this=0x55c9ae82ab40, pn=4, ps=223 server | 4.035 DEBUG ECN probing: sent 6 probes server | 4.035 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.035 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.035 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.035 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] delay duration 114.370616ms server | 4.035 DEBUG Setting timeout of 114.370616ms server | 4.035 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.035 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.035 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.035 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] delay duration 114.347302ms server | 4.035 DEBUG Setting timeout of 114.347302ms server | 4.064 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=2 type=Short pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 36 server | -> RX Ack { largest_acknowledged: 2, ack_delay: 3, first_ack_range: 2, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 3, Ce: 0})) } server | 4.064 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] Rx ACK space=ap, ranges=[0..=2] server | 4.064 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=2 server | 4.064 DEBUG on_packets_acked this=0x55c9ae82ab40, limited=1, bytes_in_flight=1455, cwnd=12320, state=SlowStart, new_acked=2612 server | 4.064 DEBUG PMTUD probe of size 1380 succeeded server | 4.064 DEBUG PMTUD started with probe size 1420 server | 4.064 DEBUG PLPMTU changed from 1232 to 1332, updating pacer server | 4.064 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.064 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.064 DEBUG Sending PMTUD probe of size 1420, count 1 server | 4.064 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=5 type=Short pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 1372 server | TX -> Ping server | TX -> Padding { len: 1345 } server | 4.064 DEBUG packet_sent this=0x55c9ae82ab40, pn=5, ps=1372 server | 4.064 DEBUG ECN probing: sent 7 probes server | 4.064 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.064 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.064 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.064 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] delay duration 103.400062ms server | 4.064 DEBUG Setting timeout of 103.400062ms server | 4.064 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.064 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.064 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.064 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] delay duration 103.351161ms server | 4.064 DEBUG Setting timeout of 103.351161ms server | 4.065 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=3 type=Short pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 39 server | -> RX Ack { largest_acknowledged: 3, ack_delay: 13, first_ack_range: 3, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 4, Ce: 0})) } server | -> RX ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "" } server | 4.065 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] Rx ACK space=ap, ranges=[0..=3] server | 4.065 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=3 server | 4.065 DEBUG on_packets_acked this=0x55c9ae82ab40, limited=1, bytes_in_flight=1595, cwnd=12320, state=SlowStart, new_acked=1232 server | 4.065 DEBUG Acked crypto frame space=ap offset=0 length=174 server | 4.065 INFO [Server c298c342094a0d403c9b8102735d2419d1a02b13] ConnectionClose received. Error code: Application(0) frame type 0 reason server | 4.065 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] State change from Confirmed -> Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 434, tv_nsec: 574101642 } } server | 4.065 DEBUG [pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294] Path validated Instant { tv_sec: 434, tv_nsec: 285969270 } server | 4.065 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.065 DEBUG Building Short dcid Some(CID [8]: 7cc1b47fabea095f) server | 4.065 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 434, tv_nsec: 285969270 } server | 4.065 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] pn=6 type=Short pri-path:7cc1b47fabea095f [::]:443->[::ffff:193.167.0.100]:59294 IpTos(Cs0, Ect0) len 38 server | TX -> Ack { largest_acknowledged: 3, ack_delay: 0, first_ack_range: 3, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 4, Ce: 0})) } server | TX -> ConnectionClose { error_code: Transport(0), frame_type: 29, reason_phrase: "" } server | 4.065 DEBUG ECN probing: sent 8 probes server | 4.065 DEBUG Setting timeout of 287.994856ms server | 4.065 DEBUG Setting timeout of 287.984397ms server | 4.066 WARN [Server ...] Dropped received packet: State Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 434, tv_nsec: 574101642 } }; Total: 1 server | 4.066 DEBUG Setting timeout of 287.013838ms server | 4.066 DEBUG Setting timeout of 286.997458ms server | 4.095 WARN [Server ...] Dropped received packet: State Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 434, tv_nsec: 574101642 } }; Total: 2 server | 4.096 DEBUG Setting timeout of 257.294136ms server | 4.096 DEBUG Setting timeout of 257.267506ms server | 4.354 DEBUG [Server c298c342094a0d403c9b8102735d2419d1a02b13] State change from Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 434, tv_nsec: 574101642 } } -> Closed(Transport(PeerApplicationError(0))) server | 4.354 INFO Closing timer expired 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 09:15:17,846 Using the client's key log file. 2025-04-30 09:15:17,859 2025-04-30 09:15:17,859 Using the client's key log file. 2025-04-30 09:15:17,859 Using the client's key log file. 2025-04-30 09:15:17,870 2025-04-30 09:15:17,870 Using the client's key log file. 2025-04-30 09:15:18,157 Check of downloaded files succeeded. 2025-04-30 09:15:18,753 Using the client's key log file. 2025-04-30 09:15:19,039 Check of downloaded files succeeded. 2025-04-30 09:15:19,910 ECN.NONE 0 2025-04-30 09:15:19,910 ECN.ECT1 0 2025-04-30 09:15:19,910 ECN.ECT0 8 2025-04-30 09:15:19,910 ECN.CE 0 2025-04-30 09:15:20,212 ECN.NONE 0 2025-04-30 09:15:20,212 ECN.ECT1 0 2025-04-30 09:15:20,212 ECN.ECT0 8 2025-04-30 09:15:20,212 ECN.CE 0