2025-04-30 09:10:58,223 Generated random file: fbwoygzbfi of size: 1024 2025-04-30 09:10:58,224 Requests: https://server4:443/fbwoygzbfi 2025-04-30 09:10:58,281 2025-04-30 09:10:58,282 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_nv58sag3/ TESTCASE_SERVER=handshake TESTCASE_CLIENT=handshake WWW=/tmp/www_z4_swrnk/ DOWNLOADS=/tmp/download_qhssr47i/ SERVER_LOGS=/tmp/logs_server_ajai2cmx CLIENT_LOGS=/tmp/logs_client_776izmkc 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/fbwoygzbfi" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-04-30 09:11:13,759 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... client | Actual changes: client | tx-checksum-ip-generic: off client | tx-tcp-segmentation: off [not requested] client | tx-tcp-ecn-segmentation: off [not requested] client | tx-tcp-mangleid-segmentation: off [not requested] client | tx-tcp6-segmentation: off [not requested] client | tx-udp-segmentation: off [not requested] client | tx-checksum-sctp: off client | Endpoint's IPv4 address is 193.167.0.100 client | Endpoint's IPv6 address is fd00:cafe:cafe::100 client | Executing client server | Setting up routes... server | Actual changes: server | tx-checksum-ip-generic: off server | tx-tcp-segmentation: off [not requested] server | tx-tcp-ecn-segmentation: off [not requested] server | tx-tcp-mangleid-segmentation: off [not requested] server | tx-tcp6-segmentation: off [not requested] server | tx-udp-segmentation: off [not requested] server | tx-checksum-sctp: off client | wait-for-it.sh: waiting 30 seconds for sim:57832 server | Endpoint's IPv4 address is 193.167.100.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 handshake ']' server | + '[' -n /logs/qlog/ ']' server | + case "$ROLE" in server | + DB=/neqo/db server | + CERT=cert server | ++ mktemp server | + P12CERT=/tmp/tmp.k8QetKs4r5 server | + mkdir -p /neqo/db server | + certutil -N -d sql:/neqo/db --empty-password server | + openssl pkcs12 -export -nodes -in /certs/cert.pem -inkey /certs/priv.key -name cert -passout pass: -out /tmp/tmp.k8QetKs4r5 server | Warning: output encryption option -nodes ignored with -export server | + pk12util -d sql:/neqo/db -i /tmp/tmp.k8QetKs4r5 -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 | 69:23:fc:71:36:21:89:a4:ec:56:d1:08:8b:55:29:ba: server | 68:02:e2:e1 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:10:58 2025 server | Not After : Sat May 10 09:10:58 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:4a:57:fc:16:fe:a2:4c:df:7b:19:66:be:52:0e:0e: server | 9d:78:76:bb:58:a0:fb:94:c8:c6:bd:c4:bc:f8:c7:dc: server | a9:82:82:07:02:ee:15:dd:07:8e:4b:dd:10:28:96:7b: server | c5:15:7b:6b:85:d8:70:e4:19:bf:31:75:5a:56:75:04: server | 43 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 | e3:fe:4c:5f:e0:14:0d:32:ef:08:57:c1:fb:34:00:a8: server | 0f:0c:0f:99 server | server | Name: Certificate Authority Key Identifier server | Key ID: server | 81:d4:54:5b:df:d3:df:b7:e7:a5:ae:05:0d:93:2a:69: server | 41:2c:a9:98 server | server | Signature Algorithm: X9.62 ECDSA signature with SHA256 server | Signature: server | 30:45:02:20:01:99:b5:ca:31:73:cc:25:f5:bf:e5:e6: server | 14:4d:b1:2f:0c:f2:6a:ef:07:3a:a0:79:79:3a:e9:fc: server | fc:6b:54:02:02:21:00:dd:82:6d:74:82:83:6c:11:51: server | c1:12:0a:f3:08:01:fa:f6:f1:2f:6a:fe:5e:4d:96:8a: server | d6:c9:24:dc:db:28:53 server | Fingerprint (SHA-256): server | EF:EF:83:77:1E:B3:4C:F6:2B:50:46:32:3E:F8:F6:D1:72:FF:B6:FD:52:C3:C2:5A:12:90:DC:1A:36:C6:24:41 server | Fingerprint (SHA1): server | 59:50:F0:BE:B9:6A:EC:74:16:1C:DC:87:47:E2:81:7E:D4:0F:97:61 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 | + '[' handshake = connectionmigration ']' server | + RUST_LOG=debug server | + RUST_BACKTRACE=1 server | + neqo-server --cc cubic --qns-test handshake --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.036467632s server | 0.783 DEBUG [Server] Unsupported version: 57414954 server | 0.783 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:52062 IpTos(Cs0, NotEct) len 15 server | 0.783 DEBUG [Server] Unsupported version: 57414954 server | 0.783 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:52062 IpTos(Cs0, NotEct) len 15 server | 0.783 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" }) server | 0.783 DEBUG [Server] Unsupported version: 57414954 server | 0.783 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:52062 IpTos(Cs0, NotEct) len 15 server | 0.783 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 | 3.979 DEBUG [Server] Handle initial server | 3.979 INFO AddressValidation: no token; accepting server | 3.979 INFO [Server] Accept connection CID [20]: 3610c43a1300aa889b6e277a83a2bb46bd698af7 server | 3.979 DEBUG Overwrite initial version Version1 ==> Version1 server | 3.981 DEBUG Outbound interface eth0 for destination ::ffff:193.167.0.100 has MTU 1500 server | 3.981 INFO [Server ...] Received valid Initial packet with scid CID [8]: 4cc3503f764d5dc0 dcid CID [20]: 3610c43a1300aa889b6e277a83a2bb46bd698af7 server | 3.981 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=3610c43a1300aa889b6e277a83a2bb46bd698af7 server | 3.981 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 server | 3.981 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 server | 3.981 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] State change from Init -> WaitInitial server | 3.981 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=0 type=Initial unv-path [::]:443->[::ffff:193.167.0.100]:43461 IpTos(Cs0, Ect0) len 1200 server | -> RX Crypto { offset: 0, len: 286 } server | -> RX Padding { len: 855 } server | 3.981 DEBUG Read Ok(286) bytes server | 3.981 DEBUG 0-RTT: no token, no 0-RTT server | 3.981 DEBUG Read secret available for Handshake: SymKey [32]: 125b8f38fa4f9f32efff37177591a8e4475d2b72424a52514e8e803b767300c3 server | 3.981 DEBUG Write secret available for Handshake: SymKey [32]: fc3939574550658ff7f9a32e9cc11c5456d1563fd95363773c0c620122a4fa90 server | 3.981 DEBUG Writing transport parameters, msg=8 server | 3.982 DEBUG Read secret available for ApplicationData: SymKey [32]: 318bb04c37a4bf338e1a186bd6dd266a0a32a35f41e86e6774481d99d305c292 server | 3.982 DEBUG Write secret available for ApplicationData: SymKey [32]: 5dc936cd22a28241bb5a574ac2ecd05177f42be34b5a63769e6bd38f243a9026 server | 3.982 DEBUG [Agent 0x55d3730e11d0] state -> InProgress server | 3.982 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865 server | 3.982 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865 server | 3.982 DEBUG [Crypto] Handshake keys installed server | 3.982 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 3.982 DEBUG [Crypto] Application write key installed server | 3.982 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 190, tv_nsec: 233130962 } server | 3.982 DEBUG [unv-path [::]:443->[::ffff:193.167.0.100]:43461] Make permanent server | 3.982 DEBUG [unv-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461] set as primary path server | 3.982 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] State change from WaitInitial -> Handshaking server | 3.982 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.982 DEBUG Building Initial dcid Some(CID [8]: 4cc3503f764d5dc0) scid Some(CID [10]: dcb9e22d7ccff55e797c) server | 3.982 DEBUG CRYPTO for in offset=0, len=90 server | 3.982 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=0 type=Initial pri-unv-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 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.982 DEBUG Building Handshake dcid Some(CID [8]: 4cc3503f764d5dc0) scid Some(CID [10]: dcb9e22d7ccff55e797c) server | 3.982 DEBUG CRYPTO for hs offset=0, len=736 server | 3.982 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=0 type=Handshake pri-unv-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 IpTos(Cs0, Ect0) len 931 server | TX -> Crypto { offset: 0, len: 736 } server | 3.982 DEBUG packet_sent this=0x55d3730e0b40, pn=0, ps=784 server | 3.982 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 3.982 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pad Initial from 931 to PLPMTU 1232 server | 3.982 DEBUG packet_sent this=0x55d3730e0b40, pn=0, ps=448 server | 3.982 DEBUG ECN probing: sent 1 probes server | 3.982 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.982 DEBUG Building Initial dcid Some(CID [8]: 4cc3503f764d5dc0) scid Some(CID [10]: dcb9e22d7ccff55e797c) server | 3.982 DEBUG Building Handshake dcid Some(CID [8]: 4cc3503f764d5dc0) scid Some(CID [10]: dcb9e22d7ccff55e797c) server | 3.982 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 3.982 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.982 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] delay duration 297.031207ms server | 3.982 DEBUG Setting timeout of 297.031207ms server | 3.982 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.982 DEBUG Building Initial dcid Some(CID [8]: 4cc3503f764d5dc0) scid Some(CID [10]: dcb9e22d7ccff55e797c) server | 3.982 DEBUG Building Handshake dcid Some(CID [8]: 4cc3503f764d5dc0) scid Some(CID [10]: dcb9e22d7ccff55e797c) server | 3.982 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 3.982 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.982 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] delay duration 296.99538ms server | 3.982 DEBUG Setting timeout of 296.99538ms server | 4.015 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=1 type=Initial pri-unv-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 IpTos(Cs0, Ect0) len 53 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 40, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } server | 4.015 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] Rx ACK space=in, ranges=[0..=0] server | 4.015 DEBUG [LossRecovery] ACK for Initial - largest_acked=0 server | 4.015 DEBUG on_packets_acked this=0x55d3730e0b40, limited=1, bytes_in_flight=784, cwnd=12320, state=SlowStart, new_acked=448 server | 4.015 DEBUG Acked crypto frame space=in offset=0 length=90 server | 4.015 DEBUG [pri-unv-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461] Path validated Instant { tv_sec: 190, tv_nsec: 268942734 } server | 4.015 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] Drop packet number space in server | 4.015 DEBUG [LossRecovery] Reset loss recovery state for Initial server | 4.015 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=0 type=Handshake pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 IpTos(Cs0, Ect0) len 1147 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 40, 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.015 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] Rx ACK space=hs, ranges=[0..=0] server | 4.015 DEBUG [LossRecovery] ACK for Handshake - largest_acked=0 server | 4.015 DEBUG on_packets_acked this=0x55d3730e0b40, limited=1, bytes_in_flight=0, cwnd=12320, state=SlowStart, new_acked=784 server | 4.015 DEBUG Acked crypto frame space=hs offset=0 length=736 server | 4.015 DEBUG Read Ok(36) bytes server | 4.015 DEBUG [Agent 0x55d3730e11d0] 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.015 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] TLS connection complete server | 4.015 DEBUG [pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461] Path validated Instant { tv_sec: 190, tv_nsec: 268942734 } server | 4.015 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 4.015 DEBUG [Crypto] application read keys installed server | 4.015 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] State change from Handshaking -> Connected server | 4.015 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] State change from Connected -> Confirmed server | 4.015 DEBUG PMTUD started with probe size 1380 server | 4.015 INFO [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] Connection established server | 4.015 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 190, tv_nsec: 268942734 } server | 4.015 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.015 DEBUG Building Handshake dcid Some(CID [8]: 4cc3503f764d5dc0) scid Some(CID [10]: dcb9e22d7ccff55e797c) server | 4.015 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=1 type=Handshake pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 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.015 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] Drop packet number space hs server | 4.015 DEBUG [LossRecovery] Reset loss recovery state for Handshake server | 4.015 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.015 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=0 type=Short pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 IpTos(Cs0, Ect0) len 1332 server | TX -> HandshakeDone server | TX -> NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [172, 89, 207, 134, 65, 75, 99, 33, 99, 25], stateless_reset_token: [136, 165, 122, 87, 255, 218, 160, 176, 38, 245, 165, 88, 8, 71, 202, 146] } server | TX -> NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [15, 245, 156, 112, 41, 157, 180, 245, 74, 26], stateless_reset_token: [198, 200, 133, 172, 183, 228, 229, 155, 237, 188, 200, 8, 82, 218, 138, 197] } server | TX -> NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [130, 192, 217, 84, 51, 12, 27, 222, 31, 208], stateless_reset_token: [170, 69, 60, 251, 118, 30, 78, 183, 71, 254, 151, 182, 19, 147, 227, 237] } server | TX -> NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [83, 178, 60, 141, 250, 90, 96, 101, 198, 92], stateless_reset_token: [226, 94, 8, 29, 17, 150, 63, 104, 37, 63, 203, 89, 228, 129, 248, 204] } server | TX -> Padding { len: 1133 } server | 4.015 DEBUG packet_sent this=0x55d3730e0b40, pn=0, ps=1280 server | 4.015 DEBUG ECN probing: sent 2 probes server | 4.015 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.016 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.016 DEBUG Sending PMTUD probe of size 1380, count 1 server | 4.016 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=1 type=Short pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 IpTos(Cs0, Ect0) len 1332 server | TX -> Ping server | TX -> Padding { len: 1305 } server | 4.016 DEBUG packet_sent this=0x55d3730e0b40, pn=1, ps=1332 server | 4.016 DEBUG ECN probing: sent 3 probes server | 4.016 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.016 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.016 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.016 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] delay duration 1.35207ms server | 4.016 DEBUG Setting timeout of 1.35207ms server | 4.016 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=0 type=Short pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 IpTos(Cs0, Ect0) len 224 server | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [208, 171, 20, 84, 225, 207, 15, 61], stateless_reset_token: [231, 62, 109, 74, 113, 136, 102, 62, 13, 238, 49, 80, 103, 188, 141, 110] } server | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [150, 220, 150, 48, 93, 57, 32, 122], stateless_reset_token: [243, 37, 135, 154, 162, 235, 146, 19, 41, 149, 218, 71, 98, 173, 99, 220] } server | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [54, 188, 37, 244, 17, 149, 160, 155], stateless_reset_token: [80, 177, 201, 5, 210, 17, 198, 61, 188, 249, 69, 202, 33, 196, 175, 234] } server | -> RX NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [0, 36, 242, 93, 26, 22, 85, 183], stateless_reset_token: [119, 95, 65, 15, 34, 240, 186, 1, 124, 0, 206, 178, 163, 176, 168, 209] } server | -> RX NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [218, 45, 58, 22, 135, 164, 37, 87], stateless_reset_token: [88, 208, 227, 243, 53, 210, 23, 41, 116, 14, 153, 78, 212, 248, 27, 199] } server | -> RX NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [185, 33, 189, 153, 94, 123, 139, 139], stateless_reset_token: [139, 224, 209, 4, 17, 182, 3, 56, 53, 208, 26, 247, 28, 117, 114, 233] } server | -> RX NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [114, 218, 168, 19, 136, 194, 13, 34], stateless_reset_token: [66, 74, 84, 218, 230, 215, 124, 209, 72, 26, 6, 223, 162, 122, 102, 201] } server | 4.016 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 190, tv_nsec: 289628202 } server | 4.016 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.016 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.016 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.016 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] delay duration 1.321452ms server | 4.016 DEBUG Setting timeout of 1.321452ms server | 4.016 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=1 type=Short pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 IpTos(Cs0, Ect0) len 48 server | -> RX Stream { stream_id: 0, offset: 0, len: 17, fin: true } server | 4.016 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 190, tv_nsec: 269712980 } server | 4.016 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.016 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.016 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=2 type=Short pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 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.016 DEBUG ECN probing: sent 4 probes server | 4.016 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.016 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.016 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.016 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] delay duration 1.166034ms server | 4.016 DEBUG Setting timeout of 1.166034ms server | 4.017 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] send session ticket 406f00143610c43a1300aa889b6e277a83a2bb46bd698af70104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0adcb9e22d7ccff55e797c110c000000019a0a6aaa000000016ab200c0000000ff02de1a0243e8200100686921 server | 4.017 DEBUG Path = 'fbwoygzbfi' server | 4.017 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.017 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.017 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.017 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] delay duration 131.226µs server | 4.017 DEBUG Setting timeout of 131.226µs server | 4.018 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.018 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.018 DEBUG CRYPTO for ap offset=0, len=174 server | 4.018 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=3 type=Short pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 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.018 DEBUG packet_sent this=0x55d3730e0b40, pn=3, ps=1232 server | 4.018 DEBUG ECN probing: sent 5 probes server | 4.018 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.018 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.018 DEBUG CRYPTO for ap offset=174, len=147 server | 4.018 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=4 type=Short pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 IpTos(Cs0, Ect0) len 223 server | TX -> Crypto { offset: 174, len: 147 } server | TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 149, 220, 30, 181, 50, 206, 159, 210, 228, 144, 173, 25, 114, 57, 6, 230, 230, 200, 43, 22, 186, 187, 232, 139, 183, 72, 140, 238, 7, 78, 248, 81, 67, 106, 158, 42] } server | 4.018 DEBUG packet_sent this=0x55d3730e0b40, pn=4, ps=223 server | 4.018 DEBUG ECN probing: sent 6 probes server | 4.018 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.018 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.018 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.018 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] delay duration 980.59µs server | 4.018 DEBUG Setting timeout of 980.59µs server | 4.018 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.018 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.018 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 4.018 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] delay duration 962.326µs server | 4.018 DEBUG Setting timeout of 962.326µs server | 4.020 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.020 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.020 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.020 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] delay duration 112.348703ms server | 4.020 DEBUG Setting timeout of 112.348703ms server | 4.020 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.020 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.020 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.020 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] delay duration 112.328616ms server | 4.020 DEBUG Setting timeout of 112.328616ms server | 4.048 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=2 type=Short pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 IpTos(Cs0, Ect0) len 36 server | -> RX Ack { largest_acknowledged: 2, ack_delay: 8, first_ack_range: 2, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 3, Ce: 0})) } server | 4.048 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] Rx ACK space=ap, ranges=[0..=2] server | 4.048 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=2 server | 4.048 DEBUG on_packets_acked this=0x55d3730e0b40, limited=1, bytes_in_flight=1455, cwnd=12320, state=SlowStart, new_acked=2612 server | 4.048 DEBUG PMTUD probe of size 1380 succeeded server | 4.048 DEBUG PMTUD started with probe size 1420 server | 4.048 DEBUG PLPMTU changed from 1232 to 1332, updating pacer server | 4.048 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.048 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.048 DEBUG Sending PMTUD probe of size 1420, count 1 server | 4.048 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=5 type=Short pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 IpTos(Cs0, Ect0) len 1372 server | TX -> Ping server | TX -> Padding { len: 1345 } server | 4.048 DEBUG packet_sent this=0x55d3730e0b40, pn=5, ps=1372 server | 4.048 DEBUG ECN probing: sent 7 probes server | 4.048 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.048 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.048 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.048 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] delay duration 103.781048ms server | 4.048 DEBUG Setting timeout of 103.781048ms server | 4.048 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.048 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.048 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.048 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] delay duration 103.74461ms server | 4.048 DEBUG Setting timeout of 103.74461ms server | 4.050 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=3 type=Short pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 IpTos(Cs0, Ect0) len 39 server | -> RX Ack { largest_acknowledged: 3, ack_delay: 14, 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.050 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] Rx ACK space=ap, ranges=[0..=3] server | 4.050 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=3 server | 4.050 DEBUG on_packets_acked this=0x55d3730e0b40, limited=1, bytes_in_flight=1595, cwnd=12320, state=SlowStart, new_acked=1232 server | 4.050 DEBUG Acked crypto frame space=ap offset=0 length=174 server | 4.050 INFO [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] ConnectionClose received. Error code: Application(0) frame type 0 reason server | 4.050 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] State change from Confirmed -> Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 190, tv_nsec: 592828611 } } server | 4.050 DEBUG [pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461] Path validated Instant { tv_sec: 190, tv_nsec: 303522696 } server | 4.050 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.050 DEBUG Building Short dcid Some(CID [8]: 4cc3503f764d5dc0) server | 4.050 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 190, tv_nsec: 303522696 } server | 4.050 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] pn=6 type=Short pri-path:4cc3503f764d5dc0 [::]:443->[::ffff:193.167.0.100]:43461 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.050 DEBUG ECN probing: sent 8 probes server | 4.050 DEBUG Setting timeout of 289.162358ms server | 4.050 WARN [Server ...] Dropped received packet: State Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 190, tv_nsec: 592828611 } }; Total: 1 server | 4.050 DEBUG Setting timeout of 289.149113ms server | 4.050 DEBUG Setting timeout of 289.138022ms server | 4.080 WARN [Server ...] Dropped received packet: State Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 190, tv_nsec: 592828611 } }; Total: 2 server | 4.080 DEBUG Setting timeout of 258.687508ms server | 4.080 DEBUG Setting timeout of 258.653134ms server | 4.340 DEBUG [Server 3610c43a1300aa889b6e277a83a2bb46bd698af7] State change from Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 190, tv_nsec: 592828611 } } -> Closed(Transport(PeerApplicationError(0))) server | 4.340 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:11:13,853 Using the client's key log file. 2025-04-30 09:11:13,862 2025-04-30 09:11:13,862 Using the client's key log file. 2025-04-30 09:11:13,863 Using the client's key log file. 2025-04-30 09:11:13,870 2025-04-30 09:11:13,870 Using the client's key log file. 2025-04-30 09:11:13,871 Using selector: EpollSelector 2025-04-30 09:11:14,150 Check of downloaded files succeeded.