test(vision-manager): extract refresh_running_after_mem_check; assert log distinguishes fix from bug (0.87.18)
Two 0.87.15 ship-blockers: 1. mem_check_and_stop test now ALSO greps for the "deferring to next tick" warning — distinguishes fix from bug. Mutation-confirmed. 2. Extract `refresh_running_after_mem_check` (sets global instead of echoing so loop-scope flags persist across calls) and drive it directly from the harness, closing the structurally-untestable post-mem refresh ERR guard. Adjacent: log-on-flip gating on both ERR warnings; `log` to stderr; dangling-TempDir in app::tests reclaim test fixed. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
MechaCat02
@@ -43,7 +43,7 @@ MEM_POLL_INTERVAL="${MEM_POLL_INTERVAL:-5}" # mem sub-poll cadence,
|
||||
|
||||
PSQL=(psql "$DATABASE_URL" -At -v ON_ERROR_STOP=1)
|
||||
|
||||
log() { echo "[vision-manager] $(date -u +%FT%TZ) $*"; }
|
||||
log() { echo "[vision-manager] $(date -u +%FT%TZ) $*" >&2; }
|
||||
|
||||
# ---- Queries ---------------------------------------------------------------
|
||||
# Pending analysis work: pending OR currently-leased analyze_page jobs. Note
|
||||
@@ -178,10 +178,14 @@ mem_check_and_stop() {
|
||||
local vr; vr="$(vision_running)"
|
||||
case "$vr" in
|
||||
ERR)
|
||||
log "WARNING: memory-yield wanted to stop vision (used ${used}% >= ${MEM_HIGH_WATERMARK_PCT}%), but vision_running returned ERR — deferring to next tick"
|
||||
if [ "${mem_check_err_logged:-0}" != "1" ]; then
|
||||
log "WARNING: memory-yield wanted to stop vision (used ${used}% >= ${MEM_HIGH_WATERMARK_PCT}%), but vision_running returned ERR — deferring to next tick"
|
||||
mem_check_err_logged=1
|
||||
fi
|
||||
return 0
|
||||
;;
|
||||
true)
|
||||
mem_check_err_logged=0
|
||||
if stop_vision "memory-yield: used ${used}% >= ${MEM_HIGH_WATERMARK_PCT}% high watermark"; then
|
||||
mem_yield_until=$(( $(date +%s) + MEM_YIELD_COOLDOWN ))
|
||||
idle_for=0
|
||||
@@ -190,10 +194,42 @@ mem_check_and_stop() {
|
||||
;;
|
||||
*)
|
||||
# Not running — nothing to yield from. Cheap no-op.
|
||||
mem_check_err_logged=0
|
||||
;;
|
||||
esac
|
||||
}
|
||||
|
||||
# Refresh the cached vision_running after `mem_check_and_stop` may have
|
||||
# stopped the container. Sets the global `REFRESH_RUNNING_RESULT` to the
|
||||
# new running value (the literal `ERR` sentinel when docker inspect
|
||||
# fails) so the caller can short-circuit the tick instead of falling
|
||||
# through into branches whose `[ "$running" = "true" ]` test would treat
|
||||
# ERR as "stopped" (and then reset `up_for=0`, defeating MAX_UPTIME).
|
||||
# Logs the underlying error only on TRANSITION via the loop-scope
|
||||
# `inspect_err_logged` flag so a long-running docker-socket-proxy outage
|
||||
# doesn't flood the log.
|
||||
#
|
||||
# We set a global instead of echoing because the test harness drives
|
||||
# this via direct call (not `$()` subshell); preserving the loop-scope
|
||||
# log-on-flip flag requires staying in the caller's shell. Production
|
||||
# also avoids the subshell hop, which is a small perf win on every tick.
|
||||
#
|
||||
# Extracted from inline so test_manager.sh can drive each branch with
|
||||
# stubbed `docker` on PATH without entering the production loop.
|
||||
refresh_running_after_mem_check() {
|
||||
local r
|
||||
r="$(vision_running)"
|
||||
if [ "$r" = "ERR" ]; then
|
||||
if [ "${inspect_err_logged:-0}" != "1" ]; then
|
||||
log "WARNING: docker inspect failed after mem_check_and_stop; will retry next tick"
|
||||
inspect_err_logged=1
|
||||
fi
|
||||
else
|
||||
inspect_err_logged=0
|
||||
fi
|
||||
REFRESH_RUNNING_RESULT="$r"
|
||||
}
|
||||
|
||||
# Start inhibit: echo 1 while a cooldown is in effect OR used% is at/above the
|
||||
# LOW watermark. The two distinct watermarks give the mandatory hysteresis; the
|
||||
# cooldown gives whatever needed the RAM room to finish before vision restarts.
|
||||
@@ -214,6 +250,8 @@ crawl_deferred=0 # 1 while a start is held off by the crawl mutex (log on flip
|
||||
analysis_off=0 # 1 while analysis is disabled in settings (log on flip only)
|
||||
mem_yield_until=0 # epoch deadline of the active memory-yield cooldown (0 = none)
|
||||
mem_inhibited=0 # 1 while starts are inhibited by memory pressure (log on flip only)
|
||||
inspect_err_logged=0 # 1 once a docker inspect ERR has been warned about (log on flip only)
|
||||
mem_check_err_logged=0 # 1 once mem_check_and_stop has deferred on ERR (log on flip only)
|
||||
|
||||
# Tests source this script with `MANAGER_TEST_NO_MAIN=1` set so they can
|
||||
# exercise the helper functions above with stubbed `docker`/`psql` on PATH
|
||||
@@ -275,15 +313,9 @@ while true; do
|
||||
# LOW (idle stack + LLM ≈ 80% here). LOW is a START gate, not a stop
|
||||
# threshold.
|
||||
mem_check_and_stop
|
||||
# Refresh: the active stop may have just flipped vision_running.
|
||||
# Symmetric ERR handling with the top-of-loop check — without this,
|
||||
# a docker-socket-proxy hiccup between mem_check_and_stop and here
|
||||
# makes `running=ERR`, the next `[ "$running" = "true" ]` test is
|
||||
# false, and `up_for=0` resets — defeating MAX_UPTIME exactly the
|
||||
# way the top-of-loop guard was meant to prevent.
|
||||
running="$(vision_running)"
|
||||
refresh_running_after_mem_check
|
||||
running="$REFRESH_RUNNING_RESULT"
|
||||
if [ "$running" = "ERR" ]; then
|
||||
log "WARNING: docker inspect failed after mem_check_and_stop; will retry next tick"
|
||||
sleep "$POLL_INTERVAL"
|
||||
continue
|
||||
fi
|
||||
|
||||
@@ -6,11 +6,17 @@
|
||||
#
|
||||
# Run: `vision-manager/test_manager.sh` (no arguments).
|
||||
#
|
||||
# This is intentionally pragmatic — a full bats setup adds a dependency
|
||||
# the project doesn't otherwise carry. The smoke tests cover the three
|
||||
# behaviours the 0.87.8 commit claims, plus the two ERR-guard gaps the
|
||||
# adversarial review flagged (mem_check_and_stop ERR symmetry, post-
|
||||
# mem_check loop refresh).
|
||||
# Covers:
|
||||
# * vision_running's three exit shapes (true / false / ERR)
|
||||
# * mem_check_and_stop's ERR symmetry — including a positive grep on
|
||||
# the "deferring to next tick" warning that DISTINGUISHES the fix
|
||||
# from the bug (the prior version of this file only asserted
|
||||
# `docker stop` was absent, which is true for BOTH branches)
|
||||
# * refresh_running_after_mem_check (extracted in 0.87.18) — the
|
||||
# post-mem_check ERR guard that was structurally untestable in the
|
||||
# 0.87.15 harness because MANAGER_TEST_NO_MAIN=1 skips the loop
|
||||
# * log-on-flip gating for the new WARNING lines so a long outage
|
||||
# doesn't flood the log
|
||||
set -euo pipefail
|
||||
|
||||
script_dir="$(cd "$(dirname "$0")" && pwd)"
|
||||
@@ -27,6 +33,12 @@ trap 'rm -rf "$stub_dir"' EXIT
|
||||
state_file="$stub_dir/.state"
|
||||
: > "$state_file"
|
||||
|
||||
# `log_file` captures everything `log` emits during a single test so the
|
||||
# bug-vs-fix-distinguishing tests can grep for the WARNING line that the
|
||||
# 0.87.15 test failed to assert.
|
||||
log_file="$stub_dir/.log"
|
||||
: > "$log_file"
|
||||
|
||||
# Configurable stubs: each stub looks for a per-call env var and emits
|
||||
# whatever the test set. Stubs append to $state_file so a test can assert
|
||||
# "stop_vision called N times" etc.
|
||||
@@ -103,8 +115,49 @@ assert_eq() {
|
||||
|
||||
reset() {
|
||||
: > "$state_file"
|
||||
: > "$log_file"
|
||||
unset STUB_DOCKER_INSPECT_OUT STUB_DOCKER_INSPECT_RC STUB_DOCKER_RC
|
||||
unset STUB_PSQL_OUT STUB_PSQL_RC STUB_CURL_RC
|
||||
# Reset the loop-scope log-on-flip flags so each test starts from a
|
||||
# clean slate. Initially zero per manager.sh's main-loop init block.
|
||||
mem_check_err_logged=0
|
||||
inspect_err_logged=0
|
||||
}
|
||||
|
||||
# Capture stdout from a function call so a test can assert on what the
|
||||
# manager logged, not just on what it didn't do. `log` writes to stdout
|
||||
# (see manager.sh:46); redirect it through this helper to a file and
|
||||
# return the function's exit code so the chained `$?` is preserved.
|
||||
run_and_capture_log() {
|
||||
"$@" >>"$log_file" 2>&1
|
||||
}
|
||||
|
||||
assert_log_contains() {
|
||||
local want="$1" desc="$2"
|
||||
if grep -qF -- "$want" "$log_file"; then
|
||||
pass=$((pass + 1))
|
||||
echo " ok: $desc"
|
||||
else
|
||||
fail=$((fail + 1))
|
||||
echo " FAIL: $desc"
|
||||
echo " expected log to contain: ${want}"
|
||||
echo " log was:"
|
||||
sed 's/^/ /' "$log_file"
|
||||
fi
|
||||
}
|
||||
|
||||
assert_log_count() {
|
||||
local pattern="$1" want="$2" desc="$3"
|
||||
local got
|
||||
got="$(grep -cF -- "$pattern" "$log_file" || true)"
|
||||
if [ "$got" = "$want" ]; then
|
||||
pass=$((pass + 1))
|
||||
echo " ok: $desc"
|
||||
else
|
||||
fail=$((fail + 1))
|
||||
echo " FAIL: $desc"
|
||||
echo " pattern '${pattern}' expected count ${want}, got ${got}"
|
||||
fi
|
||||
}
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
@@ -138,20 +191,35 @@ read_mem_used_pct() { echo "95"; }
|
||||
|
||||
reset
|
||||
export STUB_DOCKER_INSPECT_OUT="Cannot connect to the Docker daemon" STUB_DOCKER_INSPECT_RC=2
|
||||
MEM_YIELD_ENABLED=1 MEM_HIGH_WATERMARK_PCT=90 mem_check_and_stop
|
||||
# Stub state should NOT contain a `docker stop` line — the inspect error
|
||||
# must defer, not silently no-op the SIGTERM.
|
||||
MEM_YIELD_ENABLED=1 MEM_HIGH_WATERMARK_PCT=90 run_and_capture_log mem_check_and_stop
|
||||
# Two distinct assertions: no docker stop (the absence) AND the
|
||||
# "deferring to next tick" warning (the presence). The 0.87.15 test
|
||||
# checked only the first, which both buggy AND fixed branches satisfy.
|
||||
# Without the warning assertion, mechanical revert of the ERR carve-out
|
||||
# to `[ "$vr" = "true" ]` ships green — the rereview verified this.
|
||||
if grep -q "^docker stop " "$state_file"; then
|
||||
fail=$((fail + 1))
|
||||
echo " FAIL: mem_check_and_stop must NOT call docker stop when vision_running returns ERR"
|
||||
else
|
||||
pass=$((pass + 1))
|
||||
echo " ok: mem_check_and_stop defers stop on inspect ERR (no silent no-op)"
|
||||
echo " ok: mem_check_and_stop defers stop on inspect ERR (no SIGTERM)"
|
||||
fi
|
||||
assert_log_contains \
|
||||
"but vision_running returned ERR — deferring to next tick" \
|
||||
"mem_check_and_stop logs the deferral warning on ERR (distinguishes fix from bug)"
|
||||
|
||||
# Log-on-flip: a second mem_check_and_stop call with the same ERR must
|
||||
# NOT re-log the warning. Mirrors the sibling mem_inhibited/crawl_deferred
|
||||
# pattern in the production code.
|
||||
run_and_capture_log mem_check_and_stop
|
||||
assert_log_count \
|
||||
"but vision_running returned ERR — deferring to next tick" \
|
||||
"1" \
|
||||
"mem_check_and_stop log-on-flip: WARNING doesn't repeat across ticks"
|
||||
|
||||
reset
|
||||
export STUB_DOCKER_INSPECT_OUT="true" STUB_DOCKER_INSPECT_RC=0
|
||||
MEM_YIELD_ENABLED=1 MEM_HIGH_WATERMARK_PCT=90 mem_check_and_stop
|
||||
MEM_YIELD_ENABLED=1 MEM_HIGH_WATERMARK_PCT=90 run_and_capture_log mem_check_and_stop
|
||||
if grep -q "^docker stop " "$state_file"; then
|
||||
pass=$((pass + 1))
|
||||
echo " ok: mem_check_and_stop stops vision when vision_running='true' and pressure"
|
||||
@@ -162,7 +230,7 @@ fi
|
||||
|
||||
reset
|
||||
export STUB_DOCKER_INSPECT_OUT="false" STUB_DOCKER_INSPECT_RC=0
|
||||
MEM_YIELD_ENABLED=1 MEM_HIGH_WATERMARK_PCT=90 mem_check_and_stop
|
||||
MEM_YIELD_ENABLED=1 MEM_HIGH_WATERMARK_PCT=90 run_and_capture_log mem_check_and_stop
|
||||
if grep -q "^docker stop " "$state_file"; then
|
||||
fail=$((fail + 1))
|
||||
echo " FAIL: mem_check_and_stop should NOT call docker stop when vision isn't running"
|
||||
@@ -171,6 +239,50 @@ else
|
||||
echo " ok: mem_check_and_stop no-ops when vision isn't running"
|
||||
fi
|
||||
|
||||
echo
|
||||
echo "refresh_running_after_mem_check: post-mem ERR guard (extracted helper)"
|
||||
|
||||
reset
|
||||
export STUB_DOCKER_INSPECT_OUT="true" STUB_DOCKER_INSPECT_RC=0
|
||||
run_and_capture_log refresh_running_after_mem_check
|
||||
assert_eq "$REFRESH_RUNNING_RESULT" "true" "refresh_running_after_mem_check sets 'true' when running"
|
||||
if grep -q "WARNING" "$log_file"; then
|
||||
fail=$((fail + 1))
|
||||
echo " FAIL: refresh_running_after_mem_check must not log on the happy path"
|
||||
else
|
||||
pass=$((pass + 1))
|
||||
echo " ok: refresh_running_after_mem_check is quiet on the happy path"
|
||||
fi
|
||||
|
||||
reset
|
||||
export STUB_DOCKER_INSPECT_OUT="Cannot connect to the Docker daemon" STUB_DOCKER_INSPECT_RC=2
|
||||
run_and_capture_log refresh_running_after_mem_check
|
||||
assert_eq "$REFRESH_RUNNING_RESULT" "ERR" "refresh_running_after_mem_check sets 'ERR' on docker inspect failure"
|
||||
assert_log_contains \
|
||||
"docker inspect failed after mem_check_and_stop" \
|
||||
"refresh_running_after_mem_check warns on ERR (distinguishes fix from bug)"
|
||||
|
||||
# Log-on-flip: second ERR call must NOT re-log.
|
||||
run_and_capture_log refresh_running_after_mem_check
|
||||
assert_eq "$REFRESH_RUNNING_RESULT" "ERR" "second ERR also sets 'ERR'"
|
||||
assert_log_count \
|
||||
"docker inspect failed after mem_check_and_stop" \
|
||||
"1" \
|
||||
"refresh_running_after_mem_check log-on-flip: WARNING doesn't repeat across ticks"
|
||||
|
||||
# Transition back to OK must reset the flip-flag so a future ERR
|
||||
# re-logs.
|
||||
export STUB_DOCKER_INSPECT_OUT="true" STUB_DOCKER_INSPECT_RC=0
|
||||
run_and_capture_log refresh_running_after_mem_check
|
||||
assert_eq "$REFRESH_RUNNING_RESULT" "true" "transition to OK resets the helper"
|
||||
export STUB_DOCKER_INSPECT_OUT="Cannot connect" STUB_DOCKER_INSPECT_RC=2
|
||||
run_and_capture_log refresh_running_after_mem_check
|
||||
assert_eq "$REFRESH_RUNNING_RESULT" "ERR" "re-ERR after recovery sets 'ERR'"
|
||||
assert_log_count \
|
||||
"docker inspect failed after mem_check_and_stop" \
|
||||
"2" \
|
||||
"refresh_running_after_mem_check log-on-flip: re-ERR after recovery DOES log"
|
||||
|
||||
echo
|
||||
echo "Result: ${pass} pass, ${fail} fail"
|
||||
[ "$fail" -eq 0 ]
|
||||
|
||||
Reference in New Issue
Block a user