2025-04-30 12:31:00,022 Generated random file: ytvorbiyso of size: 1024
2025-04-30 12:31:00,023 Requests: https://server4:443/ytvorbiyso
2025-04-30 12:31:00,084 
2025-04-30 12:31:00,084 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_4lzwjhlc/ TESTCASE_SERVER=handshake TESTCASE_CLIENT=handshake WWW=/tmp/www_lf09hv9u/ DOWNLOADS=/tmp/download_ourghhmn/ SERVER_LOGS=/tmp/logs_server_54lq79q_ CLIENT_LOGS=/tmp/logs_client_q8g6kvp9 SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=peterdoornbosch/kwik_n_flupke-interop SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server4:443/ytvorbiyso"  docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 
2025-04-30 12:31:14,302  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
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]
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  | tx-udp-segmentation: off [not requested]
client  | tx-checksum-sctp: off
server  | Endpoint's IPv4 address is 193.167.100.100
client  | Endpoint's IPv4 address is 193.167.0.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
server  | ++ mktemp
server  | + P12CERT=/tmp/tmp.mQbxUixmQH
server  | + mkdir -p /neqo/db
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.mQbxUixmQH
server  | Warning: output encryption option -nodes ignored with -export
server  | + pk12util -d sql:/neqo/db -i /tmp/tmp.mQbxUixmQH -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  |             14:8b:81:81:d8:ed:46:c4:24:91:9b:a7:99:e8:a4:e1:
server  |             7f:1c:7b:82
server  |         Signature Algorithm: X9.62 ECDSA signature with SHA256
server  |         Issuer: "O=interop runner Root Certificate Authority"
server  |         Validity:
server  |             Not Before: Wed Apr 30 12:31:00 2025
server  |             Not After : Sat May 10 12:31:00 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:7e:b5:78:c5:c7:2f:aa:0d:be:2f:20:07:2b:46:6c:
server  |                     fb:e9:0f:ba:c8:69:93:dc:9a:f7:60:b2:68:3e:da:2b:
server  |                     8d:06:ac:26:04:86:d0:77:fb:df:77:52:ab:db:ca:c5:
server  |                     8a:a2:b3:d5:45:66:ec:8f:2b:55:9b:a1:67:94:94:e0:
server  |                     9a
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  |                 95:f0:78:5e:ec:a6:7c:4a:de:4d:0a:0a:16:9b:57:98:
server  |                 95:b7:ee:d5
server  | 
server  |             Name: Certificate Authority Key Identifier
server  |             Key ID:
server  |                 b8:56:69:3c:d3:c7:47:c5:26:c3:1b:15:91:8a:8a:18:
server  |                 2f:24:d7:8d
server  | 
server  |     Signature Algorithm: X9.62 ECDSA signature with SHA256
server  |     Signature:
server  |         30:44:02:20:7b:e4:71:be:2e:27:d3:f9:02:e6:79:ca:
server  |         7a:c9:69:67:8a:1a:62:3f:c9:d5:13:ca:61:1a:44:4d:
server  |         b4:55:11:8d:02:20:35:bc:27:11:03:a5:80:c7:2b:2b:
server  |         b5:ec:2b:11:be:5b:60:6e:12:7f:fc:f3:74:49:55:62:
server  |         6c:5f:96:ac:29:70
server  |     Fingerprint (SHA-256):
server  |         D7:43:95:A0:4A:0E:FD:D0:E4:8F:CE:6B:C6:20:7C:B1:D8:13:FF:43:ED:AD:34:4D:1F:40:0E:C8:38:70:72:35
server  |     Fingerprint (SHA1):
server  |         2A:ED:DB:90:BE:42:A8:24:90:CB:CF:77:3B:9C:65:DE:F8:2E:46:61
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.004 DEBUG Default socket send buffer size is 212992
server  | 0.004 DEBUG Default socket receive buffer size is 1048576, not changing
server  | 0.004 INFO Server waiting for connection on: [::]:443
client  | Certificate was added to keystore
client  | wait-for-it.sh: waiting 30 seconds for sim:57832
server  | 0.767 DEBUG [Server] Unsupported version: 57414954
server  | 0.767 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:52976 IpTos(Cs0, NotEct) len 15
server  | 0.768 DEBUG [Server] Unsupported version: 57414954
server  | 0.768 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:52976 IpTos(Cs0, NotEct) len 15
server  | 0.768 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" })
server  | 0.768 DEBUG [Server] Unsupported version: 57414954
server  | 0.768 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:52976 IpTos(Cs0, NotEct) len 15
server  | 0.768 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" })
sim     | server:443 is available after 1.06574745s
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  | running kwik Kwik version: 0.10.2 with openjdk 21.0.5 2024-10-15 with https://server4:443/ytvorbiyso
client  | 31:02.560 Creating connection with server4:443 with v1
client  | 31:02.645 Original destination connection id: 94662e7d019999e5 (scid: d932ad3b4ab061c3)
server  | 1.925 DEBUG [Server] Handle initial
server  | 1.925 INFO AddressValidation: no token; accepting
server  | 1.925 INFO [Server] Accept connection CID [8]: 94662e7d019999e5
server  | 1.925 DEBUG Overwrite initial version Version1 ==> Version1
server  | 1.927 DEBUG Outbound interface eth0 for destination ::ffff:193.167.0.100 has MTU 1500
server  | 1.927 INFO [Server ...] Received valid Initial packet with scid CID [8]: d932ad3b4ab061c3 dcid CID [8]: 94662e7d019999e5
server  | 1.927 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=94662e7d019999e5
server  | 1.927 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865
server  | 1.927 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865
server  | 1.927 DEBUG [Server 94662e7d019999e5] State change from Init -> WaitInitial
server  | 1.927 DEBUG [Server 94662e7d019999e5] pn=0 type=Initial unv-path [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, NotEct) len 1200
server  |   -> RX Crypto { offset: 0, len: 257 }
server  |   -> RX Padding { len: 896 }
server  | 1.927 DEBUG Read Ok(257) bytes
server  | 1.927 DEBUG 0-RTT: no token, no 0-RTT
server  | 1.928 DEBUG Read secret available for Handshake: SymKey [32]: dc7cd68a332c2e4394d053c107ce41c2e709323fce0141abbcd0399867d71f9e
server  | 1.928 DEBUG Write secret available for Handshake: SymKey [32]: dbde8ec9b8acc5b8dcd47ce45b395467c6bf6363167a108f65fc1e8968ef9e69
server  | 1.928 DEBUG Writing transport parameters, msg=8
server  | 1.928 DEBUG Read secret available for ApplicationData: SymKey [32]: 16f764722523329064efc2b8be331ee7f802891e26d63c5940c1ab975befd9bf
server  | 1.928 DEBUG Write secret available for ApplicationData: SymKey [32]: b42449987c7494c6646142c9e8ffcbd17f794f6980064fec504449592c3f3261
server  | 1.928 DEBUG [Agent 0x56042039d1d0] state -> InProgress
server  | 1.928 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865
server  | 1.928 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865
server  | 1.928 DEBUG [Crypto] Handshake keys installed
server  | 1.928 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865
server  | 1.928 DEBUG [Crypto] Application write key installed
server  | 1.928 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 421, tv_nsec: 259410227 }
server  | 1.928 DEBUG [unv-path [::]:443->[::ffff:193.167.0.100]:50058] Make permanent
server  | 1.928 DEBUG [unv-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058] set as primary path
server  | 1.928 DEBUG [Server 94662e7d019999e5] State change from WaitInitial -> Handshaking
server  | 1.928 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.928 DEBUG Building Initial dcid Some(CID [8]: d932ad3b4ab061c3) scid Some(CID [10]: 82a8840c9501e556b9b7)
server  | 1.928 DEBUG CRYPTO for in offset=0, len=123
server  | 1.928 DEBUG [Server 94662e7d019999e5] pn=0 type=Initial pri-unv-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, Ect0) len 177
server  |   TX -> Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  |   TX -> Crypto { offset: 0, len: 123 }
server  | 1.928 DEBUG Building Handshake dcid Some(CID [8]: d932ad3b4ab061c3) scid Some(CID [10]: 82a8840c9501e556b9b7)
server  | 1.928 DEBUG CRYPTO for hs offset=0, len=719
server  | 1.928 DEBUG [Server 94662e7d019999e5] pn=0 type=Handshake pri-unv-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, Ect0) len 944
server  |   TX -> Crypto { offset: 0, len: 719 }
server  | 1.928 DEBUG packet_sent this=0x56042039cb40, pn=0, ps=767
server  | 1.928 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 1.928 DEBUG [Server 94662e7d019999e5] pad Initial from 944 to PLPMTU 1232
server  | 1.928 DEBUG packet_sent this=0x56042039cb40, pn=0, ps=465
server  | 1.928 DEBUG ECN probing: sent 1 probes
server  | 1.928 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.928 DEBUG Building Initial dcid Some(CID [8]: d932ad3b4ab061c3) scid Some(CID [10]: 82a8840c9501e556b9b7)
server  | 1.928 DEBUG Building Handshake dcid Some(CID [8]: d932ad3b4ab061c3) scid Some(CID [10]: 82a8840c9501e556b9b7)
server  | 1.928 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 1.928 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.928 DEBUG [Server 94662e7d019999e5] delay duration 297.029443ms
server  | 1.928 DEBUG Setting timeout of 297.029443ms
server  | 1.928 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.928 DEBUG Building Initial dcid Some(CID [8]: d932ad3b4ab061c3) scid Some(CID [10]: 82a8840c9501e556b9b7)
server  | 1.928 DEBUG Building Handshake dcid Some(CID [8]: d932ad3b4ab061c3) scid Some(CID [10]: 82a8840c9501e556b9b7)
server  | 1.928 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 1.928 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.928 DEBUG [Server 94662e7d019999e5] delay duration 296.997283ms
server  | 1.928 DEBUG Setting timeout of 296.997283ms
client  | 31:02.894 - unsupported transport parameter 0x2ab2, size 0 (grease-quic-bit)
client  | 31:02.895 - unsupported transport parameter 0xff02de1a, size 2 (delayed-ack)
server  | 2.009 DEBUG [Server 94662e7d019999e5] pn=1 type=Initial pri-unv-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, NotEct) len 1201
server  |   -> RX Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  |   -> RX Padding { len: 1151 }
server  | 2.009 DEBUG [Server 94662e7d019999e5] Rx ACK space=in, ranges=[0..=0]
server  | 2.009 DEBUG [LossRecovery] ACK for Initial - largest_acked=0
server  | 2.009 DEBUG on_packets_acked this=0x56042039cb40, limited=1, bytes_in_flight=767, cwnd=12320, state=SlowStart, new_acked=465
server  | 2.009 DEBUG Acked crypto frame space=in offset=0 length=123
server  | 2.009 DEBUG [pri-unv-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058] Path validated Instant { tv_sec: 421, tv_nsec: 343118586 }
server  | 2.009 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.009 DEBUG Building Initial dcid Some(CID [8]: d932ad3b4ab061c3) scid Some(CID [10]: 82a8840c9501e556b9b7)
server  | 2.009 DEBUG Building Handshake dcid Some(CID [8]: d932ad3b4ab061c3) scid Some(CID [10]: 82a8840c9501e556b9b7)
server  | 2.009 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.009 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.009 DEBUG [Server 94662e7d019999e5] delay duration 167.416716ms
server  | 2.009 DEBUG Setting timeout of 167.416716ms
server  | 2.009 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.009 DEBUG Building Initial dcid Some(CID [8]: d932ad3b4ab061c3) scid Some(CID [10]: 82a8840c9501e556b9b7)
server  | 2.009 DEBUG Building Handshake dcid Some(CID [8]: d932ad3b4ab061c3) scid Some(CID [10]: 82a8840c9501e556b9b7)
server  | 2.009 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.009 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.009 DEBUG [Server 94662e7d019999e5] delay duration 167.164096ms
server  | 2.010 DEBUG Setting timeout of 167.164096ms
server  | 2.052 DEBUG [Server 94662e7d019999e5] Drop packet number space in
server  | 2.052 DEBUG [LossRecovery] Reset loss recovery state for Initial
server  | 2.052 DEBUG [Server 94662e7d019999e5] pn=0 type=Handshake pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, NotEct) len 82
server  |   -> RX Crypto { offset: 0, len: 36 }
server  | 2.052 DEBUG Read Ok(36) bytes
server  | 2.052 DEBUG [Agent 0x56042039d1d0] 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  | 2.052 DEBUG [Server 94662e7d019999e5] TLS connection complete
server  | 2.052 DEBUG [pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058] Path validated Instant { tv_sec: 421, tv_nsec: 385770001 }
server  | 2.052 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865
server  | 2.052 DEBUG [Crypto] application read keys installed
server  | 2.052 DEBUG [Server 94662e7d019999e5] State change from Handshaking -> Connected
server  | 2.052 DEBUG [Server 94662e7d019999e5] State change from Connected -> Confirmed
server  | 2.052 DEBUG PMTUD started with probe size 1380
server  | 2.052 INFO [Server 94662e7d019999e5] Connection established
server  | 2.052 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 421, tv_nsec: 385770001 }
server  | 2.052 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.052 DEBUG Building Handshake dcid Some(CID [8]: d932ad3b4ab061c3) scid Some(CID [10]: 82a8840c9501e556b9b7)
server  | 2.052 DEBUG [Server 94662e7d019999e5] pn=1 type=Handshake pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, Ect0) len 49
server  |   TX -> Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  | 2.052 DEBUG [Server 94662e7d019999e5] Drop packet number space hs
server  | 2.052 DEBUG [LossRecovery] Reset loss recovery state for Handshake
server  | 2.052 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.052 DEBUG [Server 94662e7d019999e5] pn=0 type=Short pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, Ect0) len 1332
server  |   TX -> HandshakeDone
server  |   TX -> NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [254, 22, 165, 155, 72, 55, 68, 166, 175, 124], stateless_reset_token: [230, 178, 3, 249, 159, 107, 36, 81, 132, 196, 44, 107, 11, 132, 9, 12] }
server  |   TX -> Padding { len: 1226 }
server  | 2.052 DEBUG packet_sent this=0x56042039cb40, pn=0, ps=1283
server  | 2.052 DEBUG ECN probing: sent 2 probes
server  | 2.052 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.052 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.052 DEBUG Sending PMTUD probe of size 1380, count 1
server  | 2.052 DEBUG [Server 94662e7d019999e5] pn=1 type=Short pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, Ect0) len 1332
server  |   TX -> Ping
server  |   TX -> Padding { len: 1305 }
server  | 2.052 DEBUG packet_sent this=0x56042039cb40, pn=1, ps=1332
server  | 2.052 DEBUG ECN probing: sent 3 probes
server  | 2.052 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 2.052 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.052 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 2.052 DEBUG [Server 94662e7d019999e5] delay duration 4.075934ms
server  | 2.052 DEBUG Setting timeout of 4.075934ms
server  | 2.053 DEBUG [Server 94662e7d019999e5] send session ticket 4063000894662e7d019999e50104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0a82a8840c9501e556b9b7110c00000001ea4a6a7a000000016ab200c0000000ff02de1a0243e8200100686921
server  | 2.053 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 2.053 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.053 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 2.053 DEBUG [Server 94662e7d019999e5] delay duration 3.001985ms
server  | 2.053 DEBUG Setting timeout of 3.001985ms
server  | 2.054 WARN [Server ...] Dropped received packet: Decryption failure; Total: 1
server  | 2.054 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 2.054 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.054 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 2.054 DEBUG [Server 94662e7d019999e5] delay duration 2.963814ms
server  | 2.054 DEBUG Setting timeout of 2.963814ms
server  | 2.054 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 2.054 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.054 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 2.054 DEBUG [Server 94662e7d019999e5] delay duration 2.937575ms
server  | 2.054 DEBUG Setting timeout of 2.937575ms
server  | 2.058 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.058 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.058 DEBUG CRYPTO for ap offset=0, len=305
server  | 2.058 DEBUG [Server 94662e7d019999e5] pn=2 type=Short pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, Ect0) len 380
server  |   TX -> Crypto { offset: 0, len: 305 }
server  |   TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 218, 253, 53, 45, 65, 17, 56, 131, 82, 32, 123, 49, 207, 142, 19, 131, 181, 42, 243, 158, 213, 36, 150, 44, 94, 255, 214, 188, 183, 212, 111, 67, 196, 208, 103, 255] }
server  | 2.058 DEBUG packet_sent this=0x56042039cb40, pn=2, ps=380
server  | 2.058 DEBUG ECN probing: sent 4 probes
server  | 2.058 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.058 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.058 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.058 DEBUG [Server 94662e7d019999e5] delay duration 276.031ms
server  | 2.058 DEBUG Setting timeout of 276.031ms
server  | 2.058 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.058 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.058 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.058 DEBUG [Server 94662e7d019999e5] delay duration 276.004521ms
server  | 2.058 DEBUG Setting timeout of 276.004521ms
server  | 2.060 DEBUG [Server 94662e7d019999e5] pn=0 type=Short pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, NotEct) len 49
server  |   -> RX Stream { stream_id: 0, offset: 0, len: 17, fin: true }
server  | 2.060 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 421, tv_nsec: 413587548 }
server  | 2.060 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.060 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.060 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.060 DEBUG [Server 94662e7d019999e5] delay duration 20ms
server  | 2.060 DEBUG Setting timeout of 20ms
server  | 2.060 DEBUG Path = 'ytvorbiyso'
server  | 2.060 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.060 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.060 DEBUG [Server 94662e7d019999e5] pn=3 type=Short pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, Ect0) len 1054
server  |   TX -> Stream { stream_id: 0, offset: 0, len: 1024, fin: true }
server  | 2.060 DEBUG packet_sent this=0x56042039cb40, pn=3, ps=1054
server  | 2.060 DEBUG ECN probing: sent 5 probes
server  | 2.060 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 2.060 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.060 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 2.060 DEBUG [Server 94662e7d019999e5] delay duration 1.535549ms
server  | 2.060 DEBUG Setting timeout of 1.535549ms
server  | 2.063 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.063 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.063 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.063 DEBUG [Server 94662e7d019999e5] delay duration 16.746684ms
server  | 2.063 DEBUG Setting timeout of 16.746684ms
server  | 2.063 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.063 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.063 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.063 DEBUG [Server 94662e7d019999e5] delay duration 16.716377ms
server  | 2.063 DEBUG Setting timeout of 16.716377ms
client  | Get requested finished in 0.32 sec (0.00 MB/s) : tech.kwik.h09.client.HttpResponseImpl@2ddc8ecb
server  | 2.081 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.081 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.081 DEBUG [Server 94662e7d019999e5] pn=4 type=Short pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, Ect0) len 32
server  |   TX -> Ack { largest_acknowledged: 0, ack_delay: 2674, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  | 2.081 DEBUG ECN probing: sent 6 probes
server  | 2.081 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.081 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.081 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.081 DEBUG [Server 94662e7d019999e5] delay duration 254.70837ms
server  | 2.081 DEBUG Setting timeout of 254.70837ms
server  | 2.081 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.081 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.081 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 2.081 DEBUG [Server 94662e7d019999e5] delay duration 254.690247ms
server  | 2.081 DEBUG Setting timeout of 254.690247ms
client  | 31:02.972 Closing ClientConnection[94662e7d019999e5/d932ad3b4ab061c3(V1) with server4/193.167.100.100:443] (reason: ImmediateClose)
server  | 2.087 DEBUG [Server 94662e7d019999e5] pn=1 type=Short pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, NotEct) len 33
server  |   -> RX Ack { largest_acknowledged: 1, ack_delay: 0, first_ack_range: 1, ack_ranges: [], ecn_count: None }
server  | 2.088 DEBUG [Server 94662e7d019999e5] Rx ACK space=ap, ranges=[0..=1]
server  | 2.088 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=1
server  | 2.088 DEBUG on_packets_acked this=0x56042039cb40, limited=1, bytes_in_flight=1434, cwnd=12320, state=SlowStart, new_acked=2615
server  | 2.088 DEBUG PMTUD probe of size 1380 succeeded
server  | 2.088 DEBUG PMTUD started with probe size 1420
server  | 2.088 DEBUG PLPMTU changed from 1232 to 1332, updating pacer
server  | 2.088 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 2.088 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.088 DEBUG Sending PMTUD probe of size 1420, count 1
server  | 2.088 DEBUG [Server 94662e7d019999e5] pn=5 type=Short pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, Ect0) len 1372
server  |   TX -> Ping
server  |   TX -> Padding { len: 1345 }
server  | 2.088 DEBUG packet_sent this=0x56042039cb40, pn=5, ps=1372
server  | 2.088 DEBUG ECN probing: sent 7 probes
server  | 2.088 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 2.088 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.088 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 2.088 DEBUG [Server 94662e7d019999e5] delay duration 276.602289ms
server  | 2.088 DEBUG Setting timeout of 276.602289ms
server  | 2.088 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 2.088 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.088 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 2.088 DEBUG [Server 94662e7d019999e5] delay duration 276.578645ms
server  | 2.088 DEBUG Setting timeout of 276.578645ms
server  | 2.092 DEBUG [Server 94662e7d019999e5] pn=2 type=Short pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, NotEct) len 34
server  |   -> RX Ack { largest_acknowledged: 3, ack_delay: 125, first_ack_range: 3, ack_ranges: [], ecn_count: None }
server  | 2.092 DEBUG [Server 94662e7d019999e5] Rx ACK space=ap, ranges=[0..=3]
server  | 2.092 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=3
server  | 2.092 DEBUG on_packets_acked this=0x56042039cb40, limited=1, bytes_in_flight=1372, cwnd=12320, state=SlowStart, new_acked=1434
server  | 2.092 DEBUG Acked crypto frame space=ap offset=0 length=305
server  | 2.092 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 2.092 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.092 DEBUG [Server 94662e7d019999e5] pn=6 type=Short pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, Ect0) len 28
server  |   TX -> MaxStreams { stream_type: BiDi, maximum_streams: 17 }
server  | 2.092 DEBUG packet_sent this=0x56042039cb40, pn=6, ps=29
server  | 2.092 DEBUG ECN probing: sent 8 probes
server  | 2.092 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 2.092 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.092 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 2.092 DEBUG [Server 94662e7d019999e5] delay duration 272.770678ms
server  | 2.092 DEBUG Setting timeout of 272.770678ms
server  | 2.092 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 2.092 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.092 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 2.092 DEBUG [Server 94662e7d019999e5] delay duration 272.742896ms
server  | 2.092 DEBUG Setting timeout of 272.742896ms
server  | 2.102 DEBUG [Server 94662e7d019999e5] pn=3 type=Short pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, NotEct) len 37
server  |   -> RX ConnectionClose { error_code: Transport(0), frame_type: 0, reason_phrase: "" }
server  |   -> RX Ack { largest_acknowledged: 3, ack_delay: 0, first_ack_range: 3, ack_ranges: [], ecn_count: None }
server  | 2.102 INFO [Server 94662e7d019999e5] ConnectionClose received. Error code: Transport(0) frame type 0 reason 
server  | 2.102 DEBUG [Server 94662e7d019999e5] State change from Confirmed -> Draining { error: Transport(PeerError(0)), timeout: Instant { tv_sec: 422, tv_nsec: 254844803 } }
server  | 2.102 DEBUG [Server 94662e7d019999e5] Rx ACK space=ap, ranges=[0..=3]
server  | 2.102 DEBUG [pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058] Path validated Instant { tv_sec: 421, tv_nsec: 436164795 }
server  | 2.102 DEBUG [Server 94662e7d019999e5] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 2.102 DEBUG Building Short dcid Some(CID [8]: d932ad3b4ab061c3)
server  | 2.102 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 421, tv_nsec: 436164795 }
server  | 2.102 DEBUG [Server 94662e7d019999e5] pn=7 type=Short pri-path:d932ad3b4ab061c3 [::]:443->[::ffff:193.167.0.100]:50058 IpTos(Cs0, Ect0) len 35
server  |   TX -> Ack { largest_acknowledged: 3, ack_delay: 0, first_ack_range: 3, ack_ranges: [], ecn_count: None }
server  |   TX -> ConnectionClose { error_code: Transport(0), frame_type: 28, reason_phrase: "" }
server  | 2.102 DEBUG ECN probing: sent 9 probes
server  | 2.102 DEBUG Setting timeout of 818.548172ms
server  | 2.102 DEBUG Setting timeout of 818.534076ms
server  | 2.113 WARN [Server ...] Dropped received packet: State Draining { error: Transport(PeerError(0)), timeout: Instant { tv_sec: 422, tv_nsec: 254844803 } }; Total: 2
server  | 2.113 DEBUG Setting timeout of 807.897296ms
server  | 2.113 DEBUG Setting timeout of 807.874032ms
server  | 2.120 WARN [Server ...] Dropped received packet: State Draining { error: Transport(PeerError(0)), timeout: Instant { tv_sec: 422, tv_nsec: 254844803 } }; Total: 3
server  | 2.120 DEBUG Setting timeout of 800.727099ms
server  | 2.120 DEBUG Setting timeout of 800.707292ms
server  | 2.922 DEBUG [Server 94662e7d019999e5] State change from Draining { error: Transport(PeerError(0)), timeout: Instant { tv_sec: 422, tv_nsec: 254844803 } } -> Closed(Transport(PeerError(0)))
server  | 2.922 INFO Closing timer expired
client  | Terminating Kwik

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 12:31:14,393 Using the server's key log file.
2025-04-30 12:31:14,401 
2025-04-30 12:31:14,402 Using the server's key log file.
2025-04-30 12:31:14,402 Using the server's key log file.
2025-04-30 12:31:14,409 
2025-04-30 12:31:14,410 Using the server's key log file.
2025-04-30 12:31:14,410 Using selector: EpollSelector
2025-04-30 12:31:14,731 Check of downloaded files succeeded.