diff --git a/cmd/felis/reaper.go b/cmd/felis/reaper.go index 9f8fdf0..51e2ad3 100644 --- a/cmd/felis/reaper.go +++ b/cmd/felis/reaper.go @@ -131,9 +131,23 @@ func cmdReaper(args []string, stdout, stderr io.Writer) int { fmt.Fprintf(stderr, "felis reaper: %v\n", err) return 1 } - fmt.Fprintf(stdout, "felis reaper: evaluated=%d reaped=%d awaiting_offsite=%d warned=%d skipped=%d evicted=%d expired=%d\n", - sum.Evaluated, sum.WorldsReaped, sum.AwaitingOffsite, sum.Warned, sum.Skipped, sum.EvictedEarly, sum.BackupsExpired) - return 0 + return reportReaperRun(sum, stdout, stderr) +} + +// reportReaperRun prints the run's tally and turns a run that left work undone +// into exit 1, so the Job fails and the watchdog's job-failed check (and the +// FelisWorldJobFailed rule) reach the operator: a world that cannot be archived +// is kept, and without this nobody would learn that it is never reaped. +func reportReaperRun(sum reaper.Summary, stdout, stderr io.Writer) int { + fmt.Fprintf(stdout, "felis reaper: evaluated=%d reaped=%d awaiting_offsite=%d warned=%d skipped=%d store_full=%d evicted=%d expired=%d expire_failed=%d\n", + sum.Evaluated, sum.WorldsReaped, sum.AwaitingOffsite, sum.Warned, sum.Skipped, sum.StoreFull, + sum.EvictedEarly, sum.BackupsExpired, sum.ExpireFailed) + if !sum.Failed() { + return 0 + } + fmt.Fprintf(stderr, "felis reaper: %d servers failed (%d kept because the backup store is full) and %d expired backups were not removed; the errors are above, and each is retried next run\n", + sum.Skipped, sum.StoreFull, sum.ExpireFailed) + return 1 } // mailWarner delivers a pre-reap notice to the owner's verified email — the diff --git a/cmd/felis/reaper_test.go b/cmd/felis/reaper_test.go index 040f65f..376c53e 100644 --- a/cmd/felis/reaper_test.go +++ b/cmd/felis/reaper_test.go @@ -1,6 +1,7 @@ package main import ( + "bytes" "context" "errors" "os" @@ -11,8 +12,36 @@ import ( corev1 "k8s.io/api/core/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "sigs.k8s.io/controller-runtime/pkg/client/fake" + + "felis.lolicon.best/internal/reaper" ) +// TestReportReaperRunFailsTheJob: a run that could not process a server, or +// could not remove an expired backup, exits 1 so the Job shows as failed. +func TestReportReaperRunFailsTheJob(t *testing.T) { + for _, tc := range []struct { + name string + sum reaper.Summary + want int + }{ + {"clean", reaper.Summary{Evaluated: 3, WorldsReaped: 1, AwaitingOffsite: 1}, 0}, + {"server failed", reaper.Summary{Evaluated: 3, Skipped: 1}, 1}, + {"store full", reaper.Summary{Evaluated: 3, Skipped: 1, StoreFull: 1}, 1}, + {"expiry failed", reaper.Summary{Evaluated: 3, ExpireFailed: 2}, 1}, + } { + var out, errb bytes.Buffer + if got := reportReaperRun(tc.sum, &out, &errb); got != tc.want { + t.Errorf("%s: exit %d, want %d", tc.name, got, tc.want) + } + if !strings.Contains(out.String(), "skipped=") || !strings.Contains(out.String(), "expire_failed=") { + t.Errorf("%s: summary line = %q", tc.name, out.String()) + } + if (tc.want == 1) != (errb.Len() > 0) { + t.Errorf("%s: stderr = %q", tc.name, errb.String()) + } + } +} + // TestResolveWorldDir pins the two world layouts the reaper must find, and the // fail-closed miss. The stock local-path arm is derived from the live PVC's // volumeName — a name-based guess (glob) could tar a stale deleted PV's bytes and diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index 6140877..90fc77a 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -662,6 +662,33 @@ configured neither does a backup that exists on this disk only. [GO-TESTED: `awaiting_offsite` that stays above zero for more than a day means the copy is failing: `sudo felis offsite status` (§16). +### A failed reaper Job + +Each run ends with one line: + +``` +felis reaper: evaluated=12 reaped=1 awaiting_offsite=0 warned=2 skipped=0 store_full=0 evicted=0 expired=3 expire_failed=0 +``` + +`skipped` counts servers the run failed on (steps 1–3 above, or the cluster or +the database answering with an error; exempt servers and rows whose CRD is gone +are not counted), `store_full` the subset kept because the backup store is full, +and `expire_failed` expired backups it could not remove. Any of them above zero +makes the process exit 1: the worlds are safe, but the Job fails so the watchdog +mails `world reaper Job … failed` and `FelisWorldJobFailed` fires. The Job retries +twice (`backoffLimit`), each retry re-running the whole batch, which is safe +because every step is idempotent. Read the error above the summary: + +```sh +kubectl -n minecraft logs job/ +``` + +A server that fails every day keeps its world and is retried every day, so the +Job fails every day until the cause is fixed; after 26 hours the watchdog also +reports `the world reaper has not succeeded for …`. [GO-TESTED: +`TestReportReaperRunFailsTheJob`, `TestExpiryFailureFailsTheRun`, +`TestCapacityStillFullSkipsReap`.] + ### Exemptions (world never reaped) - `spec.reaperExempt=true` → skipped entirely (system servers). [GO-TESTED diff --git a/internal/pgint/reaper_test.go b/internal/pgint/reaper_test.go index 6ce9b21..7f66903 100644 --- a/internal/pgint/reaper_test.go +++ b/internal/pgint/reaper_test.go @@ -42,7 +42,7 @@ func (a *reclaimArchiver) Archive(_ context.Context, server, _ string) (backup.A } func (a *reclaimArchiver) Restore(context.Context, backup.ArchiveRef, string) error { return nil } -func (a *reclaimArchiver) Delete(context.Context, backup.ArchiveRef) error { return nil } +func (a *reclaimArchiver) Delete(context.Context, backup.ArchiveRef) error { return nil } // TestReclaimRestartsReaperClock: a world reaped weeks ago and claimed by a new // owner is not reaped again on the next run, and when it does go idle the reap diff --git a/internal/reaper/reaper.go b/internal/reaper/reaper.go index 6e97f34..91cdd38 100644 --- a/internal/reaper/reaper.go +++ b/internal/reaper/reaper.go @@ -241,17 +241,30 @@ type Reaper struct { // Summary is the per-run tally (feeds §23 metrics). type Summary struct { - Evaluated int - WorldsReaped int - Warned int - Skipped int // exempt, CRD gone, or could not back up + Evaluated int + WorldsReaped int + Warned int + // Skipped are servers the run failed on (archive, store, cluster or + // capacity errors); their worlds are kept and retried next run. Exempt + // servers and rows whose CRD is gone are not counted. + Skipped int + // StoreFull are the Skipped servers kept because the backup store was at + // capacity and eviction could not make room. + StoreFull int EvictedEarly int BackupsExpired int + // ExpireFailed are expired backups the retention pass could not remove. + ExpireFailed int // AwaitingOffsite are idle worlds that are archived and kept until the // archive's off-site copy lands. AwaitingOffsite int } +// Failed reports whether the run left work undone: a server it could not +// process, or an expired backup it could not remove. The world is safe either +// way, but the run did not do its job and whoever operates it must hear. +func (s Summary) Failed() bool { return s.Skipped > 0 || s.ExpireFailed > 0 } + func (r *Reaper) now() time.Time { if r.Now != nil { return r.Now() @@ -281,7 +294,8 @@ func (r *Reaper) id() string { // retention pass over expired backups. It is idempotent and restart-safe, so a // Kubernetes CronJob can drive the daily cadence (spec §18). Per-server // failures are logged and counted as Skipped without aborting the batch; only -// an inability to list servers is a hard error. +// an inability to list servers is a hard error. Summary.Failed tells the +// caller whether the run as a whole should report failure. func (r *Reaper) RunOnce(ctx context.Context) (Summary, error) { var sum Summary @@ -301,6 +315,9 @@ func (r *Reaper) RunOnce(ctx context.Context) (Summary, error) { if err := r.evaluate(ctx, now, offs, c, &sum); err != nil { r.log().Error("reaper: skipping server", "server", c.Name, "err", err) sum.Skipped++ + if errors.Is(err, errStoreFull) { + sum.StoreFull++ + } } } @@ -512,15 +529,18 @@ func (r *Reaper) expireBackups(ctx context.Context, now time.Time, sum *Summary) exp, err := r.Store.ListExpiredBackups(ctx, now) if err != nil { r.log().Error("reaper: list expired backups", "err", err) + sum.ExpireFailed++ return } for _, b := range exp { if err := r.Archiver.Delete(ctx, backup.ArchiveRef(b.BackupRef)); err != nil { r.log().Error("reaper: delete expired archive", "id", b.ID, "err", err) + sum.ExpireFailed++ continue } if err := r.Store.MarkBackupDeleted(ctx, b.ID, now); err != nil { r.log().Error("reaper: mark expired deleted", "id", b.ID, "err", err) + sum.ExpireFailed++ continue } sum.BackupsExpired++ diff --git a/internal/reaper/reaper_test.go b/internal/reaper/reaper_test.go index b895d82..95c5b46 100644 --- a/internal/reaper/reaper_test.go +++ b/internal/reaper/reaper_test.go @@ -675,8 +675,8 @@ func TestCapacityStillFullSkipsReap(t *testing.T) { r.Archiver.(*fakeArchiver).deleteErr = errors.New("evict unavailable") sum := mustRun(t, r) - if sum.WorldsReaped != 0 || sum.Skipped != 1 { - t.Fatalf("summary = %+v, want 0 reaped / 1 skipped (store full)", sum) + if sum.WorldsReaped != 0 || sum.Skipped != 1 || sum.StoreFull != 1 || !sum.Failed() { + t.Fatalf("summary = %+v, want 0 reaped / 1 skipped, store full, failed", sum) } if cl.deletePVCCalls != 0 { t.Fatalf("world was deleted while the store was full") @@ -714,6 +714,24 @@ func TestExpiredBackupsDeleted(t *testing.T) { } } +// An expired backup the backend cannot delete stays present and marks the run +// failed, so the Job reports it instead of succeeding every day. +func TestExpiryFailureFailsTheRun(t *testing.T) { + r, st, _, _ := newReaper(DefaultConfig()) + st.backups = []*fakeBackup{ + {id: "gone", server: "s1", ref: "ref-gone", size: 5, status: "present", createdAt: idleBy(120 * Day), expires: idleBy(1 * Day)}, + } + r.Archiver.(*fakeArchiver).deleteErr = errors.New("permission denied") + + sum := mustRun(t, r) + if sum.BackupsExpired != 0 || sum.ExpireFailed != 1 || !sum.Failed() { + t.Fatalf("summary = %+v, want 0 expired / 1 expire_failed, failed", sum) + } + if st.backups[0].status != "present" { + t.Fatalf("the undeleted archive's row was marked %s", st.backups[0].status) + } +} + // A servers row whose CRD has been deleted is skipped (not a failure) — the // reaper never deletes world data it cannot first inspect for the exemption. func TestMissingCRDSkipped(t *testing.T) {