R-1295: the PBS DR set-up waits out PBS's 5-s permission cache. Cause measured on a throwaway PBS 4.2.5 under load (v1.3.0 failed 11/30, v1.4.0 0/30): tenantsync v1.4.0 re-checks the same token (and the admin token) up to 15 s; hub v0.172.0 retries a self_check_failed rollback 3x, 7 s apart, and a final failure mails the operator (pbsdr_provision_failed, operator-only). Red-proved. Commit only; ep0 unchanged.

scripts/CHANGELOG.md

@@ -1,3 +1,11 @@
+## 2026-10-26 — felhom-tenantsync v1.4.0: the self-check waits out the PBS permission cache (R-1295) — committed, NOT installed on ep0
+
+- **`felhom-tenantsync.sh` v1.4.0:** the new token is re-checked every 0.5 s for up to 15 s (a log line per try) before
+  the old regenerate-once-and-rollback; the transient admin token waits the same way before its first namespace list
+  (under load it met the same cache and a wrong `namespace create` died). Test `test_tenantsync_selfcheck.py` (19 checks;
+  v1.3.0 fails 11). Live on a throwaway PBS 4.2.5 under load, the hub's exact order, 30 pairs: v1.3.0 failed 11, v1.4.0
+  failed 0 (`documentation/audits/r1295-pbsdr-selfcheck-2026-10-26/`). **Installing it on ep0 is the operator's yes.**
+
 ## 2026-10-25 — installer 1.36.1: the preflight words a refusal again — PUBLISHED 2026-10-25 evening on the operator's yes (`installer-v1.36.1` → `79ee3e33`, served sha256 `e18cdd17…`; the three refusal sentences seen live)
 
 - **`felhom-host-install.sh` `http_code`** printed the status twice on a 4xx (`curl -f` prints `-w` and exits 22, and the

scripts/felhom-tenantsync.sh

@@ -1,7 +1,16 @@
 #!/usr/bin/env bash
-# felhom-tenantsync v1.3.0 — the offsite endpoint's per-customer PBS tenancy surface (PBS DR tier
+# felhom-tenantsync v1.4.0 — the offsite endpoint's per-customer PBS tenancy surface (PBS DR tier
 # SLICE 1; spike SPIKE-pbs-tier-provisioning-2026-07-10 §3).
 #
+# v1.4.0 (2026-10-26, R-1295): the self-check WAITS OUT the proxy's permission cache before it gives up. PBS caches
+#   permissions for up to 5 s and an ACL-only change does not clear that cache; a request from another client between
+#   the token create and its grant leaves „new token, old ACLs" for up to ~5 s (reproduced on a throwaway PBS 4.2.5 with
+#   a second client listing every 50 ms: 9 of 20 first checks failed, the window 4.2–5.0 s). The old one-shot retry came
+#   within a second and failed inside the same window (Tester4, 2026-10-26 09:31:15Z: rolled back, the box got no
+#   whole-guest off-site tier). Now: the SAME token is re-checked every 0.5 s for up to 15 s, a log line per failed try;
+#   only then the old regenerate-once-and-rollback path. The transient admin token waits the same way before its first
+#   namespace list (it met the same cache under load). Pinned by scripts/test_tenantsync_selfcheck.py.
+#
 # v1.3.0 (2026-10-19, R-1165): a household's namespace gets its PRUNE JOB with it. provision/reissue ensure
 #   `prune-<id>` (keep-weekly 2, 03:30, ns-scoped, max-depth 0 — the shape of the demo-hp/demo-felhom jobs, STATUS
 #   D18) unless a job on felhom-offsite already covers that namespace (idempotent: a second run changes nothing);
@@ -141,6 +150,19 @@ proxmox-backup-manager acl update "/datastore/$DS" DatastoreAdmin \
 
 ADMIN_REPO="root@pam!$ADMIN_TOKEN_NAME@$REPO_HOST:$DS"
 
+# R-1295 (v1.4.0): the transient admin token meets the SAME permission cache as the tenant token — measured on the
+# throwaway PBS under load: its first namespace list refused, then a wrong `namespace create` died on Datastore.Modify.
+# Wait (bounded, a log line per try) until it can list before any namespace op reads its answer.
+SELF_CHECK_TRIES=30
+admin_ready() {
+  PBS_PASSWORD="$ADM" proxmox-backup-client namespace list --repository "$ADMIN_REPO" --output-format json >/dev/null 2>&1
+}
+for i in $(seq 1 "$SELF_CHECK_TRIES"); do
+  admin_ready && { [ "$i" -gt 1 ] && log "admin token ready on try $i/$SELF_CHECK_TRIES (R-1295)"; break; }
+  log "admin token try $i/$SELF_CHECK_TRIES refused — the proxy may still hold the old permissions (up to 5 s); R-1295"
+  [ "$i" -lt "$SELF_CHECK_TRIES" ] && sleep 0.5 || err_json internal "the transient admin token was refused for 15 s (R-1295)"
+done
+
 # 2b. deprovision (v0.61.0 customer-RESET teardown): destroy this ONE tenant's token + namespace +
 #     backup groups. Every step is idempotent (missing = already gone = ok). The shared felhom@pbs
 #     user survives (co-tenants). Returns before the provision/reissue create-path below.
@@ -222,6 +244,20 @@ self_check() { # own-namespace list AS the new token; secret via env, never argv
     --repository "$TOKEN_ID@$REPO_HOST:$DS" >/dev/null
 }
 
+# R-1295 (v1.4.0): re-check the SAME token for up to SELF_CHECK_TRIES × 0.5 s (3 × the proxy's 5-s permission cache).
+wait_self_check() {
+  local i
+  for i in $(seq 1 "$SELF_CHECK_TRIES"); do
+    if self_check "$1" 2>/dev/null; then
+      [ "$i" -gt 1 ] && log "self-check passed on try $i/$SELF_CHECK_TRIES (the proxy's permission cache lagged; R-1295)"
+      return 0
+    fi
+    log "self-check try $i/$SELF_CHECK_TRIES refused — the proxy may still hold the old permissions (up to 5 s); R-1295"
+    [ "$i" -lt "$SELF_CHECK_TRIES" ] && sleep 0.5
+  done
+  return 1
+}
+
 rollback_token() {
   proxmox-backup-manager user delete-token "$PBS_USER" "$CID" >&2 2>/dev/null || true
   proxmox-backup-manager acl update "/datastore/$DS/$CID" DatastoreBackup \
@@ -241,14 +277,14 @@ SECRET=$(gen_token)
 [ -n "$SECRET" ] || err_json internal "token generation returned no value"
 grant_both
 
-if ! self_check "$SECRET"; then
+if ! wait_self_check "$SECRET"; then
   # The spike's transient-403 note: one delete+regen+re-grant retry, then rollback + fail.
   log "self-check failed — regenerating once (spike transient-403 note)"
   proxmox-backup-manager user delete-token "$PBS_USER" "$CID" >&2 2>/dev/null || true
   SECRET=$(gen_token)
   [ -n "$SECRET" ] || { rollback_token; err_json internal "token regeneration returned no value"; }
   grant_both
-  if ! self_check "$SECRET"; then
+  if ! wait_self_check "$SECRET"; then
     rollback_token
     err_json self_check_failed "own-namespace list as $TOKEN_ID failed twice — rolled back"
   fi

scripts/test_tenantsync_selfcheck.py

@@ -0,0 +1,145 @@
+#!/usr/bin/env python3
+# -*- coding: utf-8 -*-
+"""test_tenantsync_selfcheck.py — felhom-tenantsync v1.4.0 waits out the PBS proxy's permission cache (R-1295).
+
+Runs the REAL script against stubbed `proxmox-backup-manager` / `proxmox-backup-client` / `sleep` on PATH (real bash,
+real jq). The client stub refuses `snapshot list` (the self-check) the first FAILS times — the shape measured on a
+throwaway PBS 4.2.5 under load (a 403 for 4.2–5.0 s after the grant) — and the sleep stub only counts, so the test is
+fast. Every call is logged, so each case asserts what the script DID:
+
+  1. the check refused for ~4 s (8 tries) → the SAME token passes; one generate-token, no rollback, a log line per try;
+  2. refused for ever → bounded: two windows of 30 tries (the old regen-once path after the first), then the rollback
+     and `self_check_failed` — never a hang;
+  3. passing at once → one check, no sleep;
+  4. the transient ADMIN token's first namespace list refused for ~3 s → it waits; never a `namespace create` on a
+     refused list (measured: under load v1.3.0 then died on „missing Datastore.Modify").
+
+RED-PROOF: the v1.3.0 script (one immediate re-check after a regen) fails case 1 — it rolls back.
+Exit 0 all passed · 1 a case failed. Without bash or jq it says NOT CHECKED out loud and exits 0.
+"""
+import json
+import os
+import shutil
+import subprocess
+import sys
+import tempfile
+
+HERE = os.path.dirname(os.path.abspath(__file__))
+SCRIPT = os.environ.get("TENANTSYNC_SCRIPT") or os.path.join(HERE, "felhom-tenantsync.sh")
+
+PBM = r'''#!/usr/bin/env bash
+echo "pbm $*" >> "$CALLLOG"
+case "$1 $2" in
+  "cert info")            echo "Fingerprint (sha256): aa:bb:cc:dd" ;;
+  "datastore list")       echo '[{"name":"felhom-offsite","path":"/nonexistent"}]' ;;
+  "user generate-token")  echo '{"value": "FAKE-TOKEN-VALUE"}' ;;
+  "user list")            echo '[{"userid":"felhom@pbs"}]' ;;
+  "user list-tokens")     echo '[]' ;;
+  "prune-job list")       echo '[{"id":"prune-x","store":"felhom-offsite","ns":"Tester4"}]' ;;
+  *)                      : ;;
+esac
+'''
+PBC = r'''#!/usr/bin/env bash
+echo "pbc $*" >> "$CALLLOG"
+case "$1 $2" in
+  "namespace list")   m=$(cat "$COUNTER.adm" 2>/dev/null || echo 0); echo $((m+1)) > "$COUNTER.adm"
+                      [ "$m" -lt "${ADMIN_FAILS:-0}" ] && { echo "permission check failed" >&2; exit 1; }
+                      echo '{"data":[{"ns":"Tester4"}]}' ;;
+  "snapshot list")    n=$(cat "$COUNTER" 2>/dev/null || echo 0); echo $((n+1)) > "$COUNTER"
+                      [ "$n" -lt "$FAILS" ] && { echo "permission check failed" >&2; exit 1; }
+                      echo '[]' ;;
+  *)                  : ;;
+esac
+'''
+SLEEP = '#!/usr/bin/env bash\necho "sleep $*" >> "$CALLLOG"\n'
+
+fails = []
+ran = 0
+
+
+def check(name, cond, detail=""):
+    global ran
+    ran += 1
+    if cond:
+        print("ok   %s" % name)
+    else:
+        fails.append("%s %s" % (name, detail))
+
+
+def run(op, refuse, admin_refuse=0):
+    d = tempfile.mkdtemp(prefix="tenantsync-selfcheck-")
+    try:
+        b = os.path.join(d, "bin")
+        os.makedirs(b)
+        for name, body in (("proxmox-backup-manager", PBM), ("proxmox-backup-client", PBC), ("sleep", SLEEP)):
+            p = os.path.join(b, name)
+            open(p, "w").write(body)
+            os.chmod(p, 0o755)
+        calls = os.path.join(d, "calls.log")
+        open(calls, "w").close()
+        e = dict(os.environ, PATH=b + os.pathsep + os.environ["PATH"], CALLLOG=calls,
+                 COUNTER=os.path.join(d, "n"), FAILS=str(refuse), ADMIN_FAILS=str(admin_refuse))
+        p = subprocess.run(["bash", SCRIPT], input=json.dumps({"op": op, "customer_id": "Tester4"}), env=e,
+                           capture_output=True, text=True, timeout=60)
+        return p.returncode, p.stdout, p.stderr, open(calls).read().splitlines()
+    finally:
+        shutil.rmtree(d, ignore_errors=True)
+
+
+def gens(calls):
+    return [c for c in calls if c.startswith("pbm user generate-token felhom@pbs")]
+
+
+def checks(calls):
+    return [c for c in calls if c.startswith("pbc snapshot list")]
+
+
+def main():
+    if not shutil.which("bash") or not shutil.which("jq"):
+        print("test_tenantsync_selfcheck: NOT CHECKED — bash or jq is missing here (the workspace run has both)")
+        return 0
+
+    # 1. the measured shape: refused for ~4 s, then the same token passes.
+    for op in ("reissue", "provision"):
+        rc, out, err, calls = run(op, 8)
+        status = (json.loads(out or "{}").get("status") if out.strip().startswith("{") else None)
+        check("%s: a self-check refused for ~4 s passes on the SAME token" % op, rc == 0 and status == "ok",
+              "rc=%s out=%s" % (rc, out.strip()[:160]))
+        check("%s: one token generated, never a regen" % op, len(gens(calls)) == 1, "generate-token calls: %d" % len(gens(calls)))
+        check("%s: nine checks, eight 0.5-s waits" % op, len(checks(calls)) == 9 and calls.count("sleep 0.5") == 8,
+              "checks=%d sleeps=%d" % (len(checks(calls)), calls.count("sleep 0.5")))
+        check("%s: a log line per refused try" % op, err.count("self-check try") == 8 and "passed on try 9/30" in err,
+              err[-300:])
+        check("%s: no rollback" % op, not any(c.startswith("pbm user delete-token felhom@pbs Tester4") for c in calls[-3:]))
+        check("%s: the secret never reaches stderr" % op, "FAKE-TOKEN-VALUE" not in err)
+
+    # 2. refused for ever → bounded, rolled back, typed.
+    rc, out, err, calls = run("reissue", 10 ** 6)
+    check("refused for ever: self_check_failed, rolled back", rc == 1 and '"code":"self_check_failed"' in out, out.strip()[:200])
+    check("refused for ever: bounded — two windows of 30 checks", len(checks(calls)) == 60, "checks=%d" % len(checks(calls)))
+    check("refused for ever: the token is deleted at the end", calls[-1].startswith("pbm acl update") or
+          any(c.startswith("pbm user delete-token felhom@pbs Tester4") for c in calls[-4:]), str(calls[-4:]))
+
+    # 4. the admin token's first namespace list refused for ~3 s → it waits, and never tries to CREATE the namespace.
+    rc, out, err, calls = run("reissue", 0, admin_refuse=6)
+    check("admin token refused for ~3 s: the op still succeeds", rc == 0 and '"status":"ok"' in out, out.strip()[:160])
+    check("admin token refused: never a namespace create on a refused list",
+          not any(c.startswith("pbc namespace create") for c in calls), str([c for c in calls if "namespace" in c]))
+    check("admin token refused: a log line per try", err.count("admin token try") == 6 and "admin token ready on try 7/30" in err, err[-300:])
+
+    # 3. passing at once → no wait.
+    rc, out, err, calls = run("reissue", 0)
+    check("passing at once: one check, no sleep", rc == 0 and len(checks(calls)) == 1 and not any(c.startswith("sleep") for c in calls),
+          "checks=%d" % len(checks(calls)))
+
+    if fails:
+        for f in fails:
+            print("FAIL %s" % f)
+        print("test_tenantsync_selfcheck: %d of %d check(s) FAILED" % (len(fails), ran))
+        return 1
+    print("test_tenantsync_selfcheck: all %d checks passed" % ran)
+    return 0
+
+
+if __name__ == "__main__":
+    sys.exit(main())