2025-04-30 09:36:13,882 Generated random file: djtushuhez of size: 1024
2025-04-30 09:36:13,882 Requests: https://server4:443/djtushuhez
2025-04-30 09:36:13,939 
2025-04-30 09:36:13,940 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_l9fa6kjj/ TESTCASE_SERVER=handshake TESTCASE_CLIENT=handshake WWW=/tmp/www_plrs46f9/ DOWNLOADS=/tmp/download_sh79ba4h/ SERVER_LOGS=/tmp/logs_server_17il7fqh CLIENT_LOGS=/tmp/logs_client__s_4getl SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=martenseemann/quic-go-interop:latest SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server4:443/djtushuhez"  docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 
2025-04-30 09:36:26,049  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...
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
server  | Setting up routes...
client  | Endpoint's IPv6 address is fd00:cafe:cafe::100
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
client  | Using commit: e4bb2dbd5557c9417b30cf9fcd9032fd6fea5366
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.mNUtnVa6eR
server  | + mkdir -p /neqo/db
server  | + certutil -N -d sql:/neqo/db --empty-password
client  | wait-for-it.sh: waiting 10 seconds for sim:57832
server  | + openssl pkcs12 -export -nodes -in /certs/cert.pem -inkey /certs/priv.key -name cert -passout pass: -out /tmp/tmp.mNUtnVa6eR
server  | Warning: output encryption option -nodes ignored with -export
server  | + pk12util -d sql:/neqo/db -i /tmp/tmp.mNUtnVa6eR -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  |             5b:42:b0:cc:5e:15:98:e2:ad:d8:f5:35:4e:fe:ac:46:
server  |             c4:f5:7a:62
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 09:36:13 2025
server  |             Not After : Sat May 10 09:36:13 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:99:62:4c:15:9d:24:d4:db:7a:82:1c:04:f7:21:0f:
server  |                     d3:5b:ec:2a:8b:30:8a:17:15:e9:36:f9:cb:07:c4:ce:
server  |                     69:d6:15:df:c9:d5:0b:b1:c7:d2:25:7c:ee:9b:fe:38:
server  |                     12:8e:95:65:04:a4:1f:89:d5:b4:33:f0:d3:52:89:16:
server  |                     7a
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  |                 b9:7e:2c:f3:68:40:0e:31:30:06:4b:8e:2d:ba:8f:b8:
server  |                 3f:db:2a:37
server  | 
server  |             Name: Certificate Authority Key Identifier
server  |             Key ID:
server  |                 58:a6:7c:59:a6:12:e0:e8:5b:7c:26:c4:84:8c:1f:43:
server  |                 29:7c:3e:0a
server  | 
server  |     Signature Algorithm: X9.62 ECDSA signature with SHA256
server  |     Signature:
server  |         30:45:02:20:08:92:36:92:a3:62:42:87:83:fa:73:13:
server  |         de:4b:26:77:fd:36:f2:8d:39:0b:50:ca:0a:6b:c4:9c:
server  |         3d:ba:4c:38:02:21:00:81:7c:a7:d4:99:c9:c2:bd:f1:
server  |         40:ba:ed:8e:17:d2:ed:71:09:db:2a:76:dc:8b:cb:6b:
server  |         98:7c:f5:33:50:01:3b
server  |     Fingerprint (SHA-256):
server  |         BB:CE:57:70:A0:73:3D:92:ED:15:9F:61:2F:6F:48:D3:9B:99:FC:8E:E0:9C:73:A1:1D:8B:18:62:2D:2C:55:03
server  |     Fingerprint (SHA1):
server  |         EB:E3:1D:EC:BF:3E:22:B5:0D:60:BE:9C:21:C4:CB:F0:B6:22:5C:72
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.785 DEBUG [Server] Unsupported version: 57414954
server  | 0.785 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:59847 IpTos(Cs0, NotEct) len 15
sim     | server:443 is available after 1.051615766s
server  | 0.785 DEBUG [Server] Unsupported version: 57414954
server  | 0.785 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:59847 IpTos(Cs0, NotEct) len 15
server  | 0.785 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" })
server  | 0.785 DEBUG [Server] Unsupported version: 57414954
server  | 0.785 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:59847 IpTos(Cs0, NotEct) len 15
server  | 0.785 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  | Starting QUIC client...
client  | Client params: 
client  | Test case: handshake
server  | 0.990 DEBUG [Server] Handle initial
server  | 0.990 INFO AddressValidation: no token; accepting
server  | 0.990 INFO [Server] Accept connection CID [12]: db93a55ed387e7852ef9e898
server  | 0.990 DEBUG Overwrite initial version Version1 ==> Version1
server  | 0.992 DEBUG Outbound interface eth0 for destination ::ffff:193.167.0.100 has MTU 1500
server  | 0.992 INFO [Server ...] Received valid Initial packet with scid CID [0]:  dcid CID [12]: db93a55ed387e7852ef9e898
server  | 0.992 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=db93a55ed387e7852ef9e898
server  | 0.992 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865
server  | 0.992 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865
server  | 0.992 DEBUG [Server db93a55ed387e7852ef9e898] State change from Init -> WaitInitial
server  | 0.992 DEBUG [Server db93a55ed387e7852ef9e898] pn=0 type=Initial unv-path [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, NotEct) len 1280
server  |   -> RX Padding { len: 960 }
server  |   -> RX Crypto { offset: 0, len: 276 }
server  | 0.992 DEBUG Read Ok(276) bytes
server  | 0.992 DEBUG 0-RTT: no token, no 0-RTT
server  | 0.993 DEBUG Read secret available for Handshake: SymKey [32]: bb2ee6fc3e0b89e9144aaa929321a189988547d0045f5ec990f28649c2cebe01
server  | 0.993 DEBUG Write secret available for Handshake: SymKey [32]: 25cc509e7e306eeabdce0ec58100d5e935bb56c9166d3699def2907bdec75dd5
server  | 0.993 DEBUG Writing transport parameters, msg=8
server  | 0.993 DEBUG Read secret available for ApplicationData: SymKey [32]: 12738ce2e159cc646410e47976ab06cee1d3a1d0c2f624c6a16b01a7fc4deca8
server  | 0.993 DEBUG Write secret available for ApplicationData: SymKey [32]: 0d3dc00206341bf244cb3609abdecf0daa94eabc5af1acfff66154318f0ac975
server  | 0.993 DEBUG [Agent 0x55e8070291d0] state -> InProgress
server  | 0.993 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865
server  | 0.993 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865
server  | 0.993 DEBUG [Crypto] Handshake keys installed
server  | 0.993 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865
server  | 0.993 DEBUG [Crypto] Application write key installed
server  | 0.993 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 233, tv_nsec: 14830513 }
server  | 0.993 DEBUG [unv-path [::]:443->[::ffff:193.167.0.100]:56165] Make permanent
server  | 0.993 DEBUG [unv-path: [::]:443->[::ffff:193.167.0.100]:56165] set as primary path
server  | 0.993 DEBUG [Server db93a55ed387e7852ef9e898] State change from WaitInitial -> Handshaking
server  | 0.993 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 0.993 DEBUG Building Initial dcid Some(CID [0]: ) scid Some(CID [10]: aab700068e60049c1357)
server  | 0.993 DEBUG CRYPTO for in offset=0, len=90
server  | 0.993 DEBUG [Server db93a55ed387e7852ef9e898] pn=0 type=Initial pri-unv-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 136
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  | 0.993 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: aab700068e60049c1357)
server  | 0.993 DEBUG CRYPTO for hs offset=0, len=729
server  | 0.993 DEBUG [Server db93a55ed387e7852ef9e898] pn=0 type=Handshake pri-unv-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 905
server  |   TX -> Crypto { offset: 0, len: 729 }
server  | 0.993 DEBUG packet_sent this=0x55e807028b40, pn=0, ps=769
server  | 0.993 DEBUG Building Short dcid Some(CID [0]: )
server  | 0.993 DEBUG [Server db93a55ed387e7852ef9e898] pad Initial from 905 to PLPMTU 1232
server  | 0.993 DEBUG packet_sent this=0x55e807028b40, pn=0, ps=463
server  | 0.993 DEBUG ECN probing: sent 1 probes
server  | 0.993 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 0.993 DEBUG Building Initial dcid Some(CID [0]: ) scid Some(CID [10]: aab700068e60049c1357)
server  | 0.993 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: aab700068e60049c1357)
server  | 0.993 DEBUG Building Short dcid Some(CID [0]: )
server  | 0.993 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 0.993 DEBUG [Server db93a55ed387e7852ef9e898] delay duration 297.161333ms
server  | 0.993 DEBUG Setting timeout of 297.161333ms
server  | 0.993 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 0.993 DEBUG Building Initial dcid Some(CID [0]: ) scid Some(CID [10]: aab700068e60049c1357)
server  | 0.993 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: aab700068e60049c1357)
server  | 0.993 DEBUG Building Short dcid Some(CID [0]: )
server  | 0.993 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 0.993 DEBUG [Server db93a55ed387e7852ef9e898] delay duration 297.130375ms
server  | 0.993 DEBUG Setting timeout of 297.130375ms
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] pn=1 type=Initial pri-unv-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, NotEct) len 1204
server  |   -> RX 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  |   -> RX Padding { len: 1158 }
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] Rx ACK space=in, ranges=[0..=0]
server  | 1.027 DEBUG [LossRecovery] ACK for Initial - largest_acked=0
server  | 1.027 DEBUG on_packets_acked this=0x55e807028b40, limited=1, bytes_in_flight=769, cwnd=12320, state=SlowStart, new_acked=463
server  | 1.027 DEBUG Acked crypto frame space=in offset=0 length=90
server  | 1.027 DEBUG [pri-unv-path: [::]:443->[::ffff:193.167.0.100]:56165] Path validated Instant { tv_sec: 233, tv_nsec: 50917763 }
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] Drop packet number space in
server  | 1.027 DEBUG [LossRecovery] Reset loss recovery state for Initial
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] pn=0 type=Handshake pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, NotEct) len 76
server  |   -> RX Crypto { offset: 0, len: 36 }
server  | 1.027 DEBUG Read Ok(36) bytes
server  | 1.027 DEBUG [Agent 0x55e8070291d0] 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.027 DEBUG [Server db93a55ed387e7852ef9e898] TLS connection complete
server  | 1.027 DEBUG [pri-path: [::]:443->[::ffff:193.167.0.100]:56165] Path validated Instant { tv_sec: 233, tv_nsec: 50917763 }
server  | 1.027 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865
server  | 1.027 DEBUG [Crypto] application read keys installed
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] State change from Handshaking -> Connected
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] State change from Connected -> Confirmed
server  | 1.027 DEBUG PMTUD started with probe size 1380
server  | 1.027 INFO [Server db93a55ed387e7852ef9e898] Connection established
server  | 1.027 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 233, tv_nsec: 50917763 }
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.027 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: aab700068e60049c1357)
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] pn=1 type=Handshake pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 41
server  |   TX -> Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] Drop packet number space hs
server  | 1.027 DEBUG [LossRecovery] Reset loss recovery state for Handshake
server  | 1.027 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] pn=0 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 1332
server  |   TX -> HandshakeDone
server  |   TX -> NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [129, 50, 89, 185, 164, 204, 28, 253, 77, 241], stateless_reset_token: [227, 173, 219, 209, 123, 14, 252, 113, 97, 210, 145, 92, 109, 164, 174, 117] }
server  |   TX -> NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [103, 8, 113, 34, 52, 50, 6, 188, 151, 89], stateless_reset_token: [116, 82, 91, 87, 136, 182, 144, 203, 164, 25, 92, 53, 113, 95, 60, 144] }
server  |   TX -> NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [132, 110, 58, 144, 130, 182, 106, 82, 32, 83], stateless_reset_token: [48, 50, 143, 113, 184, 15, 142, 48, 12, 117, 39, 116, 115, 98, 22, 83] }
server  |   TX -> Padding { len: 1182 }
server  | 1.027 DEBUG packet_sent this=0x55e807028b40, pn=0, ps=1291
server  | 1.027 DEBUG ECN probing: sent 2 probes
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.027 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.027 DEBUG Sending PMTUD probe of size 1380, count 1
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] pn=1 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 1332
server  |   TX -> Ping
server  |   TX -> Padding { len: 1313 }
server  | 1.027 DEBUG packet_sent this=0x55e807028b40, pn=1, ps=1332
server  | 1.027 DEBUG ECN probing: sent 3 probes
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.027 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.027 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] delay duration 1.464135ms
server  | 1.027 DEBUG Setting timeout of 1.464135ms
server  | 1.027 WARN [Server ...] Dropped received packet: Decryption failure; Total: 1
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.027 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.027 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] delay duration 1.437756ms
server  | 1.027 DEBUG Setting timeout of 1.437756ms
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] pn=0 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 48
server  |   -> RX Stream { stream_id: 0, offset: 0, len: >>17, fin: true }
server  | 1.027 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 233, tv_nsec: 71547427 }
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.027 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.027 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.027 DEBUG [Server db93a55ed387e7852ef9e898] delay duration 1.407699ms
server  | 1.027 DEBUG Setting timeout of 1.407699ms
server  | 1.028 DEBUG [Server db93a55ed387e7852ef9e898] send session ticket 4067000cdb93a55ed387e7852ef9e8980104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0aaab700068e60049c1357110c00000001fa3aea7a000000016ab200c0000000ff02de1a0243e8200100686921
server  | 1.028 DEBUG Path = 'djtushuhez'
server  | 1.028 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.028 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.028 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.028 DEBUG [Server db93a55ed387e7852ef9e898] delay duration 283.013µs
server  | 1.028 DEBUG Setting timeout of 283.013µs
server  | 1.030 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.030 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.030 DEBUG CRYPTO for ap offset=0, len=182
server  | 1.030 DEBUG [Server db93a55ed387e7852ef9e898] pn=2 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 1232
server  |   TX -> Stream { stream_id: 0, offset: 0, len: 1024, fin: true }
server  |   TX -> Crypto { offset: 0, len: 182 }
server  | 1.030 DEBUG packet_sent this=0x55e807028b40, pn=2, ps=1232
server  | 1.030 DEBUG ECN probing: sent 4 probes
server  | 1.030 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.030 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.030 DEBUG CRYPTO for ap offset=182, len=139
server  | 1.030 DEBUG [Server db93a55ed387e7852ef9e898] pn=3 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 207
server  |   TX -> Crypto { offset: 182, len: 139 }
server  |   TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 104, 56, 251, 174, 227, 134, 30, 245, 109, 31, 210, 237, 128, 72, 214, 188, 123, 154, 61, 238, 35, 76, 34, 40, 72, 235, 79, 37, 59, 5, 177, 60, 99, 52, 81, 177] }
server  | 1.031 DEBUG packet_sent this=0x55e807028b40, pn=3, ps=207
server  | 1.031 DEBUG ECN probing: sent 5 probes
server  | 1.031 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.031 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.031 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.031 DEBUG [Server db93a55ed387e7852ef9e898] delay duration 16.620921ms
server  | 1.031 DEBUG Setting timeout of 16.620921ms
server  | 1.031 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.031 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.031 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.031 DEBUG [Server db93a55ed387e7852ef9e898] delay duration 16.600402ms
server  | 1.031 DEBUG Setting timeout of 16.600402ms
server  | 1.048 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.048 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.048 DEBUG [Server db93a55ed387e7852ef9e898] pn=4 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 27
server  |   TX -> Ack { largest_acknowledged: 0, ack_delay: 2562, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) }
server  | 1.048 DEBUG ECN probing: sent 6 probes
server  | 1.048 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.048 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.048 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.048 DEBUG [Server db93a55ed387e7852ef9e898] delay duration 116.98472ms
server  | 1.048 DEBUG Setting timeout of 116.98472ms
server  | 1.048 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.048 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.048 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.048 DEBUG [Server db93a55ed387e7852ef9e898] delay duration 116.932662ms
server  | 1.048 DEBUG Setting timeout of 116.932662ms
server  | 1.059 DEBUG [Server db93a55ed387e7852ef9e898] pn=1 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 39
server  |   -> RX Ack { largest_acknowledged: 0, ack_delay: 14, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) }
server  |   -> RX RetireConnectionId { sequence_number: 0 }
server  | 1.059 DEBUG [Server db93a55ed387e7852ef9e898] Rx ACK space=ap, ranges=[0..=0]
server  | 1.059 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=0
server  | 1.059 DEBUG on_packets_acked this=0x55e807028b40, limited=1, bytes_in_flight=2771, cwnd=12320, state=SlowStart, new_acked=1291
server  | 1.059 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 233, tv_nsec: 103729955 }
server  | 1.059 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.059 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.059 DEBUG [Server db93a55ed387e7852ef9e898] pn=5 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 48
server  |   TX -> NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [173, 220, 210, 186, 211, 172, 30, 174, 125, 51], stateless_reset_token: [56, 153, 10, 56, 204, 1, 138, 171, 36, 156, 67, 181, 38, 67, 59, 122] }
server  | 1.059 DEBUG packet_sent this=0x55e807028b40, pn=5, ps=48
server  | 1.059 DEBUG ECN probing: sent 7 probes
server  | 1.059 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.059 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.060 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.060 DEBUG [Server db93a55ed387e7852ef9e898] delay duration 19.878732ms
server  | 1.060 DEBUG Setting timeout of 19.878732ms
server  | 1.060 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.060 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.060 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.060 DEBUG [Server db93a55ed387e7852ef9e898] delay duration 19.860769ms
server  | 1.060 DEBUG Setting timeout of 19.860769ms
server  | 1.062 DEBUG [Server db93a55ed387e7852ef9e898] pn=2 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 37
server  |   -> RX Ack { largest_acknowledged: 2, ack_delay: 12, first_ack_range: 2, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 3, Ce: 0})) }
server  | 1.062 DEBUG [Server db93a55ed387e7852ef9e898] Rx ACK space=ap, ranges=[0..=2]
server  | 1.062 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=2
server  | 1.062 DEBUG on_packets_acked this=0x55e807028b40, limited=1, bytes_in_flight=255, cwnd=12320, state=SlowStart, new_acked=2564
server  | 1.062 DEBUG PMTUD probe of size 1380 succeeded
server  | 1.062 DEBUG PMTUD started with probe size 1420
server  | 1.062 DEBUG PLPMTU changed from 1232 to 1332, updating pacer
server  | 1.062 DEBUG Acked crypto frame space=ap offset=0 length=182
server  | 1.062 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.062 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.062 DEBUG Sending PMTUD probe of size 1420, count 1
server  | 1.062 DEBUG [Server db93a55ed387e7852ef9e898] pn=6 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 1372
server  |   TX -> Ping
server  |   TX -> MaxStreams { stream_type: BiDi, maximum_streams: 17 }
server  |   TX -> Padding { len: 1351 }
server  | 1.062 DEBUG packet_sent this=0x55e807028b40, pn=6, ps=1372
server  | 1.062 DEBUG ECN probing: sent 8 probes
server  | 1.062 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.062 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.062 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.062 DEBUG [Server db93a55ed387e7852ef9e898] delay duration 17.207425ms
server  | 1.062 DEBUG Setting timeout of 17.207425ms
server  | 1.062 DEBUG [Server db93a55ed387e7852ef9e898] pn=3 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 32
server  |   -> RX ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "" }
server  | 1.062 INFO [Server db93a55ed387e7852ef9e898] ConnectionClose received. Error code: Application(0) frame type 0 reason 
server  | 1.062 DEBUG [Server db93a55ed387e7852ef9e898] State change from Confirmed -> Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 233, tv_nsec: 411428055 } }
server  | 1.062 DEBUG [Server db93a55ed387e7852ef9e898] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.062 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.062 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 233, tv_nsec: 86545032 }
server  | 1.062 DEBUG [Server db93a55ed387e7852ef9e898] pn=7 type=Short pri-path: [::]:443->[::ffff:193.167.0.100]:56165 IpTos(Cs0, Ect0) len 30
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: 29, reason_phrase: "" }
server  | 1.062 DEBUG ECN probing: sent 9 probes
server  | 1.062 DEBUG Setting timeout of 324.79153ms
server  | 1.062 DEBUG Setting timeout of 324.784076ms

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 09:36:26,143 Using the client's key log file.
2025-04-30 09:36:26,151 
2025-04-30 09:36:26,152 Using the client's key log file.
2025-04-30 09:36:26,152 Using the client's key log file.
2025-04-30 09:36:26,159 
2025-04-30 09:36:26,160 Using the client's key log file.
2025-04-30 09:36:26,160 Using selector: EpollSelector
2025-04-30 09:36:26,460 Check of downloaded files succeeded.