2025-12-13 10:56:30,645 Generated random file: soft-fast-heatran of size: 10485760 2025-12-13 10:56:30,645 Requests: https://server4:443/soft-fast-heatran 2025-12-13 10:56:30,705 2025-12-13 10:56:30,706 Command: WAITFORSERVER=server:443 CERTS=/tmp/certs_mm3v_fq5/ TESTCASE_SERVER=transfer TESTCASE_CLIENT=transfer WWW=/tmp/www_ztnnvjge/ DOWNLOADS=/tmp/download_5o_v_0_n/ SERVER_LOGS=/tmp/logs_server_w4bnr0rl CLIENT_LOGS=/tmp/logs_client_i3pc8znm SCENARIO="rebind --delay=15ms --bandwidth=10Mbps --queue=25 --first-rebind=1s --rebind-freq=5s" CLIENT=privateoctopus/picoquic:latest SERVER=ghcr.io/nginx/nginx-quic-qns:latest REQUESTS="https://server4:443/soft-fast-heatran" docker compose --env-file empty.env up --abort-on-container-exit --timeout 1 sim client server 2025-12-13 10:57:30,714 Container sim Recreate Container sim Recreated Container server Recreate Container client Recreate Container server Recreated Container client Recreated Attaching to client, server, sim sim | waiting 10s for server:443 client | Setting up the simulation with setup.sh client | Setting up routes... client | Actual changes: client | tx-checksum-ip-generic: off client | tx-tcp-segmentation: off [not requested] client | tx-tcp-ecn-segmentation: off [not requested] client | tx-tcp-mangleid-segmentation: off [not requested] client | tx-tcp6-segmentation: off [not requested] client | tx-udp-segmentation: off [not requested] client | tx-checksum-sctp: off client | Endpoint's IPv4 address is 193.167.0.100 client | Endpoint's IPv6 address is fd00:cafe:cafe::100 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 client | Setup.sh completed client | Waiting for the simulator to start server | Endpoint's IPv6 address is fd00:cafe:cafe:100::100 server | >>> Starting nginx server... server | nginx version: nginx/1.29.4 (6ed1188411882086e3518eda779ab782d8ab4d3f) server | built by gcc 13.3.0 (Ubuntu 13.3.0-6ubuntu2~24.04) server | built with OpenSSL 1.1.1 (compatible; BoringSSL) (running with BoringSSL) server | TLS SNI support enabled server | configure arguments: --prefix=/etc/nginx --build=6ed1188411882086e3518eda779ab782d8ab4d3f --sbin-path=/usr/sbin/nginx --modules-path=/usr/lib/nginx/modules --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --pid-path=/run/nginx.pid --lock-path=/run/nginx.lock --http-client-body-temp-path=/var/cache/nginx/client_temp --http-proxy-temp-path=/var/cache/nginx/proxy_temp --http-fastcgi-temp-path=/var/cache/nginx/fastcgi_temp --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp --http-scgi-temp-path=/var/cache/nginx/scgi_temp --user=nginx --group=nginx --with-compat --with-debug --with-http_ssl_module --with-http_v2_module --with-http_v3_module --with-cc=c++ --with-cc-opt='-I/boringssl/include -O0 -fno-common -fno-omit-frame-pointer -x c' --with-ld-opt=-L/boringssl/build server | >>> Parameters: server | >>> Test case: transfer client | wait-for-it.sh: waiting 30 seconds for sim:57832 server | 2025/12/13 10:56:31 [notice] 21#0: using the "epoll" event method server | 2025/12/13 10:56:31 [notice] 21#0: nginx/1.29.4 (6ed1188411882086e3518eda779ab782d8ab4d3f) server | 2025/12/13 10:56:31 [notice] 21#0: built by gcc 13.3.0 (Ubuntu 13.3.0-6ubuntu2~24.04) server | 2025/12/13 10:56:31 [notice] 21#0: OS: Linux 6.11.0-1018-azure server | 2025/12/13 10:56:31 [notice] 21#0: getrlimit(RLIMIT_NOFILE): 65536:65536 server | 2025/12/13 10:56:31 [notice] 21#0: start worker processes server | 2025/12/13 10:56:31 [notice] 21#0: start worker process 22 sim | server:443 is available after 501.227269ms sim | Using scenario: rebind --delay=15ms --bandwidth=10Mbps --queue=25 --first-rebind=1s --rebind-freq=5s sim | Capturing on 'eth0' sim | Capturing on 'eth1' sim | File: /logs/trace_node_right.pcap sim | File: /logs/trace_node_left.pcap sim | 0s: first rebind in 1s, frequency 5s client | wait-for-it.sh: sim:57832 is available after 1 seconds client | Starting picoquic client for test: transfer client | Starting picoquic client ... client | Parsing server name from first request: https://server4:443/soft-fast-heatran client | Server set to: server4 client | Requests: https://server4:443/soft-fast-heatran client | parsing as client | Starting Picoquic (v1.1.26.1) connection to server = server4, port = 443 client | No token file present. Will create one as . client | Testing scenario: <-:/soft-fast-heatran;> client | Max stream id bidir remote before start = 0 (0) client | Starting client connection. Version = 1, I-CID: 7600f7dc9bf2434e client | Max stream id bidir remote after start = -4 (0) client | Waiting for packets. client | Client port (AF=2): 54982. client | Negotiated ALPN: hq-interop client | Almost ready! client | client | Connection established. Version = 1, I-CID: 7600f7dc9bf2434e, verified: 1 client | Opening stream 0 to GET /soft-fast-heatran sim | Packets: 1 Packets: 1 Packets: 5 Packets: 5 Packets: 12 Packets: 9 Packets: 35 Packets: 49 1s: rebinding: 193.167.0.100:50902 -> 193.167.0.100:57607 sim | 1.00075s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.00192s: unknown binding for destination 193.167.0.100:50902, dropping packet server | 2025/12/13 10:56:32 [info] 22#0: *2 quic migrated to path seq:1 addr:193.167.0.100:57607 while handling frames, client: 193.167.0.100, server: 0.0.0.0:443 sim | 1.0031s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.00427s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.00545s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.00663s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.0078s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.00898s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.01015s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.01133s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.01251s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.01368s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.01486s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.01603s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.01721s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.01839s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.01956s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.02074s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.02172s: unknown binding for destination 193.167.0.100:50902, dropping packet sim | 1.02271s: unknown binding for destination 193.167.0.100:50902, dropping packet server | 2025/12/13 10:56:32 [info] 22#0: *2 quic path seq:1 addr:193.167.0.100:57607 successfully validated while handling frames, client: 193.167.0.100, server: 0.0.0.0:443 sim | Packets: 288 Packets: 303 Packets: 475 Packets: 470 Packets: 631 Packets: 629 Packets: 830 Packets: 822 Packets: 1035 Packets: 1027 Packets: 1240 Packets: 1233 Packets: 1443 Packets: 1436 Packets: 1647 Packets: 1641 Packets: 1849 Packets: 1844 Packets: 2050 Packets: 2046 Packets: 2254 Packets: 2250 Packets: 2458 Packets: 2454 Packets: 2661 Packets: 2657 Packets: 2865 Packets: 2861 Packets: 3071 Packets: 3067 Packets: 3275 Packets: 3271 Packets: 3481 Packets: 3478 Packets: 3685 Packets: 3676 Packets: 3872 Packets: 3863 Packets: 4059 Packets: 4051 Packets: 4246 Packets: 4239 Packets: 4436 Packets: 4430 Packets: 4625 Packets: 4618 Packets: 4813 Packets: 4806 Packets: 5002 Packets: 4995 6s: rebinding: 193.167.0.100:57607 -> 193.167.0.100:59022 sim | 6.00071s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.00189s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.00307s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.00424s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.00502s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.0062s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.00737s: unknown binding for destination 193.167.0.100:57607, dropping packet server | 2025/12/13 10:56:37 [info] 22#0: *2 quic no available client ids for new path while handling decrypted packet, client: 193.167.0.100, server: 0.0.0.0:443 sim | 6.00855s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.00972s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.0109s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.01208s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.01325s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.01443s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.0156s: unknown binding for destination 193.167.0.100:57607, dropping packet server | 2025/12/13 10:56:37 [info] 22#0: *2 quic no available client ids for new path while handling decrypted packet, client: 193.167.0.100, server: 0.0.0.0:443 sim | 6.01678s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.01795s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.01913s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.02031s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.02147s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.02265s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.02382s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.025s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.02618s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.02735s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.02853s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.02969s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.03087s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.03204s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.03322s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.03439s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.03557s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.03675s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.03792s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.0849s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.08494s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | Packets: 5190 Packets: 5182 6.22518s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.22523s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | Packets: 5264 Packets: 5216 6.50559s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 6.50563s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | Packets: 5266 Packets: 5268 7.06628s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 7.06633s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | Packets: 5270 8.18663s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 8.18668s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | Packets: 5272 10.429s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 10.4291s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | Packets: 5274 11s: rebinding: 193.167.0.100:59022 -> 193.167.0.100:18108 sim | Packets: 5217 Packets: 5218 Packets: 5275 Packets: 5276 14.9101s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 14.9101s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | Packets: 5278 16s: rebinding: 193.167.0.100:18108 -> 193.167.0.100:39968 sim | 21s: rebinding: 193.167.0.100:39968 -> 193.167.0.100:745 sim | 23.8779s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 23.8779s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | Packets: 5279 Packets: 5280 26s: rebinding: 193.167.0.100:745 -> 193.167.0.100:38910 sim | Packets: 5219 Packets: 5281 Packets: 5283 Packets: 5220 Packets: 5284 31s: rebinding: 193.167.0.100:38910 -> 193.167.0.100:64331 sim | Packets: 5285 36s: rebinding: 193.167.0.100:64331 -> 193.167.0.100:19495 sim | 41s: rebinding: 193.167.0.100:19495 -> 193.167.0.100:51391 sim | 41.816s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | 41.8161s: unknown binding for destination 193.167.0.100:57607, dropping packet sim | Packets: 5286 Packets: 5287 46s: rebinding: 193.167.0.100:51391 -> 193.167.0.100:28302 sim | 51s: rebinding: 193.167.0.100:28302 -> 193.167.0.100:55838 sim | 56s: rebinding: 193.167.0.100:55838 -> 193.167.0.100:46157 2025-12-13 10:57:30,715 Test failed: took longer than 60s. 2025-12-13 10:57:30,773 time="2025-12-13T10:57:30Z" level=warning msg="The \"SERVER\" variable is not set. Defaulting to a blank string." time="2025-12-13T10:57:30Z" level=warning msg="The \"CLIENT\" variable is not set. Defaulting to a blank string." invalid spec: :/www:ro: empty section between colons