2025-04-30 08:41:55,725 Generated random file: scejftkwzz of size: 1024
2025-04-30 08:41:55,726 Requests: https://server4:443/scejftkwzz
2025-04-30 08:41:55,786 
2025-04-30 08:41:55,786 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_l13c7oyz/ TESTCASE_SERVER=handshake TESTCASE_CLIENT=handshake WWW=/tmp/www_n8qv_7xk/ DOWNLOADS=/tmp/download_hpkykc7w/ SERVER_LOGS=/tmp/logs_server_ast8051j CLIENT_LOGS=/tmp/logs_client_zkvbl57l SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=ghcr.io/aws/s2n-quic/s2n-quic-qns:latest SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server4:443/scejftkwzz"  docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 
2025-04-30 08:42:08,489  Container sim  Recreate
 Container sim  Recreated
 Container server  Recreate
 Container client  Recreate
 Container client  Recreated
 Container server  Recreated
Attaching to client, server, sim
sim     | waiting 10s for server:443
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.Ej7Eo3Vmvk
server  | + mkdir -p /neqo/db
client  | Setting up routes...
server  | + certutil -N -d sql:/neqo/db --empty-password
client  | Actual changes:
client  | tx-checksum-ip-generic: off
client  | tx-tcp-segmentation: off [not requested]
client  | tx-tcp-ecn-segmentation: off [not requested]
client  | tx-tcp-mangleid-segmentation: off [not requested]
client  | tx-tcp6-segmentation: off [not requested]
client  | tx-udp-segmentation: off [not requested]
client  | tx-checksum-sctp: off
client  | Endpoint's IPv4 address is 193.167.0.100
client  | Endpoint's IPv6 address is fd00:cafe:cafe::100
client  | x86_64
server  | + openssl pkcs12 -export -nodes -in /certs/cert.pem -inkey /certs/priv.key -name cert -passout pass: -out /tmp/tmp.Ej7Eo3Vmvk
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.Ej7Eo3Vmvk -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  |             1d:a6:2d:12:71:11:f9:12:d6:20:ce:b9:23:72:1c:86:
server  |             a6:68:65:ff
server  |         Signature Algorithm: X9.62 ECDSA signature with SHA256
server  |         Issuer: "O=interop runner Root Certificate Authority"
server  |         Validity:
server  |             Not Before: Wed Apr 30 08:41:55 2025
server  |             Not After : Sat May 10 08:41:55 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:a0:ef:e3:d1:05:f0:cd:0d:52:be:be:c8:bc:df:d7:
server  |                     e5:29:5b:a4:f9:6d:f6:82:42:0e:f9:82:7d:9d:82:ed:
server  |                     e2:84:98:3c:57:ac:19:68:02:bc:7f:58:fc:6e:c1:2b:
server  |                     21:53:cf:a8:83:5f:b9:db:fe:39:ca:19:20:a7:c1:87:
server  |                     46
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  |                 38:73:de:03:a3:ec:6d:94:9d:94:aa:30:06:71:f7:07:
server  |                 29:d0:f4:a2
server  | 
server  |             Name: Certificate Authority Key Identifier
server  |             Key ID:
server  |                 7e:f6:eb:ed:ec:83:75:00:b0:ca:f2:d6:34:5d:18:57:
server  |                 90:0a:88:79
server  | 
server  |     Signature Algorithm: X9.62 ECDSA signature with SHA256
server  |     Signature:
server  |         30:45:02:20:6e:42:40:dc:4c:ae:ea:92:b6:db:49:ad:
server  |         22:24:75:25:2c:4e:ee:23:6c:89:7a:a1:f8:0f:8e:df:
server  |         11:d5:9c:37:02:21:00:ff:3d:b7:26:77:fb:33:e6:29:
server  |         dd:eb:e1:41:5b:f8:1e:4f:a2:43:be:e9:02:58:13:69:
server  |         b6:30:65:1e:ea:5e:9f
server  |     Fingerprint (SHA-256):
server  |         F0:66:E1:9B:E6:A3:18:A1:70:1A:19:25:C6:7F:50:B7:3E:EB:5F:D3:2D:F5:06:BE:EC:D9:A8:F2:10:C9:B9:BC
server  |     Fingerprint (SHA1):
server  |         85:8F:D8:77:0D:CC:49:FC:9A:FB:AC:D7:ED:BF:B4:65:FF:2C:DC:FE
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.743 DEBUG [Server] Unsupported version: 57414954
server  | 0.743 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:59765 IpTos(Cs0, NotEct) len 15
server  | 0.743 DEBUG [Server] Unsupported version: 57414954
server  | 0.743 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:59765 IpTos(Cs0, NotEct) len 15
sim     | server:443 is available after 1.020730336s
server  | 0.743 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" })
server  | 0.743 DEBUG [Server] Unsupported version: 57414954
server  | 0.743 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:59765 IpTos(Cs0, NotEct) len 15
server  | 0.743 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 eth1, link-type EN10MB (Ethernet), snapshot length 262144 bytes
sim     | tcpdump: listening on eth0, link-type EN10MB (Ethernet), snapshot length 262144 bytes
client  | wait-for-it.sh: sim:57832 is available after 1 seconds
client  | connecting to server4 at 193.167.100.100:443
server  | 1.046 DEBUG [Server] Handle initial
server  | 1.046 INFO AddressValidation: no token; accepting
server  | 1.046 INFO [Server] Accept connection CID [8]: 46976141d66ae8f0
server  | 1.046 DEBUG Overwrite initial version Version1 ==> Version1
server  | 1.048 DEBUG Outbound interface eth0 for destination ::ffff:193.167.0.100 has MTU 1500
server  | 1.048 INFO [Server ...] Received valid Initial packet with scid CID [16]: c7c4ac4b6edd31b326a73164b9996a13 dcid CID [8]: 46976141d66ae8f0
server  | 1.048 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=46976141d66ae8f0
server  | 1.048 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865
server  | 1.048 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865
server  | 1.048 DEBUG [Server 46976141d66ae8f0] State change from Init -> WaitInitial
server  | 1.048 DEBUG [Server 46976141d66ae8f0] pn=0 type=Initial unv-path [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 1252
server  |   -> RX Crypto { offset: 0, len: 287 }
server  |   -> RX Padding { len: 910 }
server  | 1.048 DEBUG Read Ok(287) bytes
server  | 1.048 DEBUG 0-RTT: no token, no 0-RTT
server  | 1.049 DEBUG Read secret available for Handshake: SymKey [32]: 13d972a186b3c3a432ebeee695247008ea1ae66a7d3b2b0cde57eb4a5af03eaf
server  | 1.049 DEBUG Write secret available for Handshake: SymKey [32]: 8529f610af31e2cf705b184aa5fbeebbd63f0da0baa23ce5975d5cfaa01594f5
server  | 1.049 DEBUG Writing transport parameters, msg=8
server  | 1.049 DEBUG Read secret available for ApplicationData: SymKey [32]: 9c178b70e3160d25294cc2a0d122bb2f934b51f6f82f05b9ef38836d0d5f92b5
server  | 1.049 DEBUG Write secret available for ApplicationData: SymKey [32]: 9aea4ad6355f86c551912c46f290c3ea48601453733fb95cdf7a0e61a3a1510b
server  | 1.049 DEBUG [Agent 0x56371953c1d0] state -> InProgress
server  | 1.049 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865
server  | 1.049 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865
server  | 1.049 DEBUG [Crypto] Handshake keys installed
server  | 1.049 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865
server  | 1.050 DEBUG [Crypto] Application write key installed
server  | 1.050 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 180, tv_nsec: 872940599 }
server  | 1.050 DEBUG [unv-path [::]:443->[::ffff:193.167.0.100]:39224] Make permanent
server  | 1.050 DEBUG [unv-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224] set as primary path
server  | 1.050 DEBUG [Server 46976141d66ae8f0] State change from WaitInitial -> Handshaking
server  | 1.050 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.050 DEBUG Building Initial dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13) scid Some(CID [10]: a34c34e89fec0153e7fb)
server  | 1.050 DEBUG CRYPTO for in offset=0, len=123
server  | 1.050 DEBUG [Server 46976141d66ae8f0] pn=0 type=Initial pri-unv-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 188
server  |   TX -> Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) }
server  |   TX -> Crypto { offset: 0, len: 123 }
server  | 1.050 DEBUG Building Handshake dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13) scid Some(CID [10]: a34c34e89fec0153e7fb)
server  | 1.050 DEBUG CRYPTO for hs offset=0, len=726
server  | 1.050 DEBUG [Server 46976141d66ae8f0] pn=0 type=Handshake pri-unv-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 970
server  |   TX -> Crypto { offset: 0, len: 726 }
server  | 1.050 DEBUG packet_sent this=0x56371953bb40, pn=0, ps=782
server  | 1.050 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.050 DEBUG [Server 46976141d66ae8f0] pad Initial from 970 to PLPMTU 1232
server  | 1.050 DEBUG packet_sent this=0x56371953bb40, pn=0, ps=450
server  | 1.050 DEBUG ECN probing: sent 1 probes
server  | 1.050 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.050 DEBUG Building Initial dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13) scid Some(CID [10]: a34c34e89fec0153e7fb)
server  | 1.050 DEBUG Building Handshake dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13) scid Some(CID [10]: a34c34e89fec0153e7fb)
server  | 1.050 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.050 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.050 DEBUG [Server 46976141d66ae8f0] delay duration 296.672908ms
server  | 1.050 DEBUG Setting timeout of 296.672908ms
server  | 1.050 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.050 DEBUG Building Initial dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13) scid Some(CID [10]: a34c34e89fec0153e7fb)
server  | 1.050 DEBUG Building Handshake dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13) scid Some(CID [10]: a34c34e89fec0153e7fb)
server  | 1.050 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.050 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.050 DEBUG [Server 46976141d66ae8f0] delay duration 296.638614ms
server  | 1.050 DEBUG Setting timeout of 296.638614ms
client  | GET /scejftkwzz
server  | 1.085 DEBUG [Server 46976141d66ae8f0] pn=1 type=Initial pri-unv-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 72
server  |   -> RX Ack { largest_acknowledged: 0, ack_delay: 1891, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) }
server  |   -> RX Padding { len: 10 }
server  | 1.085 DEBUG [Server 46976141d66ae8f0] Rx ACK space=in, ranges=[0..=0]
server  | 1.085 DEBUG [LossRecovery] ACK for Initial - largest_acked=0
server  | 1.085 DEBUG on_packets_acked this=0x56371953bb40, limited=1, bytes_in_flight=782, cwnd=12320, state=SlowStart, new_acked=450
server  | 1.085 DEBUG Acked crypto frame space=in offset=0 length=123
server  | 1.085 DEBUG [pri-unv-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224] Path validated Instant { tv_sec: 180, tv_nsec: 911550535 }
server  | 1.085 DEBUG [Server 46976141d66ae8f0] Drop packet number space in
server  | 1.085 DEBUG [LossRecovery] Reset loss recovery state for Initial
server  | 1.085 DEBUG [Server 46976141d66ae8f0] pn=0 type=Handshake pri-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 1180
server  |   -> RX Ack { largest_acknowledged: 0, ack_delay: 1891, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) }
server  |   -> RX Crypto { offset: 0, len: 36 }
server  |   -> RX Padding { len: 1080 }
server  | 1.085 DEBUG [Server 46976141d66ae8f0] Rx ACK space=hs, ranges=[0..=0]
server  | 1.085 DEBUG [LossRecovery] ACK for Handshake - largest_acked=0
server  | 1.085 DEBUG on_packets_acked this=0x56371953bb40, limited=1, bytes_in_flight=0, cwnd=12320, state=SlowStart, new_acked=782
server  | 1.085 DEBUG Acked crypto frame space=hs offset=0 length=726
server  | 1.085 DEBUG Read Ok(36) bytes
server  | 1.085 DEBUG [Agent 0x56371953c1d0] state -> Complete(SecretAgentInfo { version: 772, cipher: 4865, group: 23, resumed: false, early_data: false, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 })
server  | 1.085 DEBUG [Server 46976141d66ae8f0] TLS connection complete
server  | 1.085 DEBUG [pri-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224] Path validated Instant { tv_sec: 180, tv_nsec: 911550535 }
server  | 1.085 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865
server  | 1.085 DEBUG [Crypto] application read keys installed
server  | 1.085 DEBUG [Server 46976141d66ae8f0] State change from Handshaking -> Connected
server  | 1.085 DEBUG [Server 46976141d66ae8f0] State change from Connected -> Confirmed
server  | 1.085 DEBUG PMTUD started with probe size 1380
server  | 1.085 INFO [Server 46976141d66ae8f0] Connection established
server  | 1.085 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 180, tv_nsec: 911550535 }
server  | 1.085 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.085 DEBUG Building Handshake dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13) scid Some(CID [10]: a34c34e89fec0153e7fb)
server  | 1.085 DEBUG [Server 46976141d66ae8f0] pn=1 type=Handshake pri-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 60
server  |   TX -> Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) }
server  | 1.085 DEBUG [Server 46976141d66ae8f0] Drop packet number space hs
server  | 1.085 DEBUG [LossRecovery] Reset loss recovery state for Handshake
server  | 1.085 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.086 DEBUG [Server 46976141d66ae8f0] pn=0 type=Short pri-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 1332
server  |   TX -> HandshakeDone
server  |   TX -> NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [72, 37, 29, 45, 18, 35, 42, 56, 194, 238], stateless_reset_token: [229, 152, 218, 77, 161, 162, 126, 157, 224, 174, 139, 32, 246, 159, 176, 197] }
server  |   TX -> NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [2, 164, 75, 48, 72, 165, 11, 34, 206, 103], stateless_reset_token: [60, 100, 30, 129, 52, 41, 45, 254, 23, 166, 188, 106, 222, 15, 139, 243] }
server  |   TX -> Padding { len: 1177 }
server  | 1.086 DEBUG packet_sent this=0x56371953bb40, pn=0, ps=1272
server  | 1.086 DEBUG ECN probing: sent 2 probes
server  | 1.086 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.086 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.086 DEBUG Sending PMTUD probe of size 1380, count 1
server  | 1.086 DEBUG [Server 46976141d66ae8f0] pn=1 type=Short pri-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 1332
server  |   TX -> Ping
server  |   TX -> Padding { len: 1297 }
server  | 1.086 DEBUG packet_sent this=0x56371953bb40, pn=1, ps=1332
server  | 1.086 DEBUG ECN probing: sent 3 probes
server  | 1.086 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.086 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.086 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.086 DEBUG [Server 46976141d66ae8f0] delay duration 1.322703ms
server  | 1.086 DEBUG Setting timeout of 1.322703ms
server  | 1.086 DEBUG [Server 46976141d66ae8f0] pn=0 type=Short pri-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 51
server  |   -> RX Stream { stream_id: 0, offset: 0, len: 0, fin: false }
server  |   -> RX Stream { stream_id: 0, offset: 0, len: 17, fin: true }
server  | 1.086 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 180, tv_nsec: 932412247 }
server  | 1.086 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.086 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.086 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.086 DEBUG [Server 46976141d66ae8f0] delay duration 1.28909ms
server  | 1.086 DEBUG Setting timeout of 1.28909ms
server  | 1.087 DEBUG [Server 46976141d66ae8f0] send session ticket 4063000846976141d66ae8f00104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0aa34c34e89fec0153e7fb110c00000001baaa2a4a000000016ab200c0000000ff02de1a0243e8200100686921
server  | 1.087 DEBUG Path = 'scejftkwzz'
server  | 1.087 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.087 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.087 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.087 DEBUG [Server 46976141d66ae8f0] delay duration 267.38µs
server  | 1.087 DEBUG Setting timeout of 267.38µs
server  | 1.088 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.088 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.088 DEBUG CRYPTO for ap offset=0, len=166
server  | 1.088 DEBUG [Server 46976141d66ae8f0] pn=2 type=Short pri-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 1232
server  |   TX -> Stream { stream_id: 0, offset: 0, len: 1024, fin: true }
server  |   TX -> Crypto { offset: 0, len: 166 }
server  | 1.088 DEBUG packet_sent this=0x56371953bb40, pn=2, ps=1232
server  | 1.088 DEBUG ECN probing: sent 4 probes
server  | 1.088 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.088 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.088 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.088 DEBUG [Server 46976141d66ae8f0] delay duration 1.024902ms
server  | 1.088 DEBUG Setting timeout of 1.024902ms
server  | 1.088 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.088 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.088 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.088 DEBUG [Server 46976141d66ae8f0] delay duration 1.003652ms
server  | 1.088 DEBUG Setting timeout of 1.003652ms
server  | 1.090 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.090 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.090 DEBUG CRYPTO for ap offset=166, len=139
server  | 1.090 DEBUG [Server 46976141d66ae8f0] pn=3 type=Short pri-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 223
server  |   TX -> Crypto { offset: 166, len: 139 }
server  |   TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 177, 59, 242, 101, 145, 220, 203, 156, 147, 145, 155, 99, 73, 7, 52, 96, 215, 49, 159, 59, 20, 231, 229, 27, 19, 182, 21, 215, 190, 150, 130, 101, 231, 215, 172, 137] }
server  | 1.090 DEBUG packet_sent this=0x56371953bb40, pn=3, ps=223
server  | 1.090 DEBUG ECN probing: sent 5 probes
server  | 1.090 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.090 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.090 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.090 DEBUG [Server 46976141d66ae8f0] delay duration 15.627293ms
server  | 1.090 DEBUG Setting timeout of 15.627293ms
server  | 1.090 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.090 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.090 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.090 DEBUG [Server 46976141d66ae8f0] delay duration 15.606965ms
server  | 1.090 DEBUG Setting timeout of 15.606965ms
client  | Request /scejftkwzz completed successfully
server  | 1.107 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.107 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.107 DEBUG [Server 46976141d66ae8f0] pn=4 type=Short pri-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 43
server  |   TX -> Ack { largest_acknowledged: 0, ack_delay: 2686, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) }
server  | 1.107 DEBUG ECN probing: sent 6 probes
server  | 1.107 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.107 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.107 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.107 DEBUG [Server 46976141d66ae8f0] delay duration 104.21551ms
server  | 1.107 DEBUG Setting timeout of 104.21551ms
server  | 1.107 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.107 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.107 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.107 DEBUG [Server 46976141d66ae8f0] delay duration 104.189301ms
server  | 1.107 DEBUG Setting timeout of 104.189301ms
server  | 1.120 DEBUG [Server 46976141d66ae8f0] pn=1 type=Short pri-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 1472
server  |   -> RX Ping
server  |   -> RX Padding { len: 1443 }
server  | 1.120 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 180, tv_nsec: 946556681 }
server  | 1.120 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 180, tv_nsec: 946556681 }
server  | 1.120 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.120 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.120 DEBUG [Server 46976141d66ae8f0] pn=5 type=Short pri-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 42
server  |   TX -> Ack { largest_acknowledged: 1, ack_delay: 0, first_ack_range: 1, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 2, Ce: 0})) }
server  | 1.120 DEBUG ECN probing: sent 7 probes
server  | 1.120 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.120 DEBUG Building Short dcid Some(CID [16]: c7c4ac4b6edd31b326a73164b9996a13)
server  | 1.120 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.120 DEBUG [Server 46976141d66ae8f0] delay duration 91.536789ms
server  | 1.120 DEBUG Setting timeout of 91.536789ms
server  | 1.120 DEBUG [Server 46976141d66ae8f0] pn=2 type=Short pri-path:c7c4ac4b6edd31b326a73164b9996a13 [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 147
server  |   -> RX Ack { largest_acknowledged: 0, ack_delay: 102, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) }
server  |   -> RX NewConnectionId { sequence_number: 1, retire_prior: 1, connection_id: [73, 142, 239, 30, 75, 240, 102, 252, 63, 133, 130, 61, 148, 1, 177, 11], stateless_reset_token: [204, 101, 110, 53, 141, 2, 249, 172, 231, 169, 178, 174, 241, 97, 218, 229] }
server  |   -> RX NewConnectionId { sequence_number: 2, retire_prior: 1, connection_id: [92, 219, 80, 196, 25, 132, 196, 141, 113, 192, 26, 99, 91, 1, 171, 17], stateless_reset_token: [68, 42, 69, 35, 201, 8, 78, 104, 246, 197, 32, 191, 168, 200, 16, 157] }
server  |   -> RX NewConnectionId { sequence_number: 3, retire_prior: 1, connection_id: [110, 38, 231, 39, 66, 146, 117, 164, 104, 142, 60, 193, 91, 218, 221, 198], stateless_reset_token: [146, 32, 153, 115, 220, 203, 190, 127, 143, 135, 109, 152, 91, 242, 87, 167] }
server  |   -> RX RetireConnectionId { sequence_number: 0 }
server  | 1.120 DEBUG [Server 46976141d66ae8f0] Rx ACK space=ap, ranges=[0..=0]
server  | 1.120 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=0
server  | 1.120 DEBUG on_packets_acked this=0x56371953bb40, limited=1, bytes_in_flight=2787, cwnd=12320, state=SlowStart, new_acked=1272
server  | 1.120 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 180, tv_nsec: 966735375 }
server  | 1.120 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.120 DEBUG Building Short dcid Some(CID [16]: 498eef1e4bf066fc3f85823d9401b10b)
server  | 1.120 DEBUG [Server 46976141d66ae8f0] pn=6 type=Short pri-path:498eef1e4bf066fc3f85823d9401b10b [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 66
server  |   TX -> NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [220, 126, 164, 135, 177, 81, 60, 135, 207, 50], stateless_reset_token: [60, 115, 114, 44, 127, 133, 45, 195, 125, 168, 89, 149, 221, 232, 111, 175] }
server  |   TX -> RetireConnectionId { sequence_number: 0 }
server  | 1.120 DEBUG packet_sent this=0x56371953bb40, pn=6, ps=66
server  | 1.120 DEBUG ECN probing: sent 8 probes
server  | 1.120 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.120 DEBUG Building Short dcid Some(CID [16]: 498eef1e4bf066fc3f85823d9401b10b)
server  | 1.120 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.120 DEBUG [Server 46976141d66ae8f0] delay duration 19.818541ms
server  | 1.120 DEBUG Setting timeout of 19.818541ms
server  | 1.120 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.120 DEBUG Building Short dcid Some(CID [16]: 498eef1e4bf066fc3f85823d9401b10b)
server  | 1.120 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.120 DEBUG [Server 46976141d66ae8f0] delay duration 19.792041ms
server  | 1.120 DEBUG Setting timeout of 19.792041ms
server  | 1.139 DEBUG [Server 46976141d66ae8f0] pn=3 type=Short pri-path:498eef1e4bf066fc3f85823d9401b10b [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 47
server  |   -> RX ConnectionClose { error_code: Transport(0), frame_type: 0, reason_phrase: "" }
server  |   -> RX Padding { len: 15 }
server  | 1.139 INFO [Server 46976141d66ae8f0] ConnectionClose received. Error code: Transport(0) frame type 0 reason 
server  | 1.139 DEBUG [Server 46976141d66ae8f0] State change from Confirmed -> Draining { error: Transport(PeerError(0)), timeout: Instant { tv_sec: 181, tv_nsec: 295590518 } }
server  | 1.139 DEBUG [Server 46976141d66ae8f0] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.139 DEBUG Building Short dcid Some(CID [16]: 498eef1e4bf066fc3f85823d9401b10b)
server  | 1.139 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 180, tv_nsec: 965461305 }
server  | 1.139 DEBUG [Server 46976141d66ae8f0] pn=7 type=Short pri-path:498eef1e4bf066fc3f85823d9401b10b [::]:443->[::ffff:193.167.0.100]:39224 IpTos(Cs0, Ect0) len 46
server  |   TX -> Ack { largest_acknowledged: 3, ack_delay: 0, first_ack_range: 3, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 4, Ce: 0})) }
server  |   TX -> ConnectionClose { error_code: Transport(0), frame_type: 28, reason_phrase: "" }
server  | 1.139 DEBUG ECN probing: sent 9 probes
server  | 1.139 DEBUG Setting timeout of 329.859378ms
server  | 1.139 DEBUG Setting timeout of 329.843498ms
server  | 1.205 WARN [Server ...] Dropped received packet: State Draining { error: Transport(PeerError(0)), timeout: Instant { tv_sec: 181, tv_nsec: 295590518 } }; Total: 1
server  | 1.205 DEBUG Setting timeout of 263.549148ms
server  | 1.205 DEBUG Setting timeout of 263.516748ms
server  | 1.470 DEBUG [Server 46976141d66ae8f0] State change from Draining { error: Transport(PeerError(0)), timeout: Instant { tv_sec: 181, tv_nsec: 295590518 } } -> Closed(Transport(PeerError(0)))
server  | 1.470 INFO Closing timer expired

client exited with code 0
Aborting on container exit...
 Container server  Stopping
 Container client  Stopping
 Container client  Stopped
 Container server  Stopped
 Container sim  Stopping
 Container sim  Stopped

2025-04-30 08:42:08,584 Using the client's key log file.
2025-04-30 08:42:08,594 
2025-04-30 08:42:08,594 Using the client's key log file.
2025-04-30 08:42:08,594 Using the client's key log file.
2025-04-30 08:42:08,602 
2025-04-30 08:42:08,603 Using the client's key log file.
2025-04-30 08:42:08,603 Using selector: EpollSelector
2025-04-30 08:42:08,896 Check of downloaded files succeeded.