From 722013da900939c343b2340a8b92538712590fe5 Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Mon, 26 Oct 2026 12:27:28 +0100 Subject: [PATCH] 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. --- .../README.md | 44 +++++ .../redproof-hub.txt | 10 ++ hub/CHANGELOG.md | 12 ++ hub/internal/notify/dispatcher.go | 3 + .../notify/r1295_pbsdr_failed_test.go | 43 +++++ hub/internal/notify/templates.go | 4 + hub/internal/tenantsync/client.go | 10 ++ hub/internal/tenantsync/client_test.go | 12 ++ hub/internal/web/pbsdr.go | 58 +++++- .../web/r1295_pbsdr_selfcheck_test.go | 167 ++++++++++++++++++ scripts/CHANGELOG.md | 8 + scripts/felhom-tenantsync.sh | 42 ++++- scripts/test_tenantsync_selfcheck.py | 145 +++++++++++++++ 13 files changed, 553 insertions(+), 5 deletions(-) create mode 100644 documentation/audits/r1295-pbsdr-selfcheck-2026-10-26/README.md create mode 100644 documentation/audits/r1295-pbsdr-selfcheck-2026-10-26/redproof-hub.txt create mode 100644 hub/internal/notify/r1295_pbsdr_failed_test.go create mode 100644 hub/internal/web/r1295_pbsdr_selfcheck_test.go create mode 100644 scripts/test_tenantsync_selfcheck.py diff --git a/documentation/audits/r1295-pbsdr-selfcheck-2026-10-26/README.md b/documentation/audits/r1295-pbsdr-selfcheck-2026-10-26/README.md new file mode 100644 index 00000000..88c3dc7b --- /dev/null +++ b/documentation/audits/r1295-pbsdr-selfcheck-2026-10-26/README.md @@ -0,0 +1,44 @@ +# R-1295 — a fresh install's whole-guest off-site tier failed to set up, silently (diagnosis + fix, 2026-10-26) + +## What happened (2026-10-26, Tester4's fresh install, host `Tester4-eb7371`) + +Hub 10:31:15 CET: `[ERROR] pbsdr auto-provision for Tester4 (WG-registration hook): pbsdr: F-14 auto re-issue for +Tester4: tenantsync: endpoint refused: own-namespace list as felhom@pbs!Tester4 failed twice — rolled back (code +self_check_failed)`. No operator mail. + +ep0, read only (`journalctl`, root SSH from DooPlex): 09:31:14Z `felhom-tenantsync` (provision → token_exists), 09:31:15Z +`felhom-tenantsync` (reissue), and in the same second two proxy lines `GET …/snapshots?ns=Tester4: 403 Forbidden … +permission check failed - missing Datastore.Audit|Datastore.Backup on /datastore/felhom-offsite/Tester4`. Since +2026-09-01 the only 403s of this kind on ep0: Tester4 2026-10-25 16:52:15Z (one — the script's retry then passed) and +these two. After the rollback Tester4 has no token and no ACL on ep0. + +## Candidates, each ruled in or out with evidence + +| Candidate | Verdict | Evidence | +|---|---|---| +| a version mismatch (new CLI, old running proxy) | OUT | ep0 runs AND has installed 4.2.5 (dpkg/apt history 2026-08-18; the „4.2.8" in `versions` is the repository's newest) | +| the proxy mapped a stale shared-memory version file | OUT | `/run/proxmox-backup/shmem/config-versions` inode 11 = the inode both proxy and api map | +| the capital letter in `Tester4` | OUT | 40 + 20 runs on a throwaway PBS with `Tester4`: 0 failures without load | +| a namespace/token left by the deleted host, or the ACL layout | OUT | ep0's ACL layout copied into the throwaway PBS (felhom@pbs DatastoreAdmin on the datastore, a reader token): 0 failures without load | +| **the proxy's permission cache under concurrent requests** | **IN** | throwaway PBS 4.2.5 + a second client listing every 50 ms: v1.3.0 failed 9 of 20 first checks, 1 rolled back; the stale window measured 4.2–5.0 s (`MEASURE`, 25 runs); the old retry comes within 1 s | + +**The cause:** PBS's proxy 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. The script's +one quick retry falls inside the same window, so it rolls the token back. The same cache also hits the script's own +transient ADMIN token: under load its first namespace list was refused and a wrong `namespace create` then died on +„missing Datastore.Modify". + +## The fix + +- `scripts/felhom-tenantsync.sh` v1.4.0: the SAME token is re-checked every 0.5 s for up to 15 s (a log line per try), + then the old regenerate-once-and-rollback path; the admin token waits the same way before its first namespace list. + Test `scripts/test_tenantsync_selfcheck.py` (19 checks; v1.3.0 fails 11). **Live on the throwaway PBS 4.2.5 under the + same load, the hub's exact order (provision → reissue), 30 pairs: v1.3.0 failed 11, v1.4.0 failed 0.** + Installing it on ep0 is an ep0 change — the operator's yes. +- hub v0.172.0: a `self_check_failed` rollback is retried (3 attempts in all, 7 s apart, a log line per try) in both the + provision and the F-14 re-issue paths; a final failure of the WG-registration hook raises the operator-only event + `pbsdr_provision_failed` (stored + dispatched; subject „… the whole-box off-site copy (PBS DR) could not be set up — + save the customer config to retry"). Red-proof `redproof-hub.txt`. With the hub alone (ep0 unchanged) each attempt has + the measured ~1-in-20 chance under load, so 3 attempts ≈ 1 in 8000; and a failure is never silent again. + +Throwaway: LXC 9374 on demo-hp (nvme-scratch), PBS 4.2.5 from the Proxmox repository; destroyed at the end of this run. diff --git a/documentation/audits/r1295-pbsdr-selfcheck-2026-10-26/redproof-hub.txt b/documentation/audits/r1295-pbsdr-selfcheck-2026-10-26/redproof-hub.txt new file mode 100644 index 00000000..129c77d8 --- /dev/null +++ b/documentation/audits/r1295-pbsdr-selfcheck-2026-10-26/redproof-hub.txt @@ -0,0 +1,10 @@ +# R-1295 hub red-proof (2026-10-26). The code reverted (no tenancyWithRetry, no pbsdrProvisionFailed call, no +# operator-only entry, no subject case, no typed self_check_failed), the tests kept: +--- FAIL: TestR1295_SelfCheckFailedIsTyped — got "tenantsync: endpoint refused: … (code self_check_failed)" (untyped) +--- FAIL: TestR1295_ARolledBackSelfCheckIsRetriedAndTheTierIsSetUp — descriptor +--- FAIL: TestR1295_TheF14ReissuePathIsRetriedToo — descriptor +--- FAIL: TestR1295_AFinalFailureReachesTheOperator — provision calls = 1, want 3; no pbsdr_provision_failed event +--- FAIL: TestR1295_TheMail — pbsdr_provision_failed must be operator-only +--- FAIL: TestR1295_TheFailedSetUpMailsTheOperatorOnly (notify) +(TestR1295_OtherFailuresAreNotRetried passes both ways — a guard.) +# Restored: ok tenantsync, ok web, ok notify. diff --git a/hub/CHANGELOG.md b/hub/CHANGELOG.md index 27b2727b..b4674d5b 100644 --- a/hub/CHANGELOG.md +++ b/hub/CHANGELOG.md @@ -1,3 +1,15 @@ +## v0.172.0 (unreleased, 2026-10-26) — a fresh install's whole-guest off-site set-up never fails silently (R-1295) + +- **Cause (measured, `documentation/audits/r1295-pbsdr-selfcheck-2026-10-26/`):** PBS's proxy caches permissions for up to + 5 s and an ACL-only change does not clear the cache; under concurrent requests ep0's self-check of a new token is + refused for up to ~5 s, the script's one quick retry falls in the same window, and the token is rolled back. +- `internal/tenantsync`: `ErrSelfCheckFailed` (code `self_check_failed`), typed. +- `internal/web/pbsdr.go` `tenancyWithRetry`: provision and the F-14 re-issue repeat ONLY a self-check rollback — 3 + attempts in all, 7 s apart (> the 5-s cache), a log line per try. A final failure of the WG-registration hook raises + the operator-only event `pbsdr_provision_failed` (stored on the customer's timeline + dispatched; registered in + `notify.operatorOnlyEvents`); its subject says what failed and what to do. Tests `TestR1295_*` (web, tenantsync, + notify), red-proved. + ## v0.171.0 (2026-10-25 night; RELEASED 2026-10-26 07:58 UTC, attended release run — image sha256:742d2e69…, from `7ad7c996`, CI 2352) — a set-aside mails as a set-aside (R-1287); a test build is never „the fleet's newest" (R-1289) - **R-1287** (`internal/notify`): a `backup_run_failures` digest whose every entry is leg `unit-set-aside` (a D47 diff --git a/hub/internal/notify/dispatcher.go b/hub/internal/notify/dispatcher.go index 2820a090..64a21766 100644 --- a/hub/internal/notify/dispatcher.go +++ b/hub/internal/notify/dispatcher.go @@ -935,6 +935,9 @@ var operatorOnlyEvents = map[string]bool{ // R-1165 (v0.161.0): an ep0 household namespace with no prune job (monitor/pbsdr_box.go). Hub-origin only. "passphrase_keys_refused": true, "pbsdr_namespace_without_prune_job": true, + // R-1295 (v0.172.0): the WG-registration hook could not set up a box's whole-guest off-site tier (web/pbsdr.go). + // Host ids and an instruction only the operator can carry out. Hub-origin only. + "pbsdr_provision_failed": true, } // IsOperatorOnly reports whether an event type is barred from customer dispatch. Exported so the diff --git a/hub/internal/notify/r1295_pbsdr_failed_test.go b/hub/internal/notify/r1295_pbsdr_failed_test.go new file mode 100644 index 00000000..1af60a48 --- /dev/null +++ b/hub/internal/notify/r1295_pbsdr_failed_test.go @@ -0,0 +1,43 @@ +package notify + +import ( + "strings" + "testing" +) + +// R-1295: a failed set-up of a box's whole-guest off-site tier reaches the OPERATOR — through the real dispatcher, with +// a subject that says what failed and what to do — and never the household, even when the household has every event +// switched on (the R-97c breaking configuration). +// RED-PROOF: drop "pbsdr_provision_failed" from operatorOnlyEvents → the household is mailed; drop the subject case in +// FormatOperatorEmail → the subject is the bare event type. +func TestR1295_TheFailedSetUpMailsTheOperatorOnly(t *testing.T) { + st := opOnlyStore(t) + if err := st.SaveNotificationPrefs("c1", "customer@example.com", []string{"pbsdr_provision_failed", "backup_failed"}, 6); err != nil { + t.Fatal(err) + } + var operatorSubjects []string + var to []string + d := opOnlyDispatcher(t, st, &sentTo{}) + d.sendEmailFn = func(addr, subject, body string, headers map[string]string) error { + to = append(to, addr) + if addr == "operator@felhom.eu" { + operatorSubjects = append(operatorSubjects, subject) + } + return nil + } + d.ProcessEvent("c1", "pbsdr_provision_failed", "error", + "The whole-box off-site copy (PBS DR) for c1 could not be set up for host c1-01: … save the configuration …", + `{"host_id":"c1-01"}`, "hub") + + for _, a := range to { + if a == "customer@example.com" { + t.Fatal("the household was mailed an operator-only set-up failure") + } + } + if len(operatorSubjects) != 1 { + t.Fatalf("the operator got %d mail(s), want 1 (to: %v)", len(operatorSubjects), to) + } + if s := operatorSubjects[0]; !strings.Contains(s, "could not be set up") || !strings.Contains(s, "save the customer config to retry") { + t.Fatalf("the subject must say what failed and what to do: %q", s) + } +} diff --git a/hub/internal/notify/templates.go b/hub/internal/notify/templates.go index ef07c30b..e73a2ab7 100644 --- a/hub/internal/notify/templates.go +++ b/hub/internal/notify/templates.go @@ -44,6 +44,10 @@ func FormatOperatorEmail(customerID, eventType, severity, message, detailsJSON s } subject := fmt.Sprintf("[Felhom] %s %s: %s", icon, customerID, eventType) + // R-1295: the subject says what failed and what to do, so the mail is read without being opened. + if eventType == "pbsdr_provision_failed" { + subject = fmt.Sprintf("[Felhom] %s %s: the whole-box off-site copy (PBS DR) could not be set up — save the customer config to retry", icon, customerID) + } now := nowFn().In(budapest).Format("2006-01-02 15:04 MST") body := fmt.Sprintf(`Customer: %s diff --git a/hub/internal/tenantsync/client.go b/hub/internal/tenantsync/client.go index baf1e347..d61dcfdd 100644 --- a/hub/internal/tenantsync/client.go +++ b/hub/internal/tenantsync/client.go @@ -36,6 +36,13 @@ var ErrTokenExists = errors.New("tenantsync: token already exists on the endpoin // v1.2.0, the next poll succeeds — no hub redeploy. var ErrUsageUnsupported = errors.New("tenantsync: endpoint does not support the usage op (script update pending)") +// ErrSelfCheckFailed is the typed "the new token could not list its own namespace, so the endpoint rolled it back" +// outcome (code self_check_failed). R-1295: PBS's proxy caches permissions for up to 5 s and an ACL-only change does +// not clear that cache, so another client's request between the token create and its grant leaves the token refused +// (403) for up to ~5 s — measured 4.2–5.0 s on PBS 4.2.5 under load, 9 of 20 first checks failed. The rollback leaves +// no token, so a later attempt starts clean: the hub retries it after a pause (web/pbsdr.go). +var ErrSelfCheckFailed = errors.New("tenantsync: the new token failed its own-namespace self-check and was rolled back") + // customerIDRe mirrors the script's validation — refuse client-side before a wasted SSH round-trip. var customerIDRe = regexp.MustCompile(`^[A-Za-z0-9][A-Za-z0-9_.-]{0,30}$`) @@ -219,6 +226,9 @@ func parseResponse(stdout, stderr []byte, runErr error) (*response, error) { if resp.Code == "token_exists" { return nil, ErrTokenExists } + if resp.Code == "self_check_failed" { + return nil, fmt.Errorf("%w: %s", ErrSelfCheckFailed, resp.Error) + } // An endpoint ≤ v1.1.0 has no usage op → its generic `bad_request "unknown op"`. Map it to the // typed graceful-degradation signal (the exact err_json string is the script's fixed contract). if resp.Code == "bad_request" && strings.Contains(resp.Error, "unknown op") { diff --git a/hub/internal/tenantsync/client_test.go b/hub/internal/tenantsync/client_test.go index 89d9a0a1..6dd78b69 100644 --- a/hub/internal/tenantsync/client_test.go +++ b/hub/internal/tenantsync/client_test.go @@ -356,3 +356,15 @@ func TestNew_BadInputsFailEarly(t *testing.T) { t.Error("missing addr accepted") } } + +// R-1295: the endpoint's self_check_failed is a typed outcome the hub can retry (web/pbsdr.go tenancyWithRetry). +// RED-PROOF: drop the self_check_failed branch in parseResponse → errors.Is is false. +func TestR1295_SelfCheckFailedIsTyped(t *testing.T) { + _, err := parseResponse([]byte(`{"status":"error","code":"self_check_failed","error":"own-namespace list as felhom@pbs!x failed twice — rolled back"}`), nil, errors.New("exit 1")) + if !errors.Is(err, ErrSelfCheckFailed) { + t.Fatalf("self_check_failed must map to ErrSelfCheckFailed, got %v", err) + } + if !strings.Contains(err.Error(), "rolled back") { + t.Errorf("the endpoint's sentence must survive: %v", err) + } +} diff --git a/hub/internal/web/pbsdr.go b/hub/internal/web/pbsdr.go index 5ae1a16d..03bab38a 100644 --- a/hub/internal/web/pbsdr.go +++ b/hub/internal/web/pbsdr.go @@ -229,7 +229,7 @@ func (s *Server) pbsdrProvisionAtom(ctx context.Context, customerID string, host // manual re-issue). The absolute timeout still bounds a hung SSH exec. ctx, cancel := context.WithTimeout(context.WithoutCancel(ctx), 2*time.Minute) defer cancel() - res, err := s.tenantsync.Provision(ctx, customerID) + res, err := s.tenancyWithRetry(ctx, customerID, "provision", s.tenantsync.Provision) if errors.Is(err, tenantsync.ErrTokenExists) { // ep0 has a token but the hub has no descriptor — state mismatch (lost hub state, a // half-torn earlier attempt, or the F-14 shape: host deleted, tenancy survived). @@ -248,7 +248,7 @@ func (s *Server) pbsdrProvisionAtom(ctx context.Context, customerID string, host if rec == nil || !rec.EscrowAcked { return "", fmt.Errorf("the endpoint already holds a PBS token for %s but the hub has no descriptor — use the explicit \"Re-issue PBS credentials\" action", customerID) } - res, err = s.tenantsync.Reissue(ctx, customerID) // the EXISTING re-issue op — no new endpoint interaction + res, err = s.tenancyWithRetry(ctx, customerID, "re-issue", s.tenantsync.Reissue) // the EXISTING re-issue op — no new endpoint interaction if err != nil { return "", fmt.Errorf("pbsdr: F-14 auto re-issue for %s: %w", customerID, err) } @@ -320,6 +320,7 @@ func (s *Server) PBSDRAutoProvision(ctx context.Context, customerID string) { blocked, err := s.pbsdrProvisionAtom(ctx, customerID, host, storageID) if err != nil { s.logger.Printf("[ERROR] pbsdr auto-provision for %s (WG-registration hook): %v — save the customer config to retry", customerID, err) + s.pbsdrProvisionFailed(customerID, host.HostID, err) return } if blocked != "" { @@ -560,3 +561,56 @@ func (s *Server) pbsDRViewFor(customerID string, drTier bool) pbsDRView { } return v } + +// R-1295: the endpoint's self-check of a new token can fail for up to ~5 s after the grant (see +// tenantsync.ErrSelfCheckFailed), and its one quick retry falls inside the same window. The rollback leaves no +// token, so a later attempt starts clean. pbsdrSelfCheckPause is longer than PBS's 5-second permission cache; +// a var so tests do not wait. Bounded: pbsdrSelfCheckTries attempts in all, never a loop. +const pbsdrSelfCheckTries = 3 + +var pbsdrSelfCheckPause = 7 * time.Second + +// tenancyWithRetry runs one tenancy op (provision or re-issue) and repeats it ONLY on ErrSelfCheckFailed, with a log +// line per try. Any other outcome — success, token_exists, a transport failure — returns at once, unchanged. +func (s *Server) tenancyWithRetry(ctx context.Context, customerID, op string, + fn func(context.Context, string) (*tenantsync.Result, error)) (*tenantsync.Result, error) { + for try := 1; ; try++ { + res, err := fn(ctx, customerID) + if err == nil { + if try > 1 { + s.logger.Printf("[INFO] pbsdr: %s for %s passed on try %d/%d (R-1295)", op, customerID, try, pbsdrSelfCheckTries) + } + return res, nil + } + if !errors.Is(err, tenantsync.ErrSelfCheckFailed) || try >= pbsdrSelfCheckTries { + return nil, err + } + s.logger.Printf("[WARN] pbsdr: %s for %s: the endpoint rolled the new token back — its self-check was refused "+ + "(PBS caches permissions for up to 5 s); try %d/%d, next in %s (R-1295)", op, customerID, try, pbsdrSelfCheckTries, pbsdrSelfCheckPause) + select { + case <-ctx.Done(): + return nil, fmt.Errorf("pbsdr: %s for %s: stopped while waiting to retry: %w (last: %v)", op, customerID, ctx.Err(), err) + case <-time.After(pbsdrSelfCheckPause): + } + } +} + +// eventPBSDRProvisionFailed (R-1295): operator-only, registered in notify.operatorOnlyEvents in the same commit. +const eventPBSDRProvisionFailed = "pbsdr_provision_failed" + +// pbsdrProvisionFailed tells the OPERATOR that the WG-registration hook could not set up a box's whole-guest off-site +// tier. Before R-1295 this was one hub log line and nothing else (2026-10-26, Tester4's fresh install). Stored on the +// customer's timeline AND sent through the dispatcher. The error text carries field names only, never a secret. +func (s *Server) pbsdrProvisionFailed(customerID, hostID string, cause error) { + msg := fmt.Sprintf("The whole-box off-site copy (PBS DR) for %s could not be set up for host %s: %v. Nothing was "+ + "stored for the box, so it has NO whole-box off-site copy yet. What to do: open the customer page and save the "+ + "configuration (Customers → %s → Save) — that retries the set-up. If it fails again, read the hub log line "+ + "„pbsdr auto-provision for %s“.", customerID, hostID, cause, customerID, customerID) + details, _ := json.Marshal(map[string]string{"host_id": hostID, "error": cause.Error()}) + if _, err := s.store.SaveEvent(customerID, eventPBSDRProvisionFailed, "error", msg, string(details), "hub"); err != nil { + s.logger.Printf("[WARN] pbsdr: %s event for %s not stored: %v", eventPBSDRProvisionFailed, customerID, err) + } + if s.emit != nil { + s.emit(customerID, eventPBSDRProvisionFailed, "error", msg, string(details), "hub") + } +} diff --git a/hub/internal/web/r1295_pbsdr_selfcheck_test.go b/hub/internal/web/r1295_pbsdr_selfcheck_test.go new file mode 100644 index 00000000..9ab13c6b --- /dev/null +++ b/hub/internal/web/r1295_pbsdr_selfcheck_test.go @@ -0,0 +1,167 @@ +package web + +import ( + "context" + "fmt" + "strings" + "testing" + + "gitea.dooplex.hu/admin/felhom-hub/internal/notify" + "gitea.dooplex.hu/admin/felhom-hub/internal/store" + "gitea.dooplex.hu/admin/felhom-hub/internal/tenantsync" +) + +// R-1295: Tester4's fresh install on 2026-10-26 lost its whole-guest off-site tier and only the hub log said so. ep0's +// self-check of the new token was refused twice within one second (PBS caches permissions for up to 5 s; reproduced on a +// throwaway PBS 4.2.5: 9 of 20 first checks failed under load, the stale window 4.2–5.0 s) and the endpoint rolled the +// token back. The consequences asserted: a rollback is retried after a pause and the tier IS set up; a final failure +// reaches the operator (stored + dispatched, operator-only, a subject that says what to do). +// RED-PROOF: call s.tenantsync.Provision/Reissue directly in pbsdrProvisionAtom (no tenancyWithRetry) → the first two +// tests fail; drop the pbsdrProvisionFailed call → the third fails; drop the notify entries → TestR1295_TheMail fails. + +// selfCheckTenancy fails the first `fails` calls of the chosen op with the endpoint's self_check_failed outcome. +type selfCheckTenancy struct { + fakeTenancy + provisionFails, reissueFails int +} + +func selfCheckErr() error { + return fmt.Errorf("%w: own-namespace list as felhom@pbs!peti failed twice — rolled back", tenantsync.ErrSelfCheckFailed) +} + +func (f *selfCheckTenancy) Provision(ctx context.Context, id string) (*tenantsync.Result, error) { + f.provisionCalls++ + if f.provisionErr != nil { + return nil, f.provisionErr + } + if f.provisionCalls <= f.provisionFails { + return nil, selfCheckErr() + } + return f.result(id), nil +} + +func (f *selfCheckTenancy) Reissue(ctx context.Context, id string) (*tenantsync.Result, error) { + f.reissueCalls++ + if f.reissueCalls <= f.reissueFails { + return nil, selfCheckErr() + } + return f.result(id), nil +} + +func r1295Server(t *testing.T, f *selfCheckTenancy) (*Server, *store.Store, *[]string) { + t.Helper() + old := pbsdrSelfCheckPause + pbsdrSelfCheckPause = 0 + t.Cleanup(func() { pbsdrSelfCheckPause = old }) + s, st, _ := newPBSDRServer(t, nil) + s.SetTenantSync(f) + cfg, _ := st.GetCustomerConfig("peti") + cfg.DRTier = true + if err := st.SaveCustomerConfig(cfg); err != nil { + t.Fatal(err) + } + var emitted []string + s.emit = func(c, typ, sev, msg, details, src string) { emitted = append(emitted, c+"|"+typ+"|"+sev+"|"+msg) } + return s, st, &emitted +} + +func TestR1295_ARolledBackSelfCheckIsRetriedAndTheTierIsSetUp(t *testing.T) { + f := &selfCheckTenancy{fakeTenancy: fakeTenancy{secret: "S-1295"}, provisionFails: 2} + s, st, emitted := r1295Server(t, f) + + s.PBSDRAutoProvision(context.Background(), "peti") + + if desc, js, _ := hostState(t, st); desc == nil || !desc.Enabled || desc.Namespace != "peti" { + t.Fatalf("after two rolled-back self-checks the tier must be set up on the third try: %+v (%s)", desc, js) + } + if f.provisionCalls != 3 { + t.Errorf("provision calls = %d, want 3 (two rollbacks + the passing try)", f.provisionCalls) + } + if len(*emitted) != 0 { + t.Errorf("a set-up that succeeded must not mail the operator: %v", *emitted) + } +} + +func TestR1295_TheF14ReissuePathIsRetriedToo(t *testing.T) { + f := &selfCheckTenancy{fakeTenancy: fakeTenancy{secret: "S-1295", provisionErr: tenantsync.ErrTokenExists}, reissueFails: 1} + s, st, _ := r1295Server(t, f) + // The F-14 history (the Tester4 shape): the owning host was deleted through the escrow-ack flow. + if err := st.UpsertHost(&store.Host{HostID: "peti-00-dead", CustomerID: "peti", APIKey: "old"}); err != nil { + t.Fatal(err) + } + if _, _, err := st.SaveHostEscrow("peti-00-dead", []byte("opaque"), "fp", "posture", "2026-07-01T00:00:00Z", ""); err != nil { + t.Fatal(err) + } + if err := st.DeleteHost("peti-00-dead", true); err != nil { + t.Fatal(err) + } + + s.PBSDRAutoProvision(context.Background(), "peti") + + if desc, js, _ := hostState(t, st); desc == nil || desc.Namespace != "peti" { + t.Fatalf("the re-issue path must be retried after a rollback: %+v (%s)", desc, js) + } + if f.reissueCalls != 2 { + t.Errorf("re-issue calls = %d, want 2", f.reissueCalls) + } +} + +func TestR1295_OtherFailuresAreNotRetried(t *testing.T) { + f := &selfCheckTenancy{fakeTenancy: fakeTenancy{provisionErr: tenantsync.ErrTokenExists}} + s, _, _ := r1295Server(t, f) + s.PBSDRAutoProvision(context.Background(), "peti") // token_exists with no acked deletion: the manual-path refusal + if f.provisionCalls != 1 || f.reissueCalls != 0 { + t.Fatalf("only a self-check rollback is retried: provision %d, re-issue %d", f.provisionCalls, f.reissueCalls) + } +} + +func TestR1295_AFinalFailureReachesTheOperator(t *testing.T) { + f := &selfCheckTenancy{fakeTenancy: fakeTenancy{secret: "S-1295"}, provisionFails: 99} + s, st, emitted := r1295Server(t, f) + + s.PBSDRAutoProvision(context.Background(), "peti") + + if f.provisionCalls != pbsdrSelfCheckTries { + t.Errorf("provision calls = %d, want the bound %d (never an endless loop)", f.provisionCalls, pbsdrSelfCheckTries) + } + if desc, _, _ := hostState(t, st); desc != nil && desc.Namespace != "" { + t.Fatalf("a failed set-up must not leave a descriptor: %+v", desc) + } + if len(*emitted) != 1 || !strings.HasPrefix((*emitted)[0], "peti|pbsdr_provision_failed|error|") { + t.Fatalf("the operator must get exactly one pbsdr_provision_failed event: %v", *emitted) + } + msg := (*emitted)[0] + for _, want := range []string{"peti-01", "save the configuration", "NO whole-box off-site copy"} { + if !strings.Contains(msg, want) { + t.Errorf("the event must say %q: %s", want, msg) + } + } + if strings.Contains(msg, "S-1295") { + t.Error("the event carries a secret") + } + evs, err := st.GetRecentEvents("peti", 10) + if err != nil { + t.Fatal(err) + } + found := false + for _, e := range evs { + found = found || (e.EventType == "pbsdr_provision_failed" && e.Severity == "error" && e.Source == "hub") + } + if !found { + t.Error("the event is not on the customer's timeline") + } +} + +func TestR1295_TheMail(t *testing.T) { + if !notify.IsOperatorOnly("pbsdr_provision_failed") { + t.Fatal("pbsdr_provision_failed must be operator-only (a household must never get it)") + } + subj, body := notify.FormatOperatorEmail("Tester4", "pbsdr_provision_failed", "error", "msg", "{}") + if !strings.Contains(subj, "could not be set up") || !strings.Contains(subj, "save the customer config to retry") || + !strings.Contains(subj, "Tester4") || !strings.Contains(subj, "🔴") { + t.Fatalf("the subject must say what failed and what to do: %q", subj) + } + if !strings.Contains(body, "Dashboard: https://hub.felhom.eu/customers/Tester4") { + t.Errorf("the body must link the customer: %s", body) + } +} diff --git a/scripts/CHANGELOG.md b/scripts/CHANGELOG.md index 45cf07ec..aa2f4b83 100644 --- a/scripts/CHANGELOG.md +++ b/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 diff --git a/scripts/felhom-tenantsync.sh b/scripts/felhom-tenantsync.sh index 4f86f3b3..ac981f83 100644 --- a/scripts/felhom-tenantsync.sh +++ b/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-` (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 diff --git a/scripts/test_tenantsync_selfcheck.py b/scripts/test_tenantsync_selfcheck.py new file mode 100644 index 00000000..f394dabe --- /dev/null +++ b/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())