diff --git a/backend/Cargo.lock b/backend/Cargo.lock index 7891cd5..949e167 100644 --- a/backend/Cargo.lock +++ b/backend/Cargo.lock @@ -1517,7 +1517,7 @@ checksum = "c41e0c4fef86961ac6d6f8a82609f55f31b05e4fce149ac5710e439df7619ba4" [[package]] name = "mangalord" -version = "0.87.17" +version = "0.87.18" dependencies = [ "anyhow", "argon2", diff --git a/backend/Cargo.toml b/backend/Cargo.toml index 4a9cc54..f99d493 100644 --- a/backend/Cargo.toml +++ b/backend/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "mangalord" -version = "0.87.17" +version = "0.87.18" edition = "2021" default-run = "mangalord" diff --git a/backend/src/app.rs b/backend/src/app.rs index 4abc76c..2eb63ad 100644 --- a/backend/src/app.rs +++ b/backend/src/app.rs @@ -1425,9 +1425,15 @@ mod tests { .await .unwrap(); - let storage: Arc = Arc::new(LocalStorage::new( - tempfile::tempdir().unwrap().path(), - )); + // Bind to a local so the TempDir lives for the rest of the test. + // `tempfile::tempdir().unwrap().path()` would drop the TempDir + // at end-of-expression and `LocalStorage` would hold a path to + // a deleted directory. (Today this is fine because the dispatch + // fails before storage is touched, but it makes the test fragile + // to any future code rearrangement.) + let storage_dir = tempfile::tempdir().unwrap(); + let storage: Arc = + Arc::new(LocalStorage::new(storage_dir.path())); let mut cfg = crate::config::AnalysisConfig::default(); cfg.workers = 1; cfg.job_timeout = Duration::from_secs(1); diff --git a/frontend/package.json b/frontend/package.json index 110db96..748ca0c 100644 --- a/frontend/package.json +++ b/frontend/package.json @@ -1,6 +1,6 @@ { "name": "mangalord-frontend", - "version": "0.87.17", + "version": "0.87.18", "private": true, "type": "module", "scripts": { diff --git a/vision-manager/manager.sh b/vision-manager/manager.sh index b888da5..0921acc 100644 --- a/vision-manager/manager.sh +++ b/vision-manager/manager.sh @@ -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 diff --git a/vision-manager/test_manager.sh b/vision-manager/test_manager.sh index 1a1bb01..94f1318 100755 --- a/vision-manager/test_manager.sh +++ b/vision-manager/test_manager.sh @@ -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 ]