2025-04-30 09:47:14,149 Generated random file: cpcecsevfh of size: 1024 2025-04-30 09:47:14,150 Requests: https://server4:443/cpcecsevfh 2025-04-30 09:47:14,207 2025-04-30 09:47:14,208 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_cshnr6fw/ TESTCASE_SERVER=handshake TESTCASE_CLIENT=handshake WWW=/tmp/www_3kpe009_/ DOWNLOADS=/tmp/download_pv3kwab0/ SERVER_LOGS=/tmp/logs_server_jum7ik4d CLIENT_LOGS=/tmp/logs_client_ezqrqrpc SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=us-central1-docker.pkg.dev/golang-interop-testing/quic/go-x-net:latest SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server4:443/cpcecsevfh" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-04-30 09:47:26,402 Container sim Recreate Container sim Recreated Container client Recreate Container server Recreate Container server Recreated Container client Recreated Attaching to client, server, sim sim | waiting 10s for server:443 client | Setting up routes... 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 server | ++ mktemp server | + P12CERT=/tmp/tmp.nrshIoAqar server | + mkdir -p /neqo/db server | + certutil -N -d sql:/neqo/db --empty-password client | wait-for-it.sh: 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.nrshIoAqar server | Warning: output encryption option -nodes ignored with -export server | + pk12util -d sql:/neqo/db -i /tmp/tmp.nrshIoAqar -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:30:e9:70:a6:91:48:cc:41:2f:00:e2:4c:ad:3e:74: server | 19:06:c1:bb 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:47:14 2025 server | Not After : Sat May 10 09:47:14 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:7d:b1:ac:ee:34:49:d7:20:f8:7b:4f:a6:13:31:78: server | aa:2a:15:93:63:df:92:0f:02:cc:fb:bc:39:a9:b0:24: server | ea:af:57:da:9f:c0:c1:73:d6:57:9d:a7:47:1c:87:7c: server | d5:1c:b0:8a:4c:8f:d0:5f:65:3a:ad:7f:e7:f9:9f:4b: server | 08 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 | fb:c3:51:ec:b3:5e:b2:46:eb:db:62:ef:11:ba:ee:5d: server | f7:f8:b5:49 server | server | Name: Certificate Authority Key Identifier server | Key ID: server | 55:af:d4:fc:56:a0:f1:14:a2:58:ea:ac:27:29:1d:a6: server | 25:12:e9:bf server | server | Signature Algorithm: X9.62 ECDSA signature with SHA256 server | Signature: server | 30:44:02:20:5c:d5:e1:c3:26:c3:f3:a3:e5:e7:12:a6: server | 98:27:bd:3a:fc:0c:11:a9:8d:b0:3b:31:61:73:0d:34: server | bd:e2:0b:1b:02:20:24:7a:a5:0d:a9:14:ed:98:fc:48: server | e2:b4:93:c2:e1:9c:6d:76:96:c5:3e:53:e1:f0:7f:16: server | d9:73:88:97:c4:11 server | Fingerprint (SHA-256): server | 58:EB:24:C1:E0:AE:99:01:97:7D:EC:BD:69:11:CE:AE:CB:6D:3E:24:3D:B8:42:67:9A:8E:66:C4:90:65:FA:CC server | Fingerprint (SHA1): server | 10:82:08:63:9B:71:DC:76:E1:FE:3B:48:EE:75:74:87:2F:81:A8:B2 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.761 DEBUG [Server] Unsupported version: 57414954 server | 0.761 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:47680 IpTos(Cs0, NotEct) len 15 sim | server:443 is available after 1.045792829s server | 0.761 DEBUG [Server] Unsupported version: 57414954 server | 0.761 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:47680 IpTos(Cs0, NotEct) len 15 server | 0.761 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" }) server | 0.761 DEBUG [Server] Unsupported version: 57414954 server | 0.761 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:47680 IpTos(Cs0, NotEct) len 15 server | 0.761 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 eth0tcpdump: listening on eth1, link-type EN10MB (Ethernet), snapshot length 262144 bytes sim | , link-type EN10MB (Ethernet), snapshot length 262144 bytes client | wait-for-it.sh: sim:57832 is available after 1 seconds client | 2025/04/30 09:47:15 listening on [::]:40841 server | 0.981 DEBUG [Server] Handle initial server | 0.981 INFO AddressValidation: no token; accepting server | 0.981 INFO [Server] Accept connection CID [8]: 7ad6d63699b55a12 server | 0.981 DEBUG Overwrite initial version Version1 ==> Version1 server | 0.983 DEBUG Outbound interface eth0 for destination ::ffff:193.167.0.100 has MTU 1500 server | 0.983 INFO [Server ...] Received valid Initial packet with scid CID [8]: 8a5c4c18647c1287 dcid CID [8]: 7ad6d63699b55a12 server | 0.983 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=7ad6d63699b55a12 server | 0.983 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 server | 0.983 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 server | 0.983 DEBUG [Server 7ad6d63699b55a12] State change from Init -> WaitInitial server | 0.983 DEBUG [Server 7ad6d63699b55a12] pn=0 type=Initial unv-path [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, NotEct) len 296 server | -> RX Crypto { offset: 0, len: 249 } server | 0.983 DEBUG Read Ok(249) bytes server | 0.983 DEBUG 0-RTT: no token, no 0-RTT server | 0.983 DEBUG Read secret available for Handshake: SymKey [32]: 2849a5133cf1fecf57de16ef5bf81605e663c91a8e7d716ca3ba31ee5e30267a server | 0.983 DEBUG Write secret available for Handshake: SymKey [32]: 1821c8296fbc490ffe87a55590844722f661b1c6edad8ec3949db0ee84d2784e server | 0.983 DEBUG Writing transport parameters, msg=8 server | 0.983 DEBUG Read secret available for ApplicationData: SymKey [32]: 93995a971232670ddc2c420f33a375544e2ab08cb8140f4e59502e3b1cc7bec8 server | 0.984 DEBUG Write secret available for ApplicationData: SymKey [32]: c71db536597b295bcb0a2d3df88db715bf053408184bb223a41b854d7b5c6c63 server | 0.984 DEBUG [Agent 0x55c7620721d0] state -> InProgress server | 0.984 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865 server | 0.984 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865 server | 0.984 DEBUG [Crypto] Handshake keys installed server | 0.984 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 0.984 DEBUG [Crypto] Application write key installed server | 0.984 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 180, tv_nsec: 101521018 } server | 0.984 DEBUG [unv-path [::]:443->[::ffff:193.167.0.100]:40841] Make permanent server | 0.984 DEBUG [unv-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841] set as primary path server | 0.984 DEBUG [Server 7ad6d63699b55a12] State change from WaitInitial -> Handshaking server | 0.984 WARN [Server ...] Dropped received packet: Coalesced packet has different DCID; Total: 1 server | 0.984 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 0.984 DEBUG Building Initial dcid Some(CID [8]: 8a5c4c18647c1287) scid Some(CID [10]: 626a79688be945e5deb8) server | 0.984 DEBUG CRYPTO for in offset=0, len=90 server | 0.984 DEBUG [Server 7ad6d63699b55a12] pn=0 type=Initial pri-unv-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, Ect0) len 144 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.984 DEBUG Building Handshake dcid Some(CID [8]: 8a5c4c18647c1287) scid Some(CID [10]: 626a79688be945e5deb8) server | 0.984 DEBUG CRYPTO for hs offset=0, len=724 server | 0.984 DEBUG [Server 7ad6d63699b55a12] pn=0 type=Handshake pri-unv-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, Ect0) len 916 server | TX -> Crypto { offset: 0, len: 724 } server | 0.984 DEBUG packet_sent this=0x55c762071b40, pn=0, ps=772 server | 0.984 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 0.984 DEBUG [Server 7ad6d63699b55a12] pad Initial from 916 to PLPMTU 1232 server | 0.984 DEBUG packet_sent this=0x55c762071b40, pn=0, ps=460 server | 0.984 DEBUG ECN probing: sent 1 probes server | 0.984 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 0.984 DEBUG Building Initial dcid Some(CID [8]: 8a5c4c18647c1287) scid Some(CID [10]: 626a79688be945e5deb8) server | 0.984 DEBUG Building Handshake dcid Some(CID [8]: 8a5c4c18647c1287) scid Some(CID [10]: 626a79688be945e5deb8) server | 0.984 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 0.984 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 0.984 DEBUG [Server 7ad6d63699b55a12] delay duration 297.149827ms server | 0.984 DEBUG Setting timeout of 297.149827ms server | 0.984 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 0.984 DEBUG Building Initial dcid Some(CID [8]: 8a5c4c18647c1287) scid Some(CID [10]: 626a79688be945e5deb8) server | 0.984 DEBUG Building Handshake dcid Some(CID [8]: 8a5c4c18647c1287) scid Some(CID [10]: 626a79688be945e5deb8) server | 0.984 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 0.984 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 0.984 DEBUG [Server 7ad6d63699b55a12] delay duration 297.111595ms server | 0.984 DEBUG Setting timeout of 297.111595ms client | 2025/04/30 09:47:16 connected to server4:443 server | 1.017 DEBUG [Server 7ad6d63699b55a12] pn=1 type=Initial pri-unv-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, NotEct) len 50 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | 1.017 DEBUG [Server 7ad6d63699b55a12] Rx ACK space=in, ranges=[0..=0] server | 1.017 DEBUG [LossRecovery] ACK for Initial - largest_acked=0 server | 1.017 DEBUG on_packets_acked this=0x55c762071b40, limited=1, bytes_in_flight=772, cwnd=12320, state=SlowStart, new_acked=460 server | 1.017 DEBUG Acked crypto frame space=in offset=0 length=90 server | 1.017 DEBUG [pri-unv-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841] Path validated Instant { tv_sec: 180, tv_nsec: 137384949 } server | 1.017 DEBUG [Server 7ad6d63699b55a12] Drop packet number space in server | 1.017 DEBUG [LossRecovery] Reset loss recovery state for Initial server | 1.017 DEBUG [Server 7ad6d63699b55a12] pn=0 type=Handshake pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, NotEct) len 88 server | -> RX Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | -> RX Crypto { offset: 0, len: 36 } server | 1.017 DEBUG [Server 7ad6d63699b55a12] Rx ACK space=hs, ranges=[0..=0] server | 1.017 DEBUG [LossRecovery] ACK for Handshake - largest_acked=0 server | 1.017 DEBUG on_packets_acked this=0x55c762071b40, limited=1, bytes_in_flight=0, cwnd=12320, state=SlowStart, new_acked=772 server | 1.017 DEBUG Acked crypto frame space=hs offset=0 length=724 server | 1.017 DEBUG Read Ok(36) bytes server | 1.017 DEBUG [Agent 0x55c7620721d0] 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.017 DEBUG [Server 7ad6d63699b55a12] TLS connection complete server | 1.017 DEBUG [pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841] Path validated Instant { tv_sec: 180, tv_nsec: 137384949 } server | 1.017 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865 server | 1.017 DEBUG [Crypto] application read keys installed server | 1.017 DEBUG [Server 7ad6d63699b55a12] State change from Handshaking -> Connected server | 1.017 DEBUG [Server 7ad6d63699b55a12] State change from Connected -> Confirmed server | 1.017 DEBUG PMTUD started with probe size 1380 server | 1.017 INFO [Server 7ad6d63699b55a12] Connection established server | 1.017 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 180, tv_nsec: 137384949 } server | 1.017 DEBUG [Server 7ad6d63699b55a12] pn=0 type=Short pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, NotEct) len 1062 server | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [211, 107, 250, 189, 22, 6, 88, 112], stateless_reset_token: [175, 138, 65, 44, 207, 111, 110, 200, 57, 222, 190, 130, 181, 240, 56, 102] } server | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [172, 248, 163, 80, 136, 116, 105, 183], stateless_reset_token: [37, 120, 211, 40, 159, 249, 84, 75, 249, 83, 146, 32, 242, 108, 181, 204] } server | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [66, 14, 167, 117, 26, 226, 245, 172], stateless_reset_token: [126, 240, 103, 238, 32, 20, 64, 156, 31, 204, 25, 66, 2, 199, 230, 167] } server | -> RX Padding { len: 950 } server | 1.017 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 180, tv_nsec: 157384949 } server | 1.017 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.017 DEBUG Building Handshake dcid Some(CID [8]: 8a5c4c18647c1287) scid Some(CID [10]: 626a79688be945e5deb8) server | 1.017 DEBUG [Server 7ad6d63699b55a12] pn=1 type=Handshake pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, Ect0) len 49 server | TX -> Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None } server | 1.017 DEBUG [Server 7ad6d63699b55a12] Drop packet number space hs server | 1.017 DEBUG [LossRecovery] Reset loss recovery state for Handshake server | 1.017 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.017 DEBUG [Server 7ad6d63699b55a12] pn=0 type=Short pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, Ect0) len 1332 server | TX -> HandshakeDone server | TX -> NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [174, 119, 35, 255, 220, 84, 113, 164, 39, 9], stateless_reset_token: [188, 195, 230, 178, 235, 153, 218, 191, 31, 45, 33, 248, 50, 58, 22, 222] } server | TX -> Padding { len: 1226 } server | 1.017 DEBUG packet_sent this=0x55c762071b40, pn=0, ps=1283 server | 1.017 DEBUG ECN probing: sent 2 probes server | 1.017 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.017 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.017 DEBUG Sending PMTUD probe of size 1380, count 1 server | 1.017 DEBUG [Server 7ad6d63699b55a12] pn=1 type=Short pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, Ect0) len 1332 server | TX -> Ping server | TX -> Padding { len: 1305 } server | 1.018 DEBUG packet_sent this=0x55c762071b40, pn=1, ps=1332 server | 1.018 DEBUG ECN probing: sent 3 probes server | 1.018 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.018 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.018 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.018 DEBUG [Server 7ad6d63699b55a12] delay duration 1.370999ms server | 1.018 DEBUG Setting timeout of 1.370999ms server | 1.018 DEBUG [Server 7ad6d63699b55a12] pn=1 type=Short pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, NotEct) len 48 server | -> RX Stream { stream_id: 0, offset: 0, len: 17, fin: true } server | 1.018 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 180, tv_nsec: 138064456 } server | 1.018 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.018 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.018 DEBUG [Server 7ad6d63699b55a12] pn=2 type=Short pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, Ect0) len 31 server | TX -> Ack { largest_acknowledged: 1, ack_delay: 0, first_ack_range: 1, ack_ranges: [], ecn_count: None } server | 1.018 DEBUG ECN probing: sent 4 probes server | 1.018 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.018 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.018 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.018 DEBUG [Server 7ad6d63699b55a12] delay duration 1.30887ms server | 1.018 DEBUG Setting timeout of 1.30887ms server | 1.019 DEBUG [Server 7ad6d63699b55a12] send session ticket 406300087ad6d63699b55a120104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0a626a79688be945e5deb8110c000000019a6ada9a000000016ab200c0000000ff02de1a0243e8200100686921 server | 1.019 DEBUG Path = 'cpcecsevfh' server | 1.019 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.019 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.019 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.019 DEBUG [Server 7ad6d63699b55a12] delay duration 357.516µs server | 1.019 DEBUG Setting timeout of 357.516µs server | 1.020 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.020 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.020 DEBUG CRYPTO for ap offset=0, len=174 server | 1.020 DEBUG [Server 7ad6d63699b55a12] pn=3 type=Short pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, Ect0) len 1232 server | TX -> Stream { stream_id: 0, offset: 0, len: 1024, fin: true } server | TX -> Crypto { offset: 0, len: 174 } server | 1.020 DEBUG packet_sent this=0x55c762071b40, pn=3, ps=1232 server | 1.020 DEBUG ECN probing: sent 5 probes server | 1.020 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.020 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.020 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.020 DEBUG [Server 7ad6d63699b55a12] delay duration 987.977µs server | 1.020 DEBUG Setting timeout of 987.977µs server | 1.020 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.020 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.020 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } server | 1.020 DEBUG [Server 7ad6d63699b55a12] delay duration 966.226µs server | 1.020 DEBUG Setting timeout of 966.226µs server | 1.022 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.022 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.022 DEBUG CRYPTO for ap offset=174, len=131 server | 1.022 DEBUG [Server 7ad6d63699b55a12] pn=4 type=Short pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, Ect0) len 207 server | TX -> Crypto { offset: 174, len: 131 } server | TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 253, 192, 241, 53, 50, 103, 253, 54, 97, 150, 33, 14, 159, 29, 1, 23, 213, 97, 69, 9, 244, 105, 46, 248, 127, 123, 44, 163, 194, 63, 206, 81, 123, 121, 134, 188] } server | 1.022 DEBUG packet_sent this=0x55c762071b40, pn=4, ps=207 server | 1.022 DEBUG ECN probing: sent 6 probes server | 1.022 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.022 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.022 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.022 DEBUG [Server 7ad6d63699b55a12] delay duration 114.574716ms server | 1.022 DEBUG Setting timeout of 114.574716ms server | 1.022 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.022 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.022 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false } server | 1.022 DEBUG [Server 7ad6d63699b55a12] delay duration 114.511999ms server | 1.022 DEBUG Setting timeout of 114.511999ms client | 2025/04/30 09:47:16 fetched https://server4:443/cpcecsevfh server | 1.051 DEBUG [Server 7ad6d63699b55a12] pn=2 type=Short pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, NotEct) len 33 server | -> RX Ack { largest_acknowledged: 1, ack_delay: 0, first_ack_range: 1, ack_ranges: [], ecn_count: None } server | 1.051 DEBUG [Server 7ad6d63699b55a12] Rx ACK space=ap, ranges=[0..=1] server | 1.051 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=1 server | 1.051 DEBUG on_packets_acked this=0x55c762071b40, limited=1, bytes_in_flight=1439, cwnd=12320, state=SlowStart, new_acked=2615 server | 1.051 DEBUG PMTUD probe of size 1380 succeeded server | 1.051 DEBUG PMTUD started with probe size 1420 server | 1.051 DEBUG PLPMTU changed from 1232 to 1332, updating pacer server | 1.051 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.051 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.051 DEBUG Sending PMTUD probe of size 1420, count 1 server | 1.051 DEBUG [Server 7ad6d63699b55a12] pn=5 type=Short pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, Ect0) len 1372 server | TX -> Ping server | TX -> Padding { len: 1345 } server | 1.051 DEBUG packet_sent this=0x55c762071b40, pn=5, ps=1372 server | 1.051 DEBUG ECN probing: sent 7 probes server | 1.051 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.051 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.051 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.051 DEBUG [Server 7ad6d63699b55a12] delay duration 103.462998ms server | 1.051 DEBUG Setting timeout of 103.462998ms server | 1.051 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.051 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.051 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.051 DEBUG [Server 7ad6d63699b55a12] delay duration 103.432731ms server | 1.051 DEBUG Setting timeout of 103.432731ms server | 1.052 DEBUG [Server 7ad6d63699b55a12] pn=3 type=Short pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 IpTos(Cs0, NotEct) len 32 server | -> RX ConnectionClose { error_code: Transport(0), frame_type: 0, reason_phrase: "" } server | 1.052 INFO [Server 7ad6d63699b55a12] ConnectionClose received. Error code: Transport(0) frame type 0 reason server | 1.052 DEBUG [Server 7ad6d63699b55a12] State change from Confirmed -> Draining { error: Transport(PeerError(0)), timeout: Instant { tv_sec: 180, tv_nsec: 482831218 } } server | 1.052 DEBUG [pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841] Path validated Instant { tv_sec: 180, tv_nsec: 172094536 } server | 1.052 DEBUG [Server 7ad6d63699b55a12] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false } server | 1.052 DEBUG Building Short dcid Some(CID [8]: 8a5c4c18647c1287) server | 1.052 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 180, tv_nsec: 172094536 } server | 1.052 DEBUG [Server 7ad6d63699b55a12] pn=6 type=Short pri-path:8a5c4c18647c1287 [::]:443->[::ffff:193.167.0.100]:40841 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 | 1.052 DEBUG ECN probing: sent 8 probes server | 1.052 DEBUG Setting timeout of 310.632468ms server | 1.052 DEBUG Setting timeout of 310.620866ms 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:47:26,496 Using the client's key log file. 2025-04-30 09:47:26,504 2025-04-30 09:47:26,505 Using the client's key log file. 2025-04-30 09:47:26,505 Using the client's key log file. 2025-04-30 09:47:26,512 2025-04-30 09:47:26,513 Using the client's key log file. 2025-04-30 09:47:26,513 Using selector: EpollSelector 2025-04-30 09:47:26,803 Check of downloaded files succeeded.