2025-04-30 12:23:19,292 Generated random file: vpzzxwctjj of size: 1024 2025-04-30 12:23:19,293 Requests: https://server4:443/vpzzxwctjj 2025-04-30 12:23:19,350 2025-04-30 12:23:19,350 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_p5ykljl8/ TESTCASE_SERVER=handshake TESTCASE_CLIENT=handshake WWW=/tmp/www_nln5640p/ DOWNLOADS=/tmp/download_ymufxken/ SERVER_LOGS=/tmp/logs_server_k964hdun CLIENT_LOGS=/tmp/logs_client_hyfjpxyi SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=aiortc/aioquic-qns:latest SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server4:443/vpzzxwctjj" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-04-30 12:23:31,966 Container sim Recreate Container sim Recreated Container server Recreate Container client Recreate Container server Recreated Container client 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 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 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.jW3RxJd4IF server | + mkdir -p /neqo/db client | Endpoint's IPv6 address is fd00:cafe:cafe::100 server | + certutil -N -d sql:/neqo/db --empty-password server | + openssl pkcs12 -export -nodes -in /certs/cert.pem -inkey /certs/priv.key -name cert -passout pass: -out /tmp/tmp.jW3RxJd4IF server | Warning: output encryption option -nodes ignored with -export client | wait-for-it.sh: waiting 30 seconds for sim:57832 server | + pk12util -d sql:/neqo/db -i /tmp/tmp.jW3RxJd4IF -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 | 43:b7:48:28:45:43:b1:d1:bb:8d:43:c1:07:23:a9:2f: server | ad:6c:3e:51 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:19 2025 server | Not After : Sat May 10 12:23:19 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:92:2a:16:55:b9:c1:97:45:14:d6:9c:71:6b:25:b0: server | 18:58:90:99:52:47:95:1c:9b:d8:e3:ff:69:8c:18:55: server | 87:c0:35:78:cc:27:08:1c:59:20:48:eb:75:13:a1:a8: server | fc:85:09:26:76:b6:2e:cc:a9:12:8c:48:ab:d5:5c:84: server | cc 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 | 8d:ff:94:cf:39:2f:e4:3f:e0:4f:2b:0f:95:17:d8:fb: server | d7:d3:f4:aa server | server | Name: Certificate Authority Key Identifier server | Key ID: server | a2:c0:a8:a4:a5:a0:60:6c:62:10:39:1b:96:35:9c:42: server | b0:c2:9e:c4 server | server | Signature Algorithm: X9.62 ECDSA signature with SHA256 server | Signature: server | 30:45:02:21:00:ca:dc:01:38:f5:6d:c1:6c:aa:49:72: server | 16:24:ce:ab:e1:ac:c0:5b:6a:cb:d9:07:75:1b:a4:70: server | 52:62:cf:1d:b8:02:20:05:40:58:77:55:05:35:94:43: server | cb:41:1f:a0:5f:9f:ef:c9:a6:5a:d9:44:33:0f:4e:79: server | ff:f1:07:20:6a:f4:c8 server | Fingerprint (SHA-256): server | 2B:00:64:84:F7:AD:15:49:20:FE:69:1D:85:8F:D1:99:D7:81:53:2B:22:A1:14:5D:F7:72:7B:05:F1:51:A9:ED server | Fingerprint (SHA1): server | B2:5F:AD:68:37:86:6D:99:3C:65:7B:60:EB:D3:E7:0F:49:DD:3D:B9 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.798 DEBUG [Server] Unsupported version: 57414954 server | 0.798 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:39227 IpTos(Cs0, NotEct) len 15 sim | server:443 is available after 1.048473279s server | 0.799 DEBUG [Server] Unsupported version: 57414954 server | 0.799 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:39227 IpTos(Cs0, NotEct) len 15 server | 0.799 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" }) server | 0.799 DEBUG [Server] Unsupported version: 57414954 server | 0.799 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:39227 IpTos(Cs0, NotEct) len 15 server | 0.799 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" }) sim | Using scenario: simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25 sim | tcpdump: listening on eth0, link-type EN10MB (Ethernet)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.180 DEBUG [Server] Handle initial server | 1.180 INFO AddressValidation: no token; accepting server | 1.180 INFO [Server] Accept connection CID [8]: 98dc6efca6a62cfc server | 1.180 DEBUG Overwrite initial version Version1 ==> Version1 server | 1.181 DEBUG Outbound interface eth0 for destination ::ffff:193.167.0.100 has MTU 1500 server | 1.181 INFO [Server ...] Received valid Initial packet with scid CID [8]: 72a250dd75d60448 dcid CID [8]: 98dc6efca6a62cfc server | 1.181 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=98dc6efca6a62cfc server | 1.181 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 server | 1.181 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 server | 1.181 DEBUG [Server 98dc6efca6a62cfc] State change from Init -> WaitInitial server | 1.181 DEBUG [Server 98dc6efca6a62cfc] pn=0 type=Initial unv-path [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, NotEct) len 530 server | -> RX Crypto { offset: 0, len: 482 } server | 1.181 DEBUG Read Ok(482) bytes server | 1.181 DEBUG 0-RTT: no token, no 0-RTT server | 1.182 DEBUG Read secret available for Handshake: SymKey [32]: 8d357c2f4b66e23c2a2e3a6fdc71485e34bc43112b960d6d5bfcee4daff92fee server | 1.182 DEBUG Write secret available for Handshake: SymKey [32]: e35b2aa08400bcaefef8f85a94bc2b69dcbb8c167d1732835ecae8bb8693aaa2 server | 1.182 DEBUG Writing transport parameters, msg=8 server | 1.182 DEBUG Read secret available for ApplicationData: SymKey [32]: 2f1d5ee311bc5952e5d728249f1c8d86b4f5a84f2cde7189fea96d6d227db50d server | 1.182 DEBUG Write secret available for ApplicationData: SymKey [32]: a2082f2c51635e708b908c4d478115fc358c986b6bd28149a28c019d883df2d4 server | 1.182 DEBUG [Agent 0x56185e00e1d0] state -> InProgress server | 1.182 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865 server | 1.182 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865 server | 1.182 DEBUG [Crypto] Handshake keys installed server | 1.182 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 1.182 DEBUG [Crypto] Application write key installed server | 1.182 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 443, tv_nsec: 321340419 } server | 1.182 DEBUG [unv-path [::]:443->[::ffff:193.167.0.100]:45644] Make permanent server | 1.182 DEBUG [unv-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644] set as primary path server | 1.182 DEBUG [Server 98dc6efca6a62cfc] State change from WaitInitial -> Handshaking server | 1.182 WARN [Server ...] Dropped received packet: Coalesced packet has different DCID; Total: 1 server | 1.182 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.182 DEBUG Building Initial dcid Some(CID [8]: 72a250dd75d60448) scid Some(CID [10]: ec1755381bf971f3c809) server | 1.182 DEBUG CRYPTO for in offset=0, len=90 server | 1.182 DEBUG [Server 98dc6efca6a62cfc] pn=0 type=Initial pri-unv-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 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.182 DEBUG Building Handshake dcid Some(CID [8]: 72a250dd75d60448) scid Some(CID [10]: ec1755381bf971f3c809) server | 1.182 DEBUG CRYPTO for hs offset=0, len=722 server | 1.182 DEBUG [Server 98dc6efca6a62cfc] pn=0 type=Handshake pri-unv-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, Ect0) len 914 server | TX -> Crypto { offset: 0, len: 722 } server | 1.182 DEBUG packet_sent this=0x56185e00db40, pn=0, ps=770 server | 1.182 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.182 DEBUG [Server 98dc6efca6a62cfc] pad Initial from 914 to PLPMTU 1232 server | 1.182 DEBUG packet_sent this=0x56185e00db40, pn=0, ps=462 server | 1.182 DEBUG ECN probing: sent 1 probes server | 1.182 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.182 DEBUG Building Initial dcid Some(CID [8]: 72a250dd75d60448) scid Some(CID [10]: ec1755381bf971f3c809) server | 1.182 DEBUG Building Handshake dcid Some(CID [8]: 72a250dd75d60448) scid Some(CID [10]: ec1755381bf971f3c809) server | 1.182 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.182 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.182 DEBUG [Server 98dc6efca6a62cfc] delay duration 297.046423ms server | 1.182 DEBUG Setting timeout of 297.046423ms server | 1.182 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.183 DEBUG Building Initial dcid Some(CID [8]: 72a250dd75d60448) scid Some(CID [10]: ec1755381bf971f3c809) server | 1.183 DEBUG Building Handshake dcid Some(CID [8]: 72a250dd75d60448) scid Some(CID [10]: ec1755381bf971f3c809) server | 1.183 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.183 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.183 DEBUG [Server 98dc6efca6a62cfc] delay duration 297.009745ms server | 1.183 DEBUG Setting timeout of 297.009745ms server | 1.217 DEBUG [Server 98dc6efca6a62cfc] pn=1 type=Initial pri-unv-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, NotEct) len 52 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 216, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | 1.217 DEBUG [Server 98dc6efca6a62cfc] Rx ACK space=in, ranges=[0..=0] server | 1.217 DEBUG [LossRecovery] ACK for Initial - largest_acked=0 server | 1.217 DEBUG on_packets_acked this=0x56185e00db40, limited=1, bytes_in_flight=770, cwnd=12320, state=SlowStart, new_acked=462 server | 1.217 DEBUG Acked crypto frame space=in offset=0 length=90 server | 1.217 DEBUG [pri-unv-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644] Path validated Instant { tv_sec: 443, tv_nsec: 358700009 } server | 1.217 DEBUG [Server 98dc6efca6a62cfc] Drop packet number space in server | 1.217 DEBUG [LossRecovery] Reset loss recovery state for Initial server | 1.217 DEBUG [Server 98dc6efca6a62cfc] pn=2 type=Handshake pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, NotEct) len 91 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 216, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | -> RX Crypto { offset: 0, len: 36 } server | 1.217 DEBUG [Server 98dc6efca6a62cfc] Rx ACK space=hs, ranges=[0..=0] server | 1.217 DEBUG [LossRecovery] ACK for Handshake - largest_acked=0 server | 1.217 DEBUG on_packets_acked this=0x56185e00db40, limited=1, bytes_in_flight=0, cwnd=12320, state=SlowStart, new_acked=770 server | 1.217 DEBUG Acked crypto frame space=hs offset=0 length=722 server | 1.217 DEBUG Read Ok(36) bytes server | 1.217 DEBUG [Agent 0x56185e00e1d0] 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 | 1.217 DEBUG [Server 98dc6efca6a62cfc] TLS connection complete server | 1.217 DEBUG [pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644] Path validated Instant { tv_sec: 443, tv_nsec: 358700009 } server | 1.217 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 1.217 DEBUG [Crypto] application read keys installed server | 1.217 DEBUG [Server 98dc6efca6a62cfc] State change from Handshaking -> Connected server | 1.217 DEBUG [Server 98dc6efca6a62cfc] State change from Connected -> Confirmed server | 1.217 DEBUG PMTUD started with probe size 1380 server | 1.217 INFO [Server 98dc6efca6a62cfc] Connection established server | 1.217 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 443, tv_nsec: 358700009 } server | 1.217 DEBUG [Server 98dc6efca6a62cfc] pn=3 type=Short pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, NotEct) len 1057 server | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [115, 103, 8, 189, 50, 57, 250, 81], stateless_reset_token: [174, 178, 80, 100, 227, 158, 31, 246, 188, 174, 184, 74, 22, 233, 95, 203] } server | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [96, 16, 120, 35, 27, 78, 6, 51], stateless_reset_token: [62, 110, 234, 46, 216, 92, 109, 209, 188, 103, 154, 181, 84, 98, 151, 34] } server | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [108, 213, 63, 211, 62, 126, 4, 37], stateless_reset_token: [190, 57, 41, 161, 149, 208, 38, 143, 20, 29, 108, 25, 23, 57, 144, 1] } server | -> RX NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [212, 94, 246, 178, 209, 75, 197, 134], stateless_reset_token: [180, 41, 154, 240, 238, 121, 90, 246, 61, 201, 138, 30, 112, 170, 66, 111] } server | -> RX NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [104, 128, 186, 185, 158, 38, 152, 138], stateless_reset_token: [200, 207, 87, 5, 223, 192, 115, 190, 36, 108, 161, 172, 51, 237, 96, 53] } server | -> RX NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [238, 186, 178, 250, 57, 16, 181, 230], stateless_reset_token: [239, 219, 241, 97, 211, 148, 9, 227, 41, 109, 79, 126, 36, 9, 24, 31] } server | -> RX NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [84, 212, 115, 78, 101, 99, 148, 96], stateless_reset_token: [166, 228, 227, 99, 212, 72, 233, 157, 142, 51, 235, 17, 70, 176, 237, 157] } server | -> RX Padding { len: 832 } server | 1.217 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 443, tv_nsec: 358700009 } server | 1.217 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.217 DEBUG Building Handshake dcid Some(CID [8]: 72a250dd75d60448) scid Some(CID [10]: ec1755381bf971f3c809) server | 1.217 DEBUG [Server 98dc6efca6a62cfc] pn=1 type=Handshake pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, Ect0) len 49 server | TX -> Ack { largest_acknowledged: 2, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | 1.217 DEBUG [Server 98dc6efca6a62cfc] Drop packet number space hs server | 1.217 DEBUG [LossRecovery] Reset loss recovery state for Handshake server | 1.217 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.217 DEBUG [Server 98dc6efca6a62cfc] pn=0 type=Short pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, Ect0) len 1332 server | TX -> Ack { largest_acknowledged: 3, 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: [233, 15, 97, 216, 98, 71, 193, 150, 168, 217], stateless_reset_token: [117, 188, 104, 103, 244, 73, 118, 163, 150, 188, 119, 226, 197, 126, 60, 146] } server | TX -> NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [254, 30, 23, 185, 100, 49, 238, 47, 83, 48], stateless_reset_token: [60, 94, 102, 71, 28, 88, 236, 148, 207, 227, 29, 128, 254, 119, 4, 236] } server | TX -> NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [234, 2, 168, 56, 190, 176, 193, 101, 211, 141], stateless_reset_token: [167, 226, 155, 232, 234, 80, 26, 71, 251, 67, 241, 206, 87, 157, 227, 242] } server | TX -> NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [59, 229, 254, 154, 158, 94, 28, 28, 72, 57], stateless_reset_token: [51, 131, 215, 225, 246, 114, 236, 45, 230, 48, 6, 164, 100, 5, 208, 127] } server | TX -> NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [185, 137, 251, 4, 169, 50, 194, 45, 42, 99], stateless_reset_token: [248, 211, 45, 185, 30, 229, 106, 147, 223, 167, 7, 27, 247, 190, 225, 119] } server | TX -> NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [45, 151, 227, 142, 59, 172, 68, 176, 17, 59], stateless_reset_token: [223, 179, 61, 206, 145, 188, 90, 170, 35, 114, 31, 91, 198, 201, 222, 17] } server | TX -> NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [170, 51, 45, 144, 20, 95, 235, 27, 119, 49], stateless_reset_token: [108, 207, 177, 195, 7, 226, 196, 80, 220, 81, 174, 67, 142, 91, 75, 207] } server | TX -> Padding { len: 1041 } server | 1.217 DEBUG packet_sent this=0x56185e00db40, pn=0, ps=1283 server | 1.217 DEBUG ECN probing: sent 2 probes server | 1.217 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.217 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.217 DEBUG Sending PMTUD probe of size 1380, count 1 server | 1.217 DEBUG [Server 98dc6efca6a62cfc] pn=1 type=Short pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, Ect0) len 1332 server | TX -> Ping server | TX -> Padding { len: 1305 } server | 1.217 DEBUG packet_sent this=0x56185e00db40, pn=1, ps=1332 server | 1.217 DEBUG ECN probing: sent 3 probes server | 1.218 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.218 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.218 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.218 DEBUG [Server 98dc6efca6a62cfc] delay duration 1.399218ms server | 1.218 DEBUG Setting timeout of 1.399218ms server | 1.218 DEBUG [Server 98dc6efca6a62cfc] pn=4 type=Short pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, NotEct) len 50 server | -> RX Stream { stream_id: 0, offset: 0, len: 17, fin: true } server | 1.218 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 443, tv_nsec: 379426873 } server | 1.218 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.218 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.218 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.218 DEBUG [Server 98dc6efca6a62cfc] delay duration 1.370324ms server | 1.218 DEBUG Setting timeout of 1.370324ms server | 1.219 DEBUG [Server 98dc6efca6a62cfc] send session ticket 4063000898dc6efca6a62cfc0104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0aec1755381bf971f3c809110c000000014aaafa3a000000016ab200c0000000ff02de1a0243e8200100686921 server | 1.219 DEBUG Path = 'vpzzxwctjj' server | 1.219 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.219 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.219 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.219 DEBUG [Server 98dc6efca6a62cfc] delay duration 232.436µs server | 1.219 DEBUG Setting timeout of 232.436µs server | 1.220 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.220 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.220 DEBUG CRYPTO for ap offset=0, len=174 server | 1.220 DEBUG [Server 98dc6efca6a62cfc] pn=2 type=Short pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 0, offset: 0, len: 1024, fin: true } server | TX -> Crypto { offset: 0, len: 174 } server | 1.220 DEBUG packet_sent this=0x56185e00db40, pn=2, ps=1232 server | 1.220 DEBUG ECN probing: sent 4 probes server | 1.220 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.220 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.220 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.220 DEBUG [Server 98dc6efca6a62cfc] delay duration 977.338µs server | 1.220 DEBUG Setting timeout of 977.338µs server | 1.220 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.220 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.220 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.220 DEBUG [Server 98dc6efca6a62cfc] delay duration 956.659µs server | 1.220 DEBUG Setting timeout of 956.659µs server | 1.222 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.222 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.222 DEBUG CRYPTO for ap offset=174, len=131 server | 1.222 DEBUG [Server 98dc6efca6a62cfc] pn=3 type=Short pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, Ect0) len 207 server | TX -> Crypto { offset: 174, len: 131 } server | TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 205, 224, 44, 39, 18, 208, 241, 14, 70, 216, 170, 125, 150, 103, 158, 179, 166, 159, 1, 75, 122, 166, 101, 237, 210, 222, 58, 66, 176, 140, 132, 236, 178, 211, 202, 49] } server | 1.222 DEBUG packet_sent this=0x56185e00db40, pn=3, ps=207 server | 1.222 DEBUG ECN probing: sent 5 probes server | 1.222 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.222 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.222 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.222 DEBUG [Server 98dc6efca6a62cfc] delay duration 15.553253ms server | 1.222 DEBUG Setting timeout of 15.553253ms server | 1.222 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.222 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.222 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.222 DEBUG [Server 98dc6efca6a62cfc] delay duration 15.52984ms server | 1.222 DEBUG Setting timeout of 15.52984ms server | 1.239 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.239 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.239 DEBUG [Server 98dc6efca6a62cfc] pn=4 type=Short pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, Ect0) len 32 server | TX -> Ack { largest_acknowledged: 4, ack_delay: 2699, first_ack_range: 1, ack_ranges: [], ecn_count: None } server | 1.239 DEBUG ECN probing: sent 6 probes server | 1.239 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.239 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.239 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.239 DEBUG [Server 98dc6efca6a62cfc] delay duration 101.103101ms server | 1.239 DEBUG Setting timeout of 101.103101ms server | 1.239 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.239 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.239 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.239 DEBUG [Server 98dc6efca6a62cfc] delay duration 101.075009ms server | 1.239 DEBUG Setting timeout of 101.075009ms server | 1.250 DEBUG [Server 98dc6efca6a62cfc] pn=5 type=Short pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, NotEct) len 34 server | -> RX Ack { largest_acknowledged: 1, ack_delay: 12, first_ack_range: 1, ack_ranges: [], ecn_count: None } server | 1.250 DEBUG [Server 98dc6efca6a62cfc] Rx ACK space=ap, ranges=[0..=1] server | 1.250 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=1 server | 1.250 DEBUG on_packets_acked this=0x56185e00db40, limited=1, bytes_in_flight=1439, cwnd=12320, state=SlowStart, new_acked=2615 server | 1.250 DEBUG PMTUD probe of size 1380 succeeded server | 1.250 DEBUG PMTUD started with probe size 1420 server | 1.250 DEBUG PLPMTU changed from 1232 to 1332, updating pacer server | 1.250 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.250 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.250 DEBUG Sending PMTUD probe of size 1420, count 1 server | 1.250 DEBUG [Server 98dc6efca6a62cfc] pn=5 type=Short pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, Ect0) len 1372 server | TX -> Ping server | TX -> Padding { len: 1345 } server | 1.250 DEBUG packet_sent this=0x56185e00db40, pn=5, ps=1372 server | 1.250 DEBUG ECN probing: sent 7 probes server | 1.250 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.250 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.250 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.250 DEBUG [Server 98dc6efca6a62cfc] delay duration 108.310038ms server | 1.250 DEBUG Setting timeout of 108.310038ms server | 1.250 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.250 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.250 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.250 DEBUG [Server 98dc6efca6a62cfc] delay duration 108.267191ms server | 1.250 DEBUG Setting timeout of 108.267191ms server | 1.252 DEBUG [Server 98dc6efca6a62cfc] pn=6 type=Short pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, NotEct) len 33 server | -> RX ConnectionClose { error_code: Application(256), frame_type: 0, reason_phrase: "" } server | 1.252 INFO [Server 98dc6efca6a62cfc] ConnectionClose received. Error code: Application(256) frame type 0 reason server | 1.252 DEBUG [Server 98dc6efca6a62cfc] State change from Confirmed -> Draining { error: Transport(PeerApplicationError(256)), timeout: Instant { tv_sec: 443, tv_nsec: 718902596 } } server | 1.252 DEBUG [pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644] Path validated Instant { tv_sec: 443, tv_nsec: 393500777 } server | 1.252 DEBUG [Server 98dc6efca6a62cfc] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.252 DEBUG Building Short dcid Some(CID [8]: 72a250dd75d60448) server | 1.252 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 443, tv_nsec: 393500777 } server | 1.252 DEBUG [Server 98dc6efca6a62cfc] pn=6 type=Short pri-path:72a250dd75d60448 [::]:443->[::ffff:193.167.0.100]:45644 IpTos(Cs0, Ect0) len 35 server | TX -> Ack { largest_acknowledged: 6, ack_delay: 0, first_ack_range: 3, ack_ranges: [], ecn_count: None } server | TX -> ConnectionClose { error_code: Transport(0), frame_type: 29, reason_phrase: "" } server | 1.252 DEBUG ECN probing: sent 8 probes server | 1.252 DEBUG Setting timeout of 325.301982ms server | 1.252 DEBUG Setting timeout of 325.291193ms server | 1.578 DEBUG [Server 98dc6efca6a62cfc] State change from Draining { error: Transport(PeerApplicationError(256)), timeout: Instant { tv_sec: 443, tv_nsec: 718902596 } } -> Closed(Transport(PeerApplicationError(256))) server | 1.578 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:23:32,060 Using the client's key log file. 2025-04-30 12:23:32,070 2025-04-30 12:23:32,070 Using the client's key log file. 2025-04-30 12:23:32,070 Using the client's key log file. 2025-04-30 12:23:32,078 2025-04-30 12:23:32,078 Using the client's key log file. 2025-04-30 12:23:32,079 Using selector: EpollSelector 2025-04-30 12:23:32,705 Check of downloaded files succeeded.