2025-04-30 13:39:19,954 Generated random file: jilwazpktf of size: 5120 2025-04-30 13:39:19,954 Requests: https://server4:443/jilwazpktf 2025-04-30 13:39:20,334 2025-04-30 13:39:20,335 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_jhw_7r46/ TESTCASE_SERVER=transfer TESTCASE_CLIENT=transfer WWW=/tmp/www_itpf1_a1/ DOWNLOADS=/tmp/download_w5hfg1m7/ SERVER_LOGS=/tmp/logs_server_2noo7y6a CLIENT_LOGS=/tmp/logs_client_fz3auo2a SCENARIO="droplist --delay=15ms --bandwidth=10Mbps --queue=25 --drops_to_server=2,3,4,5,6,7" CLIENT=ghcr.io/mozilla/neqo-qns:latest SERVER=ghcr.io/aws/s2n-quic/s2n-quic-qns:latest REQUESTS="https://server4:443/jilwazpktf" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-04-30 13:39:40,147 Container sim Recreate Container sim Recreated Container client Recreate Container server Recreate Container client Recreated Container server Recreated Attaching to client, server, sim sim | waiting 10s for server:443 client | Setting up routes... server | Setting up routes... 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 | 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 | Endpoint's IPv4 address is 193.167.100.100 client | Endpoint's IPv4 address is 193.167.0.100 client | Endpoint's IPv6 address is fd00:cafe:cafe::100 server | Endpoint's IPv6 address is fd00:cafe:cafe:100::100 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 transfer ']' client | + '[' -n /logs/qlog/ ']' client | + case "$ROLE" in client | + /wait-for-it.sh sim:57832 -s -t 30 server | x86_64 client | wait-for-it.sh: waiting 30 seconds for sim:57832 server | Server listening on port 443 sim | server:443 is available after 1.041346553s sim | Using scenario: droplist --delay=15ms --bandwidth=10Mbps --queue=25 --drops_to_server=2,3,4,5,6,7 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/jilwazpktf ']' client | + mapfile -d ' ' -t URLS client | + OPTIONS+=("${URLS[@]}") client | + RUST_LOG=debug client | + RUST_BACKTRACE=1 client | + neqo-client --cc cubic --qns-test transfer --qlog-dir /logs/qlog/ --output-dir /downloads 'https://server4:443/jilwazpktf 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:59733 -> 193.167.100.100:443 client | 0.001 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Client dcid=57c142764252c36b50178dcfb9e1196dd1e9 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:59733->193.167.100.100:443] Make permanent client | 0.001 DEBUG [unv-path:57c142764252c36b50178dcfb9e1196dd1e9 0.0.0.0:59733->193.167.100.100:443] set as primary path client | 0.001 DEBUG [pri-unv-path:57c142764252c36b50178dcfb9e1196dd1e9 0.0.0.0:59733->193.167.100.100:443] Path validated Instant { tv_sec: 524, tv_nsec: 225760930 } client | 0.001 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] client_start client | 0.001 DEBUG Writing transport parameters, msg=1 client | 0.001 DEBUG [Agent 0x5619ac847270] state -> InProgress client | 0.001 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] State change from Init -> WaitInitial client | 0.002 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.002 DEBUG Building Initial dcid Some(CID [18]: 57c142764252c36b50178dcfb9e1196dd1e9) scid Some(CID [0]: ) client | 0.002 DEBUG CRYPTO for in offset=0, len=1203 client | 0.002 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=0 type=Initial pri-path:57c142764252c36b50178dcfb9e1196dd1e9 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1252 client | TX -> Crypto { offset: 0, len: 1203 } client | 0.002 DEBUG packet_sent this=0x5619ac85a970, pn=0, ps=1252 client | 0.002 DEBUG ECN probing: sent 1 probes client | 0.002 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.002 DEBUG Building Initial dcid Some(CID [18]: 57c142764252c36b50178dcfb9e1196dd1e9) scid Some(CID [0]: ) client | 0.002 DEBUG CRYPTO for in offset=1203, len=336 client | 0.002 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=1 type=Initial pri-path:57c142764252c36b50178dcfb9e1196dd1e9 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 386 client | TX -> Crypto { offset: 1203, len: 336 } client | 0.002 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pad Initial from 386 to PLPMTU 1252 client | 0.002 DEBUG packet_sent this=0x5619ac85a970, pn=1, ps=1252 client | 0.002 DEBUG ECN probing: sent 2 probes client | 0.002 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG Building Initial dcid Some(CID [18]: 57c142764252c36b50178dcfb9e1196dd1e9) 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 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 3.832403ms client | 0.002 DEBUG Setting timeout of 3.832403ms client | 0.002 DEBUG StateChange(WaitInitial) client | 0.002 WARN Cannot create stream ConnectionState client | 0.002 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true } client | 0.002 DEBUG Building Initial dcid Some(CID [18]: 57c142764252c36b50178dcfb9e1196dd1e9) 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 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 3.801305ms client | 0.002 DEBUG Setting timeout of 3.801305ms client | 0.007 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.007 DEBUG Building Initial dcid Some(CID [18]: 57c142764252c36b50178dcfb9e1196dd1e9) 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 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 294.786307ms client | 0.007 DEBUG Setting timeout of 294.786307ms sim | Dropping packet 2 (1252 bytes) from 193.167.0.100 client | 0.040 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=0 type=Initial pri-path:57c142764252c36b50178dcfb9e1196dd1e9 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1232 client | -> RX Ack { largest_acknowledged: 0, ack_delay: 724, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } client | -> RX Padding { len: 1180 } client | 0.040 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] 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=0x5619ac85a970, 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=1203 client | 0.040 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Changing to use Server CID=5a9e5a721196f5814e31e8d1d3d3d187 client | 0.040 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] State change from WaitInitial -> WaitVersion client | 0.040 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.040 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) 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 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 79.058907ms client | 0.040 DEBUG Setting timeout of 79.058907ms client | 0.040 WARN Unhandled event StateChange(WaitVersion) client | 0.040 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.041 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 0.041 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.041 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 79.030483ms client | 0.041 DEBUG Setting timeout of 79.030483ms client | 0.121 DEBUG [LossRecovery] PTO timer fired for Initial client | 0.121 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 1203, length: 336 }) client | 0.121 INFO Lost crypto frame space=in offset=1203 length=336 client | 0.121 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: EcnEct0 client | 0.121 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: Some(Initial), probe: EnumSet(Initial), paced: false } client | 0.121 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 0.121 DEBUG CRYPTO for in offset=1203, len=336 client | 0.121 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=2 type=Initial pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 384 client | TX -> Crypto { offset: 1203, len: 336 } client | 0.121 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pad Initial from 384 to PLPMTU 1252 client | 0.121 DEBUG packet_sent this=0x5619ac85a970, pn=2, ps=1252 client | 0.121 DEBUG ECN probing: sent 3 probes client | 0.121 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.121 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 0.121 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.121 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 235.672411ms client | 0.121 DEBUG Setting timeout of 235.672411ms sim | Dropping packet 3 (1252 bytes) from 193.167.0.100 client | 0.358 DEBUG [LossRecovery] PTO timer fired for Initial client | 0.358 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 1203, length: 336 }) client | 0.358 INFO Lost crypto frame space=in offset=1203 length=336 client | 0.358 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: EcnEct0 client | 0.358 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: Some(Initial), probe: EnumSet(Initial), paced: false } client | 0.358 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 0.358 DEBUG CRYPTO for in offset=1203, len=336 client | 0.358 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=3 type=Initial pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 384 client | TX -> Crypto { offset: 1203, len: 336 } client | 0.358 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pad Initial from 384 to PLPMTU 1252 client | 0.358 DEBUG packet_sent this=0x5619ac85a970, pn=3, ps=1252 client | 0.358 DEBUG ECN probing: sent 4 probes client | 0.358 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.358 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 0.358 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.358 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 471.507156ms client | 0.358 DEBUG Setting timeout of 471.507156ms sim | Dropping packet 4 (1252 bytes) from 193.167.0.100 client | 0.831 DEBUG [LossRecovery] PTO timer fired for Initial client | 0.831 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 1203, length: 336 }) client | 0.831 INFO Lost crypto frame space=in offset=1203 length=336 client | 0.831 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: EcnEct0 client | 0.831 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: Some(Initial), probe: EnumSet(Initial), paced: false } client | 0.831 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 0.831 DEBUG CRYPTO for in offset=1203, len=336 client | 0.831 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=4 type=Initial pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 384 client | TX -> Crypto { offset: 1203, len: 336 } client | 0.831 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pad Initial from 384 to PLPMTU 1252 client | 0.831 DEBUG packet_sent this=0x5619ac85a970, pn=4, ps=1252 client | 0.831 DEBUG ECN probing: sent 5 probes client | 0.831 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.831 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 0.831 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 0.831 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 943.180154ms client | 0.831 DEBUG Setting timeout of 943.180154ms sim | Dropping packet 5 (1252 bytes) from 193.167.0.100 client | 1.776 DEBUG [LossRecovery] PTO timer fired for Initial client | 1.776 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 1203, length: 336 }) client | 1.776 INFO Lost crypto frame space=in offset=1203 length=336 client | 1.776 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: EcnEct0 client | 1.776 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: Some(Initial), probe: EnumSet(Initial), paced: false } client | 1.776 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 1.776 DEBUG CRYPTO for in offset=1203, len=336 client | 1.776 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=5 type=Initial pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 384 client | TX -> Crypto { offset: 1203, len: 336 } client | 1.776 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pad Initial from 384 to PLPMTU 1252 client | 1.776 DEBUG packet_sent this=0x5619ac85a970, pn=5, ps=1252 client | 1.776 DEBUG ECN probing: sent 6 probes client | 1.776 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 1.776 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 1.776 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 1.776 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 1.886415572s client | 1.776 DEBUG Setting timeout of 1.886415572s sim | Dropping packet 6 (1252 bytes) from 193.167.0.100 client | 3.663 DEBUG [LossRecovery] PTO timer fired for Initial client | 3.663 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 1203, length: 336 }) client | 3.663 INFO Lost crypto frame space=in offset=1203 length=336 client | 3.663 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: EcnEct0 client | 3.663 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: Some(Initial), probe: EnumSet(Initial), paced: false } client | 3.663 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 3.663 DEBUG CRYPTO for in offset=1203, len=336 client | 3.664 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=6 type=Initial pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 384 client | TX -> Crypto { offset: 1203, len: 336 } client | 3.664 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pad Initial from 384 to PLPMTU 1252 client | 3.664 DEBUG packet_sent this=0x5619ac85a970, pn=6, ps=1252 client | 3.664 DEBUG ECN probing: sent 7 probes client | 3.664 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 3.664 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 3.664 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 3.664 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 3.773013035s client | 3.664 DEBUG Setting timeout of 3.773013035s sim | Dropping packet 7 (1252 bytes) from 193.167.0.100 client | 7.438 DEBUG [LossRecovery] PTO timer fired for Initial client | 7.438 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 1203, length: 336 }) client | 7.438 INFO Lost crypto frame space=in offset=1203 length=336 client | 7.438 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: EcnEct0 client | 7.438 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: Some(Initial), probe: EnumSet(Initial), paced: false } client | 7.438 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.438 DEBUG CRYPTO for in offset=1203, len=336 client | 7.438 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=7 type=Initial pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 384 client | TX -> Crypto { offset: 1203, len: 336 } client | 7.438 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pad Initial from 384 to PLPMTU 1252 client | 7.438 DEBUG packet_sent this=0x5619ac85a970, pn=7, ps=1252 client | 7.438 DEBUG ECN probing: sent 8 probes client | 7.438 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.438 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.438 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.438 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 7.546181211s client | 7.438 DEBUG Setting timeout of 7.546181211s client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=1 type=Initial pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 148 client | -> RX Ack { largest_acknowledged: 7, ack_delay: 1222, first_ack_range: 0, ack_ranges: [AckRange { gap: 5, range: 0 }], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 2, Ce: 0})) } client | -> RX Crypto { offset: 0, len: 90 } client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Rx ACK space=in, ranges=[7..=7, 0..=0] client | 7.473 DEBUG [LossRecovery] ACK for Initial - largest_acked=7 client | 7.473 DEBUG packet_lost this=0x5619ac85a970, pn=1, ps=1252 client | 7.473 DEBUG packet_lost this=0x5619ac85a970, pn=2, ps=1252 client | 7.473 DEBUG packet_lost this=0x5619ac85a970, pn=3, ps=1252 client | 7.473 DEBUG packet_lost this=0x5619ac85a970, pn=4, ps=1252 client | 7.473 DEBUG packet_lost this=0x5619ac85a970, pn=5, ps=1252 client | 7.473 DEBUG packet_lost this=0x5619ac85a970, pn=6, ps=1252 client | 7.473 DEBUG [Cubic [last_max_cwnd: 12520, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 1252/8764 ssthresh 8764] Cong event -> recovery; cwnd 8764, ssthresh 8764 client | 7.473 DEBUG [Cubic [last_max_cwnd: 12520, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 1252/8764 ssthresh 8764] state -> RecoveryStart client | 7.473 INFO [Cubic [last_max_cwnd: 12520, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 1252/8764 ssthresh 8764] persistent congestion client | 7.473 DEBUG [Cubic [last_max_cwnd: 12520, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 1252/2504 ssthresh 8764] state -> PersistentCongestion client | 7.473 DEBUG on_packets_lost this=0x5619ac85a970, bytes_in_flight=1252, cwnd=2504, state=PersistentCongestion client | 7.473 DEBUG [Cubic [last_max_cwnd: 12520, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 0/2504 ssthresh 8764] slow start += 0 client | 7.473 DEBUG [Cubic [last_max_cwnd: 12520, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 0/2504 ssthresh 8764] on_packets_acked this=0x5619ac85a970, limited=0, bytes_in_flight=0, cwnd=2504, state=PersistentCongestion, new_acked=0 client | 7.473 DEBUG Acked crypto frame space=in offset=1203 length=336 client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 1203, length: 336 }) client | 7.473 INFO Lost crypto frame space=in offset=1203 length=336 client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: EcnEct0 client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 1203, length: 336 }) client | 7.473 INFO Lost crypto frame space=in offset=1203 length=336 client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: EcnEct0 client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 1203, length: 336 }) client | 7.473 INFO Lost crypto frame space=in offset=1203 length=336 client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: EcnEct0 client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 1203, length: 336 }) client | 7.473 INFO Lost crypto frame space=in offset=1203 length=336 client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: EcnEct0 client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 1203, length: 336 }) client | 7.473 INFO Lost crypto frame space=in offset=1203 length=336 client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: EcnEct0 client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: Crypto(CryptoRecoveryToken { space: Initial, offset: 1203, length: 336 }) client | 7.473 INFO Lost crypto frame space=in offset=1203 length=336 client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Lost: EcnEct0 client | 7.473 DEBUG Read Ok(90) bytes client | 7.473 DEBUG Write secret available for Handshake: SymKey [32]: 34893f3764364f16e2858b28eefc272585659691d1983442ecc277d53bbc59bc client | 7.473 DEBUG Read secret available for Handshake: SymKey [32]: e7ccb2425b4aed43d800417d87f5411be7c624d579b91ddaddd9ebfbb694eb0a client | 7.473 DEBUG [Agent 0x5619ac847270] state -> InProgress client | 7.473 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865 client | 7.473 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865 client | 7.473 DEBUG [Crypto] Handshake keys installed client | 7.473 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 698039907 } client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] State change from WaitVersion -> Handshaking client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=0 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1084 client | -> RX Crypto { offset: 0, len: 1038 } client | 7.473 DEBUG Read Ok(1038) bytes client | 7.473 DEBUG [Agent 0x5619ac847270] state -> InProgress client | 7.473 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 698039907 } client | 7.473 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.474 DEBUG Building Initial dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=8 type=Initial pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 52 client | TX -> Ack { largest_acknowledged: 1, ack_delay: 85, first_ack_range: 1, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 2, Ce: 0})) } client | 7.474 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=0 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 103 client | TX -> Ack { largest_acknowledged: 0, ack_delay: 85, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Drop packet number space in client | 7.474 DEBUG [LossRecovery] Reset loss recovery state for Initial client | 7.474 WARN [LossRecovery] ignoring in-8 from dropped space client | 7.474 DEBUG ECN probing: sent 9 probes client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.474 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.474 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 101.78371ms client | 7.474 DEBUG Setting timeout of 101.78371ms client | 7.474 DEBUG StateChange(Handshaking) client | 7.474 WARN Cannot create stream ConnectionState client | 7.474 DEBUG stream BiDi creatable client | 7.474 WARN Cannot create stream ConnectionState client | 7.474 DEBUG stream UniDi creatable client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.474 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.474 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 101.752441ms client | 7.474 DEBUG Setting timeout of 101.752441ms client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=1 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1232 client | -> RX Crypto { offset: 1038, len: 1185 } client | 7.474 DEBUG Read Ok(1185) bytes client | 7.474 DEBUG [Agent 0x5619ac847270] state -> InProgress client | 7.474 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 698998948 } client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.474 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=1 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 50 client | TX -> Ack { largest_acknowledged: 1, ack_delay: 7, first_ack_range: 1, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 2, Ce: 0})) } client | 7.474 DEBUG ECN probing: sent 10 probes client | 7.474 DEBUG ECN probing concluded with 10 probes sent client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.474 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.474 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 101.490097ms client | 7.474 DEBUG Setting timeout of 101.490097ms client | 7.474 DEBUG stream BiDi creatable client | 7.474 WARN Cannot create stream ConnectionState client | 7.474 DEBUG stream UniDi creatable client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.474 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.474 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.474 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 101.381205ms client | 7.474 DEBUG Setting timeout of 101.381205ms client | 7.475 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=2 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1232 client | -> RX Crypto { offset: 2223, len: 1185 } client | 7.475 DEBUG Read Ok(1185) bytes client | 7.475 DEBUG [Agent 0x5619ac847270] state -> InProgress client | 7.475 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 699996377 } client | 7.475 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.475 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.475 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=2 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 50 client | TX -> Ack { largest_acknowledged: 2, ack_delay: 5, first_ack_range: 2, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 3, Ce: 0})) } client | 7.475 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.475 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.475 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.475 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 100.509568ms client | 7.475 DEBUG Setting timeout of 100.509568ms client | 7.475 DEBUG stream BiDi creatable client | 7.475 WARN Cannot create stream ConnectionState client | 7.475 DEBUG stream UniDi creatable client | 7.475 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.475 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.475 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.475 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 100.477658ms client | 7.475 DEBUG Setting timeout of 100.477658ms client | 7.476 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=3 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1232 client | -> RX Crypto { offset: 3408, len: 1185 } client | 7.476 DEBUG Read Ok(1185) bytes client | 7.476 DEBUG [Agent 0x5619ac847270] state -> InProgress client | 7.476 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 701017034 } client | 7.476 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.476 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.476 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=3 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 50 client | TX -> Ack { largest_acknowledged: 3, ack_delay: 3, first_ack_range: 3, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 4, Ce: 0})) } client | 7.476 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.476 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.476 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.476 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 99.479736ms client | 7.476 DEBUG Setting timeout of 99.479736ms client | 7.476 DEBUG stream BiDi creatable client | 7.476 WARN Cannot create stream ConnectionState client | 7.476 DEBUG stream UniDi creatable client | 7.476 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.476 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.476 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.476 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 99.448738ms client | 7.476 DEBUG Setting timeout of 99.448738ms client | 7.477 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=4 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1232 client | -> RX Crypto { offset: 4593, len: 1185 } client | 7.477 DEBUG Read Ok(1185) bytes client | 7.477 DEBUG [Agent 0x5619ac847270] state -> InProgress client | 7.477 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 702030844 } client | 7.477 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.477 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.477 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=4 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 50 client | TX -> Ack { largest_acknowledged: 4, ack_delay: 4, first_ack_range: 4, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 5, Ce: 0})) } client | 7.477 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.477 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.477 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.477 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 98.498006ms client | 7.477 DEBUG Setting timeout of 98.498006ms client | 7.477 DEBUG stream BiDi creatable client | 7.477 WARN Cannot create stream ConnectionState client | 7.477 DEBUG stream UniDi creatable client | 7.477 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.477 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.477 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.477 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 98.467689ms client | 7.477 DEBUG Setting timeout of 98.467689ms client | 7.478 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=5 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1232 client | -> RX Crypto { offset: 5778, len: 1185 } client | 7.478 DEBUG Read Ok(1185) bytes client | 7.478 DEBUG [Agent 0x5619ac847270] state -> InProgress client | 7.478 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 703017004 } client | 7.478 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.478 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.478 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=5 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 50 client | TX -> Ack { largest_acknowledged: 5, ack_delay: 4, first_ack_range: 5, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 6, Ce: 0})) } client | 7.478 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.478 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.478 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.478 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 97.511315ms client | 7.478 DEBUG Setting timeout of 97.511315ms client | 7.478 DEBUG stream BiDi creatable client | 7.478 WARN Cannot create stream ConnectionState client | 7.478 DEBUG stream UniDi creatable client | 7.478 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.478 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.478 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.478 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 97.482772ms client | 7.478 DEBUG Setting timeout of 97.482772ms client | 7.506 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=6 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1232 client | -> RX Ack { largest_acknowledged: 0, ack_delay: 545, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } client | -> RX Crypto { offset: 6963, len: 1176 } client | 7.506 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Rx ACK space=hs, ranges=[0..=0] client | 7.506 DEBUG [LossRecovery] ACK for Handshake - largest_acked=0 client | 7.506 DEBUG on_packets_acked this=0x5619ac85a970, limited=1, bytes_in_flight=0, cwnd=2504, state=SlowStart, new_acked=0 client | 7.506 DEBUG Read Ok(1176) bytes client | 7.506 DEBUG [Agent 0x5619ac847270] state -> InProgress client | 7.506 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 731619628 } client | 7.506 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.506 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.506 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=6 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 50 client | TX -> Ack { largest_acknowledged: 6, ack_delay: 6, first_ack_range: 6, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 7, Ce: 0})) } client | 7.507 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.507 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.507 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.507 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 68.862732ms client | 7.507 DEBUG Setting timeout of 68.862732ms client | 7.507 DEBUG stream BiDi creatable client | 7.507 WARN Cannot create stream ConnectionState client | 7.507 DEBUG stream UniDi creatable client | 7.507 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.507 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.507 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.507 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 68.832616ms client | 7.507 DEBUG Setting timeout of 68.832616ms client | 7.507 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=7 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1232 client | -> RX Crypto { offset: 8139, len: 1185 } client | 7.507 DEBUG Read Ok(1185) bytes client | 7.507 DEBUG [Agent 0x5619ac847270] state -> InProgress client | 7.507 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 732606832 } client | 7.507 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.507 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.507 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=7 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 50 client | TX -> Ack { largest_acknowledged: 7, ack_delay: 4, first_ack_range: 7, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 8, Ce: 0})) } client | 7.507 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.507 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.507 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.507 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 67.919934ms client | 7.507 DEBUG Setting timeout of 67.919934ms client | 7.507 DEBUG stream BiDi creatable client | 7.507 WARN Cannot create stream ConnectionState client | 7.507 DEBUG stream UniDi creatable client | 7.507 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.507 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.508 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.508 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 67.89118ms client | 7.508 DEBUG Setting timeout of 67.89118ms client | 7.508 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=8 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 661 client | -> RX Crypto { offset: 9324, len: 614 } client | 7.508 DEBUG Read Ok(614) bytes client | 7.509 DEBUG [Agent 0x5619ac847270] state -> AuthenticationPending client | 7.509 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 733154669 } client | 7.509 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.509 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.509 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=8 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 51 client | TX -> Ack { largest_acknowledged: 8, ack_delay: 87, first_ack_range: 8, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 8, Ce: 0})) } client | 7.509 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.509 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.509 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.509 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 66.698637ms client | 7.509 DEBUG Setting timeout of 66.698637ms client | 7.509 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Authenticated Ok client | 7.509 DEBUG Write secret available for ApplicationData: SymKey [32]: 3182288a407fac61b884e1e9300d6db531a0da9720a0355b2d8ca4d8fe0df30a client | 7.509 DEBUG Read secret available for ApplicationData: SymKey [32]: 4c0daa47214e2f0576bb3975f99f3552fbfbeaf9962700381b610756d435d5f0 client | 7.509 DEBUG [Agent 0x5619ac847270] SSL_AuthCertificateComplete: Ok(()) client | 7.509 DEBUG [Agent 0x5619ac847270] state -> Complete(SecretAgentInfo { version: 772, cipher: 4865, group: 29, resumed: false, early_data: false, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 }) client | 7.509 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] TLS connection complete client | 7.509 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865 client | 7.509 DEBUG [Crypto] Application write key installed client | 7.509 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865 client | 7.509 DEBUG [Crypto] application read keys installed client | 7.509 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] State change from Handshaking -> Connected client | 7.509 INFO [Client 57c142764252c36b50178dcfb9e1196dd1e9] Connection established client | 7.509 DEBUG stream BiDi creatable client | 7.509 INFO Created stream 0 for https://server4/jilwazpktf client | 7.509 INFO Saving https://server4/jilwazpktf to "/downloads/jilwazpktf" client | 7.509 DEBUG stream UniDi creatable client | 7.509 DEBUG StateChange(Connected) client | 7.509 DEBUG stream 0 writable client | 7.509 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.509 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.509 DEBUG CRYPTO for hs offset=0, len=36 client | 7.509 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=9 type=Handshake pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 81 client | TX -> Crypto { offset: 0, len: 36 } client | 7.509 DEBUG packet_sent this=0x5619ac85a970, pn=9, ps=81 client | 7.509 DEBUG Building Short dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) client | 7.509 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=0 type=Short pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 135 client | TX -> Stream { stream_id: 0, offset: 0, len: 17, fin: true } client | 7.509 DEBUG packet_sent this=0x5619ac85a970, pn=0, ps=54 client | 7.509 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.509 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.509 DEBUG Building Short dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) client | 7.509 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.509 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 101.802045ms client | 7.509 DEBUG Setting timeout of 101.802045ms client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=0 type=Short pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1452 client | -> RX Ping client | -> RX Padding { len: 1433 } client | 7.542 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 531, tv_nsec: 767152286 } client | 7.542 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 767152286 } client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.542 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.542 DEBUG Building Short dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=1 type=Short pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 42 client | TX -> Ack { largest_acknowledged: 0, ack_delay: 4, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) } client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.542 DEBUG Building Handshake dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) scid Some(CID [0]: ) client | 7.542 DEBUG Building Short dcid Some(CID [16]: 5a9e5a721196f5814e31e8d1d3d3d187) client | 7.542 DEBUG TX blocked, profile=SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 68.98408ms client | 7.542 DEBUG Setting timeout of 68.98408ms client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=1 type=Short pri-path:5a9e5a721196f5814e31e8d1d3d3d187 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 133 client | -> RX Ack { largest_acknowledged: 0, ack_delay: 67, first_ack_range: 0, ack_ranges: [], ecn_count: None } client | -> RX HandshakeDone client | -> RX NewConnectionId { sequence_number: 1, retire_prior: 1, connection_id: [130, 195, 76, 154, 49, 1, 145, 188, 57, 200, 115, 17, 238, 16, 88, 161], stateless_reset_token: [49, 67, 98, 101, 78, 177, 139, 85, 111, 145, 133, 231, 127, 120, 217, 201] } client | -> RX NewConnectionId { sequence_number: 2, retire_prior: 1, connection_id: [103, 153, 69, 38, 192, 77, 22, 240, 119, 255, 53, 110, 34, 132, 67, 65], stateless_reset_token: [80, 166, 230, 196, 28, 92, 240, 243, 98, 216, 50, 187, 179, 40, 180, 95] } client | -> RX NewConnectionId { sequence_number: 3, retire_prior: 1, connection_id: [43, 209, 243, 24, 195, 218, 139, 47, 143, 125, 48, 216, 135, 244, 148, 193], stateless_reset_token: [152, 108, 12, 195, 125, 131, 230, 200, 3, 110, 213, 149, 187, 221, 28, 141] } client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Rx ACK space=ap, ranges=[0..=0] client | 7.542 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=0 client | 7.542 DEBUG [Cubic [last_max_cwnd: 12520, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 81/2558 ssthresh 8764] slow start += 54 client | 7.542 DEBUG [Cubic [last_max_cwnd: 12520, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 81/2558 ssthresh 8764] on_packets_acked this=0x5619ac85a970, limited=0, bytes_in_flight=81, cwnd=2558, state=SlowStart, new_acked=54 client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] State change from Connected -> Confirmed client | 7.542 DEBUG PMTUD started with probe size 1380 client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] Drop packet number space hs client | 7.542 DEBUG [LossRecovery] Reset loss recovery state for Handshake client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] No preferred address to migrate to client | 7.542 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 787346517 } client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1252, pto: None, probe: EnumSet(), paced: false } client | 7.542 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.542 DEBUG Sending PMTUD probe of size 1380, count 1 client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=2 type=Short pri-path:82c34c9a310191bc39c87311ee1058a1 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 1352 client | TX -> Ping client | TX -> RetireConnectionId { sequence_number: 0 } client | TX -> Padding { len: 1315 } client | 7.542 DEBUG packet_sent this=0x5619ac85a970, pn=2, ps=1352 client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.542 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.542 DEBUG TX blocked, profile=SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 19.708042ms client | 7.542 DEBUG Setting timeout of 19.708042ms client | 7.542 DEBUG stream 0 complete client | 7.542 WARN Unhandled event StateChange(Confirmed) client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.542 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.542 DEBUG TX blocked, profile=SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.542 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 19.676122ms client | 7.542 DEBUG Setting timeout of 19.676122ms client | 7.543 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=2 type=Short pri-path:82c34c9a310191bc39c87311ee1058a1 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1232 client | -> RX HandshakeDone client | -> RX Stream { stream_id: 0, offset: 0, len: >>1211, fin: false } client | 7.543 DEBUG PMTUD started with probe size 1420 client | 7.543 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] No preferred address to migrate to client | 7.543 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 768553361 } client | 7.543 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.543 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.543 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=3 type=Short pri-path:82c34c9a310191bc39c87311ee1058a1 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 42 client | TX -> Ack { largest_acknowledged: 2, ack_delay: 5, first_ack_range: 2, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 3, Ce: 0})) } client | 7.543 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.543 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.543 DEBUG TX blocked, profile=SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.543 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 115.103529ms client | 7.543 DEBUG Setting timeout of 115.103529ms client | 7.543 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.543 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.543 DEBUG TX blocked, profile=SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.543 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 115.076329ms client | 7.543 DEBUG Setting timeout of 115.076329ms client | 7.544 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=3 type=Short pri-path:82c34c9a310191bc39c87311ee1058a1 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1232 client | -> RX HandshakeDone client | -> RX Stream { stream_id: 0, offset: 1211, len: >>1209, fin: false } client | 7.544 DEBUG PMTUD started with probe size 1472 client | 7.544 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] No preferred address to migrate to client | 7.544 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 789596147 } client | 7.544 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.544 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.544 DEBUG TX blocked, profile=SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.544 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 19.967178ms client | 7.544 DEBUG Setting timeout of 19.967178ms client | 7.544 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.544 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.544 DEBUG TX blocked, profile=SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.544 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 19.945478ms client | 7.544 DEBUG Setting timeout of 19.945478ms client | 7.545 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=4 type=Short pri-path:82c34c9a310191bc39c87311ee1058a1 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1232 client | -> RX HandshakeDone client | -> RX Stream { stream_id: 0, offset: 2420, len: >>1209, fin: false } client | 7.545 DEBUG PMTUD started with probe size 1500 client | 7.545 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] No preferred address to migrate to client | 7.545 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 770612213 } client | 7.545 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.545 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.545 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=4 type=Short pri-path:82c34c9a310191bc39c87311ee1058a1 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 42 client | TX -> Ack { largest_acknowledged: 4, ack_delay: 3, first_ack_range: 4, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 5, Ce: 0})) } client | 7.545 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.545 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.545 DEBUG TX blocked, profile=SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.546 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 113.044794ms client | 7.546 DEBUG Setting timeout of 113.044794ms client | 7.546 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.546 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.546 DEBUG TX blocked, profile=SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.546 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 113.016962ms client | 7.546 DEBUG Setting timeout of 113.016962ms client | 7.546 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=5 type=Short pri-path:82c34c9a310191bc39c87311ee1058a1 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 492 client | -> RX HandshakeDone client | -> RX Stream { stream_id: 0, offset: 3629, len: 467, fin: false } client | 7.546 INFO PMTUD stopped, PLPMTU is now 1500, raise timer Some(Instant { tv_sec: 1131, tv_nsec: 771055227 }) client | 7.546 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] No preferred address to migrate to client | 7.546 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 791055227 } client | 7.546 DEBUG PLPMTU changed from 1252 to 1472, updating pacer client | 7.546 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.546 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.546 DEBUG TX blocked, profile=SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.546 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 19.966727ms client | 7.546 DEBUG Setting timeout of 19.966727ms client | 7.546 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.546 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.546 DEBUG TX blocked, profile=SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.546 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 19.950627ms client | 7.546 DEBUG Setting timeout of 19.950627ms client | 7.547 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=6 type=Short pri-path:82c34c9a310191bc39c87311ee1058a1 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, Ect0) len 1049 client | -> RX HandshakeDone client | -> RX Stream { stream_id: 0, offset: 4096, len: 1024, fin: true } client | 7.547 INFO PMTUD stopped, PLPMTU is now 1500, raise timer Some(Instant { tv_sec: 1131, tv_nsec: 771881638 }) client | 7.547 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] No preferred address to migrate to client | 7.547 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 531, tv_nsec: 771881638 } client | 7.547 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.547 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.547 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=5 type=Short pri-path:82c34c9a310191bc39c87311ee1058a1 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 42 client | TX -> Ack { largest_acknowledged: 6, ack_delay: 3, first_ack_range: 6, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 7, Ce: 0})) } client | 7.547 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.547 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.547 DEBUG TX blocked, profile=SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.547 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 111.798947ms client | 7.547 DEBUG Setting timeout of 111.798947ms client | 7.547 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.547 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.547 DEBUG TX blocked, profile=SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.547 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] delay duration 111.728255ms client | 7.547 DEBUG Setting timeout of 111.728255ms client | 7.547 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] State change from Confirmed -> Closing { error: Application(0), timeout: Instant { tv_sec: 532, tv_nsec: 120673478 } } client | 7.547 WARN Unhandled event StateChange(Closing { error: Application(0), timeout: Instant { tv_sec: 532, tv_nsec: 120673478 } }) client | 7.547 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.547 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.547 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 531, tv_nsec: 772054712 } client | 7.547 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=6 type=Short pri-path:82c34c9a310191bc39c87311ee1058a1 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 53 client | TX -> Ack { largest_acknowledged: 6, ack_delay: 21, first_ack_range: 6, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 7, Ce: 0})) } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 7.547 DEBUG Setting timeout of 348.534191ms server | error while accepting stream: The connection was closed on the application level with error application::Error(0) by the remote endpoint client | 7.578 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] output_path send_profile SendProfile { limit: 1206, pto: None, probe: EnumSet(), paced: false } client | 7.578 DEBUG Building Short dcid Some(CID [16]: 82c34c9a310191bc39c87311ee1058a1) client | 7.578 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 531, tv_nsec: 802932553 } client | 7.578 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] pn=7 type=Short pri-path:82c34c9a310191bc39c87311ee1058a1 0.0.0.0:59733->193.167.100.100:443 IpTos(Cs0, NotEct) len 54 client | TX -> Ack { largest_acknowledged: 6, ack_delay: 3881, first_ack_range: 6, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 7, Ce: 0})) } client | TX -> ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "kthxbye!" } client | 7.578 DEBUG Setting timeout of 317.625956ms client | 7.578 DEBUG Setting timeout of 317.61233ms client | 7.897 DEBUG [Client 57c142764252c36b50178dcfb9e1196dd1e9] State change from Closing { error: Application(0), timeout: Instant { tv_sec: 532, tv_nsec: 120673478 } } -> Closed(Application(0)) client | 7.897 INFO Closing timer expired client | 7.897 DEBUG Output::None client | 7.897 WARN Unhandled event StateChange(Closed(Application(0))) client | 7.897 DEBUG Timer fired while closed client | 7.897 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 13:39:40,248 Using the client's key log file. 2025-04-30 13:39:40,260 2025-04-30 13:39:40,261 Using the client's key log file. 2025-04-30 13:39:40,261 Using the client's key log file. 2025-04-30 13:39:40,271 2025-04-30 13:39:40,271 Using the client's key log file. 2025-04-30 13:39:40,271 Using the client's key log file. 2025-04-30 13:39:40,904 Check of downloaded files succeeded. 2025-04-30 13:39:41,218 Server sent 9938 bytes in Handshake CRYPTO frames. 2025-04-30 13:39:41,582 Received a 1252 byte Initial packet from the client. Amplification limit: 3756 2025-04-30 13:39:41,582 Received a 1232 byte Handshake packet from the server. Total: 1232 2025-04-30 13:39:41,582 Received a 1252 byte Initial packet from the client. Amplification limit: 7512 2025-04-30 13:39:41,582 Received a 1232 byte Handshake packet from the server. Total: 2464 2025-04-30 13:39:41,582 Received a 1232 byte Handshake packet from the server. Total: 3696 2025-04-30 13:39:41,582 Received a 1232 byte Handshake packet from the server. Total: 4928 2025-04-30 13:39:41,582 Received a 1232 byte Handshake packet from the server. Total: 6160 2025-04-30 13:39:41,582 Received a 1232 byte Handshake packet from the server. Total: 7392 2025-04-30 13:39:41,582 Received a 1232 byte Handshake packet from the server. Total: 8624 2025-04-30 13:39:41,582 Server violated the amplification limit, but stayed within 3-4x amplification. Letting it slide. 2025-04-30 13:39:41,582 Received a 103 byte Initial packet from the client. Amplification limit: 7821