From e9d9d0b283182de7b520dbf84332cf791ee736ac Mon Sep 17 00:00:00 2001 From: Ben Wisecup Date: Wed, 5 Aug 2026 16:28:10 -0400 Subject: [PATCH 1/2] fix(orders): record why an exec order failed, and stop calling informational exits failures MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An exec order that failed recorded THAT it failed and discarded WHY. The order.failed event carried the bare error ("exit status 1") and an empty payload; the run's tracking bead carried an outcome label and nothing else. Across one city's store, 264 beads carry exec-failed and not one contains an error string, because they contain no text at all. Diagnosing a failed scheduled order meant waiting to catch the next failure live. Three changes, one theme: make the record of a run say what happened. 1. Capture the reason. dispatchExec now builds an ExecRunDetail (the resolved exec string, the exit status, and the last 2 KiB of the command's combined stdout and stderr), redacts it through the same env redactor the dispatch logs already use, and writes it to the tracking bead's description and to the order.failed message. The short reason stays on the message's first line, where readers and greps have always found it. A routine exit-0 run writes no description, since a busy city carries tens of thousands of tracking beads and a successful run hasn't anything to diagnose. 2. Let an order declare informational exit codes. Plenty of useful scripts reserve a low non-zero code for a finding rather than an error: a drift detector exits 1 when it found drift, having already reported it. gc logged every such run as a failure, which makes an order with a 100% failure rate indistinguishable from a healthy one, and that's precisely where a real breakage then hides. success_exit_codes = [1] records those runs as completed. Exec-only, entries between 1 and 255, listing 0 rejected as redundant, anything unlisted still fails. `gc order run` honours it too, so the manual and scheduled paths won't disagree about whether a command succeeded. 3. Teach doctor the difference between fired and succeeded. order-firing-current 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 as well, and reports last-succeeded beside last-fired. The new signal is advisory rather than blocking: a city whose orders have been failing quietly for weeks should be informed, not gated, the moment this ships. An order with no recorded outcome either way stays silent, because its success state is unknown rather than bad, so a city whose history predates outcome recording won't light up red. Tests cover each part, and I verified each one by injection: an over-permissive success guard, a guard that refuses every declared code, a dispatch that drops the detail, and a doctor that goes back to reading fired-only. Each turns the intended test red. Generated by the operator's software factory. City: `factory-main` · Agent: `local-core.builder-1` On behalf of: @benw5483 Co-Authored-By: --- CHANGELOG.md | 26 +++ cmd/gc/cmd_order.go | 7 + cmd/gc/order_dispatch.go | 52 ++++- cmd/gc/order_dispatch_failure_detail_test.go | 177 +++++++++++++++++ docs/tutorials/07-orders.md | 48 +++++ internal/doctor/checks_order_firing.go | 100 ++++++++++ .../checks_order_firing_succeeding_test.go | 184 ++++++++++++++++++ internal/orders/order.go | 73 +++++-- internal/orders/run_detail.go | 85 ++++++++ internal/orders/run_detail_test.go | 132 +++++++++++++ internal/orders/store.go | 15 ++ internal/orders/success_exit_codes_test.go | 112 +++++++++++ 12 files changed, 992 insertions(+), 19 deletions(-) create mode 100644 cmd/gc/order_dispatch_failure_detail_test.go create mode 100644 internal/doctor/checks_order_firing_succeeding_test.go create mode 100644 internal/orders/run_detail.go create mode 100644 internal/orders/run_detail_test.go create mode 100644 internal/orders/success_exit_codes_test.go 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..cbcbabcf78 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...) + // Honour 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..369a6ce16d --- /dev/null +++ b/internal/orders/run_detail_test.go @@ -0,0 +1,132 @@ +package orders + +import ( + "bytes" + "context" + "errors" + "fmt" + "os/exec" + "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") + } +} + +func TestExitCodeFromError(t *testing.T) { + realExit := func(t *testing.T, code int) error { + t.Helper() + err := exec.CommandContext(context.Background(), "sh", "-c", fmt.Sprintf("exit %d", code)).Run() + if err == nil { + t.Fatalf("sh -c 'exit %d' returned no error", code) + } + return err + } + + 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("exit error carries its status", func(t *testing.T) { + code, ok := ExitCodeFromError(realExit(t, 3)) + if !ok || code != 3 { + t.Fatalf("ExitCodeFromError(exit 3) = (%d, %v), want (3, true)", code, ok) + } + }) + + t.Run("wrapped exit error still resolves", func(t *testing.T) { + code, ok := ExitCodeFromError(fmt.Errorf("running order: %w", realExit(t, 7))) + if !ok || code != 7 { + t.Fatalf("ExitCodeFromError(wrapped exit 7) = (%d, %v), want (7, 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) + } + }) + + // A joined error means a second failure rode along with the 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(realExit(t, 1), 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) + } + }) + } +} From aafd31531c7c2caae13cffba2a1af9fa460130a5 Mon Sep 17 00:00:00 2001 From: Ben Wisecup Date: Wed, 5 Aug 2026 16:48:46 -0400 Subject: [PATCH 2/2] fix(orders): satisfy the misspell linter and the subprocess resource ratchet MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two CI failures from the first commit, both mine. The misspell linter reads "Honour" as a misspelling of "Honor" in a cmd_order.go comment. Reworded. The resource census ratchets subprocess call sites and my ExitCodeFromError test added one, spawning `sh -c 'exit N'` to manufacture a real *exec.ExitError. The invariant reads "untagged subprocess call/file totals cannot grow", so raising the baseline is not the fix here. The unit test now covers the non-ExitError contract only: nil, a context cancellation, a plain error, a wrapped error, and a joined one. Genuine ExitError resolution stays covered where it is more honest anyway, in the cmd/gc dispatch tests, which run real commands through shellExecRunner and assert on exit 12 failing, exit 1 honored as declared informational, and exit 11 still failing. Generated by the operator's software factory. City: `factory-main` · Agent: `local-core.builder-1` On behalf of: @benw5483 Co-Authored-By: --- cmd/gc/cmd_order.go | 2 +- internal/orders/run_detail_test.go | 43 +++++++++++++----------------- 2 files changed, 20 insertions(+), 25 deletions(-) diff --git a/cmd/gc/cmd_order.go b/cmd/gc/cmd_order.go index cbcbabcf78..fd8932a36f 100644 --- a/cmd/gc/cmd_order.go +++ b/cmd/gc/cmd_order.go @@ -910,7 +910,7 @@ 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...) - // Honour success_exit_codes here too. A manual run that reported failure + // 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) { diff --git a/internal/orders/run_detail_test.go b/internal/orders/run_detail_test.go index 369a6ce16d..432c0025d1 100644 --- a/internal/orders/run_detail_test.go +++ b/internal/orders/run_detail_test.go @@ -5,7 +5,6 @@ import ( "context" "errors" "fmt" - "os/exec" "strings" "testing" ) @@ -83,16 +82,14 @@ func TestExecRunDetailStringTruncatesOutputTail(t *testing.T) { } } +// 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) { - realExit := func(t *testing.T, code int) error { - t.Helper() - err := exec.CommandContext(context.Background(), "sh", "-c", fmt.Sprintf("exit %d", code)).Run() - if err == nil { - t.Fatalf("sh -c 'exit %d' returned no error", code) - } - return err - } - t.Run("nil error is exit 0", func(t *testing.T) { code, ok := ExitCodeFromError(nil) if !ok || code != 0 { @@ -100,31 +97,29 @@ func TestExitCodeFromError(t *testing.T) { } }) - t.Run("exit error carries its status", func(t *testing.T) { - code, ok := ExitCodeFromError(realExit(t, 3)) - if !ok || code != 3 { - t.Fatalf("ExitCodeFromError(exit 3) = (%d, %v), want (3, 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("wrapped exit error still resolves", func(t *testing.T) { - code, ok := ExitCodeFromError(fmt.Errorf("running order: %w", realExit(t, 7))) - if !ok || code != 7 { - t.Fatalf("ExitCodeFromError(wrapped exit 7) = (%d, %v), want (7, true)", code, ok) + 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("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("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 the exit status — - // process-group cleanup, most often. Reducing it to the exit code alone + // 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(realExit(t, 1), errors.New("terminating process group: operation not permitted")) + 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) }