chore: fix logging and std out printing

grafana-alertcheck/cmd/grafana-alertcheck/check.go

@@ -82,7 +82,7 @@ func runCheck(args []string, stdin io.Reader, stdout, stderr io.Writer) int {
 		PidFile:              *pidfile,
 		Concurrency:          *common.concurrency,
 		Clock:                gate.SystemClock{},
-		Notes:                stderr,
+		Notes:                newNoteStyler(stderr),
 	}
 	if *to == "" {
 		fmt.Fprintln(stderr, "check: --to is required")

grafana-alertcheck/cmd/grafana-alertcheck/style.go

@@ -0,0 +1,125 @@
+package main
+
+import (
+	"bytes"
+	"io"
+	"os"
+	"strings"
+)
+
+// ANSI SGR codes for the human-facing notes and table footer. The colours are
+// applied only when the destination is a terminal (see colorEnabled); a pipe,
+// file or CI log gets plain text, so stdout stays reserved for --output json
+// and no machine reader ever sees escape sequences.
+const (
+	ansiReset  = "\x1b[0m"
+	ansiRed    = "\x1b[31m"
+	ansiGreen  = "\x1b[32m"
+	ansiYellow = "\x1b[33m"
+	ansiCyan   = "\x1b[36m"
+	// Orange has no entry in the base-16 palette; 256-colour 208 is a legible
+	// orange used for warnings, distinct from the yellow used for notes.
+	ansiOrange = "\x1b[38;5;208m"
+)
+
+// colorEnabled reports whether ANSI colour should be written to w. Colour is
+// written only when three things hold: NO_COLOR is unset, w is a real *os.File
+// (so text/tabwriter buffers, strings.Builder and bytes.Buffer tests all stay
+// plain), and that file is a character device (a terminal, not a redirect).
+func colorEnabled(w io.Writer) bool {
+	if os.Getenv("NO_COLOR") != "" {
+		return false
+	}
+	f, ok := w.(*os.File)
+	if !ok {
+		return false
+	}
+	fi, err := f.Stat()
+	if err != nil {
+		return false
+	}
+	return fi.Mode()&os.ModeCharDevice != 0
+}
+
+// styleLine applies the note vocabulary's colour to one line when enabled. The
+// colour wraps the text only; the terminating newline is written uncoloured so
+// the terminal's line discipline is never inside the escape sequence.
+func styleLine(line string, enabled bool) string {
+	if !enabled {
+		return line
+	}
+	content := strings.TrimRight(line, "\n")
+	var color string
+	switch {
+	case strings.HasPrefix(content, "warning:"):
+		color = ansiOrange
+	case strings.HasPrefix(content, "note:"):
+		color = ansiYellow
+	case strings.HasPrefix(content, "drain wait:"):
+		color = ansiCyan
+	}
+	if color == "" {
+		return line
+	}
+	return color + content + ansiReset + "\n"
+}
+
+// noteStyler wraps the gate package's Notes stream — a presentation seam that
+// keeps colour out of the library. It colourises each line by its known prefix
+// and separates the collection countdown from the setup phase with a single
+// blank line before the first "collecting:" line. The gate keeps emitting plain
+// prose; only the CLI lays it out.
+type noteStyler struct {
+	w             io.Writer
+	enabled       bool
+	pending       []byte
+	sawCollecting bool
+}
+
+func newNoteStyler(w io.Writer) *noteStyler {
+	return &noteStyler{w: w, enabled: colorEnabled(w)}
+}
+
+// startsSection reports whether a line opens a new phase of the stream and so
+// deserves a blank line above it. "collecting:" opens the countdown (once —
+// later countdown lines follow on from the first), and "drain wait:" opens the
+// drain phase. The setup lines (planned run time, warning, min-observed, notes)
+// are one contiguous block and are not separated from each other.
+func (s *noteStyler) startsSection(line string) bool {
+	switch {
+	case strings.HasPrefix(line, "warning:"):
+		return true
+	case strings.HasPrefix(line, "drain wait:"):
+		return true
+	case strings.HasPrefix(line, "collecting:"):
+		if s.sawCollecting {
+			return false
+		}
+		s.sawCollecting = true
+		return true
+	}
+	return false
+}
+
+func (s *noteStyler) Write(p []byte) (int, error) {
+	n := len(p)
+	s.pending = append(s.pending, p...)
+	for {
+		i := bytes.IndexByte(s.pending, '\n')
+		if i < 0 {
+			break
+		}
+		line := string(s.pending[:i+1])
+		s.pending = s.pending[i+1:]
+
+		if s.startsSection(line) {
+			if _, err := io.WriteString(s.w, "\n"); err != nil {
+				return n, err
+			}
+		}
+		if _, err := io.WriteString(s.w, styleLine(line, s.enabled)); err != nil {
+			return n, err
+		}
+	}
+	return n, nil
+}

grafana-alertcheck/cmd/grafana-alertcheck/table.go

@@ -14,29 +14,39 @@ import (
 // which the caller (runCheck) always points at stderr — stdout is reserved for
 // the machine-readable --output json.
 //
-// Three sections, in order:
+// Three titled tables, in order (the name column is RULE in all of them — one
+// row is one resolved alert rule, never a firing instance):
 //
-//  1. one line per rule: outcome, BadFor, pollEvery, proved-or-not with the
-//     largest gap;
-//  2. one line per Violation: a rule's worst-of outcome does not carry the
-//     State/Health of the instance that actually caused it — Violation does —
-//     so this is also where those two columns appear, sorted after the rule
-//     table rather than folded into it, and it is the only place an operator
-//     running WITHOUT --output json sees the --allow-paused hint that
-//     Violation.Note already carries (classify.go);
-//  3. a footer with the numbers that answer "why" on exit 2: each non-skipped
-//     rule's maxGap/healthGrace/evalStaleAfter, the global transitionGrace and
-//     drainTimeout, and the largest measured clock skew alongside its own
-//     error bound (RTT/2) — SkewHardLimit is a separate, fixed input threshold
-//     and is reported next to it, never as if it were that bound.
+//  1. RESULTS, one line per rule: outcome, BadFor, pollEvery, proved-or-not
+//     with the largest gap;
+//  2. VIOLATIONS, one line per Violation (only when any): a rule's worst-of
+//     outcome does not carry the State/Health of the instance that actually
+//     caused it — Violation does — so this is also where those two columns
+//     appear, sorted after the result table rather than folded into it, and it
+//     is the only place an operator running WITHOUT --output json sees the
+//     --allow-paused hint that Violation.Note already carries (classify.go);
+//  3. THRESHOLDS, the numbers that answer "why" on exit 2: each non-skipped
+//     rule's maxGap/healthGrace/evalStaleAfter, followed by the global
+//     transitionGrace and drainTimeout, and the largest measured clock skew
+//     alongside its own error bound (RTT/2) — SkewHardLimit is a separate,
+//     fixed input threshold and is reported next to it, never as if it were
+//     that bound.
 func renderTable(w io.Writer, res gate.Result) error {
 	alertOf := make(map[string]string, len(res.Verdicts))
 	for _, v := range res.Verdicts {
 		alertOf[v.RuleUID] = v.Alert
 	}
 
+	enabled := colorEnabled(w)
+	// A blank line separates the result table from the notes the gate streamed
+	// before it (planned run time, warning, min-observed, collecting, drain
+	// wait), so the verdict reads as its own section rather than the tail of a
+	// wall of progress text.
+	fmt.Fprintln(w)
+
+	fmt.Fprintln(w, "RESULTS")
 	tw := tabwriter.NewWriter(w, 0, 4, 2, ' ', 0)
-	fmt.Fprintln(tw, "ALERT\tOUTCOME\tBADFOR\tPOLLEVERY\tPROVED\tNOTE")
+	fmt.Fprintln(tw, "RULE\tOUTCOME\tBADFOR\tPOLLEVERY\tPROVED\tNOTE")
 	for _, v := range sortedVerdicts(res.Verdicts) {
 		fmt.Fprintf(tw, "%s\t%s\t%s\t%s\t%s\t%s\n",
 			v.Alert, v.Outcome, v.BadFor.Round(time.Second), v.PollEvery.Round(time.Second),
@@ -49,7 +59,7 @@ func renderTable(w io.Writer, res gate.Result) error {
 	if len(res.Violations) > 0 {
 		fmt.Fprintln(w, "\nVIOLATIONS")
 		vtw := tabwriter.NewWriter(w, 0, 4, 2, ' ', 0)
-		fmt.Fprintln(vtw, "ALERT\tOUTCOME\tSTATE\tHEALTH\tNOTE")
+		fmt.Fprintln(vtw, "RULE\tOUTCOME\tSTATE\tHEALTH\tNOTE")
 		for _, v := range sortedViolations(res.Violations) {
 			fmt.Fprintf(vtw, "%s\t%s\t%s\t%s\t%s\n", alertLabel(v, alertOf), v.Outcome, v.State, v.Health, v.Note)
 		}
@@ -58,20 +68,49 @@ func renderTable(w io.Writer, res gate.Result) error {
 		}
 	}
 
+	// The per-rule thresholds answer "why" on exit 2: a table, not the prose
+	// "rule NAME: maxGap=... healthGrace=... evalStaleAfter=..." that repeated
+	// the rule name a fourth time. It is separated from the result above by a
+	// blank line.
 	fmt.Fprintln(w)
+	fmt.Fprintln(w, "THRESHOLDS")
+	ttw := tabwriter.NewWriter(w, 0, 4, 2, ' ', 0)
+	fmt.Fprintln(ttw, "RULE\tMAXGAP\tHEALTHGRACE\tEVALSTALEAFTER")
 	for _, uid := range sortedThresholdUIDs(res.Thresholds, alertOf) {
 		t := res.Thresholds[uid]
-		fmt.Fprintf(w, "rule %s: maxGap=%s healthGrace=%s evalStaleAfter=%s\n",
+		fmt.Fprintf(ttw, "%s\t%s\t%s\t%s\n",
 			alertOr(uid, alertOf), t.MaxGap, t.HealthGrace, t.EvalStaleAfter)
 	}
+	if err := ttw.Flush(); err != nil {
+		return fmt.Errorf("render table: %w", err)
+	}
+
+	fmt.Fprintln(w)
 	fmt.Fprintf(w, "global: transitionGrace=%s (source: %s) drainTimeout=%s\n",
 		res.Global.TransitionGrace, res.Global.GraceSource, res.Global.DrainTimeout)
-	fmt.Fprintf(w, "violations: %d, largest measured clock skew: %s (bound ±%s, hard limit %s), grafana %s\n",
-		len(res.Violations), res.ClockSkew.Round(time.Millisecond), res.ClockSkewBound.Round(time.Millisecond),
+	fmt.Fprintf(w, "largest measured clock skew: %s (bound ±%s, hard limit %s), grafana %s\n",
+		res.ClockSkew.Round(time.Millisecond), res.ClockSkewBound.Round(time.Millisecond),
 		gate.SkewHardLimit, res.GrafanaVersion)
+	// The verdict — the single number a terminal operator reads last — sits on
+	// its own line at the very bottom, separated from the diagnostics above and
+	// from the shell prompt below.
+	fmt.Fprintf(w, "\n%s\n\n", violationsLabel(len(res.Violations), enabled))
 	return nil
 }
 
+// violationsLabel colours the "violations: N" prefix of the footer: green for a
+// clean run, red otherwise. The rest of the line is written uncoloured.
+func violationsLabel(n int, enabled bool) string {
+	s := fmt.Sprintf("violations: %d", n)
+	if !enabled {
+		return s
+	}
+	if n == 0 {
+		return ansiGreen + s + ansiReset
+	}
+	return ansiRed + s + ansiReset
+}
+
 // provedLabel is the table's PROVED column: "yes" for a clean coverage
 // proof, "no" with the reason and largest gap for an unobservable rule, and
 // "-" for a rule decide never asked proveCoverage about at all (skipped —

grafana-alertcheck/cmd/grafana-alertcheck/table_test.go

@@ -67,11 +67,13 @@ func TestRenderTable(t *testing.T) {
 	require.Contains(t, out, string(gate.StateFiring))
 	require.Contains(t, out, "error")
 
-	// The footer: per-rule thresholds, global thresholds, and skew with its own
-	// bound rather than the fixed hard limit.
-	require.Contains(t, out, "Ape Alert: maxGap=1m0s healthGrace=2m0s evalStaleAfter=1m0s")
-	require.Contains(t, out, "Zebra Alert: maxGap=1m0s healthGrace=1m0s evalStaleAfter=1m0s")
-	require.NotContains(t, out, "Paused Alert: maxGap")
+	// The footer: per-rule thresholds are a table (RULE/MAXGAP/HEALTHGRACE/
+	// EVALSTALEAFTER) rather than prose, followed by the global thresholds and
+	// the violations count with the skew and its own bound rather than the
+	// fixed hard limit.
+	require.Contains(t, out, "MAXGAP")
+	require.Contains(t, out, "HEALTHGRACE")
+	require.Contains(t, out, "EVALSTALEAFTER")
 	require.Contains(t, out, "global: transitionGrace=5m0s (source: Ape Alert (for=5m)) drainTimeout=2m0s")
 	require.Contains(t, out, "largest measured clock skew: 1.5s (bound ±250ms, hard limit 1m0s)")
 	require.Contains(t, out, "violations: 2")

grafana-alertcheck/cmd/grafana-alertcheck/watch.go

@@ -78,7 +78,7 @@ func runWatch(args []string, stdin io.Reader, stdout, stderr io.Writer) int {
 		DaemonLog:   *daemonLog,
 		Concurrency: *common.concurrency,
 		Clock:       gate.SystemClock{},
-		Notes:       stderr,
+		Notes:       newNoteStyler(stderr),
 	}
 	if *until != "" {
 		t, err := time.Parse(time.RFC3339, *until)

grafana-alertcheck/internal/gate/check.go

@@ -245,9 +245,9 @@ func check(ctx context.Context, cfg Config, src Source) (Result, error) {
 		// closed, never produce a false pass. This is recorder mode only: the
 		// single-step branch has no header, and its own `from < startedAt` is
 		// a warning-and-pass (see below), not an error.
-		if from.Before(earlyHdr.StartedAt) {
+		if from.Truncate(time.Second).Before(earlyHdr.StartedAt.Truncate(time.Second)) {
 			return Result{}, fmt.Errorf("check: `from` %s is before recording started at %s",
-				from.Format(time.RFC3339), earlyHdr.StartedAt.Format(time.RFC3339))
+				from.Format(time.RFC3339Nano), earlyHdr.StartedAt.Format(time.RFC3339Nano))
 		}
 		resolved, notes, err = resolveFromLog(allDefs, earlyHdr, cfg)
 	} else {
@@ -284,6 +284,16 @@ func check(ctx context.Context, cfg Config, src Source) (Result, error) {
 	}
 	summary, warning := StartupSummary(from, cfg.To, gt)
 	fmt.Fprintln(cfg.Notes, summary)
+	// MinObserved is printed with the plan, beside "planned run time", rather
+	// than after it: it is a fact about the run, not a diagnostic. Its default
+	// is the resolved rule count AFTER duplicate names collapse, which is
+	// len(resolved) by construction; decide defaults it identically, and it is
+	// resolved here rather than inferred from the verdict afterwards.
+	minObserved := cfg.MinObserved
+	if minObserved == 0 {
+		minObserved = len(resolved)
+	}
+	fmt.Fprintf(cfg.Notes, "min-observed: %d of %d resolved rule(s)\n", minObserved, len(resolved))
 	if warning != "" {
 		fmt.Fprintf(cfg.Notes, "warning: %s\n", warning)
 	}
@@ -334,17 +344,6 @@ func check(ctx context.Context, cfg Config, src Source) (Result, error) {
 		}
 	}
 
-	// ---- Apply MinObserved. -----------------------------------------------
-	// Its default is the resolved rule count AFTER duplicate names collapse,
-	// which is len(resolved) by construction. decide defaults it identically;
-	// it is resolved here as well so the value the run will judge against is
-	// printed before the wait rather than inferred from the verdict afterwards.
-	minObserved := cfg.MinObserved
-	if minObserved == 0 {
-		minObserved = len(resolved)
-	}
-	fmt.Fprintf(cfg.Notes, "min-observed: %d of %d resolved rule(s)\n", minObserved, len(resolved))
-
 	// ---- Collect the evidence. --------------------------------------------
 	// Collect ONLY. No classification happens here and there is no early exit,
 	// even once a violation is certain: the loop always runs to

grafana-alertcheck/internal/gate/check_test.go

@@ -657,6 +657,32 @@ func TestCheckFailFastWhenFromPrecedesRecordStart(t *testing.T) {
 	require.True(t, clock.Now().Equal(testNow), "it must fail before the wait")
 }
 
+// A whole-second `from` in the same second as the recording's sub-second
+// StartedAt is not a blind interval: the whole-second comparison lets the run
+// proceed to a clean pass instead of the fail-fast above.
+func TestCheckRecorderModeFromSameSecondAsStartedAtPasses(t *testing.T) {
+	dir := t.TempDir()
+	windowEnd := testNow.Add(5*time.Minute + checkGrace)
+	// StartedAt is 500ms after `from` (testNow via recorderConfig) — the same
+	// whole second. Polls still cover the whole window.
+	logPath := recordedLog(t, dir, "https://grafana.example.com",
+		testNow.Add(500*time.Millisecond), testNow.Add(-time.Minute), windowEnd.Add(30*time.Second), windowEnd.Add(30*time.Second), 0)
+	writePid(t, logPath+".pid", fmt.Sprintf("%d\n", deadPid(t)))
+
+	clock := newVirtualClock(testNow.Add(time.Minute))
+	cfg := recorderConfig(t, clock, logPath)
+	src := newCheckSource(func(title string, _ int) (Observation, error) {
+		require.Fail(t, fmt.Sprintf("the drain wait polled %q although the log already proves the evaluations", title))
+		return Observation{}, errors.New("unexpected poll")
+	})
+
+	res, err := check(context.Background(), cfg, src)
+	require.NoError(t, err)
+	require.Empty(t, res.Violations)
+	require.Len(t, res.Verdicts, 1)
+	require.Equal(t, OutcomeClean, res.Verdicts[0].Outcome)
+}
+
 // The coverage proof failed: a hole in the middle of the recording is not
 // saved by healthy data at both ends.
 func TestCheckFailClosedOnCoverageGap(t *testing.T) {

grafana-alertcheck/internal/gate/coverage.go

@@ -87,12 +87,16 @@ func proveCoverage(h Header, polls []Poll, sentinel *time.Time, t ruleTimings, d
 	// Check 2 — from bounds: from < StartedAt makes coverage unprovable, no
 	// matter how healthy the polls that DO exist look. Both are runner-domain
 	// clock reads (the recorder's own Clock.Now()), so no cross-domain
-	// translation applies here. The other half of the bound — from too far
-	// ahead of the runner's clock — is Check's input validation, once per run
-	// rather than per rule.
-	if from.Before(h.StartedAt) {
+	// translation applies here. The comparison is at whole-second granularity:
+	// `from` is supplied at second precision (--from RFC3339) while StartedAt
+	// carries the recorder's sub-second clock stamp, so an operator naming the
+	// exact second the recording opened must not be judged early for the
+	// sub-second sliver inside that same second. The other half of the bound —
+	// from too far ahead of the runner's clock — is Check's input validation,
+	// once per run rather than per rule.
+	if from.Truncate(time.Second).Before(h.StartedAt.Truncate(time.Second)) {
 		fail(ReasonFromBeforeRecord, fmt.Sprintf(
-			"requested from %s is before recording started at %s", from.Format(time.RFC3339), h.StartedAt.Format(time.RFC3339)))
+			"requested from %s is before recording started at %s", from.Format(time.RFC3339Nano), h.StartedAt.Format(time.RFC3339Nano)))
 	}
 
 	// Filtered once and threaded through every remaining check.