Skip to content

Commit fd38475

Browse files
authored
[DX-5482] fix gap exceeds maxGap on startup (#2854)
1 parent bdc1679 commit fd38475

19 files changed

Lines changed: 950 additions & 100 deletions
Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,3 @@
1+
- `watch` now stamps `ready_at` when its first-observation pass completes, and `check` refuses a `from` before it; single-step `check` declares that startup interval as a blind spot and classifies from the pass completion. A window can no longer open inside the startup pass and surface as a spurious `heartbeat_gap` mid-run.
2+
- The detached recorder and the live poller continue the first-observation pass's schedule instead of drawing fresh phases, and a new startup-handoff budget simulates the poller's first cycles and refuses, before the window, any schedule whose first polls would exceed a rule's `maxGap`.
3+
- Budget errors now name rules by title as well as UID (`"Title" (uid)`) and state the minimum `--concurrency` that would fit.

‎grafana-alertcheck/docs/advanced.md‎

Lines changed: 11 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -18,13 +18,22 @@ The scheduler staggers each rule's initial next-due time across its cadence, and
1818

1919
## The check budget
2020

21-
The gate records one observation of every rule up front and checks the schedule against those **measured** latencies (payload sizes varied ~230× across existing rules, so a fixed estimate would be meaningless). It errors at start — before waiting — if any of three conditions hold:
21+
The gate records one observation of every rule up front and checks the schedule against those **measured** latencies (payload sizes varied ~230× across existing rules, so a fixed estimate would be meaningless). It errors at start — before waiting — if any of four conditions hold:
2222

2323
- **Utilization** — total request rate exceeds `--concurrency`.
2424
- **Per-rule** — one rule's request can't fit its own cadence.
2525
- **Burst bound** — the slowest request exceeds the fleet's tightest cadence, which can open a mid-run gap.
26+
- **Startup handoff** — draining the first-observation pass's backlog at `--concurrency` would leave some rule unpolled past its own `maxGap`. A rule the pass observed early is seeded overdue, and a tight rule observed late can queue behind every rule due before it. The gate simulates the poller's first cycles from the recorded observation times and measured latencies — each wake takes every rule due at that instant, polls the batch at `--concurrency`, and wakes again when it ends — and refuses if any rule's first poll would land past its `maxGap`. Steady-state utilization cannot see this — a long pass at low concurrency is exactly the case it passes.
2627

27-
The error names the three levers only: raise `--concurrency`, raise `--poll-interval`, or watch fewer alerts. It never prescribes a single interval.
28+
The error names only the levers that can fix it: the minimum `--concurrency` when the schedule is concurrency-bound, and `--poll-interval` or a smaller alert set for single-request shapes concurrency cannot shorten. It never prescribes a single interval.
29+
30+
## The startup pass and `ready_at`
31+
32+
Before detaching, `watch` observes every non-paused rule once, sequentially bounded by `--concurrency`. With many alerts and a low concurrency that pass takes real time (120 rules at ~230 ms each and the default concurrency of 1 is ~27 s). The header's `ready_at` stamps the moment the pass completed, and `check` refuses a `from` before it: a window opening inside the pass names observations that do not exist yet, and the earliest rules have no next poll until the detached recorder starts. This is a startup validation, checked from the immutable header before the wait, so a `from` emitted before `watch` returns fails immediately with a named reason instead of surfacing as a heartbeat gap mid-window. Emit `from` only after `watch` returns.
33+
34+
The detached recorder then continues the schedule the first observations were on (each rule's next poll is one cadence after its last recorded observation) rather than drawing fresh phases, so the handoff adds no extra up-to-one-cadence delay to the rules the pass observed first. Continuing the schedule is necessary but not sufficient: the startup-handoff budget above proves the backlog can actually be drained before any rule's `maxGap`, and refuses the run at startup when it cannot.
35+
36+
Single-step `check` runs the same pass itself. It cannot watch before it started, so a `from` inside the pass is a declared blind interval: the run warns, classifies from the pass completion, and the live poller continues the pass's schedule. It never classifies a window that opens before every rule has been observed.
2837

2938
## Why the gate never queries state history
3039

‎grafana-alertcheck/docs/architecture.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -55,7 +55,7 @@ This, plus the declared supported range (Grafana >= 13.0.0, < 14.0.0), is how a
5555

5656
`watch` detaches a background recorder so observation survives the step boundary:
5757

58-
1. Parent resolves the alert set (names or labels), writes the header, observes every non-paused rule once, checks the budget.
58+
1. Parent resolves the alert set (names or labels), observes every non-paused rule once, checks the budget, then writes the header — whose `ReadyAt` stamps the pass completion — and the observations. `ReadyAt` is what `check` uses to refuse a `from` that falls inside the pass.
5959
2. Parent re-execs itself as the child (`--daemon-child`) under a new session/process group, stdout/stderr to the daemon log.
6060
3. Child re-reads the header, reopens the log `O_APPEND`, takes the exclusive `flock`, and writes one readiness byte on `--ready-fd`.
6161
4. Parent writes the pidfile **after** the readiness report, then returns.

‎grafana-alertcheck/docs/index.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -60,7 +60,7 @@ Skip the recorder and observe the window inline, from inside `check` itself:
6060
grafana-alertcheck check --alerts alerts.txt --to "$finished_at"
6161
```
6262

63-
In single-step mode the window starts at `check`'s first observation; if you give no `--from`, the interval before that first observation is declared as a blind spot with a warning (not an error).
63+
In single-step mode the window starts at `check`'s first-observation pass completion; if you give no `--from`, or a `--from` inside the pass, the interval before that point is declared as a blind spot with a warning (not an error).
6464

6565
## Exit codes
6666

‎grafana-alertcheck/docs/reference/cli.md‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -43,7 +43,7 @@ grafana-alertcheck watch --out <file> [--pidfile F] [--daemon-log F] \
4343
| `--concurrency` | `1` | Max concurrent requests to Grafana |
4444
| `--until` | run until signalled | Optional hard stop |
4545

46-
`watch` writes the header, observes every non-paused rule once, checks the budget, then detaches a background recorder and returns. Recording is **unfiltered** — there is no `--states` here, so the same log can be re-classified later under different `--states` without re-recording.
46+
`watch` observes every non-paused rule once, checks the budget, writes the header (with `ready_at` stamped once the observation pass completes) and those observations, then detaches a background recorder and returns. Recording is **unfiltered** — there is no `--states` here, so the same log can be re-classified later under different `--states` without re-recording.
4747

4848
## `stop` — reap the recorder
4949

@@ -92,7 +92,7 @@ grafana-alertcheck check [--in <file>] [--pidfile F] --from RFC3339 --to RFC3339
9292
9393
By default `check` **exits early** on a failure that cannot become a pass: a post-`from` bad onset, or an inability (a heartbeat gap, a sustained `health=error`, a stale evaluation, an in-window pause, an absent rule). This is a latency optimization, not a weaker gate — it never exits `0` early. The one observable difference is that an early exit can report `1` where a full run would have discovered an inability later and reported `2`. `--no-fail-fast` always waits for `to + transitionGrace` and the full coverage proof; the `Result` then carries no `terminated_early` marker. With early exit the JSON result includes `terminated_early` naming the rule, kind, reason and time.
9494
95-
`--from` and `--to` are RFC3339 with an explicit offset and must come from your work — `from` from the deploy step, `to` from the step that finishes. In recorder mode an absent `--from` is a hard error; in single-step mode it falls back (with a warning) to the start of the step.
95+
`--from` and `--to` are RFC3339 with an explicit offset and must come from your work — `from` from the deploy step, `to` from the step that finishes. In recorder mode an absent `--from` is a hard error, and a `from` before the recording's first-observation pass is refused; in single-step mode an absent `from`, or one inside `check`'s own first-observation pass, is a declared blind interval — the window is classified from the pass completion, with a warning.
9696
9797
## Naming alerts
9898

‎grafana-alertcheck/docs/reference/log-format.md‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@ The header must be line 1, appear once, and carry `schema_version` `1` (any othe
3131
"url": "https://grafana.example.com",
3232
"grafana_version": "13.1.0",
3333
"started_at": "2026-09-07T10:00:00Z",
34+
"ready_at": "2026-09-07T10:00:27Z",
3435
"rules": [
3536
{
3637
"uid": "rule0000001",
@@ -49,6 +50,7 @@ The header must be line 1, appear once, and carry `schema_version` `1` (any othe
4950
```
5051

5152
- `url` and `rules` are the log's identity — `check` validates them against the current environment and a fresh ruler read.
53+
- `started_at` is when the recording opened; `ready_at` is when the first-observation pass completed and every watched, non-paused rule had been observed once. The pass is sequential, so `check` refuses a `from` before `ready_at` (a window opening inside the pass would rest on observations that do not exist). `ready_at` is absent on logs written before the field existed; `check` then falls back to `started_at`.
5254
- `is_paused` records the pause state at record start (the moment `paused` means).
5355
- `poll_every_seconds` is the cadence the recording **actually used** (after any `--poll-interval` override). `check` derives `maxGap` from it, never from `interval_seconds`.
5456
- `for_seconds`, `interval_seconds`, `no_data_state`, `exec_err_state` are forensic only — `check` re-resolves definitions and never reads them back.

‎grafana-alertcheck/internal/gate/check.go‎

Lines changed: 49 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -54,9 +54,9 @@ type Config struct {
5454
NoFailFast bool
5555

5656
// From is the moment the deploy finished and To is the end of the work.
57-
// They are different moments and both come from the work. In recorder mode
58-
// an absent From is a hard error; in single-step mode it falls back to the
59-
// start of this step, with a blind-interval warning.
57+
// In recorder mode an absent From is a hard error; in single-step mode it
58+
// falls back to the start of this step, and a From before the
59+
// first-observation pass completes is a declared blind interval.
6060
From, To time.Time
6161

6262
// Log is the path of a recording made by watch; "" selects single-step
@@ -165,7 +165,7 @@ func (cfg Config) validate() error {
165165
return errors.New("check: no `from` in recorder mode: the deploy step must emit a completion timestamp")
166166
case from.IsZero():
167167
// Single-step only. The caller sees the resulting blind interval named
168-
// exactly, once the first observation has fixed its end.
168+
// exactly, once the first-observation pass has fixed its end.
169169
from = now
170170
}
171171

@@ -245,6 +245,14 @@ func check(ctx context.Context, cfg Config, src Source) (Result, error) {
245245
return Result{}, fmt.Errorf("check: `from` %s is before recording started at %s",
246246
from.Format(time.RFC3339), earlyHdr.StartedAt.Format(time.RFC3339))
247247
}
248+
// The pass is sequential, so a `from` inside it names a window
249+
// whose earliest rules were never watched. Knowable from the
250+
// immutable header, so it fails before the wait.
251+
if from.Truncate(time.Second).Before(earlyHdr.ReadyAt.Truncate(time.Second)) {
252+
return Result{}, fmt.Errorf(
253+
"check: `from` %s is inside the recorder's initial observation pass, which completed at %s; emit `from` after `watch` returns (watch observes every watched rule before returning)",
254+
from.Format(time.RFC3339), earlyHdr.ReadyAt.Format(time.RFC3339))
255+
}
248256
}
249257
} else {
250258
resolved, notes, err = resolveAlertSet(allDefs, cfg.namedAlerts(), cfg.IncludeLabels, cfg.ExcludeLabels, cfg.Folder)
@@ -308,35 +316,56 @@ func check(ctx context.Context, cfg Config, src Source) (Result, error) {
308316
// proves that interval, not this timestamp.
309317
startedAt := cfg.Clock.Now()
310318
active := activeRules(resolved)
319+
activeRT := activeTimingsOf(active, rt)
311320
var measured map[string]time.Duration
312321
initial, measured, err = firstObservations(ctx, src, active, reducer, cfg.Concurrency, cfg.Notes)
313322
if err != nil {
314323
return Result{}, err
315324
}
316-
if err := CheckBudget(activeTimingsOf(active, rt), measured, cfg.Concurrency); err != nil {
325+
// The pass is over; the live poller will start from this instant, so
326+
// both budget checks judge the schedule it will actually run.
327+
readyAt := cfg.Clock.Now()
328+
if err := CheckBudget(activeRT, measured, cfg.Concurrency); err != nil {
329+
return Result{}, err
330+
}
331+
// The clamp below is exact, so the window cannot open before readyAt.
332+
if err := CheckStartupHandoff(activeRT, measured, initial, readyAt, readyAt, cfg.Concurrency); err != nil {
317333
return Result{}, err
318334
}
319335

320336
// Single-step synthesis — how the pure layer stays unconditional. The
321337
// shell builds the Header and later stamps the sentinel itself, so the
322338
// sentinel and from-bounds coverage checks run exactly as they do over
323339
// a recording and no mode flag ever reaches proveCoverage or decide.
340+
//
341+
// ReadyAt is the pass completion: single-step cannot watch before it
342+
// started, so a `from` inside the pass is declared blind and the window
343+
// is classified from ReadyAt.
324344
header = Header{
325345
SchemaVersion: LogSchemaVersion,
326346
URL: cfg.URL,
327347
GrafanaVersion: version,
328348
StartedAt: startedAt,
349+
ReadyAt: readyAt,
329350
Rules: loggedRules(resolved, rt),
330351
}
331-
if from.Before(startedAt) {
352+
if from.Before(readyAt) {
332353
// The declared blind interval: in single-step mode this is a
333354
// warning and a pass, and ONLY here. Recorder mode keeps the
334355
// from-bounds coverage check strict, because there the recorder
335356
// was supposed to be watching and the gap means it was not.
336-
fmt.Fprintf(cfg.Notes, "warning: cannot see [%s, %s) — %s before the first observation; the window is classified from %s\n",
337-
from.Format(time.RFC3339), startedAt.Format(time.RFC3339),
338-
startedAt.Sub(from).Round(time.Second), startedAt.Format(time.RFC3339))
339-
from = startedAt
357+
//
358+
// A clamp past `to` leaves no requested window to classify (and an
359+
// inverted window can prove nothing), so fail closed instead.
360+
if !readyAt.Before(cfg.To) {
361+
return Result{}, fmt.Errorf(
362+
"check: the first-observation pass completed at %s, at or after `to` %s: no window remains to classify",
363+
readyAt.Format(time.RFC3339), cfg.To.Format(time.RFC3339))
364+
}
365+
fmt.Fprintf(cfg.Notes, "warning: cannot see [%s, %s) — %s before the first observation pass completed; the window is classified from %s\n",
366+
from.Format(time.RFC3339), readyAt.Format(time.RFC3339),
367+
readyAt.Sub(from).Round(time.Second), readyAt.Format(time.RFC3339))
368+
from = readyAt
340369
}
341370
}
342371

@@ -369,7 +398,7 @@ func check(ctx context.Context, cfg Config, src Source) (Result, error) {
369398
guard terminalCheck
370399
)
371400
if !logHasHdr {
372-
poller = newLivePoller(src, reducer, activeRules(resolved), rt, cfg.Concurrency, cfg.Clock.Now())
401+
poller = newLivePoller(src, reducer, activeRules(resolved), rt, cfg.Concurrency, cfg.Clock.Now(), initial)
373402
}
374403
failFast := !cfg.NoFailFast
375404
if failFast {
@@ -539,19 +568,26 @@ type livePoller struct {
539568
concurrency int
540569
}
541570

571+
// newLivePoller builds single-step mode's collection engine. seed, when
572+
// present, is the measurement pass's observations: the poller continues their
573+
// schedule instead of drawing fresh phases. nil falls back to the fresh stagger.
542574
func newLivePoller(src Source, reducer *Reducer, active []Definition, rt map[string]RuleTimings,
543-
concurrency int, now time.Time) *livePoller {
575+
concurrency int, now time.Time, seed []Poll) *livePoller {
544576

545577
titles := make(map[string]string, len(active))
546578
cadence := make(map[string]time.Duration, len(active))
547579
for _, d := range active {
548580
titles[d.UID] = d.Title
549581
cadence[d.UID] = rt[d.UID].pollEvery
550582
}
583+
sched := NewScheduler(cadence, now)
584+
if len(seed) > 0 {
585+
sched = NewSchedulerFromPolls(cadence, seed, now)
586+
}
551587
return &livePoller{
552588
src: src,
553589
reducer: reducer,
554-
sched: NewScheduler(cadence, now),
590+
sched: sched,
555591
titles: titles,
556592
concurrency: concurrency,
557593
}

0 commit comments

Comments
 (0)