2025-04-30 12:23:57,003 Generated random file: cbpzbocccp of size: 1024 2025-04-30 12:23:57,003 Requests: https://server4:443/cbpzbocccp 2025-04-30 12:23:57,062 2025-04-30 12:23:57,063 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_e51s9hh8/ TESTCASE_SERVER=handshake TESTCASE_CLIENT=handshake WWW=/tmp/www_xedc3x7t/ DOWNLOADS=/tmp/download_yugkbyu1/ SERVER_LOGS=/tmp/logs_server_zf7m2rbh CLIENT_LOGS=/tmp/logs_client_xmi_gepk SCENARIO="simple-p2p --delay=750ms --bandwidth=10Mbps --queue=25" CLIENT=aiortc/aioquic-qns:latest SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server4:443/cbpzbocccp" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-04-30 12:24:25,835 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 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 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.y0VcatHgfT server | + mkdir -p /neqo/db server | + certutil -N -d sql:/neqo/db --empty-password client | Setting up routes... client | Actual changes: client | tx-checksumming: off client | tx-checksum-ip-generic: off client | tx-checksum-sctp: off client | tcp-segmentation-offload: off client | tx-tcp-segmentation: off [requested on] client | tx-tcp-ecn-segmentation: off [requested on] client | tx-tcp-mangleid-segmentation: off [requested on] client | tx-tcp6-segmentation: off [requested on] client | tx-udp-segmentation: off [requested on] client | Endpoint's IPv4 address is 193.167.0.100 client | Endpoint's IPv6 address is fd00:cafe:cafe::100 server | + openssl pkcs12 -export -nodes -in /certs/cert.pem -inkey /certs/priv.key -name cert -passout pass: -out /tmp/tmp.y0VcatHgfT server | Warning: output encryption option -nodes ignored with -export server | + pk12util -d sql:/neqo/db -i /tmp/tmp.y0VcatHgfT -W '' client | wait-for-it.sh: waiting 30 seconds for sim:57832 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 | 5f:81:ad:2e:ac:3a:41:6c:db:b1:48:22:cf:43:f5:ea: server | f3:86:8f:1e 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 12:23:57 2025 server | Not After : Sat May 10 12:23:57 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:75:76:cc:a0:f9:ec:bd:9c:c4:2d:66:c7:6f:5b:fc: server | d3:3b:84:f4:27:03:b9:73:e2:3f:33:06:ee:27:36:0f: server | 22:4a:14:fb:b8:df:16:f2:25:b0:9b:45:bb:cd:73:ab: server | 84:19:f5:cb:d6:19:a8:58:4e:68:54:0b:ba:ec:69:6d: server | 4c 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 | 34:81:bf:9a:ac:35:6d:41:58:95:61:ae:17:c0:b2:bf: server | 92:b6:f6:fe server | server | Name: Certificate Authority Key Identifier server | Key ID: server | 41:04:da:c6:18:af:6f:67:5b:6f:42:d7:ba:0c:36:a1: server | 4a:4e:cb:25 server | server | Signature Algorithm: X9.62 ECDSA signature with SHA256 server | Signature: server | 30:44:02:20:33:bc:6b:a4:8c:81:e5:ba:a8:de:d2:29: server | a0:25:05:88:ab:d5:75:30:e3:0d:e3:7f:49:1f:8c:20: server | 0a:58:c8:01:02:20:72:86:37:a9:10:69:6f:c9:5f:f3: server | db:c0:ad:ce:50:e5:88:5c:4e:c2:fa:d4:58:01:ac:db: server | 59:f5:d6:98:f0:be server | Fingerprint (SHA-256): server | 17:F4:38:04:77:93:7F:7B:99:DB:BD:8B:51:6A:99:FD:4C:ED:1F:73:10:F2:67:4D:AB:5A:19:2C:D6:EC:C5:5D server | Fingerprint (SHA1): server | 52:F8:F1:D6:83:52:9A:1A:E9:F2:74:4A:48:1F:0D:E3:9C:6D:94:B6 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.812 DEBUG [Server] Unsupported version: 57414954 server | 0.812 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:51015 IpTos(Cs0, NotEct) len 15 sim | server:443 is available after 1.051426804s server | 0.813 DEBUG [Server] Unsupported version: 57414954 server | 0.813 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:51015 IpTos(Cs0, NotEct) len 15 server | 0.813 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" }) server | 0.813 DEBUG [Server] Unsupported version: 57414954 server | 0.813 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:51015 IpTos(Cs0, NotEct) len 15 server | 0.813 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 eth0, link-type EN10MB (Ethernet)tcpdump: , snapshot length 262144 bytes sim | listening on eth1, link-type EN10MB (Ethernet), snapshot length 262144 bytes client | wait-for-it.sh: sim:57832 is available after 1 seconds client | Starting client server | 1.921 DEBUG [Server] Handle initial server | 1.921 INFO AddressValidation: no token; accepting server | 1.921 INFO [Server] Accept connection CID [8]: 184a1fd574153dc0 server | 1.921 DEBUG Overwrite initial version Version1 ==> Version1 server | 1.923 DEBUG Outbound interface eth0 for destination ::ffff:193.167.0.100 has MTU 1500 server | 1.923 INFO [Server ...] Received valid Initial packet with scid CID [8]: 3161c27961eec383 dcid CID [8]: 184a1fd574153dc0 server | 1.923 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=184a1fd574153dc0 server | 1.923 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 server | 1.923 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 server | 1.923 DEBUG [Server 184a1fd574153dc0] State change from Init -> WaitInitial server | 1.923 DEBUG [Server 184a1fd574153dc0] pn=0 type=Initial unv-path [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 530 server | -> RX Crypto { offset: 0, len: 482 } server | 1.923 DEBUG Read Ok(482) bytes server | 1.923 DEBUG 0-RTT: no token, no 0-RTT server | 1.923 DEBUG Read secret available for Handshake: SymKey [32]: ed95e7bf9f09663ca202d99638e944ab15339f1708f669dbe61b2263910134f5 server | 1.924 DEBUG Write secret available for Handshake: SymKey [32]: 142b1e8d0edea979a10fb4a935e0708f84320b9da4d52bcc6d855efe0c3ce9f1 server | 1.924 DEBUG Writing transport parameters, msg=8 server | 1.924 DEBUG Read secret available for ApplicationData: SymKey [32]: 7df1e4d07e3d39262f2362dc156a177fe3329644d0f491ede860712435d13bad server | 1.924 DEBUG Write secret available for ApplicationData: SymKey [32]: e921817d2f03265e66f14fc9b069ee502faede5ae0fa5717c86d7968a12bd369 server | 1.924 DEBUG [Agent 0x55e0d075c1d0] state -> InProgress server | 1.924 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865 server | 1.924 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865 server | 1.924 DEBUG [Crypto] Handshake keys installed server | 1.924 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 1.924 DEBUG [Crypto] Application write key installed server | 1.924 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 481, tv_nsec: 681123515 } server | 1.924 DEBUG [unv-path [::]:443->[::ffff:193.167.0.100]:35941] Make permanent server | 1.924 DEBUG [unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941] set as primary path server | 1.924 DEBUG [Server 184a1fd574153dc0] State change from WaitInitial -> Handshaking server | 1.924 WARN [Server ...] Dropped received packet: Coalesced packet has different DCID; Total: 1 server | 1.924 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.924 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 1.924 DEBUG CRYPTO for in offset=0, len=90 server | 1.924 DEBUG [Server 184a1fd574153dc0] pn=0 type=Initial pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, Ect0) 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.924 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 1.924 DEBUG CRYPTO for hs offset=0, len=723 server | 1.924 DEBUG [Server 184a1fd574153dc0] pn=0 type=Handshake pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, Ect0) len 915 server | TX -> Crypto { offset: 0, len: 723 } server | 1.924 DEBUG packet_sent this=0x55e0d075bb40, pn=0, ps=771 server | 1.924 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 1.924 DEBUG [Server 184a1fd574153dc0] pad Initial from 915 to PLPMTU 1232 server | 1.924 DEBUG packet_sent this=0x55e0d075bb40, pn=0, ps=461 server | 1.924 DEBUG ECN probing: sent 1 probes server | 1.924 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.924 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 1.924 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 1.924 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 1.924 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.924 DEBUG [Server 184a1fd574153dc0] delay duration 297.04607ms server | 1.924 DEBUG Setting timeout of 297.04607ms server | 1.924 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.924 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 1.924 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 1.924 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 1.924 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.924 DEBUG [Server 184a1fd574153dc0] delay duration 297.00861ms server | 1.924 DEBUG Setting timeout of 297.00861ms server | 2.117 DEBUG [Server 184a1fd574153dc0] pn=1 type=Initial pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 530 server | -> RX Crypto { offset: 0, len: 482 } server | 2.117 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 481, tv_nsec: 876850426 } server | 2.117 WARN [Server ...] Dropped received packet: Coalesced packet has different DCID; Total: 2 server | 2.117 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.117 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.117 DEBUG CRYPTO for in offset=0, len=90 server | 2.117 DEBUG [Server 184a1fd574153dc0] pn=1 type=Initial pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, Ect0) 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.117 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.117 DEBUG CRYPTO for hs offset=0, len=723 server | 2.117 DEBUG [Server 184a1fd574153dc0] pn=1 type=Handshake pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, Ect0) len 915 server | TX -> Crypto { offset: 0, len: 723 } server | 2.117 DEBUG packet_sent this=0x55e0d075bb40, pn=1, ps=771 server | 2.117 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 2.117 DEBUG [Server 184a1fd574153dc0] pad Initial from 915 to PLPMTU 1232 server | 2.117 DEBUG packet_sent this=0x55e0d075bb40, pn=1, ps=461 server | 2.117 DEBUG ECN probing: sent 2 probes server | 2.117 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.117 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.117 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.117 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 2.117 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.117 DEBUG [Server 184a1fd574153dc0] delay duration 299.767477ms server | 2.117 DEBUG Setting timeout of 299.767477ms server | 2.117 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.117 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.117 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.117 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 2.117 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.117 DEBUG [Server 184a1fd574153dc0] delay duration 299.725328ms server | 2.117 DEBUG Setting timeout of 299.725328ms server | 2.418 DEBUG [LossRecovery] PTO timer fired for Initial server | 2.418 DEBUG [LossRecovery] PTO timer fired for Handshake server | 2.418 DEBUG [Server 184a1fd574153dc0] Lost: Ack(AckToken { space: Initial, ranges: [PacketRange { largest: 0, smallest: 0, ack_needed: true }] }) server | 2.418 DEBUG [Recvd-in] immediate_ack at Instant { tv_sec: 481, tv_nsec: 681123515 } server | 2.418 DEBUG [Server 184a1fd574153dc0] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 0, length: 90 }) server | 2.418 INFO Lost crypto frame space=in offset=0 length=90 server | 2.418 DEBUG [Server 184a1fd574153dc0] Lost: EcnEct0 server | 2.418 DEBUG [Server 184a1fd574153dc0] Lost: Ack(AckToken { space: Initial, ranges: [PacketRange { largest: 1, smallest: 0, ack_needed: true }] }) server | 2.418 DEBUG [Recvd-in] immediate_ack at Instant { tv_sec: 481, tv_nsec: 876850426 } server | 2.418 DEBUG [Server 184a1fd574153dc0] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 0, length: 90 }) server | 2.418 INFO Lost crypto frame space=in offset=0 length=90 server | 2.418 DEBUG [Server 184a1fd574153dc0] Lost: EcnEct0 server | 2.418 DEBUG [Server 184a1fd574153dc0] Lost: Crypto(CryptoRecoveryToken { space: Handshake, offset: 0, length: 723 }) server | 2.418 INFO Lost crypto frame space=hs offset=0 length=723 server | 2.418 DEBUG [Server 184a1fd574153dc0] Lost: Crypto(CryptoRecoveryToken { space: Handshake, offset: 0, length: 723 }) server | 2.418 INFO Lost crypto frame space=hs offset=0 length=723 server | 2.418 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: Some(Initial), probe: EnumSet(Initial | Handshake), paced: false } server | 2.418 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.418 DEBUG CRYPTO for in offset=0, len=90 server | 2.418 DEBUG [Server 184a1fd574153dc0] pn=2 type=Initial pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, Ect0) len 147 server | TX -> Ack { largest_acknowledged: 1, ack_delay: 37586, first_ack_range: 1, ack_ranges: [], ecn_count: None } server | TX -> Crypto { offset: 0, len: 90 } server | 2.418 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.418 DEBUG CRYPTO for hs offset=0, len=723 server | 2.418 DEBUG [Server 184a1fd574153dc0] pn=2 type=Handshake pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, Ect0) len 918 server | TX -> Crypto { offset: 0, len: 723 } server | 2.418 DEBUG packet_sent this=0x55e0d075bb40, pn=2, ps=771 server | 2.418 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 2.418 DEBUG [Server 184a1fd574153dc0] pad Initial from 918 to PLPMTU 1232 server | 2.418 DEBUG packet_sent this=0x55e0d075bb40, pn=2, ps=461 server | 2.418 DEBUG ECN probing: sent 3 probes server | 2.418 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.418 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.418 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.418 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 2.418 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.418 DEBUG [Server 184a1fd574153dc0] delay duration 599.742411ms server | 2.418 DEBUG Setting timeout of 599.742411ms server | 2.418 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.418 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.418 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.418 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 2.418 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.418 DEBUG [Server 184a1fd574153dc0] delay duration 599.711573ms server | 2.418 DEBUG Setting timeout of 599.711573ms server | 2.518 DEBUG [Server 184a1fd574153dc0] pn=2 type=Initial pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 530 server | -> RX Crypto { offset: 0, len: 482 } server | 2.518 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 482, tv_nsec: 277967012 } server | 2.518 WARN [Server ...] Dropped received packet: Coalesced packet has different DCID; Total: 3 server | 2.518 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.518 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.518 DEBUG CRYPTO for in offset=0, len=90 server | 2.518 DEBUG [Server 184a1fd574153dc0] pn=3 type=Initial pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, Ect0) len 144 server | TX -> Ack { largest_acknowledged: 2, ack_delay: 0, first_ack_range: 2, ack_ranges: [], ecn_count: None } server | TX -> Crypto { offset: 0, len: 90 } server | 2.518 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.518 DEBUG CRYPTO for hs offset=0, len=723 server | 2.518 DEBUG [Server 184a1fd574153dc0] pn=3 type=Handshake pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, Ect0) len 915 server | TX -> Crypto { offset: 0, len: 723 } server | 2.518 DEBUG packet_sent this=0x55e0d075bb40, pn=3, ps=771 server | 2.518 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 2.518 DEBUG [Server 184a1fd574153dc0] pad Initial from 915 to PLPMTU 1232 server | 2.518 DEBUG packet_sent this=0x55e0d075bb40, pn=3, ps=461 server | 2.518 DEBUG ECN probing: sent 4 probes server | 2.518 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.518 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.518 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.518 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 2.518 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.518 DEBUG [Server 184a1fd574153dc0] delay duration 599.747312ms server | 2.518 DEBUG Setting timeout of 599.747312ms server | 2.518 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.518 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.518 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 2.518 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 2.518 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 2.518 DEBUG [Server 184a1fd574153dc0] delay duration 599.707007ms server | 2.518 DEBUG Setting timeout of 599.707007ms server | 3.119 DEBUG [LossRecovery] PTO timer fired for Initial server | 3.119 DEBUG [LossRecovery] PTO timer fired for Handshake server | 3.119 DEBUG [Server 184a1fd574153dc0] Lost: Ack(AckToken { space: Initial, ranges: [PacketRange { largest: 1, smallest: 0, ack_needed: true }] }) server | 3.119 DEBUG [Recvd-in] immediate_ack at Instant { tv_sec: 482, tv_nsec: 177538815 } server | 3.119 DEBUG [Server 184a1fd574153dc0] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 0, length: 90 }) server | 3.119 INFO Lost crypto frame space=in offset=0 length=90 server | 3.119 DEBUG [Server 184a1fd574153dc0] Lost: EcnEct0 server | 3.119 DEBUG ECN validation failed, all 3 initial marked packets were lost server | 3.119 DEBUG [Server 184a1fd574153dc0] Lost: Ack(AckToken { space: Initial, ranges: [PacketRange { largest: 2, smallest: 0, ack_needed: true }] }) server | 3.119 DEBUG [Recvd-in] immediate_ack at Instant { tv_sec: 482, tv_nsec: 277967012 } server | 3.119 DEBUG [Server 184a1fd574153dc0] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 0, length: 90 }) server | 3.119 INFO Lost crypto frame space=in offset=0 length=90 server | 3.119 DEBUG [Server 184a1fd574153dc0] Lost: EcnEct0 server | 3.119 DEBUG [Server 184a1fd574153dc0] Lost: Crypto(CryptoRecoveryToken { space: Handshake, offset: 0, length: 723 }) server | 3.119 INFO Lost crypto frame space=hs offset=0 length=723 server | 3.119 DEBUG [Server 184a1fd574153dc0] Lost: Crypto(CryptoRecoveryToken { space: Handshake, offset: 0, length: 723 }) server | 3.119 INFO Lost crypto frame space=hs offset=0 length=723 server | 3.119 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: Some(Initial), probe: EnumSet(Initial | Handshake), paced: false } server | 3.119 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 3.119 DEBUG CRYPTO for in offset=0, len=90 server | 3.119 DEBUG [Server 184a1fd574153dc0] pn=4 type=Initial pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 147 server | TX -> Ack { largest_acknowledged: 2, ack_delay: 75133, first_ack_range: 2, ack_ranges: [], ecn_count: None } server | TX -> Crypto { offset: 0, len: 90 } server | 3.119 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 3.119 DEBUG CRYPTO for hs offset=0, len=723 server | 3.119 DEBUG [Server 184a1fd574153dc0] pn=4 type=Handshake pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 918 server | TX -> Crypto { offset: 0, len: 723 } server | 3.119 DEBUG packet_sent this=0x55e0d075bb40, pn=4, ps=771 server | 3.119 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.119 DEBUG [Server 184a1fd574153dc0] pad Initial from 918 to PLPMTU 1232 server | 3.119 DEBUG packet_sent this=0x55e0d075bb40, pn=4, ps=461 server | 3.120 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.120 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 3.120 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 3.120 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.120 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.120 DEBUG [Server 184a1fd574153dc0] delay duration 1.199719999s server | 3.120 DEBUG Setting timeout of 1.199719999s server | 3.120 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.120 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 3.120 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 3.120 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.120 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.120 DEBUG [Server 184a1fd574153dc0] delay duration 1.199682429s server | 3.120 DEBUG Setting timeout of 1.199682429s server | 3.320 DEBUG [Server 184a1fd574153dc0] pn=3 type=Initial pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 530 server | -> RX Crypto { offset: 0, len: 482 } server | 3.320 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 483, tv_nsec: 79368961 } server | 3.320 WARN [Server ...] Dropped received packet: Coalesced packet has different DCID; Total: 4 server | 3.320 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.320 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 3.320 DEBUG CRYPTO for in offset=0, len=90 server | 3.320 DEBUG [Server 184a1fd574153dc0] pn=5 type=Initial pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 144 server | TX -> Ack { largest_acknowledged: 3, ack_delay: 0, first_ack_range: 3, ack_ranges: [], ecn_count: None } server | TX -> Crypto { offset: 0, len: 90 } server | 3.320 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 3.320 DEBUG CRYPTO for hs offset=0, len=723 server | 3.320 DEBUG [Server 184a1fd574153dc0] pn=5 type=Handshake pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 915 server | TX -> Crypto { offset: 0, len: 723 } server | 3.320 DEBUG packet_sent this=0x55e0d075bb40, pn=5, ps=771 server | 3.320 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.320 DEBUG [Server 184a1fd574153dc0] pad Initial from 915 to PLPMTU 1232 server | 3.320 DEBUG packet_sent this=0x55e0d075bb40, pn=5, ps=461 server | 3.320 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.320 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 3.320 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 3.320 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.320 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.320 DEBUG [Server 184a1fd574153dc0] delay duration 1.199753802s server | 3.320 DEBUG Setting timeout of 1.199753802s server | 3.320 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.320 DEBUG Building Initial dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 3.320 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 3.320 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.320 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.320 DEBUG [Server 184a1fd574153dc0] delay duration 1.19971559s server | 3.320 DEBUG Setting timeout of 1.19971559s server | 3.429 DEBUG [Server 184a1fd574153dc0] pn=4 type=Initial pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 52 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 247, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | 3.429 DEBUG [Server 184a1fd574153dc0] Rx ACK space=in, ranges=[0..=0] server | 3.429 DEBUG [LossRecovery] ACK for Initial - largest_acked=0 server | 3.429 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 6931/12781 ssthresh 18446744073709551615] slow start += 461 server | 3.429 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 6931/12781 ssthresh 18446744073709551615] on_packets_acked this=0x55e0d075bb40, limited=0, bytes_in_flight=6931, cwnd=12781, state=SlowStart, new_acked=461 server | 3.429 DEBUG Acked crypto frame space=in offset=0 length=90 server | 3.429 DEBUG [pri-unv-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941] Path validated Instant { tv_sec: 483, tv_nsec: 189084221 } server | 3.429 DEBUG [Server 184a1fd574153dc0] Drop packet number space in server | 3.429 DEBUG [LossRecovery] Reset loss recovery state for Initial server | 3.429 DEBUG [Server 184a1fd574153dc0] pn=5 type=Handshake pri-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 91 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 247, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | -> RX Crypto { offset: 0, len: 36 } server | 3.429 DEBUG [Server 184a1fd574153dc0] Rx ACK space=hs, ranges=[0..=0] server | 3.429 DEBUG [LossRecovery] ACK for Handshake - largest_acked=0 server | 3.429 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 3855/13552 ssthresh 18446744073709551615] slow start += 771 server | 3.429 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 3855/13552 ssthresh 18446744073709551615] on_packets_acked this=0x55e0d075bb40, limited=0, bytes_in_flight=3855, cwnd=13552, state=SlowStart, new_acked=771 server | 3.429 DEBUG Acked crypto frame space=hs offset=0 length=723 server | 3.429 DEBUG Read Ok(36) bytes server | 3.430 DEBUG [Agent 0x55e0d075c1d0] 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.430 DEBUG [Server 184a1fd574153dc0] TLS connection complete server | 3.430 DEBUG [pri-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941] Path validated Instant { tv_sec: 483, tv_nsec: 189084221 } server | 3.430 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 3.430 DEBUG [Crypto] application read keys installed server | 3.430 DEBUG [Server 184a1fd574153dc0] State change from Handshaking -> Connected server | 3.430 DEBUG [Server 184a1fd574153dc0] State change from Connected -> Confirmed server | 3.430 DEBUG PMTUD started with probe size 1380 server | 3.430 INFO [Server 184a1fd574153dc0] Connection established server | 3.430 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 483, tv_nsec: 189084221 } server | 3.430 DEBUG [Server 184a1fd574153dc0] pn=6 type=Short pri-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 1057 server | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [160, 182, 211, 71, 220, 230, 24, 82], stateless_reset_token: [164, 93, 88, 132, 229, 22, 110, 221, 237, 126, 49, 10, 214, 190, 14, 173] } server | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [82, 123, 76, 197, 0, 211, 13, 181], stateless_reset_token: [7, 140, 153, 253, 229, 100, 37, 122, 164, 57, 176, 120, 228, 133, 215, 172] } server | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [215, 207, 161, 173, 243, 176, 74, 25], stateless_reset_token: [136, 69, 228, 109, 15, 224, 66, 93, 233, 29, 154, 71, 74, 74, 192, 249] } server | -> RX NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [96, 168, 99, 28, 154, 188, 20, 21], stateless_reset_token: [62, 77, 24, 54, 110, 199, 71, 208, 213, 78, 233, 169, 178, 40, 14, 221] } server | -> RX NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [100, 251, 125, 149, 250, 46, 65, 70], stateless_reset_token: [31, 58, 7, 116, 58, 156, 37, 129, 82, 65, 171, 84, 52, 41, 40, 216] } server | -> RX NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [102, 80, 94, 217, 206, 52, 88, 207], stateless_reset_token: [85, 190, 250, 156, 10, 189, 126, 249, 29, 128, 127, 13, 130, 5, 188, 106] } server | -> RX NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [139, 21, 158, 35, 110, 149, 53, 37], stateless_reset_token: [110, 74, 155, 115, 119, 8, 70, 208, 94, 215, 145, 136, 208, 14, 16, 250] } server | -> RX Padding { len: 832 } server | 3.430 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 483, tv_nsec: 189084221 } server | 3.430 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.430 DEBUG Building Handshake dcid Some(CID [8]: 3161c27961eec383) scid Some(CID [10]: fdd2bd12411cdb0b743f) server | 3.430 DEBUG [Server 184a1fd574153dc0] pn=6 type=Handshake pri-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 49 server | TX -> Ack { largest_acknowledged: 5, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | 3.430 DEBUG [Server 184a1fd574153dc0] Drop packet number space hs server | 3.430 DEBUG [LossRecovery] Reset loss recovery state for Handshake server | 3.430 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.430 DEBUG [Server 184a1fd574153dc0] pn=0 type=Short pri-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 1332 server | TX -> Ack { largest_acknowledged: 6, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | TX -> HandshakeDone server | TX -> NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [77, 24, 148, 36, 183, 235, 157, 50, 93, 167], stateless_reset_token: [44, 80, 205, 169, 116, 151, 161, 53, 16, 130, 85, 79, 142, 52, 190, 24] } server | TX -> NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [41, 163, 65, 4, 229, 228, 11, 198, 242, 192], stateless_reset_token: [113, 74, 122, 236, 126, 34, 56, 5, 143, 68, 73, 47, 150, 214, 143, 199] } server | TX -> NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [94, 238, 205, 231, 35, 215, 169, 114, 50, 122], stateless_reset_token: [157, 118, 210, 148, 200, 105, 70, 32, 147, 225, 101, 143, 27, 90, 189, 86] } server | TX -> NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [138, 59, 9, 112, 250, 134, 98, 204, 133, 103], stateless_reset_token: [242, 132, 70, 27, 128, 190, 100, 120, 216, 4, 251, 236, 204, 1, 189, 175] } server | TX -> NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [224, 231, 243, 202, 107, 121, 170, 14, 167, 245], stateless_reset_token: [209, 163, 16, 220, 87, 230, 186, 66, 226, 222, 253, 96, 222, 77, 115, 111] } server | TX -> NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [195, 68, 90, 49, 157, 120, 42, 24, 67, 159], stateless_reset_token: [149, 27, 185, 227, 232, 175, 46, 118, 183, 173, 224, 30, 120, 7, 106, 169] } server | TX -> NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [67, 205, 15, 219, 207, 248, 92, 39, 100, 82], stateless_reset_token: [155, 26, 109, 209, 33, 187, 197, 67, 238, 78, 169, 118, 22, 98, 202, 48] } server | TX -> Padding { len: 1041 } server | 3.430 DEBUG packet_sent this=0x55e0d075bb40, pn=0, ps=1283 server | 3.430 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.430 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.430 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.430 DEBUG [Server 184a1fd574153dc0] delay duration 2.125714ms server | 3.430 DEBUG Setting timeout of 2.125714ms server | 3.430 DEBUG [Server 184a1fd574153dc0] pn=7 type=Short pri-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 50 server | -> RX Stream { stream_id: 0, offset: 0, len: 17, fin: true } server | 3.430 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 483, tv_nsec: 209821153 } server | 3.430 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.430 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.430 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.430 DEBUG [Server 184a1fd574153dc0] delay duration 2.09679ms server | 3.430 DEBUG Setting timeout of 2.09679ms server | 3.431 DEBUG [Server 184a1fd574153dc0] send session ticket 40630008184a1fd574153dc00104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0afdd2bd12411cdb0b743f110c00000001aa8a7a3a000000016ab200c0000000ff02de1a0243e8200100686921 server | 3.431 DEBUG Path = 'cbpzbocccp' server | 3.431 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.431 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.431 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.431 DEBUG [Server 184a1fd574153dc0] delay duration 1.076884ms server | 3.431 DEBUG Setting timeout of 1.076884ms server | 3.433 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.433 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.433 DEBUG Sending PMTUD probe of size 1380, count 1 server | 3.433 DEBUG CRYPTO for ap offset=0, len=273 server | 3.433 DEBUG [Server 184a1fd574153dc0] pn=1 type=Short pri-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) 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.433 DEBUG packet_sent this=0x55e0d075bb40, pn=1, ps=1332 server | 3.433 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.433 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.433 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.433 DEBUG [Server 184a1fd574153dc0] delay duration 16.7863ms server | 3.433 DEBUG Setting timeout of 16.7863ms server | 3.433 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.433 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.433 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.433 DEBUG [Server 184a1fd574153dc0] delay duration 16.764429ms server | 3.433 DEBUG Setting timeout of 16.764429ms server | 3.451 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.451 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.451 DEBUG [Server 184a1fd574153dc0] pn=2 type=Short pri-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 32 server | TX -> Ack { largest_acknowledged: 7, ack_delay: 2665, first_ack_range: 1, ack_ranges: [], ecn_count: None } server | 3.451 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.451 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.451 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.451 DEBUG [Server 184a1fd574153dc0] delay duration 51.980686ms server | 3.451 DEBUG Setting timeout of 51.980686ms server | 3.451 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.451 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.451 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.451 DEBUG [Server 184a1fd574153dc0] delay duration 51.954418ms server | 3.451 DEBUG Setting timeout of 51.954418ms server | 3.505 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.505 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.505 DEBUG CRYPTO for ap offset=273, len=32 server | 3.505 DEBUG [Server 184a1fd574153dc0] pn=3 type=Short pri-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 107 server | TX -> Crypto { offset: 273, len: 32 } server | TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 229, 105, 222, 68, 2, 125, 247, 125, 101, 2, 96, 137, 192, 210, 239, 245, 207, 238, 2, 29, 181, 17, 16, 235, 55, 243, 174, 129, 56, 109, 252, 23, 46, 214, 81, 113] } server | 3.505 DEBUG packet_sent this=0x55e0d075bb40, pn=3, ps=107 server | 3.505 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.505 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.505 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.505 DEBUG [Server 184a1fd574153dc0] delay duration 4.573383ms server | 3.505 DEBUG Setting timeout of 4.573383ms server | 3.505 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.505 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.505 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 3.505 DEBUG [Server 184a1fd574153dc0] delay duration 4.545031ms server | 3.505 DEBUG Setting timeout of 4.545031ms server | 3.511 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.511 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.511 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.511 DEBUG [Server 184a1fd574153dc0] delay duration 3.783667533s server | 3.511 DEBUG Setting timeout of 3.783667533s server | 3.511 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.511 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.511 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.511 DEBUG [Server 184a1fd574153dc0] delay duration 3.783633831s server | 3.511 DEBUG Setting timeout of 3.783633831s server | 3.619 WARN [Server ...] Dropped received packet: Decryption failure; Total: 5 server | 3.619 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.619 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.619 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.619 DEBUG [Server 184a1fd574153dc0] delay duration 3.675177577s server | 3.619 DEBUG Setting timeout of 3.675177577s server | 3.619 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.619 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.620 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.620 DEBUG [Server 184a1fd574153dc0] delay duration 3.675112997s server | 3.620 DEBUG Setting timeout of 3.675112997s server | 3.630 WARN [Server ...] Dropped received packet: Decryption failure; Total: 6 server | 3.630 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.630 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.630 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.630 DEBUG [Server 184a1fd574153dc0] delay duration 3.664821315s server | 3.630 DEBUG Setting timeout of 3.664821315s server | 3.630 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.630 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.630 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.630 DEBUG [Server 184a1fd574153dc0] delay duration 3.664784957s server | 3.630 DEBUG Setting timeout of 3.664784957s server | 3.920 WARN [Server ...] Dropped received packet: Decryption failure; Total: 7 server | 3.920 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.920 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.920 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.920 DEBUG [Server 184a1fd574153dc0] delay duration 3.37431414s server | 3.920 DEBUG Setting timeout of 3.37431414s server | 3.920 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.920 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 3.920 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 3.920 DEBUG [Server 184a1fd574153dc0] delay duration 3.374235143s server | 3.920 DEBUG Setting timeout of 3.374235143s server | 4.021 WARN [Server ...] Dropped received packet: Decryption failure; Total: 8 server | 4.021 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.021 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 4.021 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.021 DEBUG [Server 184a1fd574153dc0] delay duration 3.273992508s server | 4.021 DEBUG Setting timeout of 3.273992508s server | 4.021 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.021 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 4.021 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.021 DEBUG [Server 184a1fd574153dc0] delay duration 3.273928809s server | 4.021 DEBUG Setting timeout of 3.273928809s server | 4.031 WARN [Server ...] Dropped received packet: Decryption failure; Total: 9 server | 4.031 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.031 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 4.031 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.031 DEBUG [Server 184a1fd574153dc0] delay duration 3.263592804s server | 4.031 DEBUG Setting timeout of 3.263592804s server | 4.031 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.031 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 4.031 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.031 DEBUG [Server 184a1fd574153dc0] delay duration 3.263545576s server | 4.031 DEBUG Setting timeout of 3.263545576s server | 4.622 WARN [Server ...] Dropped received packet: Decryption failure; Total: 10 server | 4.622 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.622 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 4.622 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.622 DEBUG [Server 184a1fd574153dc0] delay duration 2.672670391s server | 4.622 DEBUG Setting timeout of 2.672670391s server | 4.622 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.622 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 4.622 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.622 DEBUG [Server 184a1fd574153dc0] delay duration 2.672574953s server | 4.622 DEBUG Setting timeout of 2.672574953s server | 4.822 WARN [Server ...] Dropped received packet: Decryption failure; Total: 11 server | 4.822 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.822 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 4.822 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.822 DEBUG [Server 184a1fd574153dc0] delay duration 2.472548034s server | 4.822 DEBUG Setting timeout of 2.472548034s server | 4.822 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.822 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 4.822 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.822 DEBUG [Server 184a1fd574153dc0] delay duration 2.472472052s server | 4.822 DEBUG Setting timeout of 2.472472052s server | 4.832 WARN [Server ...] Dropped received packet: Decryption failure; Total: 12 server | 4.832 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.832 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 4.832 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.832 DEBUG [Server 184a1fd574153dc0] delay duration 2.462200226s server | 4.832 DEBUG Setting timeout of 2.462200226s server | 4.832 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.832 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 4.832 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.832 DEBUG [Server 184a1fd574153dc0] delay duration 2.462153158s server | 4.832 DEBUG Setting timeout of 2.462153158s server | 4.933 DEBUG [Server 184a1fd574153dc0] pn=16 type=Short pri-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 35 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 207, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | 4.933 DEBUG [Server 184a1fd574153dc0] Rx ACK space=ap, ranges=[0..=0] server | 4.934 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=0 server | 4.934 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 1439/14835 ssthresh 18446744073709551615] slow start += 1283 server | 4.934 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 1439/14835 ssthresh 18446744073709551615] on_packets_acked this=0x55e0d075bb40, limited=0, bytes_in_flight=1439, cwnd=14835, state=SlowStart, new_acked=1283 server | 4.934 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.934 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 4.934 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.934 DEBUG [Server 184a1fd574153dc0] delay duration 1.798008449s server | 4.934 DEBUG Setting timeout of 1.798008449s server | 4.934 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.934 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 4.934 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.934 DEBUG [Server 184a1fd574153dc0] delay duration 1.797904635s server | 4.934 DEBUG Setting timeout of 1.797904635s server | 4.935 DEBUG [Server 184a1fd574153dc0] pn=17 type=Short pri-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 33 server | -> RX ConnectionClose { error_code: Application(256), frame_type: 0, reason_phrase: "" } server | 4.935 INFO [Server 184a1fd574153dc0] ConnectionClose received. Error code: Application(256) frame type 0 reason server | 4.935 DEBUG [Server 184a1fd574153dc0] State change from Confirmed -> Draining { error: Transport(PeerApplicationError(256)), timeout: Instant { tv_sec: 494, tv_nsec: 375536830 } } server | 4.935 DEBUG [pri-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941] Path validated Instant { tv_sec: 484, tv_nsec: 695105558 } server | 4.935 DEBUG [Server 184a1fd574153dc0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 4.935 DEBUG Building Short dcid Some(CID [8]: 3161c27961eec383) server | 4.935 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 484, tv_nsec: 695105558 } server | 4.935 DEBUG [Server 184a1fd574153dc0] pn=4 type=Short pri-path:3161c27961eec383 [::]:443->[::ffff:193.167.0.100]:35941 IpTos(Cs0, NotEct) len 37 server | TX -> Ack { largest_acknowledged: 17, ack_delay: 0, first_ack_range: 1, ack_ranges: [AckRange { gap: 7, range: 1 }], ecn_count: None } server | TX -> ConnectionClose { error_code: Transport(0), frame_type: 29, reason_phrase: "" } server | 4.935 DEBUG Setting timeout of 9.680288486s server | 4.935 DEBUG Setting timeout of 9.680272546s server | 14.617 DEBUG [Server 184a1fd574153dc0] State change from Draining { error: Transport(PeerApplicationError(256)), timeout: Instant { tv_sec: 494, tv_nsec: 375536830 } } -> Closed(Transport(PeerApplicationError(256))) server | 14.617 INFO Closing timer expired 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 12:24:25,930 Using the client's key log file. 2025-04-30 12:24:25,939 2025-04-30 12:24:25,939 Using the client's key log file. 2025-04-30 12:24:25,939 Using the client's key log file. 2025-04-30 12:24:25,947 2025-04-30 12:24:25,947 Using the client's key log file. 2025-04-30 12:24:26,241 Check of downloaded files succeeded. 2025-04-30 12:24:27,436 Check of downloaded files succeeded.