2025-04-30 10:26:39,127 Generated random file: erkaphbcss of size: 1024
2025-04-30 10:26:39,128 Requests: https://server4:443/erkaphbcss
2025-04-30 10:26:39,185 
2025-04-30 10:26:39,185 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_8wnu564j/ TESTCASE_SERVER=handshake TESTCASE_CLIENT=handshake WWW=/tmp/www_1moxr_3v/ DOWNLOADS=/tmp/download_6fbyr443/ SERVER_LOGS=/tmp/logs_server_01qs21ej CLIENT_LOGS=/tmp/logs_client_teii3gw4 SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=cloudflare/quiche-qns:latest SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server4:443/erkaphbcss"  docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 
2025-04-30 10:26:51,575  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
client  | Setting up routes...
server  | Setting up routes...
client  | Actual changes:
client  | tx-checksum-ip-generic: off
client  | tx-tcp-segmentation: off [not requested]
client  | tx-tcp-ecn-segmentation: off [not requested]
client  | tx-tcp-mangleid-segmentation: off [not requested]
client  | tx-tcp6-segmentation: off [not requested]
client  | tx-udp-segmentation: off [not requested]
client  | tx-checksum-sctp: off
server  | Actual changes:
server  | tx-checksum-ip-generic: off
server  | tx-tcp-segmentation: off [not requested]
server  | tx-tcp-ecn-segmentation: off [not requested]
server  | tx-tcp-mangleid-segmentation: off [not requested]
server  | tx-tcp6-segmentation: off [not requested]
server  | tx-udp-segmentation: off [not requested]
server  | tx-checksum-sctp: off
client  | Endpoint's IPv4 address is 193.167.0.100
server  | Endpoint's IPv4 address is 193.167.100.100
client  | Endpoint's IPv6 address is fd00:cafe:cafe::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
client  | supported
server  | ++ mktemp
server  | + P12CERT=/tmp/tmp.ukiq2q1IIS
server  | + mkdir -p /neqo/db
server  | + certutil -N -d sql:/neqo/db --empty-password
client  | wait-for-it: waiting 30 seconds for sim:57832
server  | + openssl pkcs12 -export -nodes -in /certs/cert.pem -inkey /certs/priv.key -name cert -passout pass: -out /tmp/tmp.ukiq2q1IIS
server  | Warning: output encryption option -nodes ignored with -export
server  | + pk12util -d sql:/neqo/db -i /tmp/tmp.ukiq2q1IIS -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  |             23:ba:99:fa:31:c3:da:06:07:0a:3d:a0:f7:9b:a5:40:
server  |             e2:60:01:27
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 10:26:39 2025
server  |             Not After : Sat May 10 10:26:39 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:1e:8b:15:74:ee:5f:b0:fd:3d:e0:1c:35:42:4f:0f:
server  |                     08:10:9e:e0:38:33:98:d0:9f:dd:6f:3e:75:7b:8c:62:
server  |                     b6:5b:b0:23:ce:4a:aa:dc:4c:57:29:70:bb:e0:35:be:
server  |                     80:54:72:0f:d6:6c:b4:d8:42:d9:0c:0d:8f:c4:72:97:
server  |                     47
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  |                 6a:74:2b:51:f3:d8:3b:0f:27:39:e7:74:65:89:2d:bf:
server  |                 41:8d:e4:9f
server  | 
server  |             Name: Certificate Authority Key Identifier
server  |             Key ID:
server  |                 06:f0:d9:66:29:06:d9:48:bc:ee:16:da:58:dc:e2:d6:
server  |                 1f:cc:12:00
server  | 
server  |     Signature Algorithm: X9.62 ECDSA signature with SHA256
server  |     Signature:
server  |         30:45:02:20:55:20:b5:26:32:a2:30:07:af:d3:fa:a8:
server  |         0e:02:6f:49:64:8c:90:4c:cd:22:eb:6e:b4:8d:eb:6c:
server  |         d8:7f:65:67:02:21:00:fe:f7:55:54:53:3e:5a:df:37:
server  |         58:09:0a:7b:66:ad:95:be:fd:ad:9d:c3:38:4d:b8:8a:
server  |         a7:25:72:99:a0:ef:c2
server  |     Fingerprint (SHA-256):
server  |         C1:B9:8A:82:79:04:AD:59:28:D1:EF:A7:14:08:C6:E1:D1:E8:6C:D8:3D:F3:B0:E5:59:AD:65:5C:59:85:4C:01
server  |     Fingerprint (SHA1):
server  |         AE:CD:18:E1:4C:C0:AE:28:29:49:CC:11:46:A8:8A:1F:FF:81:D1:1B
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.754 DEBUG [Server] Unsupported version: 57414954
server  | 0.754 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:49118 IpTos(Cs0, NotEct) len 15
server  | 0.754 DEBUG [Server] Unsupported version: 57414954
server  | 0.754 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:49118 IpTos(Cs0, NotEct) len 15
sim     | server:443 is available after 1.004149743s
server  | 0.754 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" })
server  | 0.754 DEBUG [Server] Unsupported version: 57414954
server  | 0.754 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:49118 IpTos(Cs0, NotEct) len 15
server  | 0.754 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), snapshot length 262144 bytes
sim     | tcpdump: listening on eth1, link-type EN10MB (Ethernet), snapshot length 262144 bytes
client  | wait-for-it: sim:57832 is available after 1 seconds
client  | ## Starting quiche client...
client  | ## Client params: 
client  | ## Requests: https://server4:443/erkaphbcss
client  | ## Test case: handshake
server  | 1.002 DEBUG [Server] Handle initial
server  | 1.002 INFO AddressValidation: no token; accepting
server  | 1.002 INFO [Server] Accept connection CID [16]: 0ae1fd2de5859d9064da28ae26b91326
server  | 1.002 DEBUG Overwrite initial version Version1 ==> Version1
server  | 1.003 DEBUG Outbound interface eth0 for destination ::ffff:193.167.0.100 has MTU 1500
server  | 1.003 INFO [Server ...] Received valid Initial packet with scid CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 dcid CID [16]: 0ae1fd2de5859d9064da28ae26b91326
server  | 1.003 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=0ae1fd2de5859d9064da28ae26b91326
server  | 1.003 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865
server  | 1.003 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865
server  | 1.003 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] State change from Init -> WaitInitial
server  | 1.003 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=0 type=Initial unv-path [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, NotEct) len 333
server  |   -> RX Crypto { offset: 0, len: 266 }
server  | 1.003 DEBUG Read Ok(266) bytes
server  | 1.004 DEBUG 0-RTT: no token, no 0-RTT
server  | 1.004 DEBUG Read secret available for Handshake: SymKey [32]: 547528df0957719131d4bd0b6f7536d537d819ad676b38cdd51a2a7eafd809e1
server  | 1.004 DEBUG Write secret available for Handshake: SymKey [32]: 7d4b9af38653e730c65a06cf6a29c7d7cf755954ef988e14bf3248cd9e0b3849
server  | 1.004 DEBUG Writing transport parameters, msg=8
server  | 1.004 DEBUG Read secret available for ApplicationData: SymKey [32]: 91b2fc3125eb1215a9eabcc4bee036b36d20c5c143d4692338dc18b69be7bae5
server  | 1.004 DEBUG Write secret available for ApplicationData: SymKey [32]: c7cf0f89dddd530f3b8edd7cbb71130bb7ac4d7b629dd04fe5b07c71b2590ce1
server  | 1.004 DEBUG [Agent 0x557ad75961d0] state -> InProgress
server  | 1.004 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865
server  | 1.004 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865
server  | 1.004 DEBUG [Crypto] Handshake keys installed
server  | 1.004 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865
server  | 1.004 DEBUG [Crypto] Application write key installed
server  | 1.004 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 233, tv_nsec: 52081407 }
server  | 1.005 DEBUG [unv-path [::]:443->[::ffff:193.167.0.100]:36854] Make permanent
server  | 1.005 DEBUG [unv-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854] set as primary path
server  | 1.005 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] State change from WaitInitial -> Handshaking
server  | 1.005 WARN [Server ...] Dropped received packet: Coalesced packet has different DCID; Total: 1
server  | 1.005 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.005 DEBUG Building Initial dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66) scid Some(CID [10]: f0eae2291d986f710bdd)
server  | 1.005 DEBUG CRYPTO for in offset=0, len=90
server  | 1.005 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=0 type=Initial pri-unv-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, Ect0) len 156
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.005 DEBUG Building Handshake dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66) scid Some(CID [10]: f0eae2291d986f710bdd)
server  | 1.005 DEBUG CRYPTO for hs offset=0, len=731
server  | 1.005 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=0 type=Handshake pri-unv-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, Ect0) len 947
server  |   TX -> Crypto { offset: 0, len: 731 }
server  | 1.005 DEBUG packet_sent this=0x557ad7595b40, pn=0, ps=791
server  | 1.005 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.005 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pad Initial from 947 to PLPMTU 1232
server  | 1.005 DEBUG packet_sent this=0x557ad7595b40, pn=0, ps=441
server  | 1.005 DEBUG ECN probing: sent 1 probes
server  | 1.005 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.005 DEBUG Building Initial dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66) scid Some(CID [10]: f0eae2291d986f710bdd)
server  | 1.005 DEBUG Building Handshake dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66) scid Some(CID [10]: f0eae2291d986f710bdd)
server  | 1.005 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.005 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.005 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] delay duration 296.995413ms
server  | 1.005 DEBUG Setting timeout of 296.995413ms
server  | 1.005 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.005 DEBUG Building Initial dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66) scid Some(CID [10]: f0eae2291d986f710bdd)
server  | 1.005 DEBUG Building Handshake dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66) scid Some(CID [10]: f0eae2291d986f710bdd)
server  | 1.005 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.005 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.005 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] delay duration 296.957432ms
server  | 1.005 DEBUG Setting timeout of 296.957432ms
server  | 1.038 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=1 type=Initial pri-unv-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, NotEct) len 63
server  |   -> RX Ack { largest_acknowledged: 0, ack_delay: 74, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  | 1.038 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] Rx ACK space=in, ranges=[0..=0]
server  | 1.038 DEBUG [LossRecovery] ACK for Initial - largest_acked=0
server  | 1.038 DEBUG on_packets_acked this=0x557ad7595b40, limited=1, bytes_in_flight=791, cwnd=12320, state=SlowStart, new_acked=441
server  | 1.038 DEBUG Acked crypto frame space=in offset=0 length=90
server  | 1.038 DEBUG [pri-unv-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854] Path validated Instant { tv_sec: 233, tv_nsec: 88367376 }
server  | 1.038 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] Drop packet number space in
server  | 1.038 DEBUG [LossRecovery] Reset loss recovery state for Initial
server  | 1.038 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=2 type=Handshake pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, NotEct) len 101
server  |   -> RX Ack { largest_acknowledged: 0, ack_delay: 57, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  |   -> RX Crypto { offset: 0, len: 36 }
server  | 1.038 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] Rx ACK space=hs, ranges=[0..=0]
server  | 1.038 DEBUG [LossRecovery] ACK for Handshake - largest_acked=0
server  | 1.038 DEBUG on_packets_acked this=0x557ad7595b40, limited=1, bytes_in_flight=0, cwnd=12320, state=SlowStart, new_acked=791
server  | 1.038 DEBUG Acked crypto frame space=hs offset=0 length=731
server  | 1.038 DEBUG Read Ok(36) bytes
server  | 1.038 DEBUG [Agent 0x557ad75961d0] 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.038 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] TLS connection complete
server  | 1.038 DEBUG [pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854] Path validated Instant { tv_sec: 233, tv_nsec: 88367376 }
server  | 1.038 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865
server  | 1.038 DEBUG [Crypto] application read keys installed
server  | 1.038 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] State change from Handshaking -> Connected
server  | 1.038 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] State change from Connected -> Confirmed
server  | 1.038 DEBUG PMTUD started with probe size 1380
server  | 1.038 INFO [Server 0ae1fd2de5859d9064da28ae26b91326] Connection established
server  | 1.038 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 233, tv_nsec: 88367376 }
server  | 1.038 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=3 type=Short pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, NotEct) len 1186
server  |   -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [84, 219, 104, 124, 88, 50, 241, 176, 126, 217, 137, 120, 233, 11, 236, 149, 59, 255, 113, 185], stateless_reset_token: [198, 166, 237, 49, 142, 65, 125, 54, 20, 163, 220, 118, 29, 219, 132, 212] }
server  |   -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [33, 208, 119, 66, 61, 45, 169, 75, 110, 135, 124, 142, 4, 226, 10, 49, 107, 119, 116, 132], stateless_reset_token: [22, 189, 245, 16, 150, 65, 206, 51, 230, 53, 156, 209, 38, 237, 244, 173] }
server  |   -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [143, 101, 71, 119, 1, 199, 150, 183, 199, 179, 135, 233, 245, 167, 142, 209, 251, 107, 178, 60], stateless_reset_token: [124, 31, 91, 79, 193, 206, 112, 36, 254, 32, 29, 91, 25, 65, 249, 134] }
server  |   -> RX NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [34, 252, 242, 221, 181, 18, 241, 12, 79, 186, 9, 147, 226, 182, 105, 175, 156, 141, 98, 243], stateless_reset_token: [230, 185, 141, 140, 172, 191, 201, 219, 239, 229, 24, 244, 145, 54, 81, 4] }
server  |   -> RX NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [56, 81, 40, 25, 171, 1, 95, 196, 254, 117, 43, 172, 142, 30, 222, 46, 97, 241, 23, 242], stateless_reset_token: [48, 87, 204, 29, 218, 111, 10, 181, 11, 237, 28, 158, 100, 156, 11, 46] }
server  |   -> RX NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [83, 60, 48, 113, 34, 115, 81, 105, 74, 25, 3, 173, 0, 128, 141, 87, 16, 208, 228, 142], stateless_reset_token: [189, 61, 130, 206, 141, 163, 171, 120, 175, 52, 234, 160, 57, 203, 28, 190] }
server  |   -> RX NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [242, 140, 96, 218, 9, 53, 126, 128, 3, 229, 135, 99, 165, 170, 128, 28, 155, 91, 239, 148], stateless_reset_token: [94, 152, 109, 24, 16, 12, 54, 145, 94, 50, 25, 109, 24, 193, 91, 210] }
server  |   -> RX Stream { stream_id: 0, offset: 0, len: 17, fin: true }
server  |   -> RX Padding { len: 856 }
server  | 1.038 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 233, tv_nsec: 88367376 }
server  | 1.038 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.038 DEBUG Building Handshake dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66) scid Some(CID [10]: f0eae2291d986f710bdd)
server  | 1.038 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=1 type=Handshake pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, Ect0) len 61
server  |   TX -> Ack { largest_acknowledged: 2, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  | 1.038 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] Drop packet number space hs
server  | 1.038 DEBUG [LossRecovery] Reset loss recovery state for Handshake
server  | 1.038 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.039 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=0 type=Short pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 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: [145, 120, 79, 214, 49, 146, 52, 111, 96, 244], stateless_reset_token: [242, 95, 49, 25, 54, 31, 23, 56, 219, 190, 176, 183, 239, 198, 232, 22] }
server  |   TX -> NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [40, 97, 255, 206, 66, 252, 177, 99, 213, 6], stateless_reset_token: [44, 250, 49, 108, 118, 244, 195, 231, 174, 207, 181, 185, 213, 100, 211, 254] }
server  |   TX -> NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [194, 199, 154, 127, 233, 191, 41, 118, 15, 184], stateless_reset_token: [192, 185, 223, 211, 231, 180, 63, 79, 207, 185, 244, 255, 191, 72, 94, 8] }
server  |   TX -> NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [208, 148, 90, 190, 30, 169, 174, 85, 98, 56], stateless_reset_token: [195, 112, 119, 223, 11, 244, 237, 6, 182, 130, 208, 60, 172, 70, 138, 144] }
server  |   TX -> NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [125, 213, 116, 253, 221, 7, 15, 51, 76, 9], stateless_reset_token: [225, 86, 165, 104, 118, 175, 249, 66, 164, 159, 141, 137, 223, 6, 86, 226] }
server  |   TX -> NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [70, 89, 221, 212, 35, 96, 59, 218, 241, 235], stateless_reset_token: [129, 208, 170, 207, 78, 138, 56, 108, 121, 67, 107, 50, 42, 199, 60, 151] }
server  |   TX -> NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [63, 218, 189, 182, 7, 94, 134, 252, 116, 111], stateless_reset_token: [2, 213, 253, 123, 173, 101, 15, 13, 40, 228, 71, 80, 244, 4, 91, 225] }
server  |   TX -> Padding { len: 1017 }
server  | 1.039 DEBUG packet_sent this=0x557ad7595b40, pn=0, ps=1271
server  | 1.039 DEBUG ECN probing: sent 2 probes
server  | 1.039 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.039 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.039 DEBUG Sending PMTUD probe of size 1380, count 1
server  | 1.039 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=1 type=Short pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, Ect0) len 1332
server  |   TX -> Ping
server  |   TX -> Padding { len: 1293 }
server  | 1.039 DEBUG packet_sent this=0x557ad7595b40, pn=1, ps=1332
server  | 1.039 DEBUG ECN probing: sent 3 probes
server  | 1.039 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.039 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.039 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.039 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] delay duration 1.295371ms
server  | 1.039 DEBUG Setting timeout of 1.295371ms
server  | 1.040 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] send session ticket 406b00100ae1fd2de5859d9064da28ae26b913260104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0af0eae2291d986f710bdd110c000000014aeababa000000016ab200c0000000ff02de1a0243e8200100686921
server  | 1.040 DEBUG Path = 'erkaphbcss'
server  | 1.040 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.040 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.040 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.040 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] delay duration 287.39µs
server  | 1.040 DEBUG Setting timeout of 287.39µs
server  | 1.041 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.041 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.041 DEBUG CRYPTO for ap offset=0, len=162
server  | 1.041 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=2 type=Short pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, Ect0) len 1232
server  |   TX -> Stream { stream_id: 0, offset: 0, len: 1024, fin: true }
server  |   TX -> Crypto { offset: 0, len: 162 }
server  | 1.041 DEBUG packet_sent this=0x557ad7595b40, pn=2, ps=1232
server  | 1.041 DEBUG ECN probing: sent 4 probes
server  | 1.041 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.041 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.041 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.041 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] delay duration 930.134µs
server  | 1.041 DEBUG Setting timeout of 930.134µs
server  | 1.041 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.041 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.041 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.041 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] delay duration 907.683µs
server  | 1.041 DEBUG Setting timeout of 907.683µs
server  | 1.043 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.043 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.043 DEBUG CRYPTO for ap offset=162, len=159
server  | 1.043 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=3 type=Short pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, Ect0) len 247
server  |   TX -> Crypto { offset: 162, len: 159 }
server  |   TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 20, 139, 244, 68, 128, 139, 139, 170, 174, 199, 214, 215, 235, 211, 176, 29, 165, 38, 103, 1, 255, 130, 45, 10, 106, 202, 87, 239, 93, 97, 28, 60, 236, 65, 134, 205] }
server  | 1.043 DEBUG packet_sent this=0x557ad7595b40, pn=3, ps=247
server  | 1.043 DEBUG ECN probing: sent 5 probes
server  | 1.043 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.043 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.043 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.043 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] delay duration 115.638879ms
server  | 1.043 DEBUG Setting timeout of 115.638879ms
server  | 1.043 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.043 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.043 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.043 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] delay duration 115.614604ms
server  | 1.043 DEBUG Setting timeout of 115.614604ms
server  | 1.071 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=4 type=Short pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, NotEct) len 33
server  |   -> RX Ack { largest_acknowledged: 0, ack_delay: 15, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  | 1.071 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] Rx ACK space=ap, ranges=[0..=0]
server  | 1.071 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=0
server  | 1.071 DEBUG on_packets_acked this=0x557ad7595b40, limited=1, bytes_in_flight=2811, cwnd=12320, state=SlowStart, new_acked=1271
server  | 1.071 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.071 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.071 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.071 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] delay duration 77.655299ms
server  | 1.071 DEBUG Setting timeout of 77.655299ms
server  | 1.071 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.071 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.071 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.071 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] delay duration 77.558128ms
server  | 1.071 DEBUG Setting timeout of 77.558128ms
server  | 1.072 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=5 type=Short pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, NotEct) len 33
server  |   -> RX Ack { largest_acknowledged: 1, ack_delay: 4, first_ack_range: 1, ack_ranges: [], ecn_count: None }
server  | 1.072 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] Rx ACK space=ap, ranges=[0..=1]
server  | 1.072 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=1
server  | 1.072 DEBUG on_packets_acked this=0x557ad7595b40, limited=1, bytes_in_flight=1479, cwnd=12320, state=SlowStart, new_acked=1332
server  | 1.072 DEBUG PMTUD probe of size 1380 succeeded
server  | 1.072 DEBUG PMTUD started with probe size 1420
server  | 1.072 DEBUG PLPMTU changed from 1232 to 1332, updating pacer
server  | 1.072 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.072 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.072 DEBUG Sending PMTUD probe of size 1420, count 1
server  | 1.072 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=4 type=Short pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, Ect0) len 1372
server  |   TX -> Ping
server  |   TX -> Padding { len: 1333 }
server  | 1.072 DEBUG packet_sent this=0x557ad7595b40, pn=4, ps=1372
server  | 1.072 DEBUG ECN probing: sent 6 probes
server  | 1.072 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.072 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.072 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.072 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] delay duration 96.621418ms
server  | 1.072 DEBUG Setting timeout of 96.621418ms
server  | 1.072 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.072 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.072 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.072 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] delay duration 96.593376ms
server  | 1.072 DEBUG Setting timeout of 96.593376ms
server  | 1.073 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=6 type=Short pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, NotEct) len 38
server  |   -> RX ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye" }
server  | 1.073 INFO [Server 0ae1fd2de5859d9064da28ae26b91326] ConnectionClose received. Error code: Application(0) frame type 0 reason kthxbye
server  | 1.073 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] State change from Confirmed -> Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 233, tv_nsec: 413167118 } }
server  | 1.073 DEBUG [pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854] Path validated Instant { tv_sec: 233, tv_nsec: 122939666 }
server  | 1.073 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.073 DEBUG Building Short dcid Some(CID [20]: 5b1bddb3c2f10fd2ecab753ccb36b13073bfad66)
server  | 1.073 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 233, tv_nsec: 122939666 }
server  | 1.073 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] pn=5 type=Short pri-path:5b1bddb3c2f10fd2ecab753ccb36b13073bfad66 [::]:443->[::ffff:193.167.0.100]:36854 IpTos(Cs0, Ect0) len 47
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.073 DEBUG ECN probing: sent 7 probes
server  | 1.073 DEBUG Setting timeout of 290.120904ms
server  | 1.073 DEBUG Setting timeout of 290.108831ms
server  | 1.364 DEBUG [Server 0ae1fd2de5859d9064da28ae26b91326] State change from Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 233, tv_nsec: 413167118 } } -> Closed(Transport(PeerApplicationError(0)))
server  | 1.364 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 10:26:51,672 Using the client's key log file.
2025-04-30 10:26:51,680 
2025-04-30 10:26:51,681 Using the client's key log file.
2025-04-30 10:26:51,681 Using the client's key log file.
2025-04-30 10:26:51,688 
2025-04-30 10:26:51,689 Using the client's key log file.
2025-04-30 10:26:51,689 Using selector: EpollSelector
2025-04-30 10:26:51,993 Check of downloaded files succeeded.