2025-04-30 08:43:07,364 Generated random file: nnqxxjqknf of size: 1024 2025-04-30 08:43:07,364 Requests: https://server4:443/nnqxxjqknf 2025-04-30 08:43:07,421 2025-04-30 08:43:07,422 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_o_he8w6l/ TESTCASE_SERVER=handshake TESTCASE_CLIENT=handshake WWW=/tmp/www_2i3ihlg7/ DOWNLOADS=/tmp/download_1rxcb0zo/ SERVER_LOGS=/tmp/logs_server_58viugm4 CLIENT_LOGS=/tmp/logs_client_1w9chdc_ SCENARIO="simple-p2p --delay=750ms --bandwidth=10Mbps --queue=25" CLIENT=privateoctopus/picoquic:latest SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server4:443/nnqxxjqknf" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-04-30 08:43:23,913 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 the simulation with setup.sh server | Setting up routes... client | 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 | 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 | Endpoint's IPv4 address is 193.167.100.100 client | Endpoint's IPv4 address is 193.167.0.100 server | Endpoint's IPv6 address is fd00:cafe:cafe:100::100 client | Endpoint's IPv6 address is fd00:cafe:cafe::100 server | + export PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/neqo/bin server | + PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/neqo/bin server | + '[' -n handshake ']' server | + '[' -n /logs/qlog/ ']' server | + case "$ROLE" in server | + DB=/neqo/db server | + CERT=cert client | Setup.sh completed server | ++ mktemp client | Waiting for the simulator to start server | + P12CERT=/tmp/tmp.3h4jP7amVn 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.3h4jP7amVn server | Warning: output encryption option -nodes ignored with -export server | + pk12util -d sql:/neqo/db -i /tmp/tmp.3h4jP7amVn -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 | 35:de:9b:f3:19:68:91:1f:8c:68:26:95:0e:35:41:7a: server | e8:e7:a8:f0 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 08:43:07 2025 server | Not After : Sat May 10 08:43:07 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:fa:5d:dd:c5:51:8e:74:88:64:b9:3b:89:9f:dc:2c: server | e7:d4:c7:9a:36:bd:f8:f9:f7:c7:99:b1:0b:e0:de:ad: server | 14:0d:04:50:72:00:e3:54:cd:fd:fc:d1:1f:b9:21:48: server | db:6b:89:80:34:af:86:e3:6c:64:33:a7:f5:09:c1:1c: server | ab 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 | 2d:c0:0c:da:71:21:5f:91:cb:94:d1:f3:f8:d2:18:fc: server | 5d:0a:77:00 server | server | Name: Certificate Authority Key Identifier server | Key ID: server | fe:df:4a:e8:81:bb:a8:94:83:56:0e:a1:61:a3:51:89: server | cd:b0:1e:13 server | server | Signature Algorithm: X9.62 ECDSA signature with SHA256 server | Signature: server | 30:45:02:21:00:c3:63:b4:01:04:1d:49:d1:dc:c0:ac: server | 18:36:6b:66:0e:ab:2b:0f:b1:e8:d8:05:10:18:1d:77: server | 6b:28:46:7b:38:02:20:33:f3:0d:a5:05:58:b5:c3:63: server | 2a:1a:0b:57:43:d8:bc:04:98:f1:d4:77:7b:70:44:aa: server | a1:26:1e:0f:59:13:88 server | Fingerprint (SHA-256): server | 4D:92:1F:6C:1E:49:46:5B:E4:9B:95:A5:C6:36:49:A9:26:EE:4D:EF:25:29:C4:DE:FC:E0:85:B3:BD:04:D3:7D server | Fingerprint (SHA1): server | 1B:D5:6C:35:A3:3E:87:2A:17:7E:94:76:63:DE:89:02:43:1E:17:C6 server | server | Mozilla-CA-Policy: false (attribute missing) server | Certificate Trust Flags: server | SSL Flags: server | User server | Email Flags: server | User server | Object Signing Flags: server | User server | server | + OPTIONS=(--cc cubic --qns-test "$TESTCASE" --qlog-dir "$QLOGDIR" -d "$DB" -k "$CERT") server | + '[' 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 server | 0.734 DEBUG [Server] Unsupported version: 57414954 server | 0.734 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:33299 IpTos(Cs0, NotEct) len 15 sim | server:443 is available after 1.013607992s server | 0.734 DEBUG [Server] Unsupported version: 57414954 server | 0.734 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:33299 IpTos(Cs0, NotEct) len 15 server | 0.734 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" }) server | 0.734 DEBUG [Server] Unsupported version: 57414954 server | 0.734 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:33299 IpTos(Cs0, NotEct) len 15 server | 0.734 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" }) sim | Using scenario: simple-p2p --delay=750ms --bandwidth=10Mbps --queue=25 sim | tcpdump: listening on eth1, link-type EN10MB (Ethernet), snapshot length 262144 bytes sim | tcpdump: listening on eth0, link-type EN10MB (Ethernet), snapshot length 262144 bytes client | wait-for-it.sh: sim:57832 is available after 1 seconds client | Starting picoquic client for test: handshake client | Starting picoquic client ... client | Parsing server name from first request: https://server4:443/nnqxxjqknf client | Server set to: server4 client | Requests: https://server4:443/nnqxxjqknf client | parsing as client | Starting Picoquic (v1.1.26.1) connection to server = server4, port = 443 client | No token file present. Will create one as . client | Testing scenario: <-:/nnqxxjqknf;> client | Max stream id bidir remote before start = 0 (0) client | Starting client connection. Version = 1, I-CID: 71b58e4b57f6f5e7 client | Max stream id bidir remote after start = -4 (0) client | Waiting for packets. server | 1.730 DEBUG [Server] Handle initial server | 1.730 INFO AddressValidation: no token; accepting server | 1.730 INFO [Server] Accept connection CID [8]: 71b58e4b57f6f5e7 server | 1.730 DEBUG Overwrite initial version Version1 ==> Version1 server | 1.732 DEBUG Outbound interface eth0 for destination ::ffff:193.167.0.100 has MTU 1500 server | 1.732 INFO [Server ...] Received valid Initial packet with scid CID [8]: 3345aa01a38e276b dcid CID [8]: 71b58e4b57f6f5e7 server | 1.732 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=71b58e4b57f6f5e7 server | 1.732 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 server | 1.732 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 server | 1.732 DEBUG [Server 71b58e4b57f6f5e7] State change from Init -> WaitInitial server | 1.732 DEBUG [Server 71b58e4b57f6f5e7] pn=88529 type=Initial unv-path [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect1) len 1252 server | -> RX Ping server | -> RX Crypto { offset: 0, len: 285 } server | -> RX Padding { len: 916 } server | 1.732 DEBUG unmark 0-length range at 0 server | 1.732 DEBUG [Recvd-in] immediate_ack at Instant { tv_sec: 264, tv_nsec: 652616050 } server | 1.732 DEBUG Read Ok(285) bytes server | 1.732 DEBUG 0-RTT: no token, no 0-RTT server | 1.733 DEBUG Read secret available for Handshake: SymKey [32]: 68ba7ec284af963da17612d6d00b320380138bfb59310bee0df674963e4c9c33 server | 1.733 DEBUG Write secret available for Handshake: SymKey [32]: 54e652bf5d1691c388c1acded4c92b60d7c1a2cc1dba294a4e4029de2fb69b14 server | 1.733 DEBUG Writing transport parameters, msg=8 server | 1.733 DEBUG Read secret available for ApplicationData: SymKey [32]: 5b528789bcd58be12995d96adc79bde00c18c2e162de52352f07f569dceb868d server | 1.733 DEBUG Write secret available for ApplicationData: SymKey [32]: 5b7a61d14c15e21508b1541f572afaefea4c1e3096cd9384dc35823a33ce0a64 server | 1.733 DEBUG [Agent 0x56514a9401d0] state -> InProgress server | 1.733 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865 server | 1.733 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865 server | 1.733 DEBUG [Crypto] Handshake keys installed server | 1.733 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 1.733 DEBUG [Crypto] Application write key installed server | 1.733 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 264, tv_nsec: 652616050 } server | 1.733 DEBUG [unv-path [::]:443->[::ffff:193.167.0.100]:38670] Make permanent server | 1.733 DEBUG [unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670] set as primary path server | 1.733 DEBUG [Server 71b58e4b57f6f5e7] State change from WaitInitial -> Handshaking server | 1.733 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.733 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 1.733 DEBUG CRYPTO for in offset=0, len=123 server | 1.733 DEBUG [Server 71b58e4b57f6f5e7] pn=0 type=Initial pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect0) len 183 server | TX -> Ack { largest_acknowledged: 88529, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 1, Ect0: 0, Ce: 0})) } server | TX -> Crypto { offset: 0, len: 123 } server | 1.733 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 1.733 DEBUG CRYPTO for hs offset=0, len=722 server | 1.733 DEBUG [Server 71b58e4b57f6f5e7] pn=0 type=Handshake pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect0) len 953 server | TX -> Crypto { offset: 0, len: 722 } server | 1.733 DEBUG packet_sent this=0x56514a93fb40, pn=0, ps=770 server | 1.733 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 1.733 DEBUG [Server 71b58e4b57f6f5e7] pad Initial from 953 to PLPMTU 1232 server | 1.733 DEBUG packet_sent this=0x56514a93fb40, pn=0, ps=462 server | 1.733 DEBUG ECN probing: sent 1 probes server | 1.734 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.734 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 1.734 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 1.734 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 1.734 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.734 DEBUG [Server 71b58e4b57f6f5e7] delay duration 296.674688ms server | 1.734 DEBUG Setting timeout of 296.674688ms server | 1.734 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.734 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 1.734 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 1.734 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 1.734 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.734 DEBUG [Server 71b58e4b57f6f5e7] delay duration 296.638881ms server | 1.734 DEBUG Setting timeout of 296.638881ms server | 1.975 DEBUG [Server 71b58e4b57f6f5e7] pn=88530 type=Initial pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect1) len 1252 server | -> RX Ping server | -> RX Crypto { offset: 0, len: 285 } server | -> RX Padding { len: 916 } server | 1.975 DEBUG [Recvd-in] immediate_ack at Instant { tv_sec: 264, tv_nsec: 897861317 } server | 1.976 DEBUG unmark 0-length range at 0 server | 1.976 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 264, tv_nsec: 897861317 } server | 1.976 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.976 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 1.976 DEBUG CRYPTO for in offset=0, len=123 server | 1.976 DEBUG [Server 71b58e4b57f6f5e7] pn=1 type=Initial pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect0) len 183 server | TX -> Ack { largest_acknowledged: 88530, ack_delay: 0, first_ack_range: 1, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 2, Ect0: 0, Ce: 0})) } server | TX -> Crypto { offset: 0, len: 123 } server | 1.976 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 1.976 DEBUG CRYPTO for hs offset=0, len=722 server | 1.976 DEBUG [Server 71b58e4b57f6f5e7] pn=1 type=Handshake pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect0) len 953 server | TX -> Crypto { offset: 0, len: 722 } server | 1.976 DEBUG packet_sent this=0x56514a93fb40, pn=1, ps=770 server | 1.976 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 1.976 DEBUG [Server 71b58e4b57f6f5e7] pad Initial from 953 to PLPMTU 1232 server | 1.976 DEBUG packet_sent this=0x56514a93fb40, pn=1, ps=462 server | 1.976 DEBUG ECN probing: sent 2 probes server | 1.976 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.976 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 1.976 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 1.976 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 1.976 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.976 DEBUG [Server 71b58e4b57f6f5e7] delay duration 299.764209ms server | 1.976 DEBUG Setting timeout of 299.764209ms server | 1.976 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.976 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 1.976 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 1.976 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 1.976 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.976 DEBUG [Server 71b58e4b57f6f5e7] delay duration 299.724325ms server | 1.976 DEBUG Setting timeout of 299.724325ms server | 2.277 DEBUG [LossRecovery] PTO timer fired for Initial server | 2.277 DEBUG [LossRecovery] PTO timer fired for Handshake server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] Lost: Ack(AckToken { space: Initial, ranges: [PacketRange { largest: 88529, smallest: 88529, ack_needed: true }] }) server | 2.277 DEBUG [Recvd-in] immediate_ack at Instant { tv_sec: 264, tv_nsec: 652616050 } server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 0, length: 123 }) server | 2.277 INFO Lost crypto frame space=in offset=0 length=123 server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] Lost: EcnEct0 server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] Lost: Ack(AckToken { space: Initial, ranges: [PacketRange { largest: 88530, smallest: 88529, ack_needed: true }] }) server | 2.277 DEBUG [Recvd-in] immediate_ack at Instant { tv_sec: 264, tv_nsec: 897861317 } server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 0, length: 123 }) server | 2.277 INFO Lost crypto frame space=in offset=0 length=123 server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] Lost: EcnEct0 server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] Lost: Crypto(CryptoRecoveryToken { space: Handshake, offset: 0, length: 722 }) server | 2.277 INFO Lost crypto frame space=hs offset=0 length=722 server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] Lost: Crypto(CryptoRecoveryToken { space: Handshake, offset: 0, length: 722 }) server | 2.277 INFO Lost crypto frame space=hs offset=0 length=722 server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: Some(Initial), probe: EnumSet(Initial | Handshake), paced: false } server | 2.277 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.277 DEBUG CRYPTO for in offset=0, len=123 server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] pn=2 type=Initial pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect0) len 186 server | TX -> Ack { largest_acknowledged: 88530, ack_delay: 37714, first_ack_range: 1, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 2, Ect0: 0, Ce: 0})) } server | TX -> Crypto { offset: 0, len: 123 } server | 2.277 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.277 DEBUG CRYPTO for hs offset=0, len=722 server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] pn=2 type=Handshake pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect0) len 956 server | TX -> Crypto { offset: 0, len: 722 } server | 2.277 DEBUG packet_sent this=0x56514a93fb40, pn=2, ps=770 server | 2.277 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] pad Initial from 956 to PLPMTU 1232 server | 2.277 DEBUG packet_sent this=0x56514a93fb40, pn=2, ps=462 server | 2.277 DEBUG ECN probing: sent 3 probes server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.277 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.277 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.277 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 2.277 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] delay duration 599.761795ms server | 2.277 DEBUG Setting timeout of 599.761795ms server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.277 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.277 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.277 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 2.277 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.277 DEBUG [Server 71b58e4b57f6f5e7] delay duration 599.725968ms server | 2.277 DEBUG Setting timeout of 599.725968ms server | 2.476 DEBUG [Server 71b58e4b57f6f5e7] pn=88531 type=Initial pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect1) len 1252 server | -> RX Ping server | -> RX Crypto { offset: 0, len: 285 } server | -> RX Padding { len: 916 } server | 2.476 DEBUG [Recvd-in] immediate_ack at Instant { tv_sec: 265, tv_nsec: 398447091 } server | 2.476 DEBUG unmark 0-length range at 0 server | 2.476 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 265, tv_nsec: 398447091 } server | 2.476 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.476 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.476 DEBUG CRYPTO for in offset=0, len=123 server | 2.476 DEBUG [Server 71b58e4b57f6f5e7] pn=3 type=Initial pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect0) len 183 server | TX -> Ack { largest_acknowledged: 88531, ack_delay: 0, first_ack_range: 2, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 3, Ect0: 0, Ce: 0})) } server | TX -> Crypto { offset: 0, len: 123 } server | 2.476 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.476 DEBUG CRYPTO for hs offset=0, len=722 server | 2.476 DEBUG [Server 71b58e4b57f6f5e7] pn=3 type=Handshake pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect0) len 953 server | TX -> Crypto { offset: 0, len: 722 } server | 2.476 DEBUG packet_sent this=0x56514a93fb40, pn=3, ps=770 server | 2.476 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 2.476 DEBUG [Server 71b58e4b57f6f5e7] pad Initial from 953 to PLPMTU 1232 server | 2.476 DEBUG packet_sent this=0x56514a93fb40, pn=3, ps=462 server | 2.476 DEBUG ECN probing: sent 4 probes server | 2.476 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.476 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.476 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.476 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 2.476 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.476 DEBUG [Server 71b58e4b57f6f5e7] delay duration 599.800337ms server | 2.476 DEBUG Setting timeout of 599.800337ms server | 2.476 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.476 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.476 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.476 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 2.476 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.476 DEBUG [Server 71b58e4b57f6f5e7] delay duration 599.759069ms server | 2.476 DEBUG Setting timeout of 599.759069ms client | Client port (AF=2): 3735. client | Negotiated ALPN: hq-interop client | Almost ready! client | client | Connection established. Version = 1, I-CID: 71b58e4b57f6f5e7, verified: 1 client | Opening stream 0 to GET /nnqxxjqknf server | 2.977 DEBUG [Server 71b58e4b57f6f5e7] pn=88532 type=Initial pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect1) len 1252 server | -> RX Ping server | -> RX Crypto { offset: 0, len: 285 } server | -> RX Padding { len: 916 } server | 2.977 DEBUG [Recvd-in] immediate_ack at Instant { tv_sec: 265, tv_nsec: 899054217 } server | 2.977 DEBUG unmark 0-length range at 0 server | 2.977 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 265, tv_nsec: 899054217 } server | 2.977 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.977 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.977 DEBUG CRYPTO for in offset=0, len=123 server | 2.977 DEBUG [Server 71b58e4b57f6f5e7] pn=4 type=Initial pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect0) len 183 server | TX -> Ack { largest_acknowledged: 88532, ack_delay: 0, first_ack_range: 3, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 4, Ect0: 0, Ce: 0})) } server | TX -> Crypto { offset: 0, len: 123 } server | 2.977 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.977 DEBUG CRYPTO for hs offset=0, len=722 server | 2.977 DEBUG [Server 71b58e4b57f6f5e7] pn=4 type=Handshake pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect0) len 953 server | TX -> Crypto { offset: 0, len: 722 } server | 2.977 DEBUG packet_sent this=0x56514a93fb40, pn=4, ps=770 server | 2.977 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 2.977 DEBUG [Server 71b58e4b57f6f5e7] pad Initial from 953 to PLPMTU 1232 server | 2.977 DEBUG packet_sent this=0x56514a93fb40, pn=4, ps=462 server | 2.977 DEBUG ECN probing: sent 5 probes server | 2.977 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.977 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.977 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.977 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 2.977 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.977 DEBUG [Server 71b58e4b57f6f5e7] delay duration 599.755333ms server | 2.977 DEBUG Setting timeout of 599.755333ms server | 2.977 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.977 DEBUG Building Initial dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.977 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 2.977 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 2.977 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.977 DEBUG [Server 71b58e4b57f6f5e7] delay duration 599.713795ms server | 2.977 DEBUG Setting timeout of 599.713795ms server | 3.236 DEBUG [Server 71b58e4b57f6f5e7] Drop packet number space in server | 3.236 DEBUG [LossRecovery] Reset loss recovery state for Initial server | 3.236 INFO [pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670] discarding a packet without an RTT estimate; guessing RTT=1.505653253s server | 3.236 DEBUG [Server 71b58e4b57f6f5e7] pn=0 type=Handshake pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect1) len 94 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 44, 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 | 3.236 DEBUG [Server 71b58e4b57f6f5e7] Rx ACK space=hs, ranges=[0..=0] server | 3.236 DEBUG [LossRecovery] ACK for Handshake - largest_acked=0 server | 3.236 DEBUG on_packets_acked this=0x56514a93fb40, limited=1, bytes_in_flight=3080, cwnd=12320, state=SlowStart, new_acked=770 server | 3.236 DEBUG Acked crypto frame space=hs offset=0 length=722 server | 3.236 DEBUG Read Ok(36) bytes server | 3.236 DEBUG [Agent 0x56514a9401d0] state -> Complete(SecretAgentInfo { version: 772, cipher: 4865, group: 23, resumed: false, early_data: false, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 }) server | 3.236 DEBUG [Server 71b58e4b57f6f5e7] TLS connection complete server | 3.236 DEBUG [pri-unv-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670] Path validated Instant { tv_sec: 266, tv_nsec: 158269303 } server | 3.236 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 3.236 DEBUG [Crypto] application read keys installed server | 3.236 DEBUG [Server 71b58e4b57f6f5e7] State change from Handshaking -> Connected server | 3.236 DEBUG [Server 71b58e4b57f6f5e7] State change from Connected -> Confirmed server | 3.236 DEBUG PMTUD started with probe size 1380 server | 3.236 INFO [Server 71b58e4b57f6f5e7] Connection established server | 3.236 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 266, tv_nsec: 158269303 } server | 3.236 DEBUG [Server 71b58e4b57f6f5e7] pn=0 type=Short pri-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect1) len 311 server | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [69, 122, 218, 11, 167, 238, 35, 121], stateless_reset_token: [15, 8, 255, 80, 218, 206, 249, 253, 155, 46, 151, 2, 175, 32, 24, 159] } server | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [1, 67, 146, 104, 12, 36, 175, 141], stateless_reset_token: [153, 32, 99, 8, 174, 59, 45, 60, 45, 135, 85, 232, 27, 54, 46, 231] } server | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [165, 178, 138, 156, 18, 9, 120, 241], stateless_reset_token: [224, 8, 207, 200, 131, 10, 240, 204, 15, 119, 104, 216, 184, 175, 125, 218] } server | -> RX NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [34, 134, 253, 242, 75, 218, 6, 219], stateless_reset_token: [10, 214, 40, 141, 21, 142, 146, 45, 144, 229, 124, 185, 97, 61, 173, 217] } server | -> RX NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [246, 0, 115, 216, 238, 213, 103, 200], stateless_reset_token: [233, 219, 253, 184, 42, 149, 238, 227, 164, 240, 193, 222, 163, 48, 16, 224] } server | -> RX NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [18, 233, 68, 114, 180, 113, 49, 25], stateless_reset_token: [149, 206, 74, 189, 234, 223, 251, 18, 17, 165, 214, 228, 220, 37, 129, 237] } server | -> RX NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [112, 183, 172, 22, 175, 78, 239, 191], stateless_reset_token: [204, 188, 90, 169, 127, 69, 186, 106, 241, 217, 64, 22, 130, 119, 132, 53] } server | -> RX Padding { len: 87 } server | 3.236 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 266, tv_nsec: 178269303 } server | 3.236 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.236 DEBUG Building Handshake dcid Some(CID [8]: 3345aa01a38e276b) scid Some(CID [10]: d0a1f55a9ba73f945888) server | 3.236 DEBUG [Server 71b58e4b57f6f5e7] pn=5 type=Handshake pri-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 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: 1, Ect0: 0, Ce: 0})) } server | 3.236 DEBUG [Server 71b58e4b57f6f5e7] Drop packet number space hs server | 3.236 DEBUG [LossRecovery] Reset loss recovery state for Handshake server | 3.236 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.236 DEBUG [Server 71b58e4b57f6f5e7] pn=0 type=Short pri-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect0) len 1332 server | TX -> HandshakeDone server | TX -> NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [82, 180, 198, 250, 124, 45, 79, 95, 127, 9], stateless_reset_token: [89, 108, 43, 88, 11, 233, 15, 11, 150, 119, 23, 129, 180, 82, 142, 77] } server | TX -> NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [53, 157, 208, 227, 212, 30, 93, 215, 178, 21], stateless_reset_token: [183, 232, 248, 144, 197, 206, 62, 210, 64, 163, 173, 165, 127, 224, 185, 130] } server | TX -> NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [158, 215, 220, 65, 230, 244, 107, 18, 144, 36], stateless_reset_token: [27, 93, 53, 238, 240, 38, 174, 153, 19, 5, 160, 162, 150, 219, 214, 111] } server | TX -> NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [82, 186, 24, 114, 161, 89, 98, 77, 24, 179], stateless_reset_token: [159, 167, 112, 21, 25, 181, 5, 179, 33, 109, 109, 217, 221, 49, 138, 27] } server | TX -> NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [76, 161, 241, 166, 186, 91, 166, 27, 117, 137], stateless_reset_token: [99, 177, 251, 93, 25, 136, 93, 16, 178, 73, 49, 208, 126, 39, 13, 55] } server | TX -> NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [84, 211, 82, 88, 30, 228, 46, 76, 47, 36], stateless_reset_token: [33, 218, 228, 170, 203, 18, 130, 143, 137, 153, 249, 66, 145, 131, 179, 201] } server | TX -> NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [73, 30, 157, 24, 18, 244, 236, 197, 185, 244], stateless_reset_token: [192, 42, 38, 44, 45, 82, 31, 6, 82, 212, 62, 207, 31, 216, 21, 196] } server | TX -> Padding { len: 1043 } server | 3.237 DEBUG packet_sent this=0x56514a93fb40, pn=0, ps=1280 server | 3.237 DEBUG ECN probing: sent 6 probes server | 3.237 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.237 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.237 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.237 DEBUG [Server 71b58e4b57f6f5e7] delay duration 2.168873ms server | 3.237 DEBUG Setting timeout of 2.168873ms server | 3.237 DEBUG [Server 71b58e4b57f6f5e7] pn=1 type=Short pri-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect1) len 55 server | -> RX Stream { stream_id: 0, offset: 0, len: 17, fin: true } server | -> RX Padding { len: 7 } server | 3.237 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 266, tv_nsec: 159063467 } server | 3.237 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.237 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.237 DEBUG [Server 71b58e4b57f6f5e7] pn=1 type=Short pri-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 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: 2, Ect0: 0, Ce: 0})) } server | 3.237 DEBUG ECN probing: sent 7 probes server | 3.237 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.237 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.237 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.237 DEBUG [Server 71b58e4b57f6f5e7] delay duration 4.192556ms server | 3.237 DEBUG Setting timeout of 4.192556ms server | 3.238 DEBUG [Server 71b58e4b57f6f5e7] send session ticket 4063000871b58e4b57f6f5e70104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0ad0a1f55a9ba73f945888110c000000018afa6a0a000000016ab200c0000000ff02de1a0243e8200100686921 server | 3.238 DEBUG Path = 'nnqxxjqknf' server | 3.238 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.238 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.238 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.238 DEBUG [Server 71b58e4b57f6f5e7] delay duration 3.202777ms server | 3.238 DEBUG Setting timeout of 3.202777ms server | 3.242 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.242 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.242 DEBUG Sending PMTUD probe of size 1380, count 1 server | 3.242 DEBUG CRYPTO for ap offset=0, len=273 server | 3.242 DEBUG [Server 71b58e4b57f6f5e7] pn=2 type=Short pri-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(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.242 DEBUG packet_sent this=0x56514a93fb40, pn=2, ps=1332 server | 3.242 DEBUG ECN probing: sent 8 probes server | 3.242 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.242 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.242 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.242 DEBUG [Server 71b58e4b57f6f5e7] delay duration 75.210147ms server | 3.242 DEBUG Setting timeout of 75.210147ms server | 3.242 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.242 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.242 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.242 DEBUG [Server 71b58e4b57f6f5e7] delay duration 75.189318ms server | 3.242 DEBUG Setting timeout of 75.189318ms server | 3.318 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.318 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.318 DEBUG CRYPTO for ap offset=273, len=32 server | 3.318 DEBUG [Server 71b58e4b57f6f5e7] pn=3 type=Short pri-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect0) len 107 server | TX -> Crypto { offset: 273, len: 32 } server | TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 204, 202, 29, 53, 212, 33, 98, 131, 34, 82, 88, 141, 253, 116, 195, 149, 62, 234, 12, 122, 172, 59, 183, 236, 46, 227, 90, 228, 41, 182, 168, 19, 226, 27, 9, 87] } server | 3.318 DEBUG packet_sent this=0x56514a93fb40, pn=3, ps=107 server | 3.318 DEBUG ECN probing: sent 9 probes server | 3.318 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.318 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.318 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.318 DEBUG [Server 71b58e4b57f6f5e7] delay duration 5.474419ms server | 3.318 DEBUG Setting timeout of 5.474419ms server | 3.318 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.318 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.318 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.318 DEBUG [Server 71b58e4b57f6f5e7] delay duration 5.453761ms server | 3.318 DEBUG Setting timeout of 5.453761ms server | 3.325 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.325 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.325 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.325 DEBUG [Server 71b58e4b57f6f5e7] delay duration 3.766938035s server | 3.325 DEBUG Setting timeout of 3.766938035s server | 3.325 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.325 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.325 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.325 DEBUG [Server 71b58e4b57f6f5e7] delay duration 3.766918769s server | 3.325 DEBUG Setting timeout of 3.766918769s server | 3.478 WARN [Server ...] Dropped received packet: Decryption failure; Total: 1 server | 3.478 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.478 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.478 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.478 DEBUG [Server 71b58e4b57f6f5e7] delay duration 3.614655902s server | 3.478 DEBUG Setting timeout of 3.614655902s server | 3.478 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.478 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.478 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.478 DEBUG [Server 71b58e4b57f6f5e7] delay duration 3.61458538s server | 3.478 DEBUG Setting timeout of 3.61458538s server | 3.779 WARN [Server ...] Dropped received packet: Decryption failure; Total: 2 server | 3.779 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.779 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.779 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.779 DEBUG [Server 71b58e4b57f6f5e7] delay duration 3.313099509s server | 3.779 DEBUG Setting timeout of 3.313099509s server | 3.779 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.779 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.779 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.779 DEBUG [Server 71b58e4b57f6f5e7] delay duration 3.313040138s server | 3.779 DEBUG Setting timeout of 3.313040138s server | 3.978 WARN [Server ...] Dropped received packet: Decryption failure; Total: 3 server | 3.978 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.978 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.978 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.978 DEBUG [Server 71b58e4b57f6f5e7] delay duration 3.114182275s server | 3.978 DEBUG Setting timeout of 3.114182275s server | 3.978 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.978 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 3.978 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.978 DEBUG [Server 71b58e4b57f6f5e7] delay duration 3.11413628s server | 3.978 DEBUG Setting timeout of 3.11413628s client | Stream 0 ended after 1024 bytes client | All done, Closing the connection. server | 4.479 WARN [Server ...] Dropped received packet: Decryption failure; Total: 4 server | 4.479 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.479 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 4.479 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.479 DEBUG [Server 71b58e4b57f6f5e7] delay duration 2.613457761s server | 4.479 DEBUG Setting timeout of 2.613457761s server | 4.479 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.479 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 4.479 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.479 DEBUG [Server 71b58e4b57f6f5e7] delay duration 2.613397579s server | 4.479 DEBUG Setting timeout of 2.613397579s server | 4.744 DEBUG [Server 71b58e4b57f6f5e7] pn=2 type=Short pri-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect1) len 39 server | -> RX Ack { largest_acknowledged: 2, ack_delay: 20, first_ack_range: 2, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 3, Ce: 0})) } server | -> RX ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "" } server | 4.744 DEBUG [Server 71b58e4b57f6f5e7] Rx ACK space=ap, ranges=[0..=2] server | 4.744 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=2 server | 4.744 DEBUG on_packets_acked this=0x56514a93fb40, limited=1, bytes_in_flight=107, cwnd=12320, state=SlowStart, new_acked=2612 server | 4.744 DEBUG PMTUD probe of size 1380 succeeded server | 4.744 DEBUG PMTUD started with probe size 1420 server | 4.744 DEBUG PLPMTU changed from 1232 to 1332, updating pacer server | 4.744 DEBUG Acked crypto frame space=ap offset=0 length=273 server | 4.744 INFO [Server 71b58e4b57f6f5e7] ConnectionClose received. Error code: Application(0) frame type 0 reason server | 4.744 DEBUG [Server 71b58e4b57f6f5e7] State change from Confirmed -> Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 277, tv_nsec: 304420179 } } server | 4.744 DEBUG [pri-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670] Path validated Instant { tv_sec: 267, tv_nsec: 666184252 } server | 4.744 DEBUG [Server 71b58e4b57f6f5e7] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 4.744 DEBUG Building Short dcid Some(CID [8]: 3345aa01a38e276b) server | 4.744 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 267, tv_nsec: 666184252 } server | 4.744 DEBUG [Server 71b58e4b57f6f5e7] pn=4 type=Short pri-path:3345aa01a38e276b [::]:443->[::ffff:193.167.0.100]:38670 IpTos(Cs0, Ect0) len 38 server | TX -> Ack { largest_acknowledged: 2, ack_delay: 0, first_ack_range: 2, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 3, Ect0: 0, Ce: 0})) } server | TX -> ConnectionClose { error_code: Transport(0), frame_type: 29, reason_phrase: "" } server | 4.744 DEBUG ECN probing: sent 10 probes server | 4.744 DEBUG ECN probing concluded with 10 probes sent server | 4.744 DEBUG Setting timeout of 9.638027938s server | 4.744 DEBUG Setting timeout of 9.638013111s client | Received a request to close the connection. client | The connection is closed! client | Address Discovery mode: 0 / 0 (0:0) client | Quic Bit was greased by the client. client | Quic Bit was greased by the server. client | ECN was received (ect0: 4, ect1: 0, ce: 0). client | ECN was acknowledged (ect0: 0, ect1: 2, ce: 0). client | Received 1024 bytes in 4.522690 seconds, 0.001811 Mbps. client | Sent 17 bytes in 4.522690 seconds, 0.000030 Mbps. client | max_data_local: 1048576 client | max_stream_data_local: 2097152 client | max_data_remote: 4611686018427387903 client | max_stream_data_remote: 1048576 client | ack_delay_remote: 1000 ... 10000 client | max_ack_gap_remote: 2 client | ack_delay_local: 25000 ... 25000 client | max_ack_gap_local: 2 client | max_mtu_sent: 1252 client | max_mtu_received: 1332 client | System call duration max: 6 client | System call duration smoothed: 0 client | System call duration deviation: 0 client | Client exit with code = 0 client exited with code 0 Aborting on container exit... Container client Stopping Container server Stopping Container client Stopped Container server Stopped Container sim Stopping Container sim Stopped 2025-04-30 08:43:24,007 Using the client's key log file. 2025-04-30 08:43:24,016 2025-04-30 08:43:24,016 Using the client's key log file. 2025-04-30 08:43:24,016 Using the client's key log file. 2025-04-30 08:43:24,024 2025-04-30 08:43:24,024 Using the client's key log file. 2025-04-30 08:43:24,309 Check of downloaded files succeeded. 2025-04-30 08:43:25,511 Check of downloaded files succeeded.