2025-04-30 09:41:52,708 Generated random file: xyiwcoawbe of size: 5120
2025-04-30 09:41:52,708 Generated random file: sxsbyjwgau of size: 10240
2025-04-30 09:41:52,708 Requests: https://server6:443/xyiwcoawbe https://server6:443/sxsbyjwgau
2025-04-30 09:41:52,770 
2025-04-30 09:41:52,770 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_werc39y4/ TESTCASE_SERVER=transfer TESTCASE_CLIENT=transfer WWW=/tmp/www_umlz4g1n/ DOWNLOADS=/tmp/download_y8mh7d8r/ SERVER_LOGS=/tmp/logs_server_1kdz4vnj CLIENT_LOGS=/tmp/logs_client_b5oe2h1q SCENARIO="simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25" CLIENT=martenseemann/quic-go-interop:latest SERVER=ghcr.io/mozilla/neqo-qns:latest REQUESTS="https://server6:443/xyiwcoawbe https://server6:443/sxsbyjwgau"  docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 
2025-04-30 09:42:04,821  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
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
server  | Endpoint's IPv4 address is 193.167.100.100
server  | Endpoint's IPv6 address is fd00:cafe:cafe:100::100
client  | Setting up routes...
server  | + export PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/neqo/bin
server  | + PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/neqo/bin
server  | + '[' -n transfer ']'
server  | + '[' -n /logs/qlog/ ']'
server  | + case "$ROLE" in
server  | + DB=/neqo/db
server  | + CERT=cert
server  | ++ mktemp
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  | + P12CERT=/tmp/tmp.rjVaUEGwkL
server  | + mkdir -p /neqo/db
client  | Endpoint's IPv4 address is 193.167.0.100
server  | + certutil -N -d sql:/neqo/db --empty-password
client  | Endpoint's IPv6 address is fd00:cafe:cafe::100
client  | Using commit: e4bb2dbd5557c9417b30cf9fcd9032fd6fea5366
server  | + openssl pkcs12 -export -nodes -in /certs/cert.pem -inkey /certs/priv.key -name cert -passout pass: -out /tmp/tmp.rjVaUEGwkL
server  | Warning: output encryption option -nodes ignored with -export
client  | wait-for-it.sh: waiting 10 seconds for sim:57832
server  | + pk12util -d sql:/neqo/db -i /tmp/tmp.rjVaUEGwkL -W ''
server  | pk12util: PKCS12 IMPORT SUCCESSFUL
server  | + certutil -L -d sql:/neqo/db -n cert
server  | Certificate:
server  |     Data:
server  |         Version: 3 (0x2)
server  |         Serial Number:
server  |             36:ca:d8:88:86:68:f9:c9:0c:f8:e1:4d:3f:cd:7e:90:
server  |             a0:08:0f:48
server  |         Signature Algorithm: X9.62 ECDSA signature with SHA256
server  |         Issuer: "O=interop runner Root Certificate Authority"
server  |         Validity:
server  |             Not Before: Wed Apr 30 09:41:52 2025
server  |             Not After : Sat May 10 09:41:52 2025
server  |         Subject: "O=interop runner leaf"
server  |         Subject Public Key Info:
server  |             Public Key Algorithm: X9.62 elliptic curve public key
server  |                 Args:
server  |                     06:08:2a:86:48:ce:3d:03:01:07
server  |             EC Public Key:
server  |                 PublicValue:
server  |                     04:c1:d1:1c:71:e2:fa:06:58:d9:5e:7d:38:5a:10:f9:
server  |                     8a:39:79:ee:c4:52:3c:3c:29:49:f6:a4:a7:fb:6c:6a:
server  |                     ef:52:58:73:d4:ef:93:fb:1f:c3:b6:30:30:e1:6a:d4:
server  |                     f8:59:71:5c:07:a4:25:5d:62:8f:bf:fc:28:32:1d:20:
server  |                     0a
server  |                 Curve: ANSI X9.62 elliptic curve prime256v1 (aka secp256r1, NIST P-256)
server  |         Signed Extensions:
server  |             Name: Certificate Subject Alt Name
server  |             DNS name: "server"
server  |             DNS name: "server4"
server  |             DNS name: "server6"
server  |             DNS name: "server46"
server  | 
server  |             Name: Certificate Subject Key ID
server  |             Data:
server  |                 a9:77:74:71:88:ec:e6:a0:fe:f0:ac:58:a9:39:e3:5c:
server  |                 a2:88:ce:83
server  | 
server  |             Name: Certificate Authority Key Identifier
server  |             Key ID:
server  |                 e7:55:74:45:95:90:64:9e:ef:aa:25:eb:bf:aa:0d:13:
server  |                 65:5f:e3:14
server  | 
server  |     Signature Algorithm: X9.62 ECDSA signature with SHA256
server  |     Signature:
server  |         30:44:02:20:58:58:20:7e:c1:61:59:2f:1c:0f:6b:31:
server  |         7e:32:ba:6b:86:27:f8:9d:cb:45:9b:81:02:56:10:2d:
server  |         b6:e6:c5:4c:02:20:31:fc:17:cf:2b:c9:2c:d5:5b:52:
server  |         4e:62:2e:f4:b6:1f:86:54:65:cc:27:62:36:f3:86:c7:
server  |         29:a6:2b:89:c9:1c
server  |     Fingerprint (SHA-256):
server  |         02:08:11:C4:20:E6:5C:2F:AA:57:9F:C1:ED:ED:D7:06:C4:4F:A6:B5:CD:D2:F5:61:79:EF:DC:53:69:CC:AA:F1
server  |     Fingerprint (SHA1):
server  |         B2:92:58:5D:A0:0E:09:1E:70:5C:16:08:27:9D:40:14:7F:A2:63:24
server  | 
server  |     Mozilla-CA-Policy: false (attribute missing)
server  |     Certificate Trust Flags:
server  |         SSL Flags:
server  |             User
server  |         Email Flags:
server  |             User
server  |         Object Signing Flags:
server  |             User
server  | 
server  | + OPTIONS=(--cc cubic --qns-test "$TESTCASE" --qlog-dir "$QLOGDIR" -d "$DB" -k "$CERT")
server  | + '[' transfer = connectionmigration ']'
server  | + RUST_LOG=debug
server  | + RUST_BACKTRACE=1
server  | + neqo-server --cc cubic --qns-test transfer --qlog-dir /logs/qlog/ -d /neqo/db -k cert '[::]:443'
server  | ++ tee -i -a /logs/server.log
server  | 0.000 DEBUG Logging initialized
server  | 0.002 DEBUG Default socket send buffer size is 212992
server  | 0.002 DEBUG Default socket receive buffer size is 1048576, not changing
server  | 0.002 INFO Server waiting for connection on: [::]:443
server  | 0.758 DEBUG [Server] Unsupported version: 57414954
server  | 0.758 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:50334 IpTos(Cs0, NotEct) len 15
sim     | server:443 is available after 1.007312222s
server  | 0.759 DEBUG [Server] Unsupported version: 57414954
server  | 0.759 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:50334 IpTos(Cs0, NotEct) len 15
server  | 0.759 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" })
server  | 0.759 DEBUG [Server] Unsupported version: 57414954
server  | 0.759 DEBUG [Server] type=VersionNegotiation path: [::]:443->[::ffff:193.167.100.2]:50334 IpTos(Cs0, NotEct) len 15
server  | 0.759 ERROR failed to create NeqoQlog: IoError(Os { code: 17, kind: AlreadyExists, message: "File exists" })
sim     | Using scenario: simple-p2p --delay=15ms --bandwidth=10Mbps --queue=25
sim     | tcpdump: tcpdump: listening on eth1listening on eth0, link-type EN10MB (Ethernet), link-type EN10MB (Ethernet), snapshot length 262144 bytes
sim     | , snapshot length 262144 bytes
client  | wait-for-it.sh: sim:57832 is available after 1 seconds
client  | Starting QUIC client...
client  | Client params: 
client  | Test case: transfer
server  | 1.007 DEBUG [Server] Handle initial
server  | 1.007 INFO AddressValidation: no token; accepting
server  | 1.007 INFO [Server] Accept connection CID [10]: fa7d772086fdaf717a5d
server  | 1.007 DEBUG Overwrite initial version Version1 ==> Version1
server  | 1.008 DEBUG Outbound interface eth0 for destination fd00:cafe:cafe::100 has MTU 1500
server  | 1.008 INFO [Server ...] Received valid Initial packet with scid CID [0]:  dcid CID [10]: fa7d772086fdaf717a5d
server  | 1.008 DEBUG [CryptoStates] Creating initial cipher state v=Version1, role=Server dcid=fa7d772086fdaf717a5d
server  | 1.008 DEBUG Making Write Initial CryptoDxState, v=Version1 cipher=4865
server  | 1.009 DEBUG Making Read Initial CryptoDxState, v=Version1 cipher=4865
server  | 1.009 DEBUG [Server fa7d772086fdaf717a5d] State change from Init -> WaitInitial
server  | 1.009 DEBUG [Server fa7d772086fdaf717a5d] pn=0 type=Initial unv-path [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, NotEct) len 1280
server  |   -> RX Padding { len: 968 }
server  |   -> RX Crypto { offset: 0, len: 270 }
server  | 1.009 DEBUG Read Ok(270) bytes
server  | 1.009 DEBUG 0-RTT: no token, no 0-RTT
server  | 1.009 DEBUG Read secret available for Handshake: SymKey [32]: f7514dd6068167f20a0ff6923558f417497699535525f00513cc8fae925a615a
server  | 1.009 DEBUG Write secret available for Handshake: SymKey [32]: 5a24045daeeee554256c5520f33f45e67ec20ac3961009265c21471a7f5e8039
server  | 1.009 DEBUG Writing transport parameters, msg=8
server  | 1.009 DEBUG Read secret available for ApplicationData: SymKey [32]: 8efe1213fb0295acaa29f778e4c6edb8397b4bc878e6af08fd1ba4baf90dc1ce
server  | 1.009 DEBUG Write secret available for ApplicationData: SymKey [32]: 5a5eb6449f3c2f77741e516c69f8e021b137cb91b3c3fa919f24f71578bc0e31
server  | 1.009 DEBUG [Agent 0x55b902b891d0] state -> InProgress
server  | 1.009 DEBUG Making Write Handshake CryptoDxState, v=Version1 cipher=4865
server  | 1.010 DEBUG Making Read Handshake CryptoDxState, v=Version1 cipher=4865
server  | 1.010 DEBUG [Crypto] Handshake keys installed
server  | 1.010 DEBUG Making Write ApplicationData CryptoDxState, v=Version1 cipher=4865
server  | 1.010 DEBUG [Crypto] Application write key installed
server  | 1.010 DEBUG [Recvd-in] Set ACK timer to Instant { tv_sec: 571, tv_nsec: 745499681 }
server  | 1.010 DEBUG [unv-path [::]:443->[fd00:cafe:cafe::100]:45546] Make permanent
server  | 1.010 DEBUG [unv-path: [::]:443->[fd00:cafe:cafe::100]:45546] set as primary path
server  | 1.010 DEBUG [Server fa7d772086fdaf717a5d] State change from WaitInitial -> Handshaking
server  | 1.010 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.010 DEBUG Building Initial dcid Some(CID [0]: ) scid Some(CID [10]: be37e179078007176890)
server  | 1.010 DEBUG CRYPTO for in offset=0, len=90
server  | 1.010 DEBUG [Server fa7d772086fdaf717a5d] pn=0 type=Initial pri-unv-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 136
server  |   TX -> Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  |   TX -> Crypto { offset: 0, len: 90 }
server  | 1.010 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: be37e179078007176890)
server  | 1.010 DEBUG CRYPTO for hs offset=0, len=727
server  | 1.010 DEBUG [Server fa7d772086fdaf717a5d] pn=0 type=Handshake pri-unv-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 903
server  |   TX -> Crypto { offset: 0, len: 727 }
server  | 1.010 DEBUG packet_sent this=0x55b902b88b40, pn=0, ps=767
server  | 1.010 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.010 DEBUG [Server fa7d772086fdaf717a5d] pad Initial from 903 to PLPMTU 1232
server  | 1.010 DEBUG packet_sent this=0x55b902b88b40, pn=0, ps=465
server  | 1.010 DEBUG ECN probing: sent 1 probes
server  | 1.010 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.010 DEBUG Building Initial dcid Some(CID [0]: ) scid Some(CID [10]: be37e179078007176890)
server  | 1.010 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: be37e179078007176890)
server  | 1.010 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.010 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.010 DEBUG [Server fa7d772086fdaf717a5d] delay duration 296.851469ms
server  | 1.010 DEBUG Setting timeout of 296.851469ms
server  | 1.010 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.010 DEBUG Building Initial dcid Some(CID [0]: ) scid Some(CID [10]: be37e179078007176890)
server  | 1.010 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: be37e179078007176890)
server  | 1.010 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.010 DEBUG TX blocked, profile=SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.010 DEBUG [Server fa7d772086fdaf717a5d] delay duration 296.820792ms
server  | 1.010 DEBUG Setting timeout of 296.820792ms
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] pn=1 type=Initial pri-unv-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, NotEct) len 1204
server  |   -> RX Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) }
server  |   -> RX Padding { len: 1158 }
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] Rx ACK space=in, ranges=[0..=0]
server  | 1.044 DEBUG [LossRecovery] ACK for Initial - largest_acked=0
server  | 1.044 DEBUG on_packets_acked this=0x55b902b88b40, limited=1, bytes_in_flight=767, cwnd=12320, state=SlowStart, new_acked=465
server  | 1.044 DEBUG Acked crypto frame space=in offset=0 length=90
server  | 1.044 DEBUG [pri-unv-path: [::]:443->[fd00:cafe:cafe::100]:45546] Path validated Instant { tv_sec: 571, tv_nsec: 782431401 }
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] Drop packet number space in
server  | 1.044 DEBUG [LossRecovery] Reset loss recovery state for Initial
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] pn=0 type=Handshake pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, NotEct) len 76
server  |   -> RX Crypto { offset: 0, len: 36 }
server  | 1.044 DEBUG Read Ok(36) bytes
server  | 1.044 DEBUG [Agent 0x55b902b891d0] state -> Complete(SecretAgentInfo { version: 772, cipher: 4865, group: 29, resumed: false, early_data: false, ech_accepted: false, alpn: Some("hq-interop"), signature_scheme: 1027 })
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] TLS connection complete
server  | 1.044 DEBUG [pri-path: [::]:443->[fd00:cafe:cafe::100]:45546] Path validated Instant { tv_sec: 571, tv_nsec: 782431401 }
server  | 1.044 DEBUG Making Read ApplicationData CryptoDxState, v=Version1 cipher=4865
server  | 1.044 DEBUG [Crypto] application read keys installed
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] State change from Handshaking -> Connected
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] State change from Connected -> Confirmed
server  | 1.044 DEBUG PMTUD started with probe size 1380
server  | 1.044 INFO [Server fa7d772086fdaf717a5d] Connection established
server  | 1.044 DEBUG [Recvd-hs] Set ACK timer to Instant { tv_sec: 571, tv_nsec: 782431401 }
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.044 DEBUG Building Handshake dcid Some(CID [0]: ) scid Some(CID [10]: be37e179078007176890)
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] pn=1 type=Handshake pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 41
server  |   TX -> Ack { largest_acknowledged: 0, ack_delay: 0, first_ack_range: 0, ack_ranges: [], ecn_count: None }
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] Drop packet number space hs
server  | 1.044 DEBUG [LossRecovery] Reset loss recovery state for Handshake
server  | 1.044 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] pn=0 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 1332
server  |   TX -> HandshakeDone
server  |   TX -> NewConnectionId { sequence_number: 1, retire_prior: 0, connection_id: [176, 105, 251, 217, 167, 183, 238, 154, 85, 217], stateless_reset_token: [75, 107, 122, 160, 126, 239, 234, 75, 213, 155, 178, 108, 196, 106, 122, 165] }
server  |   TX -> NewConnectionId { sequence_number: 2, retire_prior: 0, connection_id: [128, 54, 173, 251, 245, 238, 114, 101, 191, 228], stateless_reset_token: [91, 239, 23, 11, 247, 225, 138, 197, 224, 98, 101, 14, 167, 225, 41, 208] }
server  |   TX -> NewConnectionId { sequence_number: 3, retire_prior: 0, connection_id: [20, 18, 67, 56, 10, 190, 60, 251, 77, 213], stateless_reset_token: [86, 116, 233, 104, 44, 235, 14, 233, 159, 228, 9, 167, 54, 38, 207, 102] }
server  |   TX -> Padding { len: 1182 }
server  | 1.044 DEBUG packet_sent this=0x55b902b88b40, pn=0, ps=1291
server  | 1.044 DEBUG ECN probing: sent 2 probes
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.044 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.044 DEBUG Sending PMTUD probe of size 1380, count 1
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] pn=1 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 1332
server  |   TX -> Ping
server  |   TX -> Padding { len: 1313 }
server  | 1.044 DEBUG packet_sent this=0x55b902b88b40, pn=1, ps=1332
server  | 1.044 DEBUG ECN probing: sent 3 probes
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.044 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.044 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] delay duration 1.475299ms
server  | 1.044 DEBUG Setting timeout of 1.475299ms
server  | 1.044 WARN [Server ...] Dropped received packet: Decryption failure; Total: 1
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.044 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.044 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] delay duration 1.445483ms
server  | 1.044 DEBUG Setting timeout of 1.445483ms
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] pn=0 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 48
server  |   -> RX Stream { stream_id: 0, offset: 0, len: >>17, fin: true }
server  | 1.044 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 571, tv_nsec: 803100830 }
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.044 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.044 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] delay duration 1.415937ms
server  | 1.044 DEBUG Setting timeout of 1.415937ms
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] pn=1 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 48
server  |   -> RX Stream { stream_id: 4, offset: 0, len: >>17, fin: true }
server  | 1.044 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 571, tv_nsec: 783149341 }
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.044 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] pn=2 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 26
server  |   TX -> Ack { largest_acknowledged: 1, ack_delay: 0, first_ack_range: 1, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 2, Ce: 0})) }
server  | 1.044 DEBUG ECN probing: sent 4 probes
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.044 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.044 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.044 DEBUG [Server fa7d772086fdaf717a5d] delay duration 1.339945ms
server  | 1.044 DEBUG Setting timeout of 1.339945ms
server  | 1.045 DEBUG [Server fa7d772086fdaf717a5d] send session ticket 4065000afa7d772086fdaf717a5d0104800075300408ffffffffffffffff0504801000000604801000000704801000000801100901100b01140e01080f0abe37e179078007176890110c000000010ada6a3a000000016ab200c0000000ff02de1a0243e8200100686921
server  | 1.045 DEBUG Path = 'sxsbyjwgau'
server  | 1.045 DEBUG Path = 'xyiwcoawbe'
server  | 1.045 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.045 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.045 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.045 DEBUG [Server fa7d772086fdaf717a5d] delay duration 274.532µs
server  | 1.045 DEBUG Setting timeout of 274.532µs
server  | 1.047 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.047 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.047 DEBUG [Server fa7d772086fdaf717a5d] pn=3 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 1232
server  |   TX -> Stream { stream_id: 0, offset: 0, len: >>1212, fin: false }
server  | 1.047 DEBUG packet_sent this=0x55b902b88b40, pn=3, ps=1232
server  | 1.047 DEBUG ECN probing: sent 5 probes
server  | 1.047 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.047 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.047 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.047 DEBUG [Server fa7d772086fdaf717a5d] delay duration 974.664µs
server  | 1.047 DEBUG Setting timeout of 974.664µs
server  | 1.047 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.047 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.047 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.047 DEBUG [Server fa7d772086fdaf717a5d] delay duration 953.814µs
server  | 1.047 DEBUG Setting timeout of 953.814µs
server  | 1.049 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.049 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.049 DEBUG [Server fa7d772086fdaf717a5d] pn=4 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 1232
server  |   TX -> Stream { stream_id: 0, offset: 1212, len: >>1210, fin: false }
server  | 1.049 DEBUG packet_sent this=0x55b902b88b40, pn=4, ps=1232
server  | 1.049 DEBUG ECN probing: sent 6 probes
server  | 1.049 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.049 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.049 DEBUG [Server fa7d772086fdaf717a5d] pn=5 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 1232
server  |   TX -> Stream { stream_id: 0, offset: 2422, len: >>1210, fin: false }
server  | 1.049 DEBUG packet_sent this=0x55b902b88b40, pn=5, ps=1232
server  | 1.049 DEBUG ECN probing: sent 7 probes
server  | 1.049 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.049 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.049 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.049 DEBUG [Server fa7d772086fdaf717a5d] delay duration 1.700501ms
server  | 1.049 DEBUG Setting timeout of 1.700501ms
server  | 1.049 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.049 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.049 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.049 DEBUG [Server fa7d772086fdaf717a5d] delay duration 1.644226ms
server  | 1.049 DEBUG Setting timeout of 1.644226ms
server  | 1.052 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.052 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.052 DEBUG [Server fa7d772086fdaf717a5d] pn=6 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 1232
server  |   TX -> Stream { stream_id: 0, offset: 3632, len: >>1210, fin: false }
server  | 1.052 DEBUG packet_sent this=0x55b902b88b40, pn=6, ps=1232
server  | 1.052 DEBUG ECN probing: sent 8 probes
server  | 1.052 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.052 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.052 DEBUG [Server fa7d772086fdaf717a5d] pn=7 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 1232
server  |   TX -> Stream { stream_id: 0, offset: 4842, len: >>1210, fin: false }
server  | 1.052 DEBUG packet_sent this=0x55b902b88b40, pn=7, ps=1232
server  | 1.052 DEBUG ECN probing: sent 9 probes
server  | 1.052 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.052 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.052 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.052 DEBUG [Server fa7d772086fdaf717a5d] delay duration 1.785261ms
server  | 1.052 DEBUG Setting timeout of 1.785261ms
server  | 1.052 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.052 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.052 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.052 DEBUG [Server fa7d772086fdaf717a5d] delay duration 1.764301ms
server  | 1.052 DEBUG Setting timeout of 1.764301ms
server  | 1.055 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.055 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.055 DEBUG [Server fa7d772086fdaf717a5d] pn=8 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 1232
server  |   TX -> Stream { stream_id: 0, offset: 6052, len: >>1210, fin: false }
server  | 1.055 DEBUG packet_sent this=0x55b902b88b40, pn=8, ps=1232
server  | 1.055 DEBUG ECN probing: sent 10 probes
server  | 1.055 DEBUG ECN probing concluded with 10 probes sent
server  | 1.055 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.055 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.055 DEBUG [Server fa7d772086fdaf717a5d] pn=9 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, NotEct) len 1232
server  |   TX -> Stream { stream_id: 0, offset: 7262, len: >>1210, fin: false }
server  | 1.055 DEBUG packet_sent this=0x55b902b88b40, pn=9, ps=1232
server  | 1.055 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1073, pto: None, probe: EnumSet(), paced: false }
server  | 1.055 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.055 DEBUG [Server fa7d772086fdaf717a5d] pn=10 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, NotEct) len 1073
server  |   TX -> Stream { stream_id: 0, offset: 8472, len: >>1051, fin: false }
server  | 1.055 DEBUG packet_sent this=0x55b902b88b40, pn=10, ps=1073
server  | 1.055 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false }
server  | 1.056 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.056 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false }
server  | 1.056 DEBUG [Server fa7d772086fdaf717a5d] delay duration 136.734085ms
server  | 1.056 DEBUG Setting timeout of 136.734085ms
server  | 1.056 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false }
server  | 1.056 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.056 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false }
server  | 1.056 DEBUG [Server fa7d772086fdaf717a5d] delay duration 136.640398ms
server  | 1.056 DEBUG Setting timeout of 136.640398ms
server  | 1.076 DEBUG [Server fa7d772086fdaf717a5d] pn=2 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 39
server  |   -> RX Ack { largest_acknowledged: 0, ack_delay: 19, first_ack_range: 0, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 1, Ce: 0})) }
server  |   -> RX RetireConnectionId { sequence_number: 0 }
server  | 1.076 DEBUG [Server fa7d772086fdaf717a5d] Rx ACK space=ap, ranges=[0..=0]
server  | 1.076 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=0
server  | 1.076 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 11029/13611 ssthresh 18446744073709551615] slow start += 1291
server  | 1.076 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 11029/13611 ssthresh 18446744073709551615] on_packets_acked this=0x55b902b88b40, limited=0, bytes_in_flight=11029, cwnd=13611, state=SlowStart, new_acked=1291
server  | 1.076 DEBUG [Recvd-ap] Set ACK timer to Instant { tv_sec: 571, tv_nsec: 834783600 }
server  | 1.076 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.076 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.076 DEBUG [Server fa7d772086fdaf717a5d] pn=11 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, NotEct) len 1232
server  |   TX -> NewConnectionId { sequence_number: 4, retire_prior: 0, connection_id: [99, 170, 237, 114, 0, 112, 192, 93, 69, 216], stateless_reset_token: [82, 161, 92, 137, 248, 53, 8, 31, 253, 176, 82, 154, 214, 88, 69, 4] }
server  |   TX -> Stream { stream_id: 0, offset: 9523, len: 717, fin: true }
server  |   TX -> Stream { stream_id: 4, offset: 0, len: >>459, fin: false }
server  | 1.076 DEBUG packet_sent this=0x55b902b88b40, pn=11, ps=1232
server  | 1.076 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1232, pto: None, probe: EnumSet(), paced: false }
server  | 1.076 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.076 DEBUG [Server fa7d772086fdaf717a5d] pn=12 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, NotEct) len 1232
server  |   TX -> Stream { stream_id: 4, offset: 459, len: >>1210, fin: false }
server  | 1.076 DEBUG packet_sent this=0x55b902b88b40, pn=12, ps=1232
server  | 1.076 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false }
server  | 1.076 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.076 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false }
server  | 1.076 DEBUG [Server fa7d772086fdaf717a5d] delay duration 19.748436ms
server  | 1.076 DEBUG Setting timeout of 19.748436ms
server  | 1.076 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false }
server  | 1.076 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.076 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: false }
server  | 1.076 DEBUG [Server fa7d772086fdaf717a5d] delay duration 19.725564ms
server  | 1.076 DEBUG Setting timeout of 19.725564ms
server  | 1.078 DEBUG [Server fa7d772086fdaf717a5d] pn=3 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 37
server  |   -> RX Ack { largest_acknowledged: 3, ack_delay: 6, first_ack_range: 3, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 4, Ce: 0})) }
server  | 1.078 DEBUG [Server fa7d772086fdaf717a5d] Rx ACK space=ap, ranges=[0..=3]
server  | 1.078 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=3
server  | 1.078 INFO ECN validation succeeded, path is capable
server  | 1.078 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 10929/16175 ssthresh 18446744073709551615] slow start += 2564
server  | 1.078 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 10929/16175 ssthresh 18446744073709551615] on_packets_acked this=0x55b902b88b40, limited=0, bytes_in_flight=10929, cwnd=16175, state=SlowStart, new_acked=2564
server  | 1.078 DEBUG PMTUD probe of size 1380 succeeded
server  | 1.078 DEBUG PMTUD started with probe size 1420
server  | 1.078 DEBUG PLPMTU changed from 1232 to 1332, updating pacer
server  | 1.078 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.078 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.078 DEBUG Sending PMTUD probe of size 1420, count 1
server  | 1.078 DEBUG [Server fa7d772086fdaf717a5d] pn=13 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 1372
server  |   TX -> Ping
server  |   TX -> Stream { stream_id: 4, offset: 1669, len: >>1349, fin: false }
server  | 1.078 DEBUG packet_sent this=0x55b902b88b40, pn=13, ps=1372
server  | 1.078 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.078 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.078 DEBUG [Server fa7d772086fdaf717a5d] pn=14 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 1332
server  |   TX -> Stream { stream_id: 4, offset: 3018, len: >>1310, fin: false }
server  | 1.078 DEBUG packet_sent this=0x55b902b88b40, pn=14, ps=1332
server  | 1.078 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.078 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.078 DEBUG CRYPTO for ap offset=0, len=305
server  | 1.078 DEBUG [Server fa7d772086fdaf717a5d] pn=15 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 1170
server  |   TX -> Stream { stream_id: 4, offset: 4328, len: 792, fin: true }
server  |   TX -> Crypto { offset: 0, len: 305 }
server  |   TX -> NewToken { token: [173, 154, 139, 141, 134, 1, 0, 191, 38, 215, 44, 193, 234, 78, 114, 6, 33, 141, 176, 46, 218, 113, 245, 247, 134, 68, 37, 207, 26, 1, 238, 174, 66, 51, 148, 248, 142, 250, 215, 173, 29, 229, 49] }
server  | 1.078 DEBUG packet_sent this=0x55b902b88b40, pn=15, ps=1170
server  | 1.078 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.078 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.078 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.078 DEBUG [Server fa7d772086fdaf717a5d] delay duration 1.416556ms
server  | 1.078 DEBUG Setting timeout of 1.416556ms
server  | 1.078 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.078 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.078 DEBUG TX blocked, profile=SendProfile { limit: 255, pto: None, probe: EnumSet(), paced: true }
server  | 1.078 DEBUG [Server fa7d772086fdaf717a5d] delay duration 1.393412ms
server  | 1.078 DEBUG Setting timeout of 1.393412ms
server  | 1.081 DEBUG [Server fa7d772086fdaf717a5d] pn=4 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 37
server  |   -> RX Ack { largest_acknowledged: 5, ack_delay: 6, first_ack_range: 5, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 6, Ce: 0})) }
server  | 1.081 DEBUG [Server fa7d772086fdaf717a5d] Rx ACK space=ap, ranges=[0..=5]
server  | 1.081 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=5
server  | 1.081 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 12339/18639 ssthresh 18446744073709551615] slow start += 2464
server  | 1.081 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 12339/18639 ssthresh 18446744073709551615] on_packets_acked this=0x55b902b88b40, limited=0, bytes_in_flight=12339, cwnd=18639, state=SlowStart, new_acked=2464
server  | 1.081 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.081 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.081 DEBUG [Server fa7d772086fdaf717a5d] pn=16 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 26
server  |   TX -> Ack { largest_acknowledged: 4, ack_delay: 0, first_ack_range: 4, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 5, Ce: 0})) }
server  | 1.081 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.081 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.081 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.081 DEBUG [Server fa7d772086fdaf717a5d] delay duration 98.890529ms
server  | 1.081 DEBUG Setting timeout of 98.890529ms
server  | 1.081 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.081 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.081 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.081 DEBUG [Server fa7d772086fdaf717a5d] delay duration 98.867075ms
server  | 1.081 DEBUG Setting timeout of 98.867075ms
server  | 1.085 DEBUG [Server fa7d772086fdaf717a5d] pn=5 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 37
server  |   -> RX Ack { largest_acknowledged: 7, ack_delay: 6, first_ack_range: 7, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 8, Ce: 0})) }
server  | 1.085 DEBUG [Server fa7d772086fdaf717a5d] Rx ACK space=ap, ranges=[0..=7]
server  | 1.085 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=7
server  | 1.085 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 9875/21103 ssthresh 18446744073709551615] slow start += 2464
server  | 1.085 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 9875/21103 ssthresh 18446744073709551615] on_packets_acked this=0x55b902b88b40, limited=0, bytes_in_flight=9875, cwnd=21103, state=SlowStart, new_acked=2464
server  | 1.085 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.085 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.085 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.085 DEBUG [Server fa7d772086fdaf717a5d] delay duration 87.637364ms
server  | 1.085 DEBUG Setting timeout of 87.637364ms
server  | 1.085 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.085 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.085 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.085 DEBUG [Server fa7d772086fdaf717a5d] delay duration 87.563185ms
server  | 1.085 DEBUG Setting timeout of 87.563185ms
server  | 1.088 DEBUG [Server fa7d772086fdaf717a5d] pn=6 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 37
server  |   -> RX Ack { largest_acknowledged: 9, ack_delay: 6, first_ack_range: 9, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 9, Ce: 0})) }
server  | 1.088 DEBUG [Server fa7d772086fdaf717a5d] Rx ACK space=ap, ranges=[0..=9]
server  | 1.088 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=9
server  | 1.088 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 7411/23567 ssthresh 18446744073709551615] slow start += 2464
server  | 1.088 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 7411/23567 ssthresh 18446744073709551615] on_packets_acked this=0x55b902b88b40, limited=0, bytes_in_flight=7411, cwnd=23567, state=SlowStart, new_acked=2464
server  | 1.088 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.088 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.088 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.088 DEBUG [Server fa7d772086fdaf717a5d] delay duration 78.420363ms
server  | 1.088 DEBUG Setting timeout of 78.420363ms
server  | 1.088 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.088 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.088 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.088 DEBUG [Server fa7d772086fdaf717a5d] delay duration 78.343108ms
server  | 1.088 DEBUG Setting timeout of 78.343108ms
server  | 1.108 DEBUG [Server fa7d772086fdaf717a5d] pn=7 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 37
server  |   -> RX Ack { largest_acknowledged: 11, ack_delay: 10, first_ack_range: 11, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 9, Ce: 0})) }
server  | 1.108 DEBUG [Server fa7d772086fdaf717a5d] Rx ACK space=ap, ranges=[0..=11]
server  | 1.108 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=11
server  | 1.108 WARN ECN validation failed, no ECT(0) packets were newly acked
server  | 1.108 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 5106/25872 ssthresh 18446744073709551615] slow start += 2305
server  | 1.108 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 5106/25872 ssthresh 18446744073709551615] on_packets_acked this=0x55b902b88b40, limited=0, bytes_in_flight=5106, cwnd=25872, state=SlowStart, new_acked=2305
server  | 1.108 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.108 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.108 DEBUG [Server fa7d772086fdaf717a5d] pn=17 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, NotEct) len 20
server  |   TX -> MaxStreams { stream_type: BiDi, maximum_streams: 17 }
server  | 1.108 DEBUG packet_sent this=0x55b902b88b40, pn=17, ps=21
server  | 1.108 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.108 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.108 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.108 DEBUG [Server fa7d772086fdaf717a5d] delay duration 83.633894ms
server  | 1.108 DEBUG Setting timeout of 83.633894ms
server  | 1.108 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.108 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.108 DEBUG TX blocked, profile=SendProfile { limit: 1332, pto: None, probe: EnumSet(), paced: false }
server  | 1.108 DEBUG [Server fa7d772086fdaf717a5d] delay duration 83.613776ms
server  | 1.108 DEBUG Setting timeout of 83.613776ms
server  | 1.110 DEBUG [Server fa7d772086fdaf717a5d] pn=8 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 37
server  |   -> RX Ack { largest_acknowledged: 13, ack_delay: 6, first_ack_range: 13, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 10, Ce: 0})) }
server  | 1.110 DEBUG [Server fa7d772086fdaf717a5d] Rx ACK space=ap, ranges=[0..=13]
server  | 1.110 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=13
server  | 1.110 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 2523/28476 ssthresh 18446744073709551615] slow start += 2604
server  | 1.110 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 2523/28476 ssthresh 18446744073709551615] on_packets_acked this=0x55b902b88b40, limited=0, bytes_in_flight=2523, cwnd=28476, state=SlowStart, new_acked=2604
server  | 1.110 DEBUG PMTUD probe of size 1420 succeeded
server  | 1.110 DEBUG PMTUD started with probe size 1470
server  | 1.110 DEBUG PLPMTU changed from 1332 to 1372, updating pacer
server  | 1.110 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false }
server  | 1.110 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.110 DEBUG Sending PMTUD probe of size 1470, count 1
server  | 1.110 DEBUG [Server fa7d772086fdaf717a5d] pn=18 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, NotEct) len 1422
server  |   TX -> Ping
server  |   TX -> Padding { len: 1403 }
server  | 1.110 DEBUG packet_sent this=0x55b902b88b40, pn=18, ps=1422
server  | 1.110 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false }
server  | 1.110 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.110 DEBUG TX blocked, profile=SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false }
server  | 1.110 DEBUG [Server fa7d772086fdaf717a5d] delay duration 79.946884ms
server  | 1.110 DEBUG Setting timeout of 79.946884ms
server  | 1.110 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false }
server  | 1.110 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.110 DEBUG TX blocked, profile=SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false }
server  | 1.110 DEBUG [Server fa7d772086fdaf717a5d] delay duration 79.925274ms
server  | 1.110 DEBUG Setting timeout of 79.925274ms
server  | 1.112 DEBUG [Server fa7d772086fdaf717a5d] pn=9 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 37
server  |   -> RX Ack { largest_acknowledged: 16, ack_delay: 11, first_ack_range: 15, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 13, Ce: 0})) }
server  | 1.112 DEBUG [Server fa7d772086fdaf717a5d] Rx ACK space=ap, ranges=[1..=16]
server  | 1.112 DEBUG [LossRecovery] ACK for ApplicationData - largest_acked=16
server  | 1.112 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 1443/30978 ssthresh 18446744073709551615] slow start += 2502
server  | 1.112 DEBUG [Cubic [last_max_cwnd: 0, k: 0, w_max: 0, ca_epoch_start: None] CongCtrl 1443/30978 ssthresh 18446744073709551615] on_packets_acked this=0x55b902b88b40, limited=0, bytes_in_flight=1443, cwnd=30978, state=SlowStart, new_acked=2502
server  | 1.112 DEBUG Acked crypto frame space=ap offset=0 length=305
server  | 1.112 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false }
server  | 1.112 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.112 DEBUG [Server fa7d772086fdaf717a5d] pn=19 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, NotEct) len 20
server  |   TX -> MaxStreams { stream_type: BiDi, maximum_streams: 18 }
server  | 1.112 DEBUG packet_sent this=0x55b902b88b40, pn=19, ps=21
server  | 1.112 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false }
server  | 1.112 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.112 DEBUG TX blocked, profile=SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false }
server  | 1.112 DEBUG [Server fa7d772086fdaf717a5d] delay duration 77.856172ms
server  | 1.112 DEBUG Setting timeout of 77.856172ms
server  | 1.112 DEBUG [Server fa7d772086fdaf717a5d] pn=10 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, Ect0) len 32
server  |   -> RX ConnectionClose { error_code: Application(0), frame_type: 0, reason_phrase: "" }
server  | 1.112 INFO [Server fa7d772086fdaf717a5d] ConnectionClose received. Error code: Application(0) frame type 0 reason 
server  | 1.112 DEBUG [Server fa7d772086fdaf717a5d] State change from Confirmed -> Draining { error: Transport(PeerApplicationError(0)), timeout: Instant { tv_sec: 572, tv_nsec: 84923644 } }
server  | 1.112 DEBUG [Server fa7d772086fdaf717a5d] output_path send_profile SendProfile { limit: 1372, pto: None, probe: EnumSet(), paced: false }
server  | 1.112 DEBUG Building Short dcid Some(CID [0]: )
server  | 1.112 DEBUG [Recvd-ap] immediate_ack at Instant { tv_sec: 571, tv_nsec: 851016842 }
server  | 1.112 DEBUG [Server fa7d772086fdaf717a5d] pn=20 type=Short pri-path: [::]:443->[fd00:cafe:cafe::100]:45546 IpTos(Cs0, NotEct) len 30
server  |   TX -> Ack { largest_acknowledged: 10, ack_delay: 0, first_ack_range: 10, ack_ranges: [], ecn_count: Some(Count({NotEct: 0, Ect1: 0, Ect0: 11, Ce: 0})) }
server  |   TX -> ConnectionClose { error_code: Transport(0), frame_type: 29, reason_phrase: "" }
server  | 1.112 DEBUG Setting timeout of 233.810331ms
server  | 1.112 DEBUG Setting timeout of 233.79942ms

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 09:42:04,924 Using the client's key log file.
2025-04-30 09:42:04,936 
2025-04-30 09:42:04,937 Using the client's key log file.
2025-04-30 09:42:04,937 Using the client's key log file.
2025-04-30 09:42:04,948 
2025-04-30 09:42:04,948 Using the client's key log file.
2025-04-30 09:42:05,526 Check of downloaded files succeeded.
2025-04-30 09:42:06,105 Check of downloaded files succeeded.