From d7729512650fbbb51696d34c79acc627847a2dbe Mon Sep 17 00:00:00 2001 From: Martin Vogel Date: Wed, 14 Oct 2026 05:15:14 +0200 Subject: [PATCH] fix(soak): the per-call read follows the soak's own latency ceiling The soak's query-leak leg failed on GitHub's windows-11-arm runner in the v0.12.0 release run (38460145605) and in the 10-12 dry run (38204190338), both times on one search_code call. On that runner image the PowerShell-backed search_code answers in ~23 s per call (mean 23.3 s over 23 calls). One call crossed the harness's fixed 30 s read, counted as a failed operation, and failed the leg, even though the harness's own latency check (Check 4) allows 60 s. It is the runner environment, not the product: the same leg on a local Windows ARM64 VM gives search_code 1.10 s mean for v0.11.0 and 1.06 s for the v0.12.0 candidate artifact, both PASSED. Linux runs it in ~50 ms, macOS in ~150-230 ms, Windows x64 in ~0.9 s. One constant, SOAK_MAX_QUERY_LATENCY_S (60), now drives the latency check. The per-call read waits 30 s past it, so the measured latency, not a timeout, gives the verdict; a reply that never comes still ends the read and fails the call. Checked: bash -n; tests/test_soak_daemon_recovery_contract.sh and tests/test_smoke_fixture_contract.sh pass; the patched harness on the Windows ARM64 VM (query-leak, 2 min, candidate binary) PASSED. Signed-off-by: Martin Vogel --- scripts/soak-test.sh | 23 +++++++++++++++++------ 1 file changed, 17 insertions(+), 6 deletions(-) diff --git a/scripts/soak-test.sh b/scripts/soak-test.sh index 31a16259f..2b00d41d2 100755 --- a/scripts/soak-test.sh +++ b/scripts/soak-test.sh @@ -66,6 +66,16 @@ CBM_SOAK_MODE="${CBM_SOAK_MODE:-default}" RESULTS_DIR="${RESULTS_DIR:-soak-results}" mkdir -p "$RESULTS_DIR" +# One latency ceiling judges a slow call (Check 4 below). The per-call read +# waits past it, so the measured latency, not the read timeout, gives the +# verdict; a reply that never comes still ends the read. GitHub's +# windows-11-arm image (2026-10) answers the PowerShell-backed search_code in +# ~23 s per call (1.1 s for v0.11.0 and v0.12.0 alike on a local Windows ARM64 +# VM), and the old fixed 30 s read failed that leg on one borderline call while +# the 60 s ceiling itself held. +SOAK_MAX_QUERY_LATENCY_S=60 +SOAK_CALL_READ_TIMEOUT_S=$((SOAK_MAX_QUERY_LATENCY_S + 30)) + # Every product process below must reach a daemon rendezvous this run owns. # Only CBM_RUNTIME_DIR moves that rendezvous — a private CBM_CACHE_DIR alone # still shares the operator's account daemon (#1691, #1696). @@ -502,12 +512,13 @@ mcp_call() { # Send request to server stdin echo "$req" >&3 - # Read and validate one response (wait up to 30s). A JSON-RPC error or - # tool-level isError is a failed operation, not a successful round-trip. + # Read and validate one response (wait past the latency ceiling, see + # SOAK_CALL_READ_TIMEOUT_S). A JSON-RPC error or tool-level isError is a + # failed operation, not a successful round-trip. local resp="" local exit_code=1 MCP_LAST_RESPONSE="" - if read -r -t 30 resp <&4 2>/dev/null; then + if read -r -t "$SOAK_CALL_READ_TIMEOUT_S" resp <&4 2>/dev/null; then MCP_LAST_RESPONSE="$resp" if json_rpc_response_ok "$id" "$resp"; then exit_code=0 @@ -947,9 +958,9 @@ fi MAX_LATENCY=$(awk -F, 'NR>1 && $2!="index_repository" { if ($3>max) max=$3 } END { print max+0 }' "$LATENCY_CSV") MAX_INDEX=$(awk -F, 'NR>1 && $2=="index_repository" { if ($3>max) max=$3 } END { print max+0 }' "$LATENCY_CSV") echo "Max query latency: ${MAX_LATENCY}ms (index: ${MAX_INDEX}ms)" | tee -a "$SUMMARY" -# 60s threshold — MSYS2/Wine adds significant overhead to all operations -if [ "${MAX_LATENCY:-0}" -gt 60000 ] 2>/dev/null; then - echo "FAIL: max query latency ${MAX_LATENCY}ms > 60s" | tee -a "$SUMMARY" +# SOAK_MAX_QUERY_LATENCY_S — MSYS2/Wine adds significant overhead to all operations +if [ "${MAX_LATENCY:-0}" -gt $((SOAK_MAX_QUERY_LATENCY_S * 1000)) ] 2>/dev/null; then + echo "FAIL: max query latency ${MAX_LATENCY}ms > ${SOAK_MAX_QUERY_LATENCY_S}s" | tee -a "$SUMMARY" PASS=false fi