2025-12-13 12:25:46,235 Generated random file: surprised-excessive-speaker of size: 1024 2025-12-13 12:25:46,235 Requests: https://server4:443/surprised-excessive-speaker 2025-12-13 12:25:46,293 2025-12-13 12:25:46,293 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_qkpwwx5c/ TESTCASE_SERVER=handshake TESTCASE_CLIENT=handshake WWW=/tmp/www_b834xb5k/ DOWNLOADS=/tmp/download_yoimaao9/ SERVER_LOGS=/tmp/logs_server_mp6mi6e9 CLIENT_LOGS=/tmp/logs_client_y2efdsb4 SCENARIO="simple-p2p --delay=750ms --bandwidth=10Mbps --queue=25" CLIENT=us-central1-docker.pkg.dev/golang-interop-testing/quic/go-x-net:latest SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server4:443/surprised-excessive-speaker" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-12-13 12:26:02,713 Container sim Recreate Container sim Recreated Container server Recreate Container client 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 server | Setting up routes... client | Endpoint's IPv6 address is fd00:cafe:cafe::100 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 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.RwQIF68ukz server | + mkdir -p /neqo/db client | wait-for-it.sh: waiting 30 seconds for sim:57832 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.RwQIF68ukz server | Warning: output encryption option -nodes ignored with -export server | + pk12util -d sql:/neqo/db -i /tmp/tmp.RwQIF68ukz -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 | 17:d4:c3:82:2b:fa:1f:8c:82:15:db:20:91:e1:93:91: server | 4a:17:99:d0 server | Signature Algorithm: X9.62 ECDSA signature with SHA256 server | Issuer: "O=interop runner Root Certificate Authority" server | Validity: server | Not Before: Sat Dec 13 12:25:46 2025 server | Not After : Tue Dec 23 12:25:46 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:32:ed:67:d3:fa:3f:b6:e2:ac:13:24:04:b7:db:fe: server | cc:7d:35:8c:e6:6e:56:83:e0:c7:61:be:bc:4e:60:38: server | 2d:5c:d4:ad:f9:16:56:9e:2e:ab:fc:22:f9:66:43:13: server | 01:65:67:c1:25:ff:85:1d:be:05:1e:dd:a6:a7:c6:1d: server | 07 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 | 2c:a8:21:67:98:36:65:5a:2a:7c:89:d3:58:68:1a:c1: server | 9b:c3:45:17 server | server | Name: Certificate Authority Key Identifier server | Key ID: server | 91:96:31:ce:97:57:a3:3b:e7:17:5e:22:45:65:10:7b: server | 2c:fc:81:fc server | server | Signature Algorithm: X9.62 ECDSA signature with SHA256 server | Signature: server | 30:46:02:21:00:ee:39:c3:d5:e2:6a:c8:b3:53:6e:e8: server | a8:5e:80:3b:d6:6c:8e:56:f2:57:69:d8:59:c7:c0:1b: server | d1:42:9c:fd:54:02:21:00:a2:2b:64:71:41:ab:1b:16: server | f4:33:65:0a:d3:bb:3f:a1:aa:dd:4d:c1:8d:f1:4e:18: server | aa:56:9a:ca:8a:1a:b0:10 server | Fingerprint (SHA-256): server | 38:4C:C8:92:19:79:93:04:B2:3A:C6:3A:20:2C:78:E7:90:CA:6C:5B:1D:47:10:EF:19:58:40:98:6A:41:1E:C2 server | Fingerprint (SHA1): server | BE:CD:A2:B5:25:38:CA:3C:7B:C6:BD:C1:C5:2C:74:3C:AF:EB:2E:D8 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 Ok(212992) server | 0.002 DEBUG Default socket receive buffer size is 1048576, not changing server | 0.002 INFO Server waiting for connection on: Ok([::]:443) server | 0.269 DEBUG [Server] Unsupported version: 57414954 server | 0.269 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:40993 Tos(Cs0, NotEct) len 15 sim | server:443 is available after 501.038847ms sim | Using scenario: simple-p2p --delay=750ms --bandwidth=10Mbps --queue=25 sim | Capturing on 'eth0' sim | Capturing on 'eth1' sim | File: /logs/trace_node_right.pcap sim | File: /logs/trace_node_left.pcap client | wait-for-it.sh: sim:57832 is available after 1 seconds client | 2025/12/13 12:25:47 listening on [::]:43919 server | 1.723 DEBUG [Server] Handle initial server | 1.723 INFO AddressValidation: no token; accepting server | 1.723 INFO [Server] Accept connection CID [8]: 559f74e3419fe39c server | 1.723 DEBUG Overwrite initial version Version1 ==> Version1 server | 1.725 DEBUG Outbound interface eth0 for destination ::ffff:193.167.0.100 has MTU 1500 server | 1.725 INFO [Server ...] Received valid Initial packet with scid CID [8]: 4a398d290e68f764 dcid CID [8]: 559f74e3419fe39c server | 1.725 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=559f74e3419fe39c server | 1.725 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 min_pn=16 server | 1.725 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 min_pn=0 server | 1.725 DEBUG [Server 559f74e3419fe39c] State change from Init -> WaitInitial server | 1.725 DEBUG [Server 559f74e3419fe39c] pn=0 type=Initial unv-path [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 296 server | -> RX Crypto { offset: 0, len: 249 } server | 1.725 DEBUG 0-RTT: no token, no 0-RTT server | 1.725 DEBUG Read secret available for Handshake: SymKey [32]: 6a1fd9096e730c10941ab4de59193e0450f27ac88d6f22b5aa18fab8e4eed897 server | 1.725 DEBUG Write secret available for Handshake: SymKey [32]: bed4f4634ed8d64f610144d7ebd10197b72301a64220a6c437d4293ceb28cb06 server | 1.725 DEBUG Writing transport parameters, msg=8 server | 1.726 DEBUG Read secret available for ApplicationData: SymKey [32]: 8d0d9c796faccec7251a81ae6ca72185b4094a538dba14238e3da333bba85a7a server | 1.726 DEBUG Write secret available for ApplicationData: SymKey [32]: b350bc3f86edd33368a3ad3cac2ad6f4b9787c29bd53b6b0a90f2dabb127fead server | 1.726 DEBUG [Agent 0x55c903663ee0] state -> InProgress server | 1.726 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865 min_pn=0 server | 1.726 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865 min_pn=0 server | 1.726 DEBUG [Crypto] Handshake keys installed server | 1.726 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865 min_pn=0 server | 1.726 DEBUG [Crypto] Application write key installed server | 1.726 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 266, tv_nsec: 735670108 } server | 1.726 DEBUG [unv-path [::]:443->[::ffff:193.167.0.100]:43919] Make permanent server | 1.726 DEBUG [unv-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919] set as primary path server | 1.726 DEBUG [Server 559f74e3419fe39c] State change from WaitInitial -> Handshaking server | 1.726 DEBUG [Server ...] Dropped received packet: Coalesced packet has different DCID; Total: 1 server | 1.726 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.726 DEBUG Building Initial dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 1.726 DEBUG CRYPTO for in offset=0, len=90 server | 1.726 DEBUG [Server 559f74e3419fe39c] pn=16 type=Initial pri-unv-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 144 server | TX -> Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | TX -> Crypto { offset: 0, len: 90 } server | 1.726 DEBUG Building Handshake dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 1.726 DEBUG CRYPTO for hs offset=0, len=725 server | 1.726 DEBUG [Server 559f74e3419fe39c] pn=0 type=Handshake pri-unv-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 917 server | TX -> Crypto { offset: 0, len: 725 } server | 1.726 DEBUG packet_sent this=0x55c9036d4c50, pn=0, ps=773 server | 1.726 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 1.726 DEBUG [Server 559f74e3419fe39c] pad Initial from 917 to PLPMTU 1232 server | 1.726 DEBUG packet_sent this=0x55c9036d4c50, pn=16, ps=459 server | 1.726 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.726 DEBUG Building Initial dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 1.726 DEBUG Building Handshake dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 1.726 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 1.726 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.726 DEBUG [Server 559f74e3419fe39c] delay duration 297.073129ms server | 1.726 DEBUG Setting timeout of 297.073129ms server | 1.726 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.726 DEBUG Building Initial dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 1.726 DEBUG Building Handshake dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 1.726 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 1.726 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.726 DEBUG [Server 559f74e3419fe39c] delay duration 297.038765ms server | 1.726 DEBUG Setting timeout of 297.038765ms server | 2.024 DEBUG [recovery::Loss] PTO timer fired for Initial server | 2.024 DEBUG [recovery::Loss] PTO timer fired for Handshake server | 2.024 DEBUG [Server 559f74e3419fe39c] Lost: Ack(AckToken { space: Initial, ranges: [PacketRange { largest: 0, smallest: 0, ack_needed: true }] }) server | 2.024 DEBUG [Recvd-in] immediate_ack at Instant { tv_sec: 266, tv_nsec: 735670108 } server | 2.024 DEBUG [Server 559f74e3419fe39c] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 0, length: 90 }) server | 2.024 INFO Lost crypto frame space=in offset=0 length=90 server | 2.024 DEBUG [Server 559f74e3419fe39c] Lost: Crypto(CryptoRecoveryToken { space: Handshake, offset: 0, length: 725 }) server | 2.024 INFO Lost crypto frame space=hs offset=0 length=725 server | 2.024 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: Some(Initial), probe: EnumSet(Initial | Handshake), paced: false } server | 2.024 DEBUG Building Initial dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.024 DEBUG CRYPTO for in offset=0, len=90 server | 2.024 DEBUG [Server 559f74e3419fe39c] pn=17 type=Initial pri-unv-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 147 server | TX -> Ack { largest_acknowledged: 0, ack_delay: 37550, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | TX -> Crypto { offset: 0, len: 90 } server | 2.024 DEBUG Building Handshake dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.024 DEBUG CRYPTO for hs offset=0, len=725 server | 2.024 DEBUG [Server 559f74e3419fe39c] pn=1 type=Handshake pri-unv-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 920 server | TX -> Crypto { offset: 0, len: 725 } server | 2.024 DEBUG packet_sent this=0x55c9036d4c50, pn=1, ps=773 server | 2.024 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 2.024 DEBUG [Server 559f74e3419fe39c] pad Initial from 920 to PLPMTU 1232 server | 2.024 DEBUG packet_sent this=0x55c9036d4c50, pn=17, ps=459 server | 2.024 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: Some(Initial), probe: EnumSet(), paced: false } server | 2.024 DEBUG Building Initial dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.024 DEBUG Building Handshake dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.024 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 2.024 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: Some(Initial), probe: EnumSet(), paced: false } server | 2.024 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1136, pto: None, probe: EnumSet(), paced: false } server | 2.024 DEBUG Building Initial dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.024 DEBUG Building Handshake dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.024 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 2.024 DEBUG TX blocked, profile=SendProfile { limit: 1136, pto: None, probe: EnumSet(), paced: false } server | 2.024 DEBUG [Server 559f74e3419fe39c] delay duration 29.699321577s server | 2.024 DEBUG Setting timeout of 29.699321577s server | 2.024 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1136, pto: None, probe: EnumSet(), paced: false } server | 2.024 DEBUG Building Initial dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.024 DEBUG Building Handshake dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.024 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 2.024 DEBUG TX blocked, profile=SendProfile { limit: 1136, pto: None, probe: EnumSet(), paced: false } server | 2.024 DEBUG [Server 559f74e3419fe39c] delay duration 29.699287564s server | 2.024 DEBUG Setting timeout of 29.699287564s client | 2025/12/13 12:25:49 connected to server4:443 server | 2.718 DEBUG [Server 559f74e3419fe39c] pn=1 type=Initial pri-unv-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 296 server | -> RX Crypto { offset: 0, len: 249 } server | 2.718 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 267, tv_nsec: 729930885 } server | 2.718 DEBUG [Server ...] Dropped received packet: Coalesced packet has different DCID; Total: 2 server | 2.718 DEBUG [recovery::Loss] PTO timer fired for Initial server | 2.718 DEBUG [recovery::Loss] PTO timer fired for Handshake server | 2.718 DEBUG [Server 559f74e3419fe39c] Lost: Ack(AckToken { space: Initial, ranges: [PacketRange { largest: 0, smallest: 0, ack_needed: true }] }) server | 2.718 DEBUG [Recvd-in] immediate_ack at Instant { tv_sec: 267, tv_nsec: 36074550 } server | 2.718 DEBUG [Server 559f74e3419fe39c] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 0, length: 90 }) server | 2.718 INFO Lost crypto frame space=in offset=0 length=90 server | 2.718 DEBUG [Server 559f74e3419fe39c] Lost: Crypto(CryptoRecoveryToken { space: Handshake, offset: 0, length: 725 }) server | 2.718 INFO Lost crypto frame space=hs offset=0 length=725 server | 2.718 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: Some(Initial), probe: EnumSet(Initial | Handshake), paced: false } server | 2.718 DEBUG Building Initial dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.718 DEBUG CRYPTO for in offset=0, len=90 server | 2.718 DEBUG [Server 559f74e3419fe39c] pn=18 type=Initial pri-unv-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 144 server | TX -> Ack { largest_acknowledged: 1, ack_delay: 0, first_ack_range: 1, ack_ranges: [], ecn_count: None } server | TX -> Crypto { offset: 0, len: 90 } server | 2.718 DEBUG Building Handshake dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.718 DEBUG CRYPTO for hs offset=0, len=725 server | 2.718 DEBUG [Server 559f74e3419fe39c] pn=2 type=Handshake pri-unv-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 917 server | TX -> Crypto { offset: 0, len: 725 } server | 2.718 DEBUG packet_sent this=0x55c9036d4c50, pn=2, ps=773 server | 2.718 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 2.718 DEBUG [Server 559f74e3419fe39c] pad Initial from 917 to PLPMTU 1232 server | 2.718 DEBUG packet_sent this=0x55c9036d4c50, pn=18, ps=459 server | 2.718 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: Some(Initial), probe: EnumSet(), paced: false } server | 2.718 DEBUG Building Initial dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.718 DEBUG Building Handshake dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.718 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 2.718 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: Some(Initial), probe: EnumSet(), paced: false } server | 2.718 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.718 DEBUG Building Initial dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.718 DEBUG Building Handshake dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.718 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 2.718 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.718 DEBUG [Server 559f74e3419fe39c] delay duration 1.199700951s server | 2.718 DEBUG Setting timeout of 1.199700951s server | 2.718 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.718 DEBUG Building Initial dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.718 DEBUG Building Handshake dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 2.718 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 2.718 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.718 DEBUG [Server 559f74e3419fe39c] delay duration 1.199662809s server | 2.718 DEBUG Setting timeout of 1.199662809s server | 3.230 DEBUG [Server 559f74e3419fe39c] pn=2 type=Initial pri-unv-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 50 server | -> RX Ack { largest_acknowledged: 16, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | 3.230 DEBUG [Server 559f74e3419fe39c] Rx ACK space=in, ranges=[16..=16] server | 3.230 DEBUG [recovery::Loss] ACK for Initial - largest_acked=16 server | 3.230 DEBUG on_packets_acked this=0x55c9036d4c50, limited=1, bytes_in_flight=3237, cwnd=12320, state=SlowStart, new_acked=459 server | 3.230 DEBUG Acked crypto frame space=in offset=0 length=90 server | 3.230 DEBUG [pri-unv-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919] Path validated Instant { tv_sec: 268, tv_nsec: 242045986 } server | 3.230 DEBUG [Server 559f74e3419fe39c] Drop packet number space in server | 3.230 DEBUG [recovery::Loss] Reset loss recovery state for Initial server | 3.230 DEBUG [Server 559f74e3419fe39c] pn=0 type=Handshake pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 88 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | -> RX Crypto { offset: 0, len: 36 } server | 3.230 DEBUG [Server 559f74e3419fe39c] Rx ACK space=hs, ranges=[0..=0] server | 3.230 DEBUG [recovery::Loss] ACK for Handshake - largest_acked=0 server | 3.230 DEBUG on_packets_acked this=0x55c9036d4c50, limited=1, bytes_in_flight=1546, cwnd=12320, state=SlowStart, new_acked=773 server | 3.230 DEBUG Acked crypto frame space=hs offset=0 length=725 server | 3.230 DEBUG [Agent 0x55c903663ee0] 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 | 3.230 DEBUG [Server 559f74e3419fe39c] TLS connection complete server | 3.230 DEBUG [pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919] Path validated Instant { tv_sec: 268, tv_nsec: 242045986 } server | 3.230 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865 min_pn=0 server | 3.230 DEBUG [Crypto] application read keys installed server | 3.230 DEBUG [Server 559f74e3419fe39c] State change from Handshaking -> Connected server | 3.230 DEBUG [Server 559f74e3419fe39c] State change from Connected -> Confirmed server | 3.230 DEBUG PMTUD started, PLPMTU is now 1280 server | 3.230 DEBUG PMTUD started with probe size 1380 server | 3.230 INFO [Server 559f74e3419fe39c] Connection established server | 3.230 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 268, tv_nsec: 242045986 } server | 3.230 DEBUG [Server 559f74e3419fe39c] pn=0 type=Short pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 1062 server | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [216, 107, 122, 68, 154, 161, 242, 197], stateless_reset_token: Token([149, 182, 127, 186, 255, 170, 215, 70, 185, 53, 136, 48, 126, 164, 172, 136]) } server | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [230, 91, 53, 85, 138, 39, 27, 231], stateless_reset_token: Token([201, 4, 127, 242, 13, 63, 201, 139, 95, 97, 53, 187, 152, 252, 221, 26]) } server | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [215, 173, 173, 125, 190, 58, 47, 228], stateless_reset_token: Token([233, 248, 142, 221, 15, 75, 31, 190, 3, 231, 35, 176, 214, 210, 51, 190]) } server | -> RX Padding { len: 950 } server | 3.230 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 268, tv_nsec: 262045986 } server | 3.230 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.230 DEBUG Building Handshake dcid Some(CID [8]: 4a398d290e68f764) scid Some(CID [10]: 8af3b4c0f300bc228758) server | 3.230 DEBUG [Server 559f74e3419fe39c] pn=3 type=Handshake pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, Ect0) len 49 server | TX -> Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | 3.230 DEBUG [Server 559f74e3419fe39c] Drop packet number space hs server | 3.230 DEBUG [recovery::Loss] Reset loss recovery state for Handshake server | 3.230 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.230 DEBUG [Server 559f74e3419fe39c] pn=0 type=Short pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, Ect0) len 1332 server | TX -> HandshakeDone server | TX -> NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [3, 95, 154, 227, 206, 103, 117, 69, 43, 228], stateless_reset_token: Token([145, 226, 98, 94, 208, 210, 99, 193, 168, 126, 205, 183, 52, 233, 58, 100]) } server | TX -> Padding { len: 1226 } server | 3.230 DEBUG packet_sent this=0x55c9036d4c50, pn=0, ps=1283 server | 3.230 DEBUG ECN probing: sent 1 probes server | 3.230 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.230 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.230 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.230 DEBUG [Server 559f74e3419fe39c] delay duration 2.476139ms server | 3.230 DEBUG Setting timeout of 2.476139ms server | 3.230 DEBUG [Server 559f74e3419fe39c] pn=1 type=Short pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 65 server | -> RX Stream { stream_id: 0, offset: 0, len: 34, fin: true } server | 3.230 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 268, tv_nsec: 242717065 } server | 3.230 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.230 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.230 DEBUG [Server 559f74e3419fe39c] pn=1 type=Short pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, Ect0) len 31 server | TX -> Ack { largest_acknowledged: 1, ack_delay: 0, first_ack_range: 1, ack_ranges: [], ecn_count: None } server | 3.230 DEBUG ECN probing: sent 2 probes server | 3.230 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.230 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.230 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.230 DEBUG [Server 559f74e3419fe39c] delay duration 4.325364ms server | 3.230 DEBUG Setting timeout of 4.325364ms server | 3.231 DEBUG [Server 559f74e3419fe39c] send session ticket 40620008559f74e3419fe39c0104800075300404802000000504801000000604801000000704801000000801100901100b01140e01080f0a8af3b4c0f300bc228758110c000000017a4a3aaa000000016ab200c0000000ff02de1a0243e820048000ffff686921 server | 3.231 DEBUG Path = 'surprised-excessive-speaker' server | 3.231 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.231 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.231 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.231 DEBUG [Server 559f74e3419fe39c] delay duration 3.234633ms server | 3.231 DEBUG Setting timeout of 3.234633ms server | 3.236 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.236 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.236 DEBUG Sending PMTUD probe of size 1380, count 1 server | 3.236 DEBUG CRYPTO for ap offset=0, len=273 server | 3.236 DEBUG [Server 559f74e3419fe39c] pn=2 type=Short pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, Ect0) len 1332 server | TX -> Ping server | TX -> Stream { stream_id: 0, offset: 0, len: 1024, fin: true } server | TX -> Crypto { offset: 0, len: 273 } server | 3.236 DEBUG packet_sent this=0x55c9036d4c50, pn=2, ps=1332 server | 3.236 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.236 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.236 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.236 DEBUG ECN probing: sent 3 probes server | 3.236 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.236 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.236 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.236 DEBUG [Server 559f74e3419fe39c] delay duration 80.42743ms server | 3.236 DEBUG Setting timeout of 80.42743ms server | 3.236 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.236 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.236 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.236 DEBUG [Server 559f74e3419fe39c] delay duration 80.400019ms server | 3.236 DEBUG Setting timeout of 80.400019ms server | 3.317 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.317 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.317 DEBUG CRYPTO for ap offset=273, len=32 server | 3.317 DEBUG [Server 559f74e3419fe39c] pn=3 type=Short pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, Ect0) len 107 server | TX -> Crypto { offset: 273, len: 32 } server | TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 51, 106, 141, 4, 196, 155, 83, 66, 122, 194, 75, 210, 176, 16, 64, 37, 134, 59, 159, 35, 120, 114, 35, 67, 187, 211, 67, 8, 57, 91, 28, 149, 209, 121, 124, 239] } server | 3.317 DEBUG packet_sent this=0x55c9036d4c50, pn=3, ps=107 server | 3.317 DEBUG ECN probing: sent 4 probes server | 3.317 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.317 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.317 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.317 DEBUG [Server 559f74e3419fe39c] delay duration 5.723925ms server | 3.317 DEBUG Setting timeout of 5.723925ms server | 3.317 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.317 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.317 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.317 DEBUG [Server 559f74e3419fe39c] delay duration 5.702735ms server | 3.317 DEBUG Setting timeout of 5.702735ms server | 3.324 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.324 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.324 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.324 DEBUG [Server 559f74e3419fe39c] delay duration 3.783724545s server | 3.324 DEBUG Setting timeout of 3.783724545s server | 3.324 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.324 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.324 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.324 DEBUG [Server 559f74e3419fe39c] delay duration 3.783703045s server | 3.324 DEBUG Setting timeout of 3.783703045s server | 3.526 DEBUG [Server ...] Dropped received packet: Decryption failure; Total: 3 server | 3.526 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.526 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.526 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.526 DEBUG [Server 559f74e3419fe39c] delay duration 3.58225778s server | 3.526 DEBUG Setting timeout of 3.58225778s server | 3.526 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.526 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 3.526 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.526 DEBUG [Server 559f74e3419fe39c] delay duration 3.582154047s server | 3.526 DEBUG Setting timeout of 3.582154047s client | 2025/12/13 12:25:50 fetched https://server4:443/surprised-excessive-speaker server | 4.220 DEBUG [Server ...] Dropped received packet: Decryption failure; Total: 4 server | 4.220 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.220 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 4.220 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.220 DEBUG [Server 559f74e3419fe39c] delay duration 2.888340006s server | 4.220 DEBUG Setting timeout of 2.888340006s server | 4.220 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.220 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 4.220 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.220 DEBUG [Server 559f74e3419fe39c] delay duration 2.888247964s server | 4.220 DEBUG Setting timeout of 2.888247964s server | 4.737 DEBUG [Server 559f74e3419fe39c] pn=2 type=Short pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 33 server | -> RX Ack { largest_acknowledged: 2, ack_delay: 0, first_ack_range: 2, ack_ranges: [], ecn_count: None } server | 4.737 DEBUG [Server 559f74e3419fe39c] Rx ACK space=ap, ranges=[0..=2] server | 4.737 DEBUG [recovery::Loss] ACK for ApplicationData - largest_acked=2 server | 4.737 DEBUG on_packets_acked this=0x55c9036d4c50, limited=1, bytes_in_flight=107, cwnd=12320, state=SlowStart, new_acked=2615 server | 4.737 DEBUG PMTUD probe of size 1380 succeeded server | 4.737 DEBUG PMTUD started with probe size 1420 server | 4.737 DEBUG PLPMTU changed from 1232 to 1332, updating pacer server | 4.737 DEBUG Acked crypto frame space=ap offset=0 length=273 server | 4.738 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.738 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 4.738 DEBUG Sending PMTUD probe of size 1420, count 1 server | 4.738 DEBUG [Server 559f74e3419fe39c] pn=4 type=Short pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, Ect0) len 1372 server | TX -> Ping server | TX -> MaxStreams { stream_type: BiDi, maximum_streams: 17 } server | TX -> Padding { len: 1343 } server | 4.738 DEBUG packet_sent this=0x55c9036d4c50, pn=4, ps=1372 server | 4.738 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.738 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 4.738 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.738 DEBUG ECN probing: sent 5 probes server | 4.738 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.738 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 4.738 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.738 DEBUG [Server 559f74e3419fe39c] delay duration 3.22974898s server | 4.738 DEBUG Setting timeout of 3.22974898s server | 4.738 DEBUG [Server 559f74e3419fe39c] pn=3 type=Short pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, NotEct) len 32 server | -> RX ConnectionClose { error_code: Transport(0), frame_type: 0, reason_phrase: "" } server | 4.738 INFO [Server 559f74e3419fe39c] ConnectionClose received. Error code: Transport(0) frame type 0 reason server | 4.738 DEBUG [Server 559f74e3419fe39c] State change from Confirmed -> Draining { error: Transport(Peer(0)), timeout: Instant { tv_sec: 279, tv_nsec: 440085452 } } server | 4.738 DEBUG [pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919] Path validated Instant { tv_sec: 269, tv_nsec: 750127569 } server | 4.738 DEBUG [Server 559f74e3419fe39c] output_dgram_on_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.738 DEBUG Building Short dcid Some(CID [8]: 4a398d290e68f764) server | 4.738 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 269, tv_nsec: 750127569 } server | 4.738 DEBUG [Server 559f74e3419fe39c] pn=5 type=Short pri-path:4a398d290e68f764 [::]:443->[::ffff:193.167.0.100]:43919 Tos(Cs0, Ect0) len 35 server | TX -> Ack { largest_acknowledged: 3, ack_delay: 0, first_ack_range: 3, ack_ranges: [], ecn_count: None } server | TX -> ConnectionClose { error_code: Transport(0), frame_type: 28, reason_phrase: "" } server | 4.738 DEBUG ECN probing: sent 6 probes server | 4.738 DEBUG Setting timeout of 9.689813104s server | 4.738 DEBUG Setting timeout of 9.689802494s 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-12-13 12:26:02,800 Using the client's key log file. 2025-12-13 12:26:02,809 2025-12-13 12:26:02,809 Using the client's key log file. 2025-12-13 12:26:02,809 Using the client's key log file. 2025-12-13 12:26:02,817 2025-12-13 12:26:02,818 Using the client's key log file. 2025-12-13 12:26:03,041 Check of downloaded files succeeded. 2025-12-13 12:26:03,933 Check of downloaded files succeeded.