fix(orders): record why an exec order failed, and honour informational exit codes

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

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 {

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,
 	})
 }
 

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")
+	}
+}

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
+<bead>`:
+
+```
+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