2025-04-30 12:55:57,035 Generated random file: gaohtcagab of size: 5120 2025-04-30 12:55:57,035 Generated random file: abmnjjkqze of size: 10240 2025-04-30 12:55:57,036 Requests: https://server4:443/gaohtcagab https://server4:443/abmnjjkqze 2025-04-30 12:55:57,096 2025-04-30 12:55:57,096 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_dy9srmma/ TESTCASE_SERVER=resumption TESTCASE_CLIENT=resumption WWW=/tmp/www_tyhplnlq/ DOWNLOADS=/tmp/download_ltny5my2/ SERVER_LOGS=/tmp/logs_server_37h11c7h CLIENT_LOGS=/tmp/logs_client_me8pew9m SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=ghcr.io/mozilla/neqo-qns:latest SERVER=aiortc/aioquic-qns:latest REQUESTS="https://server4:443/gaohtcagab https://server4:443/abmnjjkqze" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-04-30 12:56:09,970 Container sim Created Container server Recreate Container client Recreate Container client Recreated Container server Recreated Attaching to client, server, sim sim | waiting 10s for server:443 server | Setting up routes... server | Actual changes: server | tx-checksumming: off server | tx-checksum-ip-generic: off server | tx-checksum-sctp: off server | tcp-segmentation-offload: off server | tx-tcp-segmentation: off [requested on] server | tx-tcp-ecn-segmentation: off [requested on] server | tx-tcp-mangleid-segmentation: off [requested on] server | tx-tcp6-segmentation: off [requested on] server | tx-udp-segmentation: off [requested on] server | Endpoint's IPv4 address is 193.167.100.100 server | Endpoint's IPv6 address is fd00:cafe:cafe:100::100 server | Starting server 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 client | Endpoint's IPv6 address is fd00:cafe:cafe::100 client | + export PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/neqo/bin client | + PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/neqo/bin client | + '[' -n resumption ']' client | + '[' -n /logs/qlog/ ']' client | + case "$ROLE" in client | + /wait-for-it.sh sim:57832 -s -t 30 client | wait-for-it.sh: waiting 30 seconds for sim:57832 sim | server:443 is available after 1.063181398s 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 | + OPTIONS=(--cc cubic --qns-test "$TESTCASE" --qlog-dir "$QLOGDIR" --output-dir /downloads) client | + '[' 'https://server4:443/gaohtcagab https://server4:443/abmnjjkqze' ']' client | + mapfile -d ' ' -t URLS client | + OPTIONS+=("${URLS[@]}") client | + RUST_LOG=debug client | + RUST_BACKTRACE=1 client | + neqo-client --cc cubic --qns-test resumption --qlog-dir /logs/qlog/ --output-dir /downloads https://server4:443/gaohtcagab 'https://server4:443/abmnjjkqze client | ' client | ++ tee -i -a /logs/client.log client | 0.000 DEBUG Logging initialized client | 0.001 DEBUG Default socket send buffer size is 212992 client | 0.001 DEBUG Default socket receive buffer size is 1048576, not changing client | 0.001 INFO hq-interop Client connecting: 0.0.0.0:47352 -> 193.167.100.100:443 client | 0.001 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Client dcid=c057a71ce224b6df4bdd3576bb8301953a84e701 client | 0.001 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 client | 0.001 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 client | 0.001 DEBUG Outbound interface eth0 for destination 193.167.100.100 has MTU 1500 client | 0.001 DEBUG [unv-path 0.0.0.0:47352->193.167.100.100:443] Make permanent client | 0.001 DEBUG [unv-path:c057a71ce224b6df4bdd3576bb8301953a84e701 0.0.0.0:47352->193.167.100.100:443] set as primary path client | 0.001 DEBUG [pri-unv-path:c057a71ce224b6df4bdd3576bb8301953a84e701 0.0.0.0:47352->193.167.100.100:443] Path validated Instant { tv_sec: 507, tv_nsec: 799484203 } client | 0.001 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] client_start client | 0.002 DEBUG Writing transport parameters, msg=1 client | 0.002 DEBUG [Agent 0x55fd3b455f20] state -> InProgress client | 0.002 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] State change from Init -> WaitInitial client | 0.002 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.002 DEBUG Building Initial dcid Some(CID [20]: c057a71ce224b6df4bdd3576bb8301953a84e701) scid Some(CID [0]: ) client | 0.002 DEBUG CRYPTO for in offset=0, len=1201 client | 0.002 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=0 type=Initial pri-path:c057a71ce224b6df4bdd3576bb8301953a84e701 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 1252 client | TX -> Crypto { offset: 0, len: 1201 } client | 0.002 DEBUG packet_sent this=0x55fd3b469630, pn=0, ps=1252 client | 0.002 DEBUG ECN probing: sent 1 probes client | 0.002 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.002 DEBUG Building Initial dcid Some(CID [20]: c057a71ce224b6df4bdd3576bb8301953a84e701) scid Some(CID [0]: ) client | 0.002 DEBUG CRYPTO for in offset=1201, len=338 client | 0.002 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=1 type=Initial pri-path:c057a71ce224b6df4bdd3576bb8301953a84e701 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 390 client | TX -> Crypto { offset: 1201, len: 338 } client | 0.002 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pad Initial from 390 to PLPMTU 1252 client | 0.002 DEBUG packet_sent this=0x55fd3b469630, pn=1, ps=1252 client | 0.002 DEBUG ECN probing: sent 2 probes client | 0.002 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG Building Initial dcid Some(CID [20]: c057a71ce224b6df4bdd3576bb8301953a84e701) scid Some(CID [0]: ) client | 0.002 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 3.816787ms client | 0.002 DEBUG Setting timeout of 3.816787ms client | 0.002 DEBUG StateChange(WaitInitial) client | 0.002 WARN Cannot create stream ConnectionState client | 0.002 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG Building Initial dcid Some(CID [20]: c057a71ce224b6df4bdd3576bb8301953a84e701) scid Some(CID [0]: ) client | 0.002 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 3.757967ms client | 0.002 DEBUG Setting timeout of 3.757967ms client | 0.007 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.007 DEBUG Building Initial dcid Some(CID [20]: c057a71ce224b6df4bdd3576bb8301953a84e701) scid Some(CID [0]: ) client | 0.007 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.007 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 294.717286ms client | 0.007 DEBUG Setting timeout of 294.717286ms client | 0.040 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=0 type=Initial pri-path:c057a71ce224b6df4bdd3576bb8301953a84e701 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 42 client | -> RX Ack { largest_acknowledged: 0, ack_delay: 165, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | 0.040 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] Rx ACK space=in, ranges=[0..=0] client | 0.040 DEBUG [LossRecovery] ACK for Initial - largest_acked=0 client | 0.040 DEBUG on_packets_acked this=0x55fd3b469630, limited=1, bytes_in_flight=1252, cwnd=12520, state=SlowStart, new_acked=1252 client | 0.040 DEBUG Acked crypto frame space=in offset=0 length=1201 client | 0.040 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] Changing to use Server CID=5b24b377b3a417c5 client | 0.040 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] State change from WaitInitial -> WaitVersion client | 0.040 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.040 DEBUG Building Initial dcid Some(CID [8]: 5b24b377b3a417c5) scid Some(CID [0]: ) client | 0.040 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.040 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 78.197435ms client | 0.040 DEBUG Setting timeout of 78.197435ms client | 0.040 WARN Unhandled event StateChange(WaitVersion) client | 0.040 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.040 DEBUG Building Initial dcid Some(CID [8]: 5b24b377b3a417c5) scid Some(CID [0]: ) client | 0.040 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.040 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 78.15728ms client | 0.040 DEBUG Setting timeout of 78.15728ms client | 0.044 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=1 type=Initial pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 136 client | -> RX Ack { largest_acknowledged: 1, ack_delay: 271, first_ack_range: 1, ack_ranges: [], ecn_count: None } client | -> RX Crypto { offset: 0, len: 90 } client | 0.044 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] Rx ACK space=in, ranges=[0..=1] client | 0.044 DEBUG [LossRecovery] ACK for Initial - largest_acked=1 client | 0.044 DEBUG on_packets_acked this=0x55fd3b469630, limited=1, bytes_in_flight=0, cwnd=12520, state=SlowStart, new_acked=1252 client | 0.044 DEBUG Acked crypto frame space=in offset=1201 length=338 client | 0.044 DEBUG Read Ok(90) bytes client | 0.044 DEBUG Write secret available for Handshake: SymKey [48]: c2c5150c930906fbe469f31a2e41ba84fd079eeb47704f3531576df9253d0103ed26fbbb3e6bea0cb9013e7657579300 client | 0.044 DEBUG Read secret available for Handshake: SymKey [48]: 29991efee17234e8efb81ffcfc48f494fa9a4106d2b2ea8d51c8f94abc0d843b33bde872f8bb6c66b22397b8b4a05b96 client | 0.044 DEBUG [Agent 0x55fd3b455f20] state -> InProgress client | 0.044 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4866 client | 0.044 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4866 client | 0.044 DEBUG [Crypto] Handshake keys installed client | 0.044 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 507, tv_nsec: 842336993 } client | 0.044 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] State change from WaitVersion -> Handshaking client | 0.044 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=2 type=Handshake pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 785 client | -> RX Crypto { offset: 0, len: 746 } client | 0.044 DEBUG Read Ok(746) bytes client | 0.045 DEBUG [Agent 0x55fd3b455f20] state -> AuthenticationPending client | 0.045 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 507, tv_nsec: 842336993 } client | 0.045 DEBUG saving datagram of 279 bytes client | 0.045 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.045 DEBUG Building Initial dcid Some(CID [8]: 5b24b377b3a417c5) scid Some(CID [0]: ) client | 0.045 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=2 type=Initial pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 41 client | TX -> Ack { largest_acknowledged: 1, ack_delay: 162, first_ack_range: 1, ack_ranges: [], ecn_count: None } client | 0.045 DEBUG Building Handshake dcid Some(CID [8]: 5b24b377b3a417c5) scid Some(CID [0]: ) client | 0.045 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=0 type=Handshake pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 81 client | TX -> Ack { largest_acknowledged: 2, ack_delay: 162, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | 0.045 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] Drop packet number space in client | 0.045 DEBUG [LossRecovery] Reset loss recovery state for Initial client | 0.045 WARN [LossRecovery] ignoring in-2 from dropped space client | 0.045 DEBUG ECN probing: sent 3 probes client | 0.045 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.045 DEBUG Building Handshake dcid Some(CID [8]: 5b24b377b3a417c5) scid Some(CID [0]: ) client | 0.045 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.045 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 100.354664ms client | 0.045 DEBUG Setting timeout of 100.354664ms client | 0.045 DEBUG StateChange(Handshaking) client | 0.045 WARN Cannot create stream ConnectionState client | 0.045 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] Authenticated Ok client | 0.045 DEBUG Write secret available for ApplicationData: SymKey [48]: 10e67710132b5c4975e5f743378d018dbe8d942f5f1c79289aac72ceba294494d1decbeab2adbcc8479d9c16d9d1e72d client | 0.045 DEBUG Read secret available for ApplicationData: SymKey [48]: 33a75a1cfa4fe7d21cb09ef0433a714bff9a32ca73ef683158954d77fd8c456eeb0418121b9af5b72f1cc64ff42f2b94 client | 0.045 DEBUG [Agent 0x55fd3b455f20] SSL_AuthCertificateComplete: Ok(()) client | 0.045 DEBUG [Agent 0x55fd3b455f20] state -> Complete(SecretAgentInfo { version: 772, cipher: 4866, group: 29, resumed: false, early_data: false, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 }) client | 0.045 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] TLS connection complete client | 0.045 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4866 client | 0.045 DEBUG [Crypto] Application write key installed client | 0.045 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4866 client | 0.045 DEBUG [Crypto] application read keys installed client | 0.045 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] State change from Handshaking -> Connected client | 0.045 INFO [Client c057a71ce224b6df4bdd3576bb8301953a84e701] Connection established client | 0.045 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] process saved for epoch ApplicationData client | 0.045 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=3 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 279 client | -> RX Crypto { offset: 0, len: 89 } client | -> RX Padding { len: 167 } client | 0.045 DEBUG Read Ok(89) bytes client | 0.045 DEBUG [0x55fd3b455f20] Got resumption token [761]: 02000633fe70482a..6094438601c58e70 client | 0.045 DEBUG [Agent 0x55fd3b455f20] state -> Complete(SecretAgentInfo { version: 772, cipher: 4866, group: 29, resumed: false, early_data: false, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 }) client | 0.045 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 507, tv_nsec: 842336993 } client | 0.045 DEBUG stream BiDi creatable client | 0.045 INFO Created stream 0 for https://server4/gaohtcagab client | 0.045 INFO Saving https://server4/gaohtcagab to "/downloads/gaohtcagab" client | 0.046 DEBUG stream UniDi creatable client | 0.046 DEBUG StateChange(Connected) client | 0.046 DEBUG stream 0 writable client | 0.046 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.046 DEBUG Building Handshake dcid Some(CID [8]: 5b24b377b3a417c5) scid Some(CID [0]: ) client | 0.046 DEBUG CRYPTO for hs offset=0, len=52 client | 0.046 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=1 type=Handshake pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 89 client | TX -> Crypto { offset: 0, len: 52 } client | 0.046 DEBUG packet_sent this=0x55fd3b469630, pn=1, ps=89 client | 0.046 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.046 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=0 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 141 client | TX -> Ack { largest_acknowledged: 3, ack_delay: 258, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | TX -> Stream { stream_id: 0, offset: 0, len: 17, fin: true } client | 0.046 DEBUG packet_sent this=0x55fd3b469630, pn=0, ps=52 client | 0.046 DEBUG ECN probing: sent 4 probes client | 0.046 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.046 DEBUG Building Handshake dcid Some(CID [8]: 5b24b377b3a417c5) scid Some(CID [0]: ) client | 0.046 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.046 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.046 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 100.360445ms client | 0.046 DEBUG Setting timeout of 100.360445ms client | 0.078 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=4 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 222 client | -> RX Ack { largest_acknowledged: 0, ack_delay: 125, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | -> RX HandshakeDone client | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [200, 246, 87, 215, 149, 205, 251, 159], stateless_reset_token: [99, 145, 136, 156, 231, 32, 84, 135, 34, 123, 99, 16, 213, 19, 103, 211] } client | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [207, 196, 193, 40, 95, 214, 124, 96], stateless_reset_token: [108, 237, 61, 94, 78, 114, 237, 23, 20, 69, 224, 189, 39, 52, 125, 208] } client | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [7, 82, 89, 138, 32, 67, 160, 201], stateless_reset_token: [137, 210, 119, 155, 207, 110, 1, 3, 124, 143, 150, 102, 47, 174, 180, 61] } client | -> RX NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [199, 229, 238, 175, 40, 232, 129, 182], stateless_reset_token: [164, 183, 77, 148, 51, 242, 232, 25, 75, 81, 44, 233, 6, 209, 107, 228] } client | -> RX NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [141, 101, 82, 149, 90, 63, 15, 223], stateless_reset_token: [153, 31, 175, 76, 206, 35, 137, 150, 46, 150, 77, 27, 241, 6, 35, 80] } client | -> RX NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [212, 243, 54, 165, 96, 250, 250, 138], stateless_reset_token: [81, 4, 2, 160, 182, 28, 158, 152, 9, 225, 243, 20, 64, 9, 39, 215] } client | -> RX NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [225, 134, 154, 175, 65, 44, 226, 124], stateless_reset_token: [3, 211, 177, 7, 72, 11, 181, 3, 138, 18, 185, 220, 111, 56, 33, 242] } client | 0.078 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] Rx ACK space=ap, ranges=[0..=0] client | 0.078 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=0 client | 0.078 DEBUG on_packets_acked this=0x55fd3b469630, limited=1, bytes_in_flight=89, cwnd=12520, state=SlowStart, new_acked=52 client | 0.078 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] State change from Connected -> Confirmed client | 0.078 DEBUG PMTUD started with probe size 1380 client | 0.078 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] Drop packet number space hs client | 0.078 DEBUG [LossRecovery] Reset loss recovery state for Handshake client | 0.078 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] No preferred address to migrate to client | 0.078 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 507, tv_nsec: 896329960 } client | 0.078 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.078 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.078 DEBUG Sending PMTUD probe of size 1380, count 1 client | 0.078 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=1 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 1352 client | TX -> Ping client | TX -> Padding { len: 1325 } client | 0.078 DEBUG packet_sent this=0x55fd3b469630, pn=1, ps=1352 client | 0.078 DEBUG ECN probing: sent 5 probes client | 0.078 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.078 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.078 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.078 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 19.713944ms client | 0.078 DEBUG Setting timeout of 19.713944ms client | 0.078 DEBUG stream 0 complete client | 0.078 WARN Unhandled event StateChange(Confirmed) client | 0.078 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.078 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.078 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.078 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 19.676234ms client | 0.078 DEBUG Setting timeout of 19.676234ms client | 0.085 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=5 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 1200 client | -> RX Stream { stream_id: 0, offset: 0, len: 1177, fin: false } client | 0.085 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 507, tv_nsec: 883884729 } client | 0.085 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.085 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.085 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=2 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 31 client | TX -> Ack { largest_acknowledged: 5, ack_delay: 4, first_ack_range: 2, ack_ranges: [], ecn_count: None } client | 0.085 DEBUG ECN probing: sent 6 probes client | 0.085 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.085 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.085 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.085 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 109.089901ms client | 0.085 DEBUG Setting timeout of 109.089901ms client | 0.085 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.085 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.085 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.085 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 109.045297ms client | 0.085 DEBUG Setting timeout of 109.045297ms client | 0.086 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=6 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 1200 client | -> RX Stream { stream_id: 0, offset: 1177, len: 1175, fin: false } client | 0.086 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 507, tv_nsec: 904855638 } client | 0.086 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.086 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 19.976456ms client | 0.086 DEBUG Setting timeout of 19.976456ms client | 0.086 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.086 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.086 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 19.955637ms client | 0.086 DEBUG Setting timeout of 19.955637ms client | 0.087 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=7 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 1200 client | -> RX Stream { stream_id: 0, offset: 2352, len: 1175, fin: false } client | 0.087 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 507, tv_nsec: 885838308 } client | 0.087 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.087 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.087 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=3 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 31 client | TX -> Ack { largest_acknowledged: 7, ack_delay: 3, first_ack_range: 4, ack_ranges: [], ecn_count: None } client | 0.087 DEBUG ECN probing: sent 7 probes client | 0.087 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.087 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.087 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.087 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 107.146771ms client | 0.087 DEBUG Setting timeout of 107.146771ms client | 0.087 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.087 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.087 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.087 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 107.120222ms client | 0.087 DEBUG Setting timeout of 107.120222ms client | 0.088 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=8 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 1200 client | -> RX Stream { stream_id: 0, offset: 3527, len: 1175, fin: false } client | 0.089 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 507, tv_nsec: 907313351 } client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.089 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.089 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 19.978159ms client | 0.089 DEBUG Setting timeout of 19.978159ms client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.089 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.089 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 19.95723ms client | 0.089 DEBUG Setting timeout of 19.95723ms client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=9 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 443 client | -> RX Stream { stream_id: 0, offset: 4702, len: 418, fin: true } client | 0.089 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 507, tv_nsec: 887691245 } client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.089 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=4 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 31 client | TX -> Ack { largest_acknowledged: 9, ack_delay: 8, first_ack_range: 6, ack_ranges: [], ecn_count: None } client | 0.089 DEBUG ECN probing: sent 8 probes client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.089 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.089 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 105.249091ms client | 0.089 DEBUG Setting timeout of 105.249091ms client | 0.089 DEBUG resumption token [886]: 0000000126407500..6094438601c58e70 client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.089 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.089 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] delay duration 105.182806ms client | 0.089 DEBUG Setting timeout of 105.182806ms client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] State change from Confirmed -> Closing { error: Application(0), timeout: Instant { tv_sec: 508, tv_nsec: 237629845 } } client | 0.089 WARN Unhandled event StateChange(Closing { error: Application(0), timeout: Instant { tv_sec: 508, tv_nsec: 237629845 } }) client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.089 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.089 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 507, tv_nsec: 887917940 } client | 0.089 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=5 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 42 client | TX -> Ack { largest_acknowledged: 9, ack_delay: 28, first_ack_range: 6, ack_ranges: [], ecn_count: None } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 0.089 DEBUG ECN probing: sent 9 probes client | 0.089 DEBUG Setting timeout of 349.61278ms client | 0.111 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.111 DEBUG Building Short dcid Some(CID [8]: 5b24b377b3a417c5) client | 0.111 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 507, tv_nsec: 909648874 } client | 0.111 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] pn=6 type=Short pri-path:5b24b377b3a417c5 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 43 client | TX -> Ack { largest_acknowledged: 9, ack_delay: 2744, first_ack_range: 6, ack_ranges: [], ecn_count: None } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 0.111 DEBUG ECN probing: sent 10 probes client | 0.111 DEBUG ECN probing concluded with 10 probes sent client | 0.111 DEBUG Setting timeout of 327.859494ms client | 0.111 DEBUG Setting timeout of 327.845598ms client | 0.440 DEBUG [Client c057a71ce224b6df4bdd3576bb8301953a84e701] State change from Closing { error: Application(0), timeout: Instant { tv_sec: 508, tv_nsec: 237629845 } } -> Closed(Application(0)) client | 0.440 INFO Closing timer expired client | 0.440 DEBUG Output::None client | 0.440 WARN Unhandled event StateChange(Closed(Application(0))) client | 0.440 DEBUG Timer fired while closed client | 0.440 DEBUG Output::None client | 0.441 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Client dcid=c4a859584c8a62bca356f80f53395073a51107 client | 0.441 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865 client | 0.441 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865 client | 0.441 DEBUG Outbound interface eth0 for destination 193.167.100.100 has MTU 1500 client | 0.441 DEBUG [unv-path 0.0.0.0:47352->193.167.100.100:443] Make permanent client | 0.441 DEBUG [unv-path:c4a859584c8a62bca356f80f53395073a51107 0.0.0.0:47352->193.167.100.100:443] set as primary path client | 0.441 DEBUG [pri-unv-path:c4a859584c8a62bca356f80f53395073a51107 0.0.0.0:47352->193.167.100.100:443] Path validated Instant { tv_sec: 508, tv_nsec: 239539985 } client | 0.441 INFO [Client c4a859584c8a62bca356f80f53395073a51107] resumption token [886]: 0000000126407500..6094438601c58e70 client | 0.441 DEBUG Overwrite initial version Version1 ==> Version1 client | 0.441 DEBUG Overwrite initial version Version1 ==> Version1 client | 0.441 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] client_start client | 0.441 DEBUG Writing transport parameters, msg=1 client | 0.442 DEBUG Write secret available for ZeroRtt: SymKey [48]: 264b15cc92d8dc48c2ceef10fd1306bcd3b68a2883404ee5c6fbcfaff40e0fea35340326fe39f96848c787e929b374f1 client | 0.442 DEBUG [Agent 0x55fd3b469b30] state -> InProgress client | 0.442 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] State change from Init -> WaitInitial client | 0.442 DEBUG Making Write ZeroRtt CryptoDxState, v=Version1 cipher=4866 client | 0.442 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] Enabled 0-RTT client | 0.442 DEBUG stream BiDi creatable client | 0.442 INFO Created stream 0 for https://server4/abmnjjkqze client | 0.442 INFO Saving https://server4/abmnjjkqze to "/downloads/abmnjjkqze" client | 0.442 DEBUG stream UniDi creatable client | 0.442 DEBUG StateChange(WaitInitial) client | 0.442 DEBUG stream 0 writable client | 0.442 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.442 DEBUG Building Initial dcid Some(CID [19]: c4a859584c8a62bca356f80f53395073a51107) scid Some(CID [0]: ) client | 0.442 DEBUG CRYPTO for in offset=0, len=1202 client | 0.442 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=0 type=Initial pri-path:c4a859584c8a62bca356f80f53395073a51107 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 1252 client | TX -> Crypto { offset: 0, len: 1202 } client | 0.442 DEBUG packet_sent this=0x55fd3b469630, pn=0, ps=1252 client | 0.442 DEBUG ECN probing: sent 1 probes client | 0.442 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.442 DEBUG Building Initial dcid Some(CID [19]: c4a859584c8a62bca356f80f53395073a51107) scid Some(CID [0]: ) client | 0.442 DEBUG CRYPTO for in offset=1202, len=468 client | 0.442 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=1 type=Initial pri-path:c4a859584c8a62bca356f80f53395073a51107 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 519 client | TX -> Crypto { offset: 1202, len: 468 } client | 0.442 DEBUG Building ZeroRtt dcid Some(CID [19]: c4a859584c8a62bca356f80f53395073a51107) scid Some(CID [0]: ) client | 0.442 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=0 type=ZeroRtt pri-path:c4a859584c8a62bca356f80f53395073a51107 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 584 client | TX -> Stream { stream_id: 0, offset: 0, len: 17, fin: true } client | 0.442 DEBUG packet_sent this=0x55fd3b469630, pn=0, ps=65 client | 0.442 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pad Initial from 584 to PLPMTU 1252 client | 0.442 DEBUG packet_sent this=0x55fd3b469630, pn=1, ps=1187 client | 0.442 DEBUG ECN probing: sent 2 probes client | 0.442 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.442 DEBUG Building Initial dcid Some(CID [19]: c4a859584c8a62bca356f80f53395073a51107) scid Some(CID [0]: ) client | 0.442 DEBUG Building ZeroRtt dcid Some(CID [19]: c4a859584c8a62bca356f80f53395073a51107) scid Some(CID [0]: ) client | 0.442 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.442 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 113.910332ms client | 0.442 DEBUG Setting timeout of 113.910332ms client | 0.475 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=0 type=Initial pri-path:c4a859584c8a62bca356f80f53395073a51107 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 42 client | -> RX Ack { largest_acknowledged: 0, ack_delay: 118, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | 0.475 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] Rx ACK space=in, ranges=[0..=0] client | 0.475 DEBUG [LossRecovery] ACK for Initial - largest_acked=0 client | 0.475 DEBUG on_packets_acked this=0x55fd3b469630, limited=1, bytes_in_flight=1252, cwnd=12520, state=SlowStart, new_acked=1252 client | 0.475 DEBUG Acked crypto frame space=in offset=0 length=1202 client | 0.475 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] Changing to use Server CID=3638d2e09399e3ce client | 0.475 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] State change from WaitInitial -> WaitVersion client | 0.475 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.475 DEBUG Building Initial dcid Some(CID [8]: 3638d2e09399e3ce) scid Some(CID [0]: ) client | 0.475 DEBUG Building ZeroRtt dcid Some(CID [8]: 3638d2e09399e3ce) scid Some(CID [0]: ) client | 0.475 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.475 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 66.151267ms client | 0.475 DEBUG Setting timeout of 66.151267ms client | 0.475 WARN Unhandled event StateChange(WaitVersion) client | 0.475 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.475 DEBUG Building Initial dcid Some(CID [8]: 3638d2e09399e3ce) scid Some(CID [0]: ) client | 0.475 DEBUG Building ZeroRtt dcid Some(CID [8]: 3638d2e09399e3ce) scid Some(CID [0]: ) client | 0.475 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.475 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 66.110501ms client | 0.475 DEBUG Setting timeout of 66.110501ms client | 0.478 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=1 type=Initial pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 142 client | -> RX Ack { largest_acknowledged: 1, ack_delay: 183, first_ack_range: 1, ack_ranges: [], ecn_count: None } client | -> RX Crypto { offset: 0, len: 96 } client | 0.478 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] Rx ACK space=in, ranges=[0..=1] client | 0.478 DEBUG [LossRecovery] ACK for Initial - largest_acked=1 client | 0.478 DEBUG on_packets_acked this=0x55fd3b469630, limited=1, bytes_in_flight=65, cwnd=12520, state=SlowStart, new_acked=1187 client | 0.478 DEBUG Acked crypto frame space=in offset=1202 length=468 client | 0.478 DEBUG Read Ok(96) bytes client | 0.478 DEBUG Write secret available for Handshake: SymKey [48]: 0e3e01557cb5c18a134cc8911d736065946793e277fa086fae116b03117e4b24035e9dcd0ea7ce4f8816af0de29cce07 client | 0.478 DEBUG Read secret available for Handshake: SymKey [48]: f75d5eb0943c5d7e49983dd08aa835372fbc0a4c67d8497db5b7a5e2d686fa1da69785b339673e7b32cd23572dd68e99 client | 0.478 DEBUG [Agent 0x55fd3b469b30] state -> InProgress client | 0.478 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4866 client | 0.478 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4866 client | 0.478 DEBUG [Crypto] Handshake keys installed client | 0.478 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 508, tv_nsec: 276439627 } client | 0.478 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] State change from WaitVersion -> Handshaking client | 0.478 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=2 type=Handshake pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 238 client | -> RX Crypto { offset: 0, len: 199 } client | 0.478 DEBUG Read Ok(199) bytes client | 0.478 DEBUG Write secret available for ApplicationData: SymKey [48]: dee7d5d738bcc8287d92d885e50fd60a3378aecdfcfcd60f14729ed4fe43beafdaddc45e1c3defd90c68aa54d15aa761 client | 0.478 DEBUG Read secret available for ApplicationData: SymKey [48]: 1a8ff217b1efe9588df880b3fc61fab6b47058ad5c88e078c204e9814b360e6a8c7bc74148bfb3505136bb2f174b5ab1 client | 0.478 DEBUG [Agent 0x55fd3b469b30] state -> Complete(SecretAgentInfo { version: 772, cipher: 4866, group: 29, resumed: true, early_data: true, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 }) client | 0.478 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] TLS connection complete client | 0.478 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4866 client | 0.478 DEBUG [Crypto] Application write key installed client | 0.478 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4866 client | 0.479 DEBUG [Crypto] application read keys installed client | 0.479 DEBUG setting max_stream_data to 1048576 client | 0.479 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] State change from Handshaking -> Connected client | 0.479 INFO [Client c4a859584c8a62bca356f80f53395073a51107] Connection established client | 0.479 DEBUG setting max_stream_data to 1048576 client | 0.479 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 508, tv_nsec: 276439627 } client | 0.479 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=3 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 820 client | -> RX Crypto { offset: 0, len: 89 } client | -> RX Padding { len: 708 } client | 0.479 DEBUG Read Ok(89) bytes client | 0.479 DEBUG [0x55fd3b469b30] Got resumption token [761]: 02000633fe704eca..8d49d0e4ac32b255 client | 0.479 DEBUG [Agent 0x55fd3b469b30] state -> Complete(SecretAgentInfo { version: 772, cipher: 4866, group: 29, resumed: true, early_data: true, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 }) client | 0.479 DEBUG setting max_stream_data to 1048576 client | 0.479 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 508, tv_nsec: 276439627 } client | 0.479 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.479 DEBUG Building Initial dcid Some(CID [8]: 3638d2e09399e3ce) scid Some(CID [0]: ) client | 0.479 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=2 type=Initial pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 41 client | TX -> Ack { largest_acknowledged: 1, ack_delay: 128, first_ack_range: 1, ack_ranges: [], ecn_count: None } client | 0.479 DEBUG Building Handshake dcid Some(CID [8]: 3638d2e09399e3ce) scid Some(CID [0]: ) client | 0.479 DEBUG CRYPTO for hs offset=0, len=52 client | 0.479 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=0 type=Handshake pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 136 client | TX -> Ack { largest_acknowledged: 2, ack_delay: 128, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | TX -> Crypto { offset: 0, len: 52 } client | 0.479 DEBUG packet_sent this=0x55fd3b469630, pn=0, ps=95 client | 0.479 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] Drop packet number space in client | 0.479 DEBUG [LossRecovery] Reset loss recovery state for Initial client | 0.479 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.479 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=1 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 168 client | TX -> Ack { largest_acknowledged: 3, ack_delay: 128, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | 0.479 WARN [LossRecovery] ignoring in-2 from dropped space client | 0.479 DEBUG ECN probing: sent 3 probes client | 0.479 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.479 DEBUG Building Handshake dcid Some(CID [8]: 3638d2e09399e3ce) scid Some(CID [0]: ) client | 0.479 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.479 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.479 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 85.300338ms client | 0.479 DEBUG Setting timeout of 85.300338ms client | 0.479 DEBUG StateChange(Handshaking) client | 0.479 DEBUG stream BiDi creatable client | 0.479 DEBUG stream UniDi creatable client | 0.479 DEBUG StateChange(Connected) client | 0.479 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.479 DEBUG Building Handshake dcid Some(CID [8]: 3638d2e09399e3ce) scid Some(CID [0]: ) client | 0.479 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.479 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.479 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 85.265502ms client | 0.479 DEBUG Setting timeout of 85.265502ms client | 0.565 DEBUG [LossRecovery] PTO timer fired for Handshake client | 0.565 DEBUG [LossRecovery] PTO timer fired for ApplicationData client | 0.565 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] Lost: Ack(AckToken { space: Handshake, ranges: [PacketRange { largest: 2, smallest: 2, ack_needed: true }] }) client | 0.565 DEBUG [Recvd-hs] immediate_ack at Instant { tv_sec: 508, tv_nsec: 277470157 } client | 0.565 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] Lost: Crypto(CryptoRecoveryToken { space: Handshake, offset: 0, length: 52 }) client | 0.565 INFO Lost crypto frame space=hs offset=0 length=52 client | 0.565 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] Lost: Stream(Stream(SendStreamRecoveryToken { id: StreamId(0), offset: 0, length: 17, fin: true })) client | 0.565 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] Lost: Ack(AckToken { space: ApplicationData, ranges: [PacketRange { largest: 3, smallest: 3, ack_needed: true }] }) client | 0.565 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: Some(Handshake), probe: EnumSet(Handshake | ApplicationData), paced: false } client | 0.565 DEBUG Building Handshake dcid Some(CID [8]: 3638d2e09399e3ce) scid Some(CID [0]: ) client | 0.565 DEBUG CRYPTO for hs offset=0, len=52 client | 0.565 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=1 type=Handshake pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 95 client | TX -> Ack { largest_acknowledged: 2, ack_delay: 10923, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | TX -> Crypto { offset: 0, len: 52 } client | 0.565 DEBUG packet_sent this=0x55fd3b469630, pn=1, ps=95 client | 0.565 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.565 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=2 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 141 client | TX -> Stream { stream_id: 0, offset: 0, len: 17, fin: true } client | 0.565 DEBUG packet_sent this=0x55fd3b469630, pn=2, ps=46 client | 0.565 DEBUG ECN probing: sent 4 probes client | 0.565 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.565 DEBUG Building Handshake dcid Some(CID [8]: 3638d2e09399e3ce) scid Some(CID [0]: ) client | 0.565 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.565 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.565 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 170.624039ms client | 0.565 DEBUG Setting timeout of 170.624039ms client | 0.597 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=4 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 224 client | -> RX Ack { largest_acknowledged: 2, ack_delay: 115, first_ack_range: 0, ack_ranges: [AckRange { gap: 0, range: 0 }], ecn_count: None } client | -> RX HandshakeDone client | -> RX NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [34, 2, 174, 148, 184, 57, 164, 174], stateless_reset_token: [57, 45, 102, 191, 132, 230, 133, 24, 213, 164, 204, 226, 237, 64, 132, 171] } client | -> RX NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [143, 32, 69, 105, 10, 179, 74, 118], stateless_reset_token: [247, 8, 102, 86, 77, 164, 92, 97, 104, 117, 87, 194, 231, 125, 63, 142] } client | -> RX NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [8, 185, 230, 185, 191, 94, 155, 178], stateless_reset_token: [241, 211, 96, 127, 37, 243, 191, 90, 180, 160, 82, 24, 168, 234, 89, 47] } client | -> RX NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [178, 153, 43, 188, 90, 171, 99, 143], stateless_reset_token: [17, 95, 122, 116, 194, 23, 249, 68, 29, 89, 162, 25, 50, 66, 166, 207] } client | -> RX NewConnectionId { sequence_number: 5, retire_prior: 0, connection_id: [102, 253, 166, 184, 76, 104, 59, 214], stateless_reset_token: [75, 97, 13, 56, 181, 60, 100, 98, 132, 71, 171, 228, 88, 7, 203, 236] } client | -> RX NewConnectionId { sequence_number: 6, retire_prior: 0, connection_id: [169, 217, 134, 136, 54, 46, 12, 224], stateless_reset_token: [241, 245, 158, 230, 71, 126, 0, 106, 102, 118, 148, 40, 3, 110, 153, 181] } client | -> RX NewConnectionId { sequence_number: 7, retire_prior: 0, connection_id: [229, 107, 28, 59, 228, 40, 2, 43], stateless_reset_token: [164, 57, 118, 15, 175, 165, 41, 147, 9, 142, 68, 177, 129, 142, 196, 24] } client | 0.597 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] Rx ACK space=ap, ranges=[2..=2, 0..=0] client | 0.597 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=2 client | 0.597 DEBUG [Cubic [last_max_cwnd: 12520, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 301/8764 ssthresh 8764] Cong event -> recovery; cwnd 8764, ssthresh 8764 client | 0.597 DEBUG [Cubic [last_max_cwnd: 12520, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 301/8764 ssthresh 8764] state -> RecoveryStart client | 0.597 DEBUG on_packets_lost this=0x55fd3b469630, bytes_in_flight=301, cwnd=8764, state=RecoveryStart client | 0.597 DEBUG on_packets_acked this=0x55fd3b469630, limited=1, bytes_in_flight=190, cwnd=8764, state=RecoveryStart, new_acked=0 client | 0.597 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] Lost: Ack(AckToken { space: ApplicationData, ranges: [PacketRange { largest: 3, smallest: 3, ack_needed: true }] }) client | 0.597 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] State change from Connected -> Confirmed client | 0.597 DEBUG PMTUD started with probe size 1380 client | 0.597 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] Drop packet number space hs client | 0.597 DEBUG [LossRecovery] Reset loss recovery state for Handshake client | 0.597 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] No preferred address to migrate to client | 0.597 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 508, tv_nsec: 416066482 } client | 0.597 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.597 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.597 DEBUG Sending PMTUD probe of size 1380, count 1 client | 0.597 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=3 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 1352 client | TX -> Ack { largest_acknowledged: 4, ack_delay: 23, first_ack_range: 1, ack_ranges: [], ecn_count: None } client | TX -> Ping client | TX -> Padding { len: 1320 } client | 0.597 DEBUG packet_sent this=0x55fd3b469630, pn=3, ps=1352 client | 0.597 DEBUG ECN probing: sent 5 probes client | 0.598 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.598 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.598 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.598 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 98.268759ms client | 0.598 DEBUG Setting timeout of 98.268759ms client | 0.598 DEBUG stream 0 complete client | 0.598 WARN Unhandled event StateChange(Confirmed) client | 0.598 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.598 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.598 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.598 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 98.234304ms client | 0.598 DEBUG Setting timeout of 98.234304ms client | 0.599 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=5 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 1200 client | -> RX Stream { stream_id: 0, offset: 0, len: 1177, fin: false } client | 0.599 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 508, tv_nsec: 417358522 } client | 0.599 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.599 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.599 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.599 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 19.958974ms client | 0.599 DEBUG Setting timeout of 19.958974ms client | 0.599 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.599 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.599 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.599 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 19.932845ms client | 0.599 DEBUG Setting timeout of 19.932845ms client | 0.600 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=6 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 1200 client | -> RX Stream { stream_id: 0, offset: 1177, len: 1175, fin: false } client | 0.600 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 508, tv_nsec: 398356758 } client | 0.600 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.600 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.600 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=4 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 31 client | TX -> Ack { largest_acknowledged: 6, ack_delay: 9, first_ack_range: 3, ack_ranges: [], ecn_count: None } client | 0.600 DEBUG ECN probing: sent 6 probes client | 0.600 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.600 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.600 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.600 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 96.162468ms client | 0.600 DEBUG Setting timeout of 96.162468ms client | 0.600 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.600 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.600 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.600 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 96.134626ms client | 0.600 DEBUG Setting timeout of 96.134626ms client | 0.611 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=7 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 1200 client | -> RX Stream { stream_id: 0, offset: 2352, len: 1175, fin: false } client | 0.611 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 508, tv_nsec: 430120721 } client | 0.611 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.611 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.611 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.611 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 19.937453ms client | 0.611 DEBUG Setting timeout of 19.937453ms client | 0.611 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.611 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.611 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.611 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 19.890275ms client | 0.611 DEBUG Setting timeout of 19.890275ms client | 0.612 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=8 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 1200 client | -> RX Stream { stream_id: 0, offset: 3527, len: 1175, fin: false } client | 0.612 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 508, tv_nsec: 411076000 } client | 0.612 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.612 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.612 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=5 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 31 client | TX -> Ack { largest_acknowledged: 8, ack_delay: 3, first_ack_range: 5, ack_ranges: [], ecn_count: None } client | 0.612 DEBUG ECN probing: sent 7 probes client | 0.612 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.612 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.612 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.612 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 83.485194ms client | 0.612 DEBUG Setting timeout of 83.485194ms client | 0.612 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.612 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.612 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.612 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 83.445129ms client | 0.612 DEBUG Setting timeout of 83.445129ms client | 0.624 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=9 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 1200 client | -> RX Stream { stream_id: 0, offset: 4702, len: 1175, fin: false } client | 0.624 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 508, tv_nsec: 442720573 } client | 0.624 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.624 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.624 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.624 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 19.944356ms client | 0.624 DEBUG Setting timeout of 19.944356ms client | 0.624 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.624 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.624 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.624 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 19.915672ms client | 0.624 DEBUG Setting timeout of 19.915672ms client | 0.625 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=10 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 1200 client | -> RX Stream { stream_id: 0, offset: 5877, len: 1175, fin: false } client | 0.625 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 508, tv_nsec: 423681252 } client | 0.625 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.625 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.625 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=6 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 31 client | TX -> Ack { largest_acknowledged: 10, ack_delay: 4, first_ack_range: 7, ack_ranges: [], ecn_count: None } client | 0.625 DEBUG ECN probing: sent 8 probes client | 0.625 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.625 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.625 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.625 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 70.868881ms client | 0.625 DEBUG Setting timeout of 70.868881ms client | 0.625 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.625 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.625 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.625 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 70.838925ms client | 0.625 DEBUG Setting timeout of 70.838925ms client | 0.630 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=11 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 1200 client | -> RX Stream { stream_id: 0, offset: 7052, len: 1175, fin: false } client | 0.630 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 508, tv_nsec: 449226708 } client | 0.630 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.630 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.630 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.630 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 19.945578ms client | 0.630 DEBUG Setting timeout of 19.945578ms client | 0.630 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.630 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.630 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.630 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 19.911173ms client | 0.631 DEBUG Setting timeout of 19.911173ms client | 0.631 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=12 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 1200 client | -> RX Ack { largest_acknowledged: 4, ack_delay: 12, first_ack_range: 1, ack_ranges: [], ecn_count: None } client | -> RX Stream { stream_id: 0, offset: 8227, len: 1170, fin: false } client | 0.631 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] Rx ACK space=ap, ranges=[3..=4] client | 0.631 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=4 client | 0.631 DEBUG [Cubic [last_max_cwnd: 12520, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 0/8764 ssthresh 8764] state -> CongestionAvoidance client | 0.631 DEBUG on_packets_acked this=0x55fd3b469630, limited=1, bytes_in_flight=0, cwnd=8764, state=CongestionAvoidance, new_acked=1352 client | 0.631 DEBUG PMTUD probe of size 1380 succeeded client | 0.631 DEBUG PMTUD started with probe size 1420 client | 0.631 DEBUG PLPMTU changed from 1252 to 1352, updating pacer client | 0.631 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 508, tv_nsec: 430204570 } client | 0.631 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1352, pto: None, probe: EnumSet(), paced: false } client | 0.631 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.631 DEBUG Sending PMTUD probe of size 1420, count 1 client | 0.631 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=7 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 1392 client | TX -> Ack { largest_acknowledged: 12, ack_delay: 7, first_ack_range: 9, ack_ranges: [], ecn_count: None } client | TX -> Ping client | TX -> Padding { len: 1360 } client | 0.631 DEBUG packet_sent this=0x55fd3b469630, pn=7, ps=1392 client | 0.631 DEBUG ECN probing: sent 9 probes client | 0.632 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1352, pto: None, probe: EnumSet(), paced: false } client | 0.632 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.632 DEBUG TX blocked, profile=SendProfile { limit: 1352, pto: None, probe: EnumSet(), paced: false } client | 0.632 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 89.518513ms client | 0.632 DEBUG Setting timeout of 89.518513ms client | 0.632 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1352, pto: None, probe: EnumSet(), paced: false } client | 0.632 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.632 DEBUG TX blocked, profile=SendProfile { limit: 1352, pto: None, probe: EnumSet(), paced: false } client | 0.632 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 89.475773ms client | 0.632 DEBUG Setting timeout of 89.475773ms client | 0.640 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=13 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 868 client | -> RX Stream { stream_id: 0, offset: 9397, len: 843, fin: true } client | 0.640 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 508, tv_nsec: 458331017 } client | 0.640 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1352, pto: None, probe: EnumSet(), paced: false } client | 0.640 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.640 DEBUG TX blocked, profile=SendProfile { limit: 1352, pto: None, probe: EnumSet(), paced: false } client | 0.640 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 19.935268ms client | 0.640 DEBUG Setting timeout of 19.935268ms client | 0.640 DEBUG resumption token [885]: 0000000121407400..8d49d0e4ac32b255 client | 0.640 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1352, pto: None, probe: EnumSet(), paced: false } client | 0.640 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.640 DEBUG TX blocked, profile=SendProfile { limit: 1352, pto: None, probe: EnumSet(), paced: false } client | 0.640 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] delay duration 19.822357ms client | 0.640 DEBUG Setting timeout of 19.822357ms client | 0.640 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] State change from Confirmed -> Closing { error: Application(0), timeout: Instant { tv_sec: 508, tv_nsec: 707422087 } } client | 0.640 WARN Unhandled event StateChange(Closing { error: Application(0), timeout: Instant { tv_sec: 508, tv_nsec: 707422087 } }) client | 0.640 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1352, pto: None, probe: EnumSet(), paced: false } client | 0.640 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.640 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 508, tv_nsec: 438544677 } client | 0.640 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=8 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, Ect0) len 42 client | TX -> Ack { largest_acknowledged: 13, ack_delay: 26, first_ack_range: 10, ack_ranges: [], ecn_count: None } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 0.640 DEBUG ECN probing: sent 10 probes client | 0.640 DEBUG ECN probing concluded with 10 probes sent client | 0.640 DEBUG Setting timeout of 268.759609ms client | 0.665 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] output_path send_profile SendProfile { limit: 1352, pto: None, probe: EnumSet(), paced: false } client | 0.665 DEBUG Building Short dcid Some(CID [8]: 3638d2e09399e3ce) client | 0.665 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 508, tv_nsec: 463775252 } client | 0.665 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] pn=9 type=Short pri-path:3638d2e09399e3ce 0.0.0.0:47352->193.167.100.100:443 IpTos(Cs0, NotEct) len 43 client | TX -> Ack { largest_acknowledged: 13, ack_delay: 3180, first_ack_range: 10, ack_ranges: [], ecn_count: None } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 0.665 DEBUG Setting timeout of 243.51656ms client | 0.665 DEBUG Setting timeout of 243.504468ms client | 0.909 DEBUG [Client c4a859584c8a62bca356f80f53395073a51107] State change from Closing { error: Application(0), timeout: Instant { tv_sec: 508, tv_nsec: 707422087 } } -> Closed(Application(0)) client | 0.909 INFO Closing timer expired client | 0.909 DEBUG Output::None client | 0.909 WARN Unhandled event StateChange(Closed(Application(0))) client | 0.909 DEBUG Timer fired while closed client | 0.909 DEBUG Output::None 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:56:10,068 Using the client's key log file. 2025-04-30 12:56:10,079 2025-04-30 12:56:10,079 Using the client's key log file. 2025-04-30 12:56:10,079 Using the client's key log file. 2025-04-30 12:56:10,089 2025-04-30 12:56:10,089 Using the client's key log file. 2025-04-30 12:56:10,089 Using the client's key log file. 2025-04-30 12:56:10,970 Check of downloaded files succeeded.