2025-09-12 03:24:32,283 Generated random file: ycecirbjic of size: 1024
2025-09-12 03:24:32,284 Requests: https://server4:443/ycecirbjic
2025-09-12 03:24:32,343 
2025-09-12 03:24:32,343 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_4h8hvvv5/ TESTCASE_SERVER=handshake TESTCASE_CLIENT=handshake WWW=/tmp/www_mb9gro3h/ DOWNLOADS=/tmp/download_i0gm441g/ SERVER_LOGS=/tmp/logs_server_d7dyoqjv CLIENT_LOGS=/tmp/logs_client_sr5q3qaj SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=ghcr.io/microsoft/msquic/qns:main SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server4:443/ycecirbjic"  docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 
2025-09-12 03:24:49,524  Container sim  Recreate
 Container sim  Recreated
 Container client  Recreate
 Container server  Recreate
 Container server  Recreated
 Container client  Recreated
Attaching to client, server, sim
sim     | waiting 10s for server:443
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  | 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.0qHG5nBPKw
server  | + mkdir -p /neqo/db
client  | wait-for-it.sh: waiting 30 seconds for sim:57832
server  | + certutil -N -d sql:/neqo/db --empty-password
server  | + openssl pkcs12 -export -nodes -in /certs/cert.pem -inkey /certs/priv.key -name cert -passout pass: -out /tmp/tmp.0qHG5nBPKw
server  | Warning: output encryption option -nodes ignored with -export
server  | + pk12util -d sql:/neqo/db -i /tmp/tmp.0qHG5nBPKw -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  |             5f:b8:3a:c1:b9:c5:91:1d:49:f8:3e:3d:50:af:29:de:
server  |             93:e9:d8:33
server  |         Signature Algorithm: X9.62 ECDSA signature with SHA256
server  |         Issuer: "O=interop runner Root Certificate Authority"
server  |         Validity:
server  |             Not Before: Fri Sep 12 03:24:32 2025
server  |             Not After : Mon Sep 22 03:24:32 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:2c:67:9c:75:b8:9b:40:33:9d:c5:fc:d4:57:0a:43:
server  |                     0e:cd:99:d7:d1:44:b8:a2:60:e8:aa:c8:d8:05:d4:fe:
server  |                     31:f7:9e:51:5e:33:1f:35:ed:b1:bb:6c:02:86:de:30:
server  |                     9a:f4:1a:a0:28:74:d9:a9:54:41:b0:09:4d:33:14:4e:
server  |                     1d
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  |                 48:8d:7e:ad:0d:03:b9:2f:fc:56:6d:ee:09:84:87:24:
server  |                 58:99:df:c9
server  | 
server  |             Name: Certificate Authority Key Identifier
server  |             Key ID:
server  |                 80:85:e6:94:9a:d7:a1:c4:8b:03:9e:08:b8:ca:2b:fe:
server  |                 20:c2:7a:86
server  | 
server  |     Signature Algorithm: X9.62 ECDSA signature with SHA256
server  |     Signature:
server  |         30:46:02:21:00:ae:a3:30:95:e0:c3:18:36:20:7c:e6:
server  |         70:35:8b:5d:84:e5:d7:88:b7:17:9d:13:f5:1b:8e:4a:
server  |         5d:ba:0b:ea:14:02:21:00:df:4f:6c:76:1a:32:c4:90:
server  |         7f:5b:fa:75:ae:60:48:68:8b:f9:39:21:ee:73:f0:a8:
server  |         b4:7b:a5:0b:25:4b:42:3c
server  |     Fingerprint (SHA-256):
server  |         C8:FE:B5:CA:78:EE:EB:54:88:A7:89:DE:32:39:F7:EF:33:61:D1:25:3D:08:65:5C:B3:A6:2C:C8:91:17:F4:E2
server  |     Fingerprint (SHA1):
server  |         0F:C2:17:83:62:A0:C1:2B:78:B2:0C:F3:E9:98:9B:33:F5:7E:AE:2A
server  | 
server  |     Mozilla-CA-Policy: false (attribute missing)
server  |     Certificate Trust Flags:
server  |         SSL Flags:
server  |             User
server  |         Email Flags:
server  |             User
server  |         Object Signing Flags:
server  |             User
server  | 
server  | + OPTIONS=(--cc cubic --qns-test "$TESTCASE" --qlog-dir "$QLOGDIR" -d "$DB" -k "$CERT")
server  | + '[' handshake = connectionmigration ']'
server  | + RUST_LOG=debug
server  | + RUST_BACKTRACE=1
server  | + neqo-server --cc cubic --qns-test handshake --qlog-dir /logs/qlog/ -d /neqo/db -k cert '[::]:443'
server  | ++ tee -i -a /logs/server.log
server  | 0.000 DEBUG Logging initialized
server  | 0.002 DEBUG Default socket send buffer size is Ok(212992)
server  | 0.002 DEBUG Default socket receive buffer size is 1048576, not changing
server  | 0.002 INFO Server waiting for connection on: Ok([::]:443)
server  | 0.294 DEBUG [Server] Unsupported version: 57414954
server  | 0.294 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:45025 Tos(Cs0, NotEct) len 15
sim     | server:443 is available after 501.161566ms
sim     | Using scenario: simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25
sim     | tcpdump: listening on eth0, link-type EN10MB (Ethernet), snapshot length 262144 bytes
sim     | tcpdump: listening on eth1, link-type EN10MB (Ethernet), snapshot length 262144 bytes
client  | wait-for-it.sh: sim:57832 is available after 1 seconds
client  | Connecting to server4
client  | Client params (before files):-test:H -sslkeylogfile:/logs/keys.log 
server  | 1.001 DEBUG [Server] Handle initial
server  | 1.001 INFO AddressValidation: no token; accepting
server  | 1.001 INFO [Server] Accept connection CID [8]: 22e51265a916a8b3
server  | 1.001 DEBUG Overwrite initial version Version1 ==> Version1
server  | 1.002 DEBUG Outbound interface eth0 for destination ::ffff:193.167.0.100 has MTU 1500
server  | 1.002 INFO [Server ...] Received valid Initial packet with scid CID [0]:  dcid CID [8]: 22e51265a916a8b3
server  | 1.002 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=22e51265a916a8b3
server  | 1.002 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 min_pn=27
server  | 1.002 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 min_pn=0
server  | 1.002 DEBUG [Server 22e51265a916a8b3] State change from Init -> WaitInitial
server  | 1.002 DEBUG [Server 22e51265a916a8b3] pn=60 type=Initial unv-path [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, NotEct) len 1220
server  |   -> RX Crypto { offset: 0, len: 297 }
server  |   -> RX Padding { len: 881 }
server  | 1.002 DEBUG 0-RTT: no token, no 0-RTT
server  | 1.003 DEBUG Read secret available for Handshake: SymKey [32]: beaf86db1f07b4213799680877f3e62287f40976ab3fc4852810329ad867ef56
server  | 1.003 DEBUG Write secret available for Handshake: SymKey [32]: 371153b81c620c63622b64446543b566e02edb6e519eb069a87392bfe0a7cf40
server  | 1.003 DEBUG Writing transport parameters, msg=8
server  | 1.003 DEBUG Read secret available for ApplicationData: SymKey [32]: cd70f8dde3cc9a2675bfadddf8adbf34eca5e1ada226a4141d47bd8b28a6a0d5
server  | 1.003 DEBUG Write secret available for ApplicationData: SymKey [32]: 280665c9f95ae414a347587574e8e78760d2eedca2712085efd2005fa82f45dc
server  | 1.003 DEBUG [Agent 0x55864f7ae650] state -> InProgress
server  | 1.003 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865 min_pn=0
server  | 1.003 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865 min_pn=0
server  | 1.003 DEBUG [Crypto] Handshake keys installed
server  | 1.003 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865 min_pn=0
server  | 1.003 DEBUG [Crypto] Application write key installed
server  | 1.003 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 187, tv_nsec: 703976743 }
server  | 1.003 DEBUG [unv-path [::]:443->[::ffff:193.167.0.100]:40144] Make permanent
server  | 1.003 DEBUG [unv-path: [::]:443->[::ffff:193.167.0.100]:40144] set as primary path
server  | 1.003 DEBUG [Server 22e51265a916a8b3] State change from WaitInitial -> Handshaking
server  | 1.003 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.003 DEBUG Building Initial dcid Some(CID [0]: ) scid Some(CID [10]: 7558c3dcddc122d2541f)
server  | 1.003 DEBUG CRYPTO for in offset=0, len=90
server  | 1.003 DEBUG [Server 22e51265a916a8b3] pn=27 type=Initial pri-unv-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, NotEct) len 136
server  |   TX -> Ack { largest_acknowledged: 60, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  |   TX -> Crypto { offset: 0, len: 90 }
server  | 1.003 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: 7558c3dcddc122d2541f)
server  | 1.003 DEBUG CRYPTO for hs offset=0, len=728
server  | 1.003 DEBUG [Server 22e51265a916a8b3] pn=0 type=Handshake pri-unv-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, NotEct) len 904
server  |   TX -> Crypto { offset: 0, len: 728 }
server  | 1.003 DEBUG packet_sent this=0x55864f7ae6d0, pn=0, ps=768
server  | 1.003 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.003 DEBUG [Server 22e51265a916a8b3] pad Initial from 904 to PLPMTU 1232
server  | 1.003 DEBUG packet_sent this=0x55864f7ae6d0, pn=27, ps=464
server  | 1.003 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.004 DEBUG Building Initial dcid Some(CID [0]: ) scid Some(CID [10]: 7558c3dcddc122d2541f)
server  | 1.004 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: 7558c3dcddc122d2541f)
server  | 1.004 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.004 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.004 DEBUG [Server 22e51265a916a8b3] delay duration 297.081777ms
server  | 1.004 DEBUG Setting timeout of 297.081777ms
server  | 1.004 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.004 DEBUG Building Initial dcid Some(CID [0]: ) scid Some(CID [10]: 7558c3dcddc122d2541f)
server  | 1.004 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: 7558c3dcddc122d2541f)
server  | 1.004 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.004 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.004 DEBUG [Server 22e51265a916a8b3] delay duration 297.043807ms
server  | 1.004 DEBUG Setting timeout of 297.043807ms
client  | Sending request: GET /ycecirbjic

server  | 1.036 DEBUG [Server 22e51265a916a8b3] Drop packet number space in
server  | 1.036 DEBUG [recovery::Loss] Reset loss recovery state for Initial
server  | 1.036 INFO [pri-unv-path: [::]:443->[::ffff:193.167.0.100]:40144] discarding a packet without an RTT estimate; guessing RTT=35.042938ms
server  | 1.036 DEBUG [Server 22e51265a916a8b3] pn=61 type=Handshake pri-unv-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, NotEct) len 83
server  |   -> RX Ack { largest_acknowledged: 0, ack_delay: 1, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  |   -> RX Crypto { offset: 0, len: 36 }
server  | 1.036 DEBUG [Server 22e51265a916a8b3] Rx ACK space=hs, ranges=[0..=0]
server  | 1.036 DEBUG [recovery::Loss] ACK for Handshake - largest_acked=0
server  | 1.036 DEBUG on_packets_acked this=0x55864f7ae6d0, limited=1, bytes_in_flight=0, cwnd=12320, state=SlowStart, new_acked=768
server  | 1.036 DEBUG Acked crypto frame space=hs offset=0 length=728
server  | 1.036 DEBUG [Agent 0x55864f7ae650] 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.036 DEBUG [Server 22e51265a916a8b3] TLS connection complete
server  | 1.036 DEBUG [pri-unv-path: [::]:443->[::ffff:193.167.0.100]:40144] Path validated Instant { tv_sec: 187, tv_nsec: 739019681 }
server  | 1.036 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865 min_pn=0
server  | 1.036 DEBUG [Crypto] application read keys installed
server  | 1.036 DEBUG [Server 22e51265a916a8b3] State change from Handshaking -> Connected
server  | 1.036 DEBUG [Server 22e51265a916a8b3] State change from Connected -> Confirmed
server  | 1.036 DEBUG PMTUD started with probe size 1380
server  | 1.036 INFO [Server 22e51265a916a8b3] Connection established
server  | 1.036 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 187, tv_nsec: 739019681 }
server  | 1.036 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.036 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: 7558c3dcddc122d2541f)
server  | 1.036 DEBUG [Server 22e51265a916a8b3] pn=1 type=Handshake pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, Ect0) len 41
server  |   TX -> Ack { largest_acknowledged: 61, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  | 1.036 DEBUG [Server 22e51265a916a8b3] Drop packet number space hs
server  | 1.036 DEBUG [recovery::Loss] Reset loss recovery state for Handshake
server  | 1.036 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.036 DEBUG [Server 22e51265a916a8b3] pn=0 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, Ect0) len 1332
server  |   TX -> HandshakeDone
server  |   TX -> NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [128, 242, 193, 109, 41, 116, 113, 201, 56, 209], stateless_reset_token: [173, 245, 110, 25, 100, 244, 30, 247, 26, 180, 8, 230, 216, 233, 115, 1] }
server  |   TX -> NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [155, 253, 192, 119, 18, 178, 74, 227, 95, 215], stateless_reset_token: [35, 30, 102, 242, 222, 181, 107, 153, 98, 119, 173, 90, 93, 67, 174, 4] }
server  |   TX -> NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [44, 32, 153, 92, 63, 2, 85, 166, 254, 249], stateless_reset_token: [135, 170, 132, 56, 191, 219, 245, 77, 239, 7, 68, 24, 186, 2, 13, 184] }
server  |   TX -> Padding { len: 1182 }
server  | 1.036 DEBUG packet_sent this=0x55864f7ae6d0, pn=0, ps=1291
server  | 1.036 DEBUG ECN probing: sent 1 probes
server  | 1.036 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.036 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.036 DEBUG Sending PMTUD probe of size 1380, count 1
server  | 1.036 DEBUG [Server 22e51265a916a8b3] pn=1 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, Ect0) len 1332
server  |   TX -> Ping
server  |   TX -> Padding { len: 1313 }
server  | 1.036 DEBUG packet_sent this=0x55864f7ae6d0, pn=1, ps=1332
server  | 1.036 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.036 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.036 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.036 DEBUG ECN probing: sent 2 probes
server  | 1.036 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.036 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.036 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.036 DEBUG [Server 22e51265a916a8b3] delay duration 1.430183ms
server  | 1.036 DEBUG Setting timeout of 1.430183ms
server  | 1.037 DEBUG [Server 22e51265a916a8b3] send session ticket 4064000822e51265a916a8b30104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0a7558c3dcddc122d2541f110c000000014a0afa7a000000016ab200c0000000ff02de1a0243e8200244b0686921
server  | 1.037 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.037 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.037 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.037 DEBUG [Server 22e51265a916a8b3] delay duration 355.507µs
server  | 1.037 DEBUG Setting timeout of 355.507µs
server  | 1.037 DEBUG [Server 22e51265a916a8b3] pn=62 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, NotEct) len 1252
server  |   -> RX Ping
server  |   -> RX Padding { len: 1220 }
server  | 1.037 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 187, tv_nsec: 740678913 }
server  | 1.037 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 187, tv_nsec: 740678913 }
server  | 1.037 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.037 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.037 DEBUG [Server 22e51265a916a8b3] pn=2 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, Ect0) len 23
server  |   TX -> Ack { largest_acknowledged: 62, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  | 1.037 DEBUG ECN probing: sent 3 probes
server  | 1.037 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.037 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.037 DEBUG CRYPTO for ap offset=0, len=305
server  | 1.037 DEBUG [Server 22e51265a916a8b3] pn=3 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, Ect0) len 372
server  |   TX -> Crypto { offset: 0, len: 305 }
server  |   TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 145, 59, 95, 41, 92, 85, 72, 234, 157, 97, 235, 160, 117, 186, 200, 133, 77, 253, 232, 105, 155, 176, 115, 250, 180, 196, 245, 55, 174, 80, 214, 142, 218, 166, 209, 82] }
server  | 1.037 DEBUG packet_sent this=0x55864f7ae6d0, pn=3, ps=372
server  | 1.037 DEBUG ECN probing: sent 4 probes
server  | 1.037 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.037 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.037 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.037 DEBUG [Server 22e51265a916a8b3] delay duration 113.538857ms
server  | 1.037 DEBUG Setting timeout of 113.538857ms
server  | 1.037 DEBUG [Server 22e51265a916a8b3] pn=63 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, NotEct) len 52
server  |   -> RX Stream { stream_id: 0, offset: 0, len: 17, fin: true }
server  | 1.037 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 187, tv_nsec: 760841433 }
server  | 1.037 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.037 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.037 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.037 DEBUG [Server 22e51265a916a8b3] delay duration 20ms
server  | 1.038 DEBUG Setting timeout of 20ms
server  | 1.038 DEBUG Path = 'ycecirbjic'
server  | 1.038 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.038 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.038 DEBUG [Server 22e51265a916a8b3] pn=4 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, Ect0) len 1046
server  |   TX -> Stream { stream_id: 0, offset: 0, len: 1024, fin: true }
server  | 1.038 DEBUG packet_sent this=0x55864f7ae6d0, pn=4, ps=1046
server  | 1.038 DEBUG ECN probing: sent 5 probes
server  | 1.038 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.038 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.038 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.038 DEBUG [Server 22e51265a916a8b3] delay duration 1.680093ms
server  | 1.038 DEBUG Setting timeout of 1.680093ms
server  | 1.041 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.041 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.041 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.041 DEBUG [Server 22e51265a916a8b3] delay duration 16.686343ms
server  | 1.041 DEBUG Setting timeout of 16.686343ms
server  | 1.041 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.041 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.041 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.041 DEBUG [Server 22e51265a916a8b3] delay duration 16.660886ms
server  | 1.041 DEBUG Setting timeout of 16.660886ms
client  | ycecirbjic: Wrote 1024 bytes.(0 ms/0 ms/0 ms)
client  | ycecirbjic: Completed download! (1 ms)
server  | 1.059 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.059 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.059 DEBUG [Server 22e51265a916a8b3] pn=5 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, Ect0) len 24
server  |   TX -> Ack { largest_acknowledged: 63, ack_delay: 2678, first_ack_range: 1, ack_ranges: [], ecn_count: None }
server  | 1.059 DEBUG ECN probing: sent 6 probes
server  | 1.059 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.059 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.059 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.059 DEBUG [Server 22e51265a916a8b3] delay duration 92.257778ms
server  | 1.059 DEBUG Setting timeout of 92.257778ms
server  | 1.059 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.059 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.059 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.059 DEBUG [Server 22e51265a916a8b3] delay duration 92.232501ms
server  | 1.059 DEBUG Setting timeout of 92.232501ms
server  | 1.069 DEBUG [Server 22e51265a916a8b3] pn=64 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, NotEct) len 39
server  |   -> RX Ack { largest_acknowledged: 2, ack_delay: 0, first_ack_range: 2, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 3, Ce: 0})) }
server  | 1.069 DEBUG [Server 22e51265a916a8b3] Rx ACK space=ap, ranges=[0..=2]
server  | 1.069 DEBUG [recovery::Loss] ACK for ApplicationData - largest_acked=2
server  | 1.069 DEBUG on_packets_acked this=0x55864f7ae6d0, limited=1, bytes_in_flight=1418, cwnd=12320, state=SlowStart, new_acked=2623
server  | 1.069 DEBUG PMTUD probe of size 1380 succeeded
server  | 1.069 DEBUG PMTUD started with probe size 1420
server  | 1.069 DEBUG PLPMTU changed from 1232 to 1332, updating pacer
server  | 1.069 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.069 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.069 DEBUG Sending PMTUD probe of size 1420, count 1
server  | 1.069 DEBUG [Server 22e51265a916a8b3] pn=6 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, Ect0) len 1372
server  |   TX -> Ping
server  |   TX -> Padding { len: 1353 }
server  | 1.069 DEBUG packet_sent this=0x55864f7ae6d0, pn=6, ps=1372
server  | 1.069 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.069 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.069 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.069 DEBUG ECN probing: sent 7 probes
server  | 1.069 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.069 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.069 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.069 DEBUG [Server 22e51265a916a8b3] delay duration 103.593742ms
server  | 1.069 DEBUG Setting timeout of 103.593742ms
server  | 1.069 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.069 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.069 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.069 DEBUG [Server 22e51265a916a8b3] delay duration 103.569136ms
server  | 1.069 DEBUG Setting timeout of 103.569136ms
server  | 1.070 DEBUG [Server 22e51265a916a8b3] pn=65 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, NotEct) len 1332
server  |   -> RX Ping
server  |   -> RX Padding { len: 1300 }
server  | 1.070 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 187, tv_nsec: 773077459 }
server  | 1.070 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 187, tv_nsec: 773077459 }
server  | 1.070 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.070 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.070 DEBUG [Server 22e51265a916a8b3] pn=7 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, Ect0) len 24
server  |   TX -> Ack { largest_acknowledged: 65, ack_delay: 0, first_ack_range: 3, ack_ranges: [], ecn_count: None }
server  | 1.070 DEBUG ECN probing: sent 8 probes
server  | 1.070 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.070 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.070 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.070 DEBUG [Server 22e51265a916a8b3] delay duration 102.563248ms
server  | 1.070 DEBUG Setting timeout of 102.563248ms
server  | 1.070 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.070 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.070 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.070 DEBUG [Server 22e51265a916a8b3] delay duration 102.539283ms
server  | 1.070 DEBUG Setting timeout of 102.539283ms
server  | 1.070 DEBUG [Server 22e51265a916a8b3] pn=66 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, NotEct) len 44
server  |   -> RX Ack { largest_acknowledged: 4, ack_delay: 0, first_ack_range: 4, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 5, Ce: 0})) }
server  |   -> RX MaxData { maximum_data: 16778240 }
server  | 1.070 DEBUG [Server 22e51265a916a8b3] Rx ACK space=ap, ranges=[0..=4]
server  | 1.070 DEBUG [recovery::Loss] ACK for ApplicationData - largest_acked=4
server  | 1.070 DEBUG on_packets_acked this=0x55864f7ae6d0, limited=1, bytes_in_flight=1372, cwnd=12320, state=SlowStart, new_acked=1418
server  | 1.070 DEBUG Acked crypto frame space=ap offset=0 length=305
server  | 1.070 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 187, tv_nsec: 793368579 }
server  | 1.070 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.070 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.070 DEBUG [Server 22e51265a916a8b3] pn=8 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, Ect0) len 20
server  |   TX -> MaxStreams { stream_type: BiDi, maximum_streams: 17 }
server  | 1.070 DEBUG packet_sent this=0x55864f7ae6d0, pn=8, ps=21
server  | 1.070 DEBUG ECN probing: sent 9 probes
server  | 1.070 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.070 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.070 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.070 DEBUG [Server 22e51265a916a8b3] delay duration 19.905294ms
server  | 1.070 DEBUG Setting timeout of 19.905294ms
server  | 1.070 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.070 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.070 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.070 DEBUG [Server 22e51265a916a8b3] delay duration 19.886218ms
server  | 1.070 DEBUG Setting timeout of 19.886218ms
server  | 1.089 DEBUG [Server 22e51265a916a8b3] pn=67 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, NotEct) len 42
server  |   -> RX Ack { largest_acknowledged: 5, ack_delay: 0, first_ack_range: 5, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 6, Ce: 0})) }
server  |   -> RX ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "" }
server  | 1.089 DEBUG [Server 22e51265a916a8b3] Rx ACK space=ap, ranges=[0..=5]
server  | 1.089 DEBUG [recovery::Loss] ACK for ApplicationData - largest_acked=5
server  | 1.089 DEBUG on_packets_acked this=0x55864f7ae6d0, limited=1, bytes_in_flight=1393, cwnd=12320, state=SlowStart, new_acked=0
server  | 1.089 INFO [Server 22e51265a916a8b3] ConnectionClose received. Error code: Application(0) frame type 0 reason 
server  | 1.089 DEBUG [Server 22e51265a916a8b3] State change from Confirmed -> Draining { error: Transport(PeerApplication(0)), timeout: Instant { tv_sec: 188, tv_nsec: 77449771 } }
server  | 1.090 DEBUG [pri-path: [::]:443->[::ffff:193.167.0.100]:40144] Path validated Instant { tv_sec: 187, tv_nsec: 792843554 }
server  | 1.090 DEBUG [Server 22e51265a916a8b3] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.090 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.090 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 187, tv_nsec: 792843554 }
server  | 1.090 DEBUG [Server 22e51265a916a8b3] pn=9 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:40144 Tos(Cs0, Ect0) len 28
server  |   TX -> Ack { largest_acknowledged: 67, ack_delay: 0, first_ack_range: 5, ack_ranges: [], ecn_count: None }
server  |   TX -> ConnectionClose { error_code: Transport(0), frame_type: 29, reason_phrase: "" }
server  | 1.090 DEBUG ECN probing: sent 10 probes
server  | 1.090 DEBUG ECN probing concluded with 10 probes sent
server  | 1.090 DEBUG Setting timeout of 284.484751ms
server  | 1.090 DEBUG Setting timeout of 284.474111ms
server  | 1.100 DEBUG [Server ...] Dropped received packet: State Draining { error: Transport(PeerApplication(0)), timeout: Instant { tv_sec: 188, tv_nsec: 77449771 } }; Total: 1
server  | 1.100 DEBUG Setting timeout of 273.856045ms
server  | 1.100 DEBUG Setting timeout of 273.836629ms
client  | 
client  |       TARGET  VHDCRZSQUMBGA2E    VERSION   ALPN
client  |  ============================================
client  |      server4  -H-------------  0x00000001  hq-interop
client  | 
client  | Total execution time: 0.127s
client  | 
server  | 1.120 DEBUG [Server ...] Dropped received packet: State Draining { error: Transport(PeerApplication(0)), timeout: Instant { tv_sec: 188, tv_nsec: 77449771 } }; Total: 2
server  | 1.120 DEBUG Setting timeout of 254.067553ms
server  | 1.120 DEBUG Setting timeout of 254.046915ms
server  | 1.375 DEBUG [Server 22e51265a916a8b3] State change from Draining { error: Transport(PeerApplication(0)), timeout: Instant { tv_sec: 188, tv_nsec: 77449771 } } -> Closed(Transport(PeerApplication(0)))
server  | 1.375 INFO Closing timer expired
client  | Client complete.
client  | Script complete.

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-09-12 03:24:49,607 Using the client's key log file.
2025-09-12 03:24:49,615 
2025-09-12 03:24:49,616 Using the client's key log file.
2025-09-12 03:24:49,616 Using the client's key log file.
2025-09-12 03:24:49,623 
2025-09-12 03:24:49,624 Using the client's key log file.
2025-09-12 03:24:49,624 Using selector: EpollSelector
2025-09-12 03:24:50,015 Check of downloaded files succeeded.