diff --git a/CHANGELOG.md b/CHANGELOG.md index de6f0342a1..f9d91fb0ef 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -21,8 +21,34 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 store "X" has no configured control-dispatcher for its store scope` to name the missing scope. +### Added + +- **Exec orders can declare informational exit codes.** A script whose + documented contract reserves a low non-zero code for a finding rather than an + error — a drift detector that exits 1 when it found drift, having already + reported it — was recorded as `order.failed` on every run, which made an order + with a 100% failure rate indistinguishable from a healthy one. Listing those + codes in `success_exit_codes = [1]` records such runs as completed. The key is + exec-only, entries must be between 1 and 255, and listing 0 is rejected as + redundant. Anything not listed still fails. + ### Fixed +- **A failed exec order now records why it failed.** `order.failed` carried the + bare error (`exit status 1`) and an empty payload, and the run's tracking bead + carried only an outcome label, so diagnosing a failed scheduled order meant + catching the next failure live. Both now carry the resolved exec string, the + exit status, and the last 2 KiB of the command's combined stdout and stderr, + redacted through the same env redactor the dispatch logs use. A routine exit-0 + run still writes no description, so a busy city's tracking beads do not grow. +- **`gc doctor` distinguishes an order that fired from one that succeeded.** The + `order-firing-current` check read only `order.fired`, so an order firing + exactly on schedule and failing every time reported green. It now reads + `order.completed` and `order.failed` too, and reports last-succeeded alongside + last-fired. The new signal is advisory rather than blocking, so a city whose + orders have been failing quietly is informed rather than gated; an order with + no recorded outcome either way stays silent instead of being reported as never + having succeeded. - **Attempt/fanout control routing no longer fails closed on a transient route-config load.** The store-scoped dispatcher routing made attempt-spawn (`spawnNextAttempt`) and fanout (`routeFanoutFragmentSteps`) control routing diff --git a/cmd/gc/cmd_order.go b/cmd/gc/cmd_order.go index 97ae0c849a..fd8932a36f 100644 --- a/cmd/gc/cmd_order.go +++ b/cmd/gc/cmd_order.go @@ -910,6 +910,13 @@ func doOrderRunExecResult(a orders.Order, cityPath string, cfg *config.City, var // and combined output against the projected env on both the failure and // success paths, matching the controller dispatch path (order_dispatch.go). redactionEnv := append(os.Environ(), env...) + // Honor success_exit_codes here too. A manual run that reported failure + // for a code the scheduled run treats as informational would disagree with + // the controller about whether the same command succeeded. + if exitCode, resolved := orders.ExitCodeFromError(err); err != nil && resolved && ctx.Err() == nil && a.IsSuccessExitCode(exitCode) { + fmt.Fprintf(stderr, "gc order run: exec exited %d (declared informational by success_exit_codes)\n", exitCode) //nolint:errcheck + err = nil + } if err != nil { fmt.Fprintf(stderr, "gc order run: exec failed: %s\n", execenv.RedactText(err.Error(), redactionEnv)) //nolint:errcheck if len(output) > 0 { diff --git a/cmd/gc/order_dispatch.go b/cmd/gc/order_dispatch.go index cf8106aa01..06429892f5 100644 --- a/cmd/gc/order_dispatch.go +++ b/cmd/gc/order_dispatch.go @@ -1362,15 +1362,51 @@ func (m *memoryOrderDispatcher) dispatchExec(ctx context.Context, front *orders. env, err := orderExecEnvWithError(cityPath, m.cfg, target, a, vars) var output []byte var execErrMsg string + // runDetail is the durable "what ran, how it exited, what it said" record. + // It is written to the tracking bead whenever the command exits non-zero, + // whether that code means failure or is one the order declares + // informational, so the record of a run finally carries its reason. + var runDetail string if err != nil { redactionEnv := append(os.Environ(), env...) redacted := redactOrderEnvError(err, redactionEnv) execErrMsg = "exec env failed: " + redacted outcome = orders.RunOutcomeExecEnvFailed + runDetail = execenv.RedactText(orders.ExecRunDetail{ + Command: a.Exec, + ExitCode: -1, + Err: "exec env failed: " + err.Error(), + }.String(), redactionEnv) logDispatchError(m.stderr, "gc: order exec %s env failed: %s", scoped, redacted) } else { output, err = m.execRun(ctx, a.Exec, target.ScopeRoot, env) - if err != nil { + exitCode, resolved := orders.ExitCodeFromError(err) + if !resolved { + exitCode = -1 + } + informational := err != nil && resolved && ctx.Err() == nil && a.IsSuccessExitCode(exitCode) + if err != nil || exitCode != 0 { + redactionEnv := append(os.Environ(), env...) + detailErr := "" + if err != nil { + detailErr = err.Error() + } + runDetail = execenv.RedactText(orders.ExecRunDetail{ + Command: a.Exec, + ExitCode: exitCode, + Err: detailErr, + Output: output, + }.String(), redactionEnv) + } + switch { + case informational: + // The command's contract reserves this code for "I ran, and here + // is what I found". Leaving execErrMsg empty records a completed + // run, so a real failure stays distinguishable from a healthy + // informational one; the findings themselves reach the tracking + // bead via runDetail. + logDispatchError(m.stderr, "gc: order exec %s exited %d (declared informational by success_exit_codes)", scoped, exitCode) + case err != nil: redactionEnv := append(os.Environ(), env...) execErrMsg = execenv.RedactText(err.Error(), redactionEnv) outcome = orders.RunOutcomeExecFailed @@ -1381,6 +1417,13 @@ func (m *memoryOrderDispatcher) dispatchExec(ctx context.Context, front *orders. } } + // Persist the run's diagnostic detail before the outcome label. A detail + // write that fails must not cost us the outcome stamp, so it is logged and + // the dispatch continues. + if err := front.SetDetail(trackingID, runDetail); err != nil { + logDispatchError(m.stderr, "gc: order %s: failed to record exec detail on tracking bead %s: %v", scoped, trackingID, err) + } + // Label tracking bead with outcome via store (not CLI). For event execs, // cursor labels were already persisted before the command ran. if err := front.SetOutcome(trackingID, outcome); err != nil { @@ -1401,6 +1444,12 @@ func (m *memoryOrderDispatcher) dispatchExec(ctx context.Context, front *orders. if hasEventCursor { execErrMsg = fmt.Sprintf("seq=%d: %s", headSeq, execErrMsg) } + // Keep the short reason on the first line — readers and greps have + // always found it there — and append the detail block beneath it, so + // the event alone answers why the order failed. + if runDetail != "" { + execErrMsg = execErrMsg + "\n" + runDetail + } m.rec.Record(events.Event{ Type: events.OrderFailed, Actor: "controller", @@ -1413,6 +1462,7 @@ func (m *memoryOrderDispatcher) dispatchExec(ctx context.Context, front *orders. Type: events.OrderCompleted, Actor: "controller", Subject: scoped, + Message: runDetail, }) } diff --git a/cmd/gc/order_dispatch_failure_detail_test.go b/cmd/gc/order_dispatch_failure_detail_test.go new file mode 100644 index 0000000000..77c628a9b7 --- /dev/null +++ b/cmd/gc/order_dispatch_failure_detail_test.go @@ -0,0 +1,177 @@ +package main + +import ( + "context" + "strings" + "testing" + + "github.com/gastownhall/gascity/internal/beads" + "github.com/gastownhall/gascity/internal/events" + "github.com/gastownhall/gascity/internal/orders" +) + +// messagesOfType returns the recorded messages for one event type, so a test +// can assert on what an order.failed event actually says rather than only that +// one was emitted. +func (r *memRecorder) messagesOfType(typ string) []string { + r.mu.Lock() + defer r.mu.Unlock() + var out []string + for _, e := range r.events { + if e.Type == typ { + out = append(out, e.Message) + } + } + return out +} + +// dispatchExecForDetailTest runs one exec order end to end through the real +// shell runner and returns its tracking bead plus the recorder. Using the real +// runner is deliberate: the exit-status plumbing under test only exists on a +// genuine *exec.ExitError. +func dispatchExecForDetailTest(t *testing.T, order orders.Order) (beads.Bead, *memRecorder) { + t.Helper() + store := beads.NewMemStore() + label := "order-run:" + order.Name + tracking, err := store.Create(beads.Bead{ + Title: "order:" + order.Name, + Labels: []string{label, labelOrderTracking}, + }) + if err != nil { + t.Fatalf("creating tracking bead: %v", err) + } + + var rec memRecorder + ad := buildOrderDispatcherFromListExec([]orders.Order{order}, store, events.NewFake(), shellExecRunner, &rec) + if ad == nil { + t.Fatal("expected non-nil dispatcher") + } + mad := ad.(*memoryOrderDispatcher) + + captureCmdOrderLogs(t, func() { + mad.dispatchExec(context.Background(), orders.NewStore(beads.OrdersStore{Store: store}), + execStoreTarget{ScopeRoot: t.TempDir()}, mad.aa[0], t.TempDir(), tracking.ID, nil) + }) + + all := trackingBeads(t, store, label) + if len(all) != 1 { + t.Fatalf("tracking beads = %d, want 1", len(all)) + } + return all[0], &rec +} + +// The defect: a failed order recorded THAT it failed and discarded WHY, so +// diagnosing one meant catching the next failure live. +func TestOrderDispatchExecFailureRecordsDiagnosticDetail(t *testing.T) { + bead, rec := dispatchExecForDetailTest(t, orders.Order{ + Name: "preflight", + Trigger: "cooldown", + Interval: "1h", + Exec: `echo "gc: unknown command \"doctor\"" >&2; exit 12`, + }) + + if !slicesContain(bead.Labels, "exec-failed") { + t.Fatalf("tracking bead labels = %v, want exec-failed", bead.Labels) + } + if !strings.Contains(bead.Description, "unknown command") { + t.Fatalf("tracking bead description = %q, want the command's stderr", bead.Description) + } + if !strings.Contains(bead.Description, "exit status: 12") { + t.Fatalf("tracking bead description = %q, want the exit status", bead.Description) + } + if !strings.Contains(bead.Description, "exec: echo") { + t.Fatalf("tracking bead description = %q, want the resolved exec string", bead.Description) + } + + msgs := rec.messagesOfType(events.OrderFailed) + if len(msgs) != 1 { + t.Fatalf("order.failed messages = %d, want 1", len(msgs)) + } + // The short reason stays on the first line; readers and greps have always + // found it there. + if first, _, _ := strings.Cut(msgs[0], "\n"); first != "exit status 12" { + t.Fatalf("order.failed first line = %q, want the bare exit status", first) + } + if !strings.Contains(msgs[0], "unknown command") { + t.Fatalf("order.failed message = %q, want the output tail appended", msgs[0]) + } +} + +// branch_protection.py's documented contract reserves exit 1 for "drift +// detected, already reported". Without success_exit_codes gc logs that as a +// failure, and an order with a 100% failure rate becomes indistinguishable +// from a healthy one. +func TestOrderDispatchExecDeclaredInformationalExitCompletes(t *testing.T) { + bead, rec := dispatchExecForDetailTest(t, orders.Order{ + Name: "branch-protection", + Trigger: "cron", + Schedule: "0 10 * * *", + Exec: `echo "drift detected on 2 repos"; exit 1`, + SuccessExitCodes: []int{1}, + }) + + if slicesContain(bead.Labels, "exec-failed") { + t.Fatalf("tracking bead labels = %v, want no exec-failed for a declared informational exit", bead.Labels) + } + if !slicesContain(bead.Labels, "exec") { + t.Fatalf("tracking bead labels = %v, want exec", bead.Labels) + } + if rec.hasType(events.OrderFailed) { + t.Fatal("recorded order.failed for an exit code the order declares informational") + } + if !rec.hasType(events.OrderCompleted) { + t.Fatal("missing order.completed for a declared informational exit") + } + // The findings are the whole point of the informational exit, so they must + // survive on the run even though it is not a failure. + if !strings.Contains(bead.Description, "drift detected on 2 repos") { + t.Fatalf("tracking bead description = %q, want the command's findings", bead.Description) + } + if !strings.Contains(bead.Description, "exit status: 1") { + t.Fatalf("tracking bead description = %q, want the informational exit status", bead.Description) + } +} + +// Negative control. An undeclared non-zero exit must still fail — otherwise the +// success_exit_codes plumbing would be swallowing real failures rather than +// classifying declared ones. +func TestOrderDispatchExecUndeclaredExitStillFails(t *testing.T) { + bead, rec := dispatchExecForDetailTest(t, orders.Order{ + Name: "branch-protection-strict", + Trigger: "cron", + Schedule: "0 10 * * *", + Exec: `echo "gh: not authenticated" >&2; exit 11`, + SuccessExitCodes: []int{1}, + }) + + if !slicesContain(bead.Labels, "exec-failed") { + t.Fatalf("tracking bead labels = %v, want exec-failed for an undeclared exit code", bead.Labels) + } + if !rec.hasType(events.OrderFailed) { + t.Fatal("missing order.failed for an undeclared exit code") + } + if !strings.Contains(bead.Description, "not authenticated") { + t.Fatalf("tracking bead description = %q, want the command's stderr", bead.Description) + } +} + +// A city carries tens of thousands of order-tracking beads. A routine success +// has nothing to diagnose, so it must not write a description on every run. +func TestOrderDispatchExecSuccessWritesNoDetail(t *testing.T) { + bead, rec := dispatchExecForDetailTest(t, orders.Order{ + Name: "worktree-cleanup", + Trigger: "cooldown", + Interval: "1h", + Exec: `echo "nothing to clean"`, + }) + + if bead.Description != "" { + t.Fatalf("tracking bead description = %q, want empty for a routine exit-0 run", bead.Description) + } + if !rec.hasType(events.OrderCompleted) { + t.Fatal("missing order.completed for a successful run") + } + if rec.hasType(events.OrderFailed) { + t.Fatal("recorded order.failed for a successful run") + } +} diff --git a/docs/tutorials/07-orders.md b/docs/tutorials/07-orders.md index 56aa4d0d89..bf6eb06137 100644 --- a/docs/tutorials/07-orders.md +++ b/docs/tutorials/07-orders.md @@ -224,6 +224,35 @@ The rules: handy for tuning thresholds without editing it. `env` is exec-only. - Default timeout is 30s for formula orders, 300s for exec orders. +## Informational exit codes + +An exec order succeeds on exit 0 and fails on anything else. That is the right +default, but plenty of useful scripts reserve a low non-zero code to report a +finding rather than an error — a drift detector that exits 1 when it found +drift, having already filed it. Recording every such run as a failure makes an +order with a 100% failure rate indistinguishable from a perfectly healthy one, +which is exactly the state a real breakage then hides in. + +List those codes and they are recorded as completed runs: + +```toml +[order] +description = "Report branch-protection drift" +trigger = "cron" +schedule = "0 10 * * *" +exec = "scripts/branch_protection.py" +success_exit_codes = [1] # 1 = drift detected and reported; 10..16 = real failures +``` + +The rules: + +- `success_exit_codes` is exec-only, and each entry is between 1 and 255. +- Exit 0 always succeeds. Listing it is an error, not a redundancy. +- Anything not listed still fails. Above, exit 10 is a real failure and is + recorded as one. +- The run's output is stored either way (see [Order history](#order-history)), + so an informational run keeps its findings. + ## Timeouts Each order can set a timeout: @@ -378,6 +407,25 @@ launches — which is what keeps the cooldown trigger from re-firing on the very next tick. The trigger checks for recent tracking beads when deciding if the order is due. +When an exec order's command exits non-zero, its tracking bead's description +records what ran, how it exited, and the last 2 KiB of the command's combined +stdout and stderr, redacted through the same env redactor the logs use. The +same detail is appended to the `order.failed` event. Read it with `bd show +`: + +``` +exec: scripts/preflight.sh +exit status: 127 +error: exit status 127 +output (48 bytes): +scripts/preflight.sh: gc: unknown command "doctor" +``` + +Without it a failed order records only *that* it failed, and diagnosing one +means waiting to catch the next failure live. A routine exit-0 run writes no +description — there is nothing to diagnose, and a busy city accumulates tens of +thousands of tracking beads. + ## Duplicate prevention Before dispatching, the orchestrator checks whether the order already has open diff --git a/internal/doctor/checks_order_firing.go b/internal/doctor/checks_order_firing.go index b5636c0e69..3b0a9ec1b1 100644 --- a/internal/doctor/checks_order_firing.go +++ b/internal/doctor/checks_order_firing.go @@ -127,6 +127,16 @@ func (c *OrderFiringCurrentCheck) run(ctx *CheckContext) *CheckResult { result.Message = fmt.Sprintf("read order firing events: %v", err) return result } + // Firing is not succeeding. An order that fires on schedule and exits + // non-zero every time leaves a perfect order.fired trail, so the outcome + // events are the only signal that separates "the controller dispatched it" + // from "the scheduled work actually happened". + completedAt, failedAt, err := latestOrderOutcomes(eventPath) + if err != nil { + result.Status = StatusError + result.Message = fmt.Sprintf("read order outcome events: %v", err) + return result + } startedAt, err := latestControllerStartedAt(eventPath) if err != nil { result.Status = StatusError @@ -145,6 +155,9 @@ func (c *OrderFiringCurrentCheck) run(ctx *CheckContext) *CheckResult { // Track severity contributions across error-level entries. Warnings should // stay visible without converting an advisory error into a blocking gate. var blockingErrors, advisoryErrors int + // Counted separately so the summary line can say which of the two failure + // modes it found: nothing fired, or things fired and did not succeed. + var firingErrors, succeedingErrors int suspendedRigs := orderFiringCurrentSuspendedRigs(c.cfg) for _, order := range allOrders { @@ -183,6 +196,7 @@ func (c *OrderFiringCurrentCheck) run(ctx *CheckContext) *CheckResult { firstNonOK = orderHistoryHintTarget(order) } if status == StatusError { + firingErrors++ if severity == SeverityBlocking { blockingErrors++ } else { @@ -190,6 +204,28 @@ func (c *OrderFiringCurrentCheck) run(ctx *CheckContext) *CheckResult { } } } + + scoped := order.ScopedName() + successStatus, successDetail := classifyOrderSucceeding(order, now, expected, completedAt[scoped], failedAt[scoped]) + if successDetail == "" { + continue + } + worst = worseStatus(worst, successStatus) + result.Details = append(result.Details, successDetail) + if successStatus == StatusOK { + continue + } + if firstNonOK == "" { + firstNonOK = orderHistoryHintTarget(order) + } + if successStatus == StatusError { + // Advisory, not blocking. An order that has been failing quietly + // for weeks is exactly what this signal exists to surface, and + // turning that history into a blocking gate the moment the check + // ships would wedge the city instead of informing its operator. + succeedingErrors++ + advisoryErrors++ + } } if monitored == 0 { @@ -206,6 +242,9 @@ func (c *OrderFiringCurrentCheck) run(ctx *CheckContext) *CheckResult { result.Message = "scheduled orders are overdue" case StatusError: result.Message = "scheduled orders are stale" + if firingErrors == 0 && succeedingErrors > 0 { + result.Message = "scheduled orders are firing but not succeeding" + } } if blockingErrors == 0 && advisoryErrors > 0 { result.Severity = SeverityAdvisory @@ -581,6 +620,67 @@ func (c *OrderFiringCurrentCheck) latestOrderFiredAt(evts []events.Event, order return latest, nil } +// latestOrderOutcomes returns, per scoped order name, the newest order.completed +// and order.failed timestamps in the event log. Absence from either map means +// no outcome of that kind was ever recorded for the order. +func latestOrderOutcomes(eventPath string) (completed, failed map[string]time.Time, err error) { + completed, err = latestEventTimesBySubject(eventPath, events.OrderCompleted) + if err != nil { + return nil, nil, err + } + failed, err = latestEventTimesBySubject(eventPath, events.OrderFailed) + if err != nil { + return nil, nil, err + } + return completed, failed, nil +} + +func latestEventTimesBySubject(eventPath, eventType string) (map[string]time.Time, error) { + evts, err := events.ReadFiltered(eventPath, events.Filter{Type: eventType}) + if err != nil { + return nil, err + } + latest := make(map[string]time.Time, len(evts)) + for _, event := range evts { + if event.Subject == "" { + continue + } + if event.Ts.After(latest[event.Subject]) { + latest[event.Subject] = event.Ts + } + } + return latest, nil +} + +// classifyOrderSucceeding reports whether an order's runs are reaching a +// successful outcome, which is a different question from whether the +// controller is dispatching them on schedule. An empty detail means the check +// has nothing to say: the order has no recorded outcome either way, so its +// success state is unknown rather than bad. +// +// Unlike the firing classification there is no manual-run fallback here. The +// outcome events are the only success signal, so an order whose history +// predates them stays silent instead of being reported as never succeeding. +func classifyOrderSucceeding(order orders.Order, now time.Time, expected time.Duration, lastSucceeded, lastFailed time.Time) (CheckStatus, string) { + name := orderDisplayName(order) + if lastSucceeded.IsZero() && lastFailed.IsZero() { + return StatusOK, "" + } + if lastSucceeded.IsZero() { + return StatusError, fmt.Sprintf("%s: has never succeeded (last failed %s ago)", name, formatOrderFiringDuration(nonNegativeDuration(now.Sub(lastFailed)))) + } + + age := nonNegativeDuration(now.Sub(lastSucceeded)) + switch { + case age >= expected*3: + return StatusError, fmt.Sprintf("%s: last succeeded %s ago, expected every %s (CRITICAL: firing but not succeeding)", name, formatOrderFiringDuration(age), formatOrderFiringDuration(expected)) + case age >= expected+expected/2: + return StatusWarning, fmt.Sprintf("%s: last succeeded %s ago, expected every %s (overdue)", name, formatOrderFiringDuration(age), formatOrderFiringDuration(expected)) + default: + return StatusOK, fmt.Sprintf("%s: last succeeded %s ago", name, formatOrderFiringDuration(age)) + } +} + func latestOrderFiredAt(evts []events.Event, subject string) time.Time { var latest time.Time for _, event := range evts { diff --git a/internal/doctor/checks_order_firing_succeeding_test.go b/internal/doctor/checks_order_firing_succeeding_test.go new file mode 100644 index 0000000000..bc87d1575b --- /dev/null +++ b/internal/doctor/checks_order_firing_succeeding_test.go @@ -0,0 +1,184 @@ +package doctor + +import ( + "path/filepath" + "strings" + "testing" + "time" + + "github.com/gastownhall/gascity/internal/citylayout" + "github.com/gastownhall/gascity/internal/events" + "github.com/gastownhall/gascity/internal/orders" +) + +func orderFiringTestEventPath(cityPath string) string { + return filepath.Join(cityPath, citylayout.RuntimeRoot, "events.jsonl") +} + +// A green "last fired" says nothing about whether the scheduled work actually +// happened. An order firing exactly on schedule and failing every time is the +// case this check exists to separate from a healthy one. +func TestOrderFiringCurrent_FiringButNeverSucceeding(t *testing.T) { + now := time.Date(2026, 7, 10, 12, 0, 0, 0, time.UTC) + cityPath, cfg := orderFiringTestCity(t) + writeOrderFiringTestOrder(t, cityPath, "branch-protection", "cron", "0 10 * * *") + writeOrderFiringTestEvents(t, cityPath, + events.Event{Type: events.ControllerStarted, Ts: now.Add(-72 * time.Hour)}, + events.Event{Type: events.OrderFired, Subject: "branch-protection", Ts: now.Add(-2 * time.Hour)}, + events.Event{Type: events.OrderFailed, Subject: "branch-protection", Ts: now.Add(-2 * time.Hour)}, + ) + + result := runOrderFiringCurrentTest(t, cfg, cityPath, now) + if result.Status != StatusError { + t.Fatalf("status = %v, want error; msg = %s; details = %v", result.Status, result.Message, result.Details) + } + if result.Message != "scheduled orders are firing but not succeeding" { + t.Fatalf("Message = %q, want the firing-but-not-succeeding summary", result.Message) + } + details := strings.Join(result.Details, "\n") + if !strings.Contains(details, "has never succeeded") { + t.Fatalf("details = %v, want a never-succeeded entry", result.Details) + } + // The order IS firing on schedule, so the firing entry must stay green. + // Losing that distinction is the defect, not the fix. + if !strings.Contains(details, "last fired 2h ago") { + t.Fatalf("details = %v, want the firing entry to still report a recent fire", result.Details) + } + if result.Severity != SeverityAdvisory { + t.Fatalf("Severity = %v, want SeverityAdvisory: a city whose orders have been failing for weeks must not be red-gated the moment this check ships", result.Severity) + } +} + +func TestOrderFiringCurrent_SucceedingOrderReportsBothSignals(t *testing.T) { + now := time.Date(2026, 7, 10, 12, 0, 0, 0, time.UTC) + cityPath, cfg := orderFiringTestCity(t) + writeOrderFiringTestOrder(t, cityPath, "worktree-cleanup", "cooldown", "1h") + writeOrderFiringTestEvents(t, cityPath, + events.Event{Type: events.ControllerStarted, Ts: now.Add(-72 * time.Hour)}, + events.Event{Type: events.OrderFired, Subject: "worktree-cleanup", Ts: now.Add(-20 * time.Minute)}, + events.Event{Type: events.OrderCompleted, Subject: "worktree-cleanup", Ts: now.Add(-20 * time.Minute)}, + ) + + result := runOrderFiringCurrentTest(t, cfg, cityPath, now) + if result.Status != StatusOK { + t.Fatalf("status = %v, want ok; msg = %s; details = %v", result.Status, result.Message, result.Details) + } + details := strings.Join(result.Details, "\n") + if !strings.Contains(details, "last fired 20m ago") { + t.Fatalf("details = %v, want a last-fired entry", result.Details) + } + if !strings.Contains(details, "last succeeded 20m ago") { + t.Fatalf("details = %v, want a last-succeeded entry alongside last-fired", result.Details) + } +} + +// Negative control for the new signal. A city whose event log predates outcome +// recording has no order.completed or order.failed rows at all; the success +// state is unknown, not bad, and the check must stay silent about it rather +// than reporting every legacy order as never having succeeded. +func TestOrderFiringCurrent_NoOutcomeHistoryStaysSilent(t *testing.T) { + now := time.Date(2026, 7, 10, 12, 0, 0, 0, time.UTC) + cityPath, cfg := orderFiringTestCity(t) + writeOrderFiringTestOrder(t, cityPath, "legacy-order", "cooldown", "1h") + writeOrderFiringTestEvents(t, cityPath, + events.Event{Type: events.ControllerStarted, Ts: now.Add(-72 * time.Hour)}, + events.Event{Type: events.OrderFired, Subject: "legacy-order", Ts: now.Add(-20 * time.Minute)}, + ) + + result := runOrderFiringCurrentTest(t, cfg, cityPath, now) + if result.Status != StatusOK { + t.Fatalf("status = %v, want ok; msg = %s; details = %v", result.Status, result.Message, result.Details) + } + for _, detail := range result.Details { + if strings.Contains(detail, "succeeded") { + t.Fatalf("detail %q mentions success, but the order has no outcome history to judge", detail) + } + } +} + +func TestClassifyOrderSucceeding(t *testing.T) { + now := time.Date(2026, 7, 10, 12, 0, 0, 0, time.UTC) + expected := time.Hour + order := orders.Order{Name: "freshness-check", Trigger: "cooldown"} + + tests := []struct { + name string + lastSucceeded time.Time + lastFailed time.Time + wantStatus CheckStatus + wantDetail string + }{ + { + name: "no outcome history is unknown, not bad", + wantStatus: StatusOK, + wantDetail: "", + }, + { + name: "failures with no success ever", + lastFailed: now.Add(-30 * time.Minute), + wantStatus: StatusError, + wantDetail: "freshness-check: has never succeeded (last failed 30m ago)", + }, + { + name: "recent success", + lastSucceeded: now.Add(-10 * time.Minute), + wantStatus: StatusOK, + wantDetail: "freshness-check: last succeeded 10m ago", + }, + { + name: "success overdue at 1.5x the interval", + lastSucceeded: now.Add(-2 * time.Hour), + lastFailed: now.Add(-10 * time.Minute), + wantStatus: StatusWarning, + wantDetail: "freshness-check: last succeeded 2h ago, expected every 1h (overdue)", + }, + { + name: "success critical at 3x the interval", + lastSucceeded: now.Add(-5 * time.Hour), + lastFailed: now.Add(-10 * time.Minute), + wantStatus: StatusError, + wantDetail: "freshness-check: last succeeded 5h ago, expected every 1h (CRITICAL: firing but not succeeding)", + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + status, detail := classifyOrderSucceeding(order, now, expected, tc.lastSucceeded, tc.lastFailed) + if status != tc.wantStatus { + t.Fatalf("status = %v, want %v (detail %q)", status, tc.wantStatus, detail) + } + if detail != tc.wantDetail { + t.Fatalf("detail = %q, want %q", detail, tc.wantDetail) + } + }) + } +} + +func TestLatestOrderOutcomes(t *testing.T) { + now := time.Date(2026, 7, 10, 12, 0, 0, 0, time.UTC) + cityPath, _ := orderFiringTestCity(t) + writeOrderFiringTestEvents(t, cityPath, + events.Event{Type: events.OrderCompleted, Subject: "alpha", Ts: now.Add(-3 * time.Hour)}, + events.Event{Type: events.OrderCompleted, Subject: "alpha", Ts: now.Add(-1 * time.Hour)}, + events.Event{Type: events.OrderFailed, Subject: "beta", Ts: now.Add(-2 * time.Hour)}, + // A subject-less outcome cannot be attributed to an order and is skipped. + events.Event{Type: events.OrderFailed, Ts: now}, + ) + + completed, failed, err := latestOrderOutcomes(orderFiringTestEventPath(cityPath)) + if err != nil { + t.Fatalf("latestOrderOutcomes: %v", err) + } + if got := completed["alpha"]; !got.Equal(now.Add(-1 * time.Hour)) { + t.Fatalf("completed[alpha] = %v, want the newest of the two completions", got) + } + if _, ok := completed["beta"]; ok { + t.Fatalf("completed[beta] present, want absent: beta only ever failed") + } + if got := failed["beta"]; !got.Equal(now.Add(-2 * time.Hour)) { + t.Fatalf("failed[beta] = %v, want the recorded failure time", got) + } + if _, ok := failed[""]; ok { + t.Fatalf("failed[\"\"] present, want the subject-less event skipped") + } +} diff --git a/internal/orders/order.go b/internal/orders/order.go index 43248d4c11..f1f53fede3 100644 --- a/internal/orders/order.go +++ b/internal/orders/order.go @@ -73,6 +73,15 @@ type Order struct { // (gastownhall/gascity#2893). Non-idempotent orders (the // default, false) keep failing CLOSED on gate timeout. Idempotent bool `toml:"idempotent,omitempty"` + // SuccessExitCodes lists non-zero exit codes an exec order's command + // treats as a successful (informational) outcome rather than a failure. + // Exit 0 is always success and never needs listing. Use it for scripts + // whose documented contract reserves a low non-zero code for "I ran, and + // here is what I found" — e.g. a drift detector that exits 1 when drift + // exists, having already reported it. Without this, every such run is + // recorded as order.failed and a real failure becomes indistinguishable + // from a healthy one. Supported only for exec orders. + SuccessExitCodes []int `toml:"success_exit_codes,omitempty"` // Env is a map of environment variables exported into an exec // order's child process. Use the `[order.env]` TOML table to // override thresholds (e.g. GC_DOCTOR_LATENCY_WARN_S) without @@ -129,6 +138,7 @@ type orderDecode struct { CheckTimeout string `toml:"check_timeout,omitempty"` Enabled *bool `toml:"enabled,omitempty"` Idempotent bool `toml:"idempotent,omitempty"` + SuccessExit []int `toml:"success_exit_codes,omitempty"` Env map[string]string `toml:"env,omitempty"` Params map[string]OrderParam `toml:"params,omitempty"` SkipAliases []string `toml:"skip_aliases,omitempty"` @@ -140,24 +150,25 @@ func (d orderDecode) normalized() Order { trigger = d.Gate } return Order{ - Description: d.Description, - Formula: d.Formula, - Exec: d.Exec, - Scope: d.Scope, - Trigger: trigger, - Interval: d.Interval, - Schedule: d.Schedule, - TZ: d.TZ, - Check: d.Check, - On: d.On, - Pool: d.Pool, - Timeout: d.Timeout, - CheckTimeout: d.CheckTimeout, - Enabled: d.Enabled, - Idempotent: d.Idempotent, - Env: d.Env, - Params: d.Params, - skipAliases: d.SkipAliases, + Description: d.Description, + Formula: d.Formula, + Exec: d.Exec, + Scope: d.Scope, + Trigger: trigger, + Interval: d.Interval, + Schedule: d.Schedule, + TZ: d.TZ, + Check: d.Check, + On: d.On, + Pool: d.Pool, + Timeout: d.Timeout, + CheckTimeout: d.CheckTimeout, + Enabled: d.Enabled, + Idempotent: d.Idempotent, + SuccessExitCodes: d.SuccessExit, + Env: d.Env, + Params: d.Params, + skipAliases: d.SkipAliases, } } @@ -180,6 +191,21 @@ func (a *Order) IsExec() bool { return a.Exec != "" } +// IsSuccessExitCode reports whether an exec order's child process exit code +// counts as a successful outcome. Exit 0 always does. Any other code counts +// only when the order lists it in success_exit_codes. +func (a *Order) IsSuccessExitCode(code int) bool { + if code == 0 { + return true + } + for _, allowed := range a.SuccessExitCodes { + if allowed == code { + return true + } + } + return false +} + // IsCityScoped reports whether the order is city-scoped, i.e. instantiated // exactly once during pack expansion regardless of how many rigs import the // pack. The default (empty Scope) is rig-scoped. @@ -241,6 +267,17 @@ func Validate(a Order) error { if len(a.Env) > 0 && a.Exec == "" { return fmt.Errorf("order %q: env is supported only for exec orders", a.Name) } + if len(a.SuccessExitCodes) > 0 && a.Exec == "" { + return fmt.Errorf("order %q: success_exit_codes is supported only for exec orders", a.Name) + } + for _, code := range a.SuccessExitCodes { + if code == 0 { + return fmt.Errorf("order %q: success_exit_codes must not list 0 (exit 0 is always success)", a.Name) + } + if code < 1 || code > 255 { + return fmt.Errorf("order %q: invalid success_exit_codes entry %d: must be between 1 and 255", a.Name, code) + } + } // Exec orders must not have a pool (no agent pipeline). if a.Exec != "" && a.Pool != "" { return fmt.Errorf("order %q: exec orders cannot have a pool", a.Name) diff --git a/internal/orders/run_detail.go b/internal/orders/run_detail.go new file mode 100644 index 0000000000..7c62022279 --- /dev/null +++ b/internal/orders/run_detail.go @@ -0,0 +1,85 @@ +package orders + +import ( + "errors" + "fmt" + "os/exec" + "strings" +) + +// ExecOutputTailLimit bounds how many bytes of an exec order's combined +// stdout/stderr are retained in the run's diagnostic detail. A failing order +// is usually explained by its last few lines, and the detail is stored on a +// tracking bead and echoed into an event message, so the whole transcript is +// neither needed nor affordable. +const ExecOutputTailLimit = 2048 + +// ExecRunDetail describes one exec order run in enough detail to diagnose it +// after the fact. It is the antidote to a tracking bead that records THAT an +// order failed and discards WHY: rendered through String and stored on the +// run, it answers "what ran, how did it exit, and what did it say" without +// having to catch the failure live. +type ExecRunDetail struct { + // Command is the resolved shell command the controller ran. + Command string + // ExitCode is the child's exit status. It is negative when no exit code + // could be resolved — the command never started, the context was + // canceled, or the process was killed by a signal. + ExitCode int + // Err is the dispatch error string, e.g. "exit status 1". Empty on a + // successful run. + Err string + // Output is the child's combined stdout and stderr. + Output []byte +} + +// String renders the detail as the plain-text block stored on the run's +// tracking bead and echoed into the order.failed event message. Callers are +// responsible for redacting the result before it is persisted; every field can +// carry values interpolated from the order's environment. +func (d ExecRunDetail) String() string { + var b strings.Builder + fmt.Fprintf(&b, "exec: %s\n", strings.TrimSpace(d.Command)) + if d.ExitCode >= 0 { + fmt.Fprintf(&b, "exit status: %d\n", d.ExitCode) + } else { + b.WriteString("exit status: unknown (no exit code; canceled, signaled, or never started)\n") + } + if d.Err != "" { + fmt.Fprintf(&b, "error: %s\n", d.Err) + } + total := len(d.Output) + switch { + case total == 0: + b.WriteString("output: (empty)") + case total > ExecOutputTailLimit: + fmt.Fprintf(&b, "output (last %d of %d bytes):\n%s", ExecOutputTailLimit, total, d.Output[total-ExecOutputTailLimit:]) + default: + fmt.Fprintf(&b, "output (%d bytes):\n%s", total, d.Output) + } + return b.String() +} + +// ExitCodeFromError resolves the child process exit code carried by an +// ExecRunner error. The second return reports whether a code was resolvable: +// a nil error is exit 0, an *exec.ExitError carries its own status, and +// everything else — a context cancellation, a start failure, or an error +// joined with a second failure such as process-group cleanup — is +// unresolvable and must not be reduced to a code. +func ExitCodeFromError(err error) (int, bool) { + if err == nil { + return 0, true + } + // A joined error carries a second, independent failure alongside any exit + // status. Reducing it to the exit code alone would silently drop that + // failure, so refuse it here and let the caller treat the run as failed. + var joined interface{ Unwrap() []error } + if errors.As(err, &joined) { + return 0, false + } + var exitErr *exec.ExitError + if errors.As(err, &exitErr) { + return exitErr.ExitCode(), true + } + return 0, false +} diff --git a/internal/orders/run_detail_test.go b/internal/orders/run_detail_test.go new file mode 100644 index 0000000000..432c0025d1 --- /dev/null +++ b/internal/orders/run_detail_test.go @@ -0,0 +1,127 @@ +package orders + +import ( + "bytes" + "context" + "errors" + "fmt" + "strings" + "testing" +) + +func TestExecRunDetailString(t *testing.T) { + tests := []struct { + name string + detail ExecRunDetail + want string + }{ + { + name: "failed run carries command, status, error, and output", + detail: ExecRunDetail{ + Command: "gc doctor --json", + ExitCode: 1, + Err: "exit status 1", + Output: []byte("gc: unknown command \"doctor\"\n"), + }, + want: "exec: gc doctor --json\n" + + "exit status: 1\n" + + "error: exit status 1\n" + + "output (29 bytes):\ngc: unknown command \"doctor\"\n", + }, + { + name: "silent failure still names what ran and how it exited", + detail: ExecRunDetail{ + Command: "scripts/preflight.sh", + ExitCode: 2, + Err: "exit status 2", + }, + want: "exec: scripts/preflight.sh\n" + + "exit status: 2\n" + + "error: exit status 2\n" + + "output: (empty)", + }, + { + name: "no resolvable exit code says so rather than implying 0", + detail: ExecRunDetail{ + Command: "scripts/slow.sh", + ExitCode: -1, + Err: "context deadline exceeded", + }, + want: "exec: scripts/slow.sh\n" + + "exit status: unknown (no exit code; canceled, signaled, or never started)\n" + + "error: context deadline exceeded\n" + + "output: (empty)", + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + if got := tc.detail.String(); got != tc.want { + t.Fatalf("String() =\n%q\nwant\n%q", got, tc.want) + } + }) + } +} + +// A chatty command must not be able to write an unbounded description onto its +// tracking bead, and the reader has to be told the transcript was cut. +func TestExecRunDetailStringTruncatesOutputTail(t *testing.T) { + output := append(bytes.Repeat([]byte("a"), ExecOutputTailLimit+500), []byte("TAIL-MARKER")...) + detail := ExecRunDetail{Command: "scripts/chatty.sh", ExitCode: 1, Err: "exit status 1", Output: output} + + got := detail.String() + header := fmt.Sprintf("output (last %d of %d bytes):", ExecOutputTailLimit, len(output)) + if !strings.Contains(got, header) { + t.Fatalf("String() missing truncation header %q; got:\n%s", header, got) + } + if !strings.HasSuffix(got, "TAIL-MARKER") { + t.Fatal("String() dropped the tail of the output; the last lines are the ones that explain a failure") + } + if strings.Contains(got, string(bytes.Repeat([]byte("a"), ExecOutputTailLimit+1))) { + t.Fatal("String() retained more than the tail limit of output") + } +} + +// The genuine *exec.ExitError paths are covered end to end by the dispatch +// tests in cmd/gc, which run real commands through shellExecRunner and assert +// on the resolved status (exit 12 reported as a failure, exit 1 honored as +// declared informational, exit 11 still failing). This package's tests cover +// the non-ExitError contract without spawning a process of their own: the +// repo's resource census ratchets subprocess call sites, and a unit test is +// not worth a new one. +func TestExitCodeFromError(t *testing.T) { + t.Run("nil error is exit 0", func(t *testing.T) { + code, ok := ExitCodeFromError(nil) + if !ok || code != 0 { + t.Fatalf("ExitCodeFromError(nil) = (%d, %v), want (0, true)", code, ok) + } + }) + + t.Run("context cancellation has no exit code", func(t *testing.T) { + if code, ok := ExitCodeFromError(context.Canceled); ok { + t.Fatalf("ExitCodeFromError(context.Canceled) = (%d, true), want unresolvable", code) + } + }) + + t.Run("a plain error has no exit code", func(t *testing.T) { + if code, ok := ExitCodeFromError(errors.New("fork/exec: no such file or directory")); ok { + t.Fatalf("ExitCodeFromError(plain) = (%d, true), want unresolvable", code) + } + }) + + t.Run("wrapping does not invent an exit code", func(t *testing.T) { + if code, ok := ExitCodeFromError(fmt.Errorf("running order: %w", context.DeadlineExceeded)); ok { + t.Fatalf("ExitCodeFromError(wrapped deadline) = (%d, true), want unresolvable", code) + } + }) + + // A joined error means a second failure rode along with any exit status, + // process-group cleanup most often. Reducing it to the exit code alone + // would let a declared-informational code swallow that failure whole. + t.Run("joined error refuses to reduce to an exit code", func(t *testing.T) { + joined := errors.Join(context.Canceled, errors.New("terminating process group: operation not permitted")) + if code, ok := ExitCodeFromError(joined); ok { + t.Fatalf("ExitCodeFromError(joined) = (%d, true), want unresolvable", code) + } + }) +} diff --git a/internal/orders/store.go b/internal/orders/store.go index 0c8c62eedd..17f22fa7ba 100644 --- a/internal/orders/store.go +++ b/internal/orders/store.go @@ -276,6 +276,21 @@ func (s *Store) SetOutcome(runID string, outcome RunOutcome) error { return nil } +// SetDetail stores an order run's diagnostic detail on its tracking bead's +// description — what ran, how it exited, and a bounded tail of what it said. +// Without it a tracking bead records only the outcome label, so diagnosing a +// failed scheduled order means catching the next failure live. An empty detail +// is a no-op so routine successes do not rewrite every tracking bead. +func (s *Store) SetDetail(runID, detail string) error { + if detail == "" { + return nil + } + if err := s.store.Update(runID, beads.UpdateOpts{Description: &detail}); err != nil { + return fmt.Errorf("setting order run detail on %q: %w", runID, err) + } + return nil +} + // SetCursor stamps the event cursor as the label pair (order:, // seq:) on an existing tracking bead. Replaces the cursor-persist Update // sites in order_dispatch.go. diff --git a/internal/orders/success_exit_codes_test.go b/internal/orders/success_exit_codes_test.go new file mode 100644 index 0000000000..49a28ea62f --- /dev/null +++ b/internal/orders/success_exit_codes_test.go @@ -0,0 +1,112 @@ +package orders + +import ( + "reflect" + "strings" + "testing" +) + +func TestParseSuccessExitCodes(t *testing.T) { + order, err := Parse([]byte(`[order] +exec = "scripts/branch_protection.py" +trigger = "cron" +schedule = "0 10 * * *" +success_exit_codes = [1] +`)) + if err != nil { + t.Fatalf("Parse: %v", err) + } + if !reflect.DeepEqual(order.SuccessExitCodes, []int{1}) { + t.Fatalf("SuccessExitCodes = %v, want [1]", order.SuccessExitCodes) + } +} + +func TestParseWithoutSuccessExitCodesLeavesItEmpty(t *testing.T) { + order, err := Parse([]byte(`[order] +exec = "true" +trigger = "cooldown" +interval = "1h" +`)) + if err != nil { + t.Fatalf("Parse: %v", err) + } + if len(order.SuccessExitCodes) != 0 { + t.Fatalf("SuccessExitCodes = %v, want empty for an order that declares none", order.SuccessExitCodes) + } +} + +func TestIsSuccessExitCode(t *testing.T) { + declared := Order{Name: "branch-protection", Exec: "scripts/branch_protection.py", SuccessExitCodes: []int{1}} + plain := Order{Name: "preflight", Exec: "scripts/preflight.sh"} + + tests := []struct { + name string + order Order + code int + want bool + }{ + {name: "exit 0 always succeeds", order: plain, code: 0, want: true}, + {name: "exit 0 succeeds even with codes declared", order: declared, code: 0, want: true}, + {name: "declared informational code succeeds", order: declared, code: 1, want: true}, + {name: "undeclared code still fails", order: declared, code: 10, want: false}, + {name: "no declaration means any non-zero fails", order: plain, code: 1, want: false}, + // A signaled process reports -1. It must never be read as declared. + {name: "signaled process is not a success", order: declared, code: -1, want: false}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + if got := tc.order.IsSuccessExitCode(tc.code); got != tc.want { + t.Fatalf("IsSuccessExitCode(%d) = %v, want %v", tc.code, got, tc.want) + } + }) + } +} + +func TestValidateSuccessExitCodes(t *testing.T) { + tests := []struct { + name string + order Order + wantErr string + }{ + { + name: "valid on an exec order", + order: Order{Name: "branch-protection", Exec: "scripts/bp.py", Trigger: "cron", Schedule: "0 10 * * *", SuccessExitCodes: []int{1, 2}}, + }, + { + name: "rejected on a formula order", + order: Order{Name: "sweep", Formula: "sweep", Trigger: "cooldown", Interval: "1h", SuccessExitCodes: []int{1}}, + wantErr: "success_exit_codes is supported only for exec orders", + }, + { + name: "zero is redundant and rejected", + order: Order{Name: "bp", Exec: "scripts/bp.py", Trigger: "cooldown", Interval: "1h", SuccessExitCodes: []int{0}}, + wantErr: "must not list 0", + }, + { + name: "out-of-range code rejected", + order: Order{Name: "bp", Exec: "scripts/bp.py", Trigger: "cooldown", Interval: "1h", SuccessExitCodes: []int{256}}, + wantErr: "must be between 1 and 255", + }, + { + name: "negative code rejected", + order: Order{Name: "bp", Exec: "scripts/bp.py", Trigger: "cooldown", Interval: "1h", SuccessExitCodes: []int{-1}}, + wantErr: "must be between 1 and 255", + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + err := Validate(tc.order) + if tc.wantErr == "" { + if err != nil { + t.Fatalf("Validate: %v, want nil", err) + } + return + } + if err == nil || !strings.Contains(err.Error(), tc.wantErr) { + t.Fatalf("Validate = %v, want error containing %q", err, tc.wantErr) + } + }) + } +}