From 02a25f8725a7cf5602af1f0006b19c29d9314c90 Mon Sep 17 00:00:00 2001 From: dborup Date: Tue, 29 Sep 2026 06:12:02 +0000 Subject: [PATCH 1/2] test(qa): reproduce the topology warm-up flake on a fake clock CI run 36250468641 (master b3e44761) failed "topology warm-up then 200" while the same tree passed in PR CI. fetch_topology's deadline is $(date +%s) + RESTART_WAIT_S, in whole seconds, so a wait that starts late in a second has less than RESTART_WAIT_S. With RESTART_WAIT_S=4 and two 503s (3s apart), the retry after the second 503 is lost when the wait starts late enough. The fake target can now run the script on a fake clock: with FAKE_CLOCK_START_MS, `date +%s` and `sleep` in the logexec shim read and advance a millisecond clock instead of the real one, and each fake curl request takes FAKE_CLOCK_CALL_MS. The warm-up case now starts the topology wait at .950s with 50ms per request (a fixture guard checks that), which fails deterministically: the second 503 comes back at .050s past the deadline second. This commit is red on purpose; the next one fixes the test. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_019TcZHooUiiknVWbECVWzk8 --- qa/scripts/test-blacklist-sql.sh | 33 ++++++++++++++++++++++++++++++-- 1 file changed, 31 insertions(+), 2 deletions(-) diff --git a/qa/scripts/test-blacklist-sql.sh b/qa/scripts/test-blacklist-sql.sh index 7b5ec9edf..03dd69690 100755 --- a/qa/scripts/test-blacklist-sql.sh +++ b/qa/scripts/test-blacklist-sql.sh @@ -264,6 +264,17 @@ SQL # Record this exec's argv, then run the real command from FAKE_REAL_PATH. name=${0##*/} { printf '%s' "$name"; printf ' %q' "$@"; printf '\n'; } >>"$FAKE_ARGV_LOG" +# With FAKE_CLOCK (a file holding the time in milliseconds), `date +%s` reads +# that clock and `sleep N` advances it instead of waiting, so a run can start +# at any point within a second, deterministically. +if [ -n "${FAKE_CLOCK:-}" ]; then + case $name:$* in + date:+%s) ms=$(<"$FAKE_CLOCK"); echo $((ms / 1000)); exit 0 ;; + sleep:[0-9]*) [[ $1 =~ ^[0-9]+$ ]] || { echo "logexec: fake sleep takes whole seconds: $1" >&2; exit 2; } + ms=$(<"$FAKE_CLOCK"); echo $((ms + $1 * 1000)) >"$FAKE_CLOCK"; exit 0 ;; + date:*|sleep:*) echo "logexec: fake clock does not support: $name $*" >&2; exit 2 ;; + esac +fi set -f; IFS=: for d in $FAKE_REAL_PATH; do if [ -x "$d/$name" ] && [ ! -d "$d/$name" ]; then exec "$d/$name" "$@"; fi @@ -359,6 +370,12 @@ if [ "$path" = "$url" ]; then printf '000'; exit 7; fi hits_file="$FAKE_STATE/hits.${path//[^a-z]/_}" hits=0; [ -f "$hits_file" ] && hits=$(<"$hits_file"); hits=$((hits + 1)); echo "$hits" >"$hits_file" +# On the fake clock every request takes FAKE_CLOCK_CALL_MS; clock.log records +# when each one started. +if [ -n "${FAKE_CLOCK:-}" ]; then + ms=$(<"$FAKE_CLOCK"); echo "$ms $path" >>"$FAKE_STATE/clock.log" + echo $((ms + ${FAKE_CLOCK_CALL_MS:-0})) >"$FAKE_CLOCK" +fi if [ -n "${FAKE_SIGNAL_ON:-}" ] && [ "$path" = "$FAKE_SIGNAL_ON" ] && [ "$hits" = "${FAKE_SIGNAL_NTH:-1}" ]; then kill -s "$FAKE_SIGNAL" "$(<"$FAKE_STATE/script.pid")" fi @@ -516,7 +533,7 @@ FAKE unset TARGET_DB_PATH ADMIN_API_TOKEN TARGET_CONTAINER_DB_PATH TARGET_HOST_DB_PATH \ FAKE_CONTAINER_SQLITE FAKE_SIGNAL_ON FAKE_SIGNAL FAKE_SIGNAL_NTH FAKE_LEAK \ FAKE_DETAIL_LEAK FAKE_LIST_CODE FAKE_TOPO FAKE_TOPO_503 FAKE_TOPO_LEAK \ - FAKE_SSH_FAIL_CMD FAKE_SSH_FAIL_FROM + FAKE_SSH_FAIL_CMD FAKE_SSH_FAIL_FROM FAKE_CLOCK FAKE_CLOCK_START_MS FAKE_CLOCK_CALL_MS export TEST_NODE_PUBKEY="$PK_A" TARGET_SSH_HOST="stub-host" TARGET_SSH_KEY="/nonexistent/key" \ TARGET_CONFIG_PATH="$FAKE_CONFIG" TARGET_CONTAINER="$FAKE_CONTAINER" \ CURL_TIMEOUT=2 RESTART_WAIT_S=4 TMPDIR="$FAKE_TMPDIR" \ @@ -524,6 +541,11 @@ FAKE while [ $# -gt 0 ] && [ "$1" != -- ]; do kv=$1; export "${kv?}"; shift; done [ "${1:-}" = -- ] && shift wrap=("$@") + # FAKE_CLOCK_START_MS= runs the script on the fake clock. + if [ -n "${FAKE_CLOCK_START_MS:-}" ]; then + echo "$FAKE_CLOCK_START_MS" >"$FAKE_STATE/clock.ms" + export FAKE_CLOCK="$FAKE_STATE/clock.ms" + fi export PATH="$SHIM_DIR:$ORIG_PATH" # Optional kernel-level evidence (Linux): strace every execve of the # run, including anything the PATH shims cannot see. @@ -860,7 +882,14 @@ FAKE common_after "topology $v" done # Warm-up 503s after the restart are waited out; a 503 that never ends fails. - run_full TARGET_HOST_DB_PATH="$HOST_DB_PATH" FAKE_TOPO_503=2 + # On the fake clock every request takes 50ms and the topology wait starts + # 50ms before a whole second (three requests after the start), so the + # whole-second deadline leaves the shortest window, as when a real run + # starts late in a second (CI run 36250468641 flaked on this). + CLOCK_LATE=(FAKE_CLOCK_START_MS=1790000000800 FAKE_CLOCK_CALL_MS=50) + first_topo_ms() { awk '$2 == "/api/analytics/topology" { print $1 % 1000; exit }' "$FAKE_STATE/clock.log"; } + run_full TARGET_HOST_DB_PATH="$HOST_DB_PATH" FAKE_TOPO_503=2 "${CLOCK_LATE[@]}" + assert_eq "topology warm-up then 200: fixture starts the wait at .950s" "950" "$(first_topo_ms)" assert_eq "topology warm-up then 200: passes" "0" "$RUN_RC" assert_true "topology warm-up then 200: clean" contains "$RUN_OUT" "✅ topology clean" run_full TARGET_HOST_DB_PATH="$HOST_DB_PATH" FAKE_TOPO_503=999 From 2b37fa0e2562b9b860cd5782cdb9ff76537a6564 Mon Sep 17 00:00:00 2001 From: dborup Date: Tue, 29 Sep 2026 06:15:05 +0000 Subject: [PATCH 2/2] fix(qa-test): wait out topology warm-up with a whole-second margin fetch_topology's deadline is whole seconds, so it leaves between RESTART_WAIT_S-1 and RESTART_WAIT_S seconds. Two 503s need the retry decided about 3.1s after the wait starts, which RESTART_WAIT_S=4 misses from a start at .900s on. The warm-up and stuck cases now pass RESTART_WAIT_S=5 and run on the fake clock from two starts, .950s and .000s, with a fixture guard for each: - warm-up (two 503s, then 200): passes, clean, three topology requests; - stuck (503 forever): fails, classified as HTTP 503, retried at least once, and leaves config, databases and files as they were. On the fake clock these cases no longer sleep, so the suite is about 12s faster. blacklist-test.sh is unchanged. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_019TcZHooUiiknVWbECVWzk8 --- qa/scripts/test-blacklist-sql.sh | 37 +++++++++++++++++++++----------- 1 file changed, 24 insertions(+), 13 deletions(-) diff --git a/qa/scripts/test-blacklist-sql.sh b/qa/scripts/test-blacklist-sql.sh index 03dd69690..363551335 100755 --- a/qa/scripts/test-blacklist-sql.sh +++ b/qa/scripts/test-blacklist-sql.sh @@ -882,20 +882,31 @@ FAKE common_after "topology $v" done # Warm-up 503s after the restart are waited out; a 503 that never ends fails. - # On the fake clock every request takes 50ms and the topology wait starts - # 50ms before a whole second (three requests after the start), so the - # whole-second deadline leaves the shortest window, as when a real run - # starts late in a second (CI run 36250468641 flaked on this). - CLOCK_LATE=(FAKE_CLOCK_START_MS=1790000000800 FAKE_CLOCK_CALL_MS=50) + # Both run on a fake clock where every request takes 50ms. The deadline is + # whole seconds ($(date +%s) + RESTART_WAIT_S), so it leaves between + # RESTART_WAIT_S-1 and RESTART_WAIT_S seconds, least when the wait starts + # late in a second. Two 503s need the retry decided about 3.1s after the + # wait starts; RESTART_WAIT_S=4 lost it from a start at .900s on (CI run + # 36250468641 flaked on this), so these cases use 5. Each case starts the + # topology wait (three requests after the run starts) at .950s and at .000s; + # a fixture guard checks that. first_topo_ms() { awk '$2 == "/api/analytics/topology" { print $1 % 1000; exit }' "$FAKE_STATE/clock.log"; } - run_full TARGET_HOST_DB_PATH="$HOST_DB_PATH" FAKE_TOPO_503=2 "${CLOCK_LATE[@]}" - assert_eq "topology warm-up then 200: fixture starts the wait at .950s" "950" "$(first_topo_ms)" - assert_eq "topology warm-up then 200: passes" "0" "$RUN_RC" - assert_true "topology warm-up then 200: clean" contains "$RUN_OUT" "✅ topology clean" - run_full TARGET_HOST_DB_PATH="$HOST_DB_PATH" FAKE_TOPO_503=999 - assert_eq "topology stuck warming up: fails" "1" "$RUN_RC" - assert_true "topology stuck warming up: classified" contains "$RUN_OUT" "/api/analytics/topology HTTP 503" - common_after "topology stuck warming up" + topo_requests() { awk '$2 == "/api/analytics/topology" { n++ } END { print n + 0 }' "$FAKE_STATE/clock.log"; } + for clock in 1790000000800:950 1790000000850:000; do + at=${clock#*:} + CLOCK=(RESTART_WAIT_S=5 FAKE_CLOCK_START_MS="${clock%:*}" FAKE_CLOCK_CALL_MS=50) + run_full TARGET_HOST_DB_PATH="$HOST_DB_PATH" FAKE_TOPO_503=2 "${CLOCK[@]}" + assert_eq "topology warm-up then 200 (wait from .$at): fixture" "$((10#$at))" "$(first_topo_ms)" + assert_eq "topology warm-up then 200 (wait from .$at): passes" "0" "$RUN_RC" + assert_true "topology warm-up then 200 (wait from .$at): clean" contains "$RUN_OUT" "✅ topology clean" + assert_eq "topology warm-up then 200 (wait from .$at): two 503s, then 200" "3" "$(topo_requests)" + run_full TARGET_HOST_DB_PATH="$HOST_DB_PATH" FAKE_TOPO_503=999 "${CLOCK[@]}" + assert_eq "topology stuck warming up (wait from .$at): fixture" "$((10#$at))" "$(first_topo_ms)" + assert_eq "topology stuck warming up (wait from .$at): fails" "1" "$RUN_RC" + assert_true "topology stuck warming up (wait from .$at): classified" contains "$RUN_OUT" "/api/analytics/topology HTTP 503" + assert_true "topology stuck warming up (wait from .$at): retried before giving up" test "$(topo_requests)" -ge 2 + common_after "topology stuck warming up (wait from .$at)" + done # Arrays the server nulls out after filtering are a valid, clean shape. run_full TARGET_HOST_DB_PATH="$HOST_DB_PATH" FAKE_TOPO=nulls assert_eq "topology null arrays: clean" "0" "$RUN_RC"