dw-staged-active-snapshot: retry transient blips + post-push heartbeat (TK-11298)

96f279ad84006c4de20c1bfcdfa04e35ebb27e1e · 2026-09-16 14:15:49 -0700 · Steve

The hourly job fired but crashed 61 times in 2042 runs (97% OK). Every failure was a
transient infra blip that self-healed on the next fire: 31 local-postgres socket
down/"database system is starting up" (exit 2), 28 rsync/ssh blips (exit 1). The script
had set -euo pipefail and NO retry, so a one-second blip killed the run and left prod an
hour stale — producing 14 warn/recover pairs on the canary ticket.

- retry with backoff around the DB build and the push; each attempt is logged, so a blip
stays visible in refresh.log instead of being silently swallowed.
- per-run unique remote .tmp name. 8 of the 61 were "mv: cannot stat …json.tmp" with NO
rsync error, i.e. rsync exited 0 without leaving the shared tmp. A unique name makes the
"something else consumed my tmp" mechanism impossible and any residue self-describing.
- single-instance lock (mkdir; macOS has no flock(1)) with stale reclaim.
- remote mv now verifies the tmp is non-empty before replacing the live file.
- data/heartbeat.json written ONLY after the remote mv succeeds. This is the artifact
cron-fire-canary measures, so freshness proves PROD HAS THE DATA. Deliberately not
data/staged-snapshot.json, which is written BEFORE the push and would read fresh while
prod is stale — the false-green class that hides push-side failure (28 of the 61).
- one run-evidence line on launchd's own stdout: the plist declares StandardOutPath but
the body redirects into refresh.log, so that file sat 0 bytes since Jun 23, which is why
artifact discovery rejected it and the canary could not time-correlate a failing exit.

Verified: dry run, lock-skip, retry absorb + give-up, real run (prod 21:11Z, heartbeat
PASS, no tmp residue). Negative test: push forced to fail -> retries exhausted -> exit 1
-> heartbeat NOT written (false green stays closed).

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01F1QMWkgyXkmmVQe6gSQUVb

Files touched

M .gitignore
M scripts/refresh-and-push.sh

Diff

commit 96f279ad84006c4de20c1bfcdfa04e35ebb27e1e
Author: Steve <steve@designerwallcoverings.com>
Date:   Wed Sep 16 14:15:49 2026 -0700

    dw-staged-active-snapshot: retry transient blips + post-push heartbeat (TK-11298)
    
    The hourly job fired but crashed 61 times in 2042 runs (97% OK). Every failure was a
    transient infra blip that self-healed on the next fire: 31 local-postgres socket
    down/"database system is starting up" (exit 2), 28 rsync/ssh blips (exit 1). The script
    had set -euo pipefail and NO retry, so a one-second blip killed the run and left prod an
    hour stale — producing 14 warn/recover pairs on the canary ticket.
    
    - retry with backoff around the DB build and the push; each attempt is logged, so a blip
      stays visible in refresh.log instead of being silently swallowed.
    - per-run unique remote .tmp name. 8 of the 61 were "mv: cannot stat …json.tmp" with NO
      rsync error, i.e. rsync exited 0 without leaving the shared tmp. A unique name makes the
      "something else consumed my tmp" mechanism impossible and any residue self-describing.
    - single-instance lock (mkdir; macOS has no flock(1)) with stale reclaim.
    - remote mv now verifies the tmp is non-empty before replacing the live file.
    - data/heartbeat.json written ONLY after the remote mv succeeds. This is the artifact
      cron-fire-canary measures, so freshness proves PROD HAS THE DATA. Deliberately not
      data/staged-snapshot.json, which is written BEFORE the push and would read fresh while
      prod is stale — the false-green class that hides push-side failure (28 of the 61).
    - one run-evidence line on launchd's own stdout: the plist declares StandardOutPath but
      the body redirects into refresh.log, so that file sat 0 bytes since Jun 23, which is why
      artifact discovery rejected it and the canary could not time-correlate a failing exit.
    
    Verified: dry run, lock-skip, retry absorb + give-up, real run (prod 21:11Z, heartbeat
    PASS, no tmp residue). Negative test: push forced to fail -> retries exhausted -> exit 1
    -> heartbeat NOT written (false green stays closed).
    
    Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
    Claude-Session: https://claude.ai/code/session_01F1QMWkgyXkmmVQe6gSQUVb
---
 .gitignore                  |   3 ++
 scripts/refresh-and-push.sh | 103 ++++++++++++++++++++++++++++++++++++++++----
 2 files changed, 97 insertions(+), 9 deletions(-)

diff --git a/.gitignore b/.gitignore
index 1a66059..d13a70a 100644
--- a/.gitignore
+++ b/.gitignore
@@ -9,3 +9,6 @@ build/
 .next/
 data/staged-snapshot.json
 *.bak
+
+# TK-11298: runtime heartbeat (post-push liveness artifact), rewritten every successful run
+data/heartbeat.json
diff --git a/scripts/refresh-and-push.sh b/scripts/refresh-and-push.sh
index 0e9ef28..11df0a2 100755
--- a/scripts/refresh-and-push.sh
+++ b/scripts/refresh-and-push.sh
@@ -2,26 +2,111 @@
 # refresh-and-push.sh  (Mac2-only)
 # Regenerates the staged snapshot from Mac2-local dw_unified, then rsyncs it to the
 # Kamatera-hosted viewer so https://staged.designerwallcoverings.com stays current.
-# Runs hourly via launchd (com.steve.dw-staged-active-snapshot), aligned ~with the cadence.
-# READ-ONLY against the DB; the only write is the static JSON + the rsync to Kamatera.
+# Runs hourly via launchd (com.steve.dw-staged-active-snapshot).
+# READ-ONLY against the DB; the only writes are the static JSON, the heartbeat, and the push.
+#
+# TK-11298 hardening. Measured over 2042 runs: 1981 OK (97%), 61 failures, EVERY one a
+# transient infra blip that self-healed on the next hourly fire — 31 local-postgres
+# socket down/"database system is starting up" (exit 2), 28 rsync/ssh blips (exit 1).
+# The old script had set -euo pipefail and NO retry, so a one-second blip killed the whole
+# run and left prod an hour stale. Four changes:
+#   1. RETRY with backoff around the DB build and the push, so a blip is absorbed, not fatal.
+#   2. PER-RUN UNIQUE remote tmp name. 8 of the 61 were "mv: cannot stat …json.tmp" with NO
+#      rsync error, i.e. rsync exited 0 without leaving the shared .tmp. A unique name makes
+#      the "someone else consumed my tmp" mechanism impossible and any residue self-describing.
+#   3. SINGLE-INSTANCE LOCK. macOS has no flock(1); mkdir is the atomic primitive.
+#   4. POST-PUSH HEARTBEAT (data/heartbeat.json), written ONLY after the remote mv succeeds.
+#      This is the artifact cron-fire-canary measures (registered in that skill's
+#      ARTIFACT_OVERRIDES). Deliberately PASS-only: freshness therefore proves PROD HAS THE
+#      DATA, not merely "the builder ran". Pointing the canary at data/staged-snapshot.json
+#      instead would be a FALSE GREEN — that file is written BEFORE the push, so it reads
+#      fresh even when the push failed and prod is stale.
 set -euo pipefail
 
 PROJ="$HOME/Projects/dw-staged-active-viewer"
 REMOTE_HOST="my-server"
 REMOTE_PATH="/root/public-projects/staged-viewer/data/staged-snapshot.json"
 LOG="$PROJ/tmp/refresh.log"
-mkdir -p "$PROJ/tmp"
+HEARTBEAT="$PROJ/data/heartbeat.json"
+LOCKDIR="$PROJ/tmp/refresh.lock"
+STALE_LOCK_SEC=1800
+DRY="${DRY_RUN:-0}"
+mkdir -p "$PROJ/tmp" "$PROJ/data"
 
 # Use a login shell PATH so node + psql resolve under launchd.
 export PATH="/opt/homebrew/bin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin:$PATH"
 
+# Run-evidence line on launchd's OWN stdout (outside the redirect block below). The plist
+# declares StandardOutPath=tmp/snapshot.out.log but the body redirects everything into
+# refresh.log, so that file sat 0 bytes from Jun 23 — which is (a) why artifact discovery
+# rejected it and this job fell back to the raw runs counter, and (b) why the canary could
+# never time-correlate a failing exit against a run. One line per fire fixes the correlation.
+echo "[$(date '+%Y-%m-%d %H:%M:%S')] dw-staged-active-snapshot fired (pid $$)"
+
+# ---- single-instance lock -----------------------------------------------------------
+if ! mkdir "$LOCKDIR" 2>/dev/null; then
+  lock_age=$(( $(date +%s) - $(stat -f %m "$LOCKDIR" 2>/dev/null || echo 0) ))
+  if [ "$lock_age" -gt "$STALE_LOCK_SEC" ]; then
+    echo "=== $(date '+%Y-%m-%d %H:%M:%S') reclaiming stale lock (age ${lock_age}s) ===" >> "$LOG"
+    rm -rf "$LOCKDIR"; mkdir "$LOCKDIR" 2>/dev/null || exit 0
+  else
+    echo "=== $(date '+%Y-%m-%d %H:%M:%S') another instance holds the lock (age ${lock_age}s); skipping ===" >> "$LOG"
+    exit 0
+  fi
+fi
+
+REMOTE_TMP="${REMOTE_PATH}.$$-$(date +%s).tmp"
+cleanup() {
+  rc=$?
+  rm -rf "$LOCKDIR"
+  if [ "$rc" -ne 0 ] && [ "$DRY" != "1" ]; then
+    ssh -o ConnectTimeout=10 "$REMOTE_HOST" "rm -f '$REMOTE_TMP'" >/dev/null 2>&1 || true
+  fi
+}
+trap cleanup EXIT
+
+# retry <label> <tries> <cmd...>  — exponential backoff, logs every attempt so a transient
+# blip stays VISIBLE in refresh.log instead of being silently swallowed by the retry.
+retry() {
+  local what="$1" tries="$2"; shift 2
+  local n=1 delay=5
+  while true; do
+    if "$@"; then
+      if [ "$n" -gt 1 ]; then echo "[retry] $what recovered on attempt $n/$tries"; fi
+      return 0
+    fi
+    if [ "$n" -ge "$tries" ]; then
+      echo "[retry] $what FAILED after $n attempts — giving up"
+      return 1
+    fi
+    echo "[retry] $what failed (attempt $n/$tries); retrying in ${delay}s"
+    sleep "$delay"; n=$((n+1)); delay=$((delay*3))
+  done
+}
+
 {
+  started=$(date +%s)
   echo "=== $(date '+%Y-%m-%d %H:%M:%S') refresh start ==="
   cd "$PROJ"
-  node scripts/build-snapshot.js
-  # atomic rsync to a temp name then mv on the remote so the live reader never sees a half file
-  rsync -az --timeout=60 "$PROJ/data/staged-snapshot.json" \
-    "$REMOTE_HOST:${REMOTE_PATH}.tmp"
-  ssh "$REMOTE_HOST" "mv -f '${REMOTE_PATH}.tmp' '${REMOTE_PATH}'"
-  echo "=== $(date '+%Y-%m-%d %H:%M:%S') refresh + push OK ==="
+
+  retry "build-snapshot" 3 node scripts/build-snapshot.js
+
+  if [ "$DRY" = "1" ]; then
+    echo "=== DRY_RUN=1: skipping push + heartbeat (would push to $REMOTE_TMP) ==="
+    echo "=== $(date '+%Y-%m-%d %H:%M:%S') refresh OK (dry) ==="
+  else
+    # atomic: rsync to a per-run temp name, then verify non-empty and mv on the remote so the
+    # live reader never sees a half file and a stale tmp can never be mistaken for this run's.
+    retry "rsync-push" 3 rsync -az --timeout=60 "$PROJ/data/staged-snapshot.json" "$REMOTE_HOST:$REMOTE_TMP"
+    retry "remote-verify-mv" 3 ssh -o ConnectTimeout=15 "$REMOTE_HOST" "test -s '$REMOTE_TMP' && mv -f '$REMOTE_TMP' '$REMOTE_PATH'"
+
+    # ---- heartbeat: reached ONLY when the remote mv succeeded -------------------------
+    bytes=$(stat -f %z "$PROJ/data/staged-snapshot.json" 2>/dev/null || echo 0)
+    rows=$(grep -o '([0-9]* rows' "$LOG" 2>/dev/null | tail -1 | tr -cd '0-9' || true)
+    tmpf="$HEARTBEAT.tmp.$$"
+    printf '{\n  "verdict": "PASS",\n  "status": "PASS",\n  "ts": "%s",\n  "epoch": %s,\n  "rows": %s,\n  "bytes": %s,\n  "pushed": true,\n  "remote_path": "%s",\n  "duration_s": %s\n}\n' \
+      "$(date -u '+%Y-%m-%dT%H:%M:%SZ')" "$(date +%s)" "${rows:-0}" "$bytes" "$REMOTE_PATH" "$(( $(date +%s) - started ))" > "$tmpf"
+    mv -f "$tmpf" "$HEARTBEAT"
+    echo "=== $(date '+%Y-%m-%d %H:%M:%S') refresh + push OK ==="
+  fi
 } >> "$LOG" 2>&1

← d211839 fix: take infinite-scroll .loading indicator out of flow (ki · back to Dw Staged Active Viewer · (newest)