Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
37 changes: 33 additions & 4 deletions docs/observability.md
Original file line number Diff line number Diff line change
Expand Up @@ -202,11 +202,40 @@ reconcile errors, lifecycle-event timestamps, and repeated gaps before alerting.
Capacity acknowledgement has its own transition signal. While a listener is
accepting a new resource-driven capacity, the pool transition timestamp remains
stable instead of resetting on each heartbeat. `host doctor` treats that state
as healthy for one configured listener request timeout plus two reconciliation
intervals; a transition still pending after that bounded grace is unhealthy.
as healthy for a bounded grace window, and a transition still pending after it
is unhealthy — a non-advisory fault that degrades the exit code, because a
listener that never acknowledges shows sustained, monotonically growing lag.
This reuses the existing schema-version-1 pool `updatedAt` field and does not
change the rollback-readable observed-state shape.

The window is derived from the configured retry policy. An acknowledgement
crosses two request paths — the controller advertising capacity, and a later
reconcile reading back the state that acknowledges it — and each is a complete
retry envelope: up to `github.retry.maxAttempts` attempts, each capped at
`github.requestTimeout`, separated by backoff waits of
`github.retry.maximum` × (1 + `github.retry.jitterRatio`), since jitter is
applied after the backoff base is capped. The window budgets that full envelope
per path, plus two reconciliation intervals.

The acknowledgement is not a protocol signal (the scale-set protocol never
acknowledges capacity back) but this controller's own convergence check, so the
window has to cover the request path convergence actually travels — and it has
to cover all of it, because nothing else in `host doctor` notices a poll that is
still legitimately retrying. While a poll is open the controller keeps writing
observed state on the reconciliation cadence, so the heartbeat stays fresh while
the pool transition timestamp stays deliberately pinned. Budgeting less than the
retry policy therefore hard-faults a listener whose configured retry sequence
has not finished, which is what previously made benign busy-fleet lag trip a
hard fault.

The cost is detection latency, which now scales with the retry policy; raising
`github.retry.maxAttempts` or `github.retry.maximum` widens this window too.
Detection itself is unaffected: a wedged listener never acknowledges, so its lag
grows past any bounded window. This bound is unrelated to the observed-state
freshness limit above — one bounds pending convergence across several
reconciles, the other bounds heartbeat staleness — so neither constrains the
other and the grace is expected to be the larger.

JIT registration, Docker start, validated job start, and finalization record
bounded counters and event timestamps. Registration/start/finalization also
record durations; job start records runner-assignment-to-durable-observation
Expand Down Expand Up @@ -238,8 +267,8 @@ CPU, and both admission gates. Useful alerts include:

- assigned capacity remaining above desired capacity for multiple reconciles;
- advertised capacity at zero while enabled and neither gate is active;
- unacknowledged capacity persisting beyond one listener request timeout plus
two reconciliation intervals;
- unacknowledged capacity persisting beyond the acknowledgement grace window
described above;
- repeated reconcile errors or worker finalization runtime errors;
- sustained resource-gate activation;
- recurring `memory-clamped-capacity` log lines while a `workerMemoryBudget`
Expand Down
30 changes: 19 additions & 11 deletions internal/app/controller_main.go
Original file line number Diff line number Diff line change
Expand Up @@ -387,14 +387,10 @@ const reconcileStepJITBudgetFloorWorkers = 64
// retryable operations per target, multiply by the per-attempt cap and the
// attempt count to upper bound one full sweep.
//
// Each of those backoff waits is not itself capped at bare Retry.Maximum:
// BackoffPolicy.delay (internal/controller/retry.go) applies jitter after
// capping the base delay to Maximum, drawing uniformly from
// [1-JitterRatio, 1+JitterRatio], so a single policy-compliant wait can reach
// Maximum*(1+JitterRatio) — up to nearly 2x Maximum when JitterRatio is at its
// validated ceiling of 1. Every retry-budget calculation below therefore uses
// that jittered worst-case delay (maxJitteredBackoff), not bare Retry.Maximum,
// so a legitimately jittered retry loop can never exceed this deadline.
// Each of those backoff waits is not itself capped at bare Retry.Maximum, so
// every retry-budget calculation below sizes them with maxJitteredBackoff (see
// its doc comment) rather than Retry.Maximum, leaving a legitimately jittered
// retry loop unable to exceed this deadline.
//
// Step's worker-start section also calls CreateJITConfig once per worker it
// starts, each likewise run through RetryValue for up to Retry.MaxAttempts
Expand Down Expand Up @@ -492,9 +488,7 @@ func reconcileStepTimeout(cfg config.Config, effectiveMaxConcurrentWorkers int)
registrationCheckOps := reconcileStepRegistrationCheckOpsPerWorker * staticWorkerCap
totalOps := saturatingAddInt(stepOps, saturatingAddInt(jitOps, saturatingAddInt(retirementOps, registrationCheckOps)))
totalRetryUnits := saturatingMulInt(totalOps, attempts)
maxJitteredBackoff := cfg.GitHub.Retry.Maximum.Duration +
time.Duration(float64(cfg.GitHub.Retry.Maximum.Duration)*cfg.GitHub.Retry.JitterRatio)
perAttemptBudget := cfg.GitHub.RequestTimeout.Duration + maxJitteredBackoff
perAttemptBudget := cfg.GitHub.RequestTimeout.Duration + maxJitteredBackoff(cfg)
retryBudget := saturatingScaleDuration(perAttemptBudget, totalRetryUnits)
githubBudget := saturatingAddDuration(retryBudget, retryBudget/2)
desktopBudget := saturatingAddDuration(
Expand All @@ -509,6 +503,20 @@ func reconcileStepTimeout(cfg config.Config, effectiveMaxConcurrentWorkers int)
return saturatingAddDuration(saturatingAddDuration(githubBudget, desktopBudget), idleConfirmationBudget)
}

// maxJitteredBackoff is the longest single policy-compliant backoff wait a
// GitHub retry loop can take. A wait is not capped at bare Retry.Maximum:
// BackoffPolicy.delay (internal/controller/retry.go) applies jitter AFTER
// capping the base delay to Maximum, drawing uniformly from
// [1-JitterRatio, 1+JitterRatio], so one wait can reach
// Maximum*(1+JitterRatio) — up to nearly 2x Maximum when JitterRatio is at its
// validated ceiling of 1. Any bound that must not expire during a legitimate
// retry sequence therefore has to size its waits from this value, never from
// Retry.Maximum.
func maxJitteredBackoff(cfg config.Config) time.Duration {
return cfg.GitHub.Retry.Maximum.Duration +
time.Duration(float64(cfg.GitHub.Retry.Maximum.Duration)*cfg.GitHub.Retry.JitterRatio)
}

// saturatingMulInt multiplies two non-negative ints, clamping to math.MaxInt
// instead of silently wrapping negative on overflow, mirroring
// internal/controller/reconciler.go's saturatingAddUint64 for the
Expand Down
85 changes: 62 additions & 23 deletions internal/app/doctor.go
Original file line number Diff line number Diff line change
Expand Up @@ -176,17 +176,54 @@ func (a *Application) doctor(ctx context.Context, args []string) int {
return ExitOK
}

// listenerAcknowledgementConvergenceLegs counts the GitHub request paths a
// capacity acknowledgement has to cross before this check can observe it: the
// controller advertising the new capacity, and a later reconcile reading back
// the pool state that acknowledges it.
const listenerAcknowledgementConvergenceLegs = 2

// listenerAcknowledgementGrace bounds how long a pool may sit with capacity
// advertised but unacknowledged before the doctor calls the listener unhealthy.
//
// The acknowledgement is not a protocol signal -- the scale-set protocol never
// acknowledges capacity back -- but this controller's own convergence check, so
// the window has to cover the request path that convergence actually travels.
// Each convergence leg is one full controller.RetryValue envelope: up to
// Retry.MaxAttempts attempts, each capped at RequestTimeout, separated by
// backoff waits sized at maxJitteredBackoff. So the bound is that complete
// envelope per leg, derived from the configured retry policy rather than from
// any observation of how long convergence has happened to take.
//
// It has to be the complete envelope, not a sample of it, because nothing else
// in the doctor notices a poll that is still legitimately retrying: while a poll
// is open, Reconciler.pollCheckpoint keeps writing observed state on the
// reconcile cadence, so the heartbeat stays fresh for observedFreshnessLimit
// while the pool transition timestamp this age measures stays deliberately
// pinned. A window shorter than the retry policy therefore hard-faults a
// listener whose configured retry sequence has not finished -- which is what
// budgeting a single request with no retry allowance did, and what let benign
// busy-fleet lag (2m9s, per the ci-runner-alignment audit's D4 finding) trip a
// hard fault. Deriving from the policy contains that observation with wide
// margin as a consequence, not as the calibration target.
//
// This is a bound on legitimate convergence, so it is unrelated to
// observedFreshnessLimit's bound on heartbeat staleness and carries no
// ordering against it: a transition legitimately spans several reconciles and
// several retry envelopes, while pollCheckpoint refreshes the heartbeat every
// reconcile interval. The cost of the wider window is detection latency, which
// now scales with the configured retry policy. Detection itself is unchanged: a
// wedged listener never acknowledges, so its lag grows monotonically past any
// bounded window and still hard-faults.
func listenerAcknowledgementGrace(cfg config.Config) time.Duration {
const maximum = time.Duration(1<<63 - 1)
reconcile := cfg.Controller.ReconcileInterval.Duration
if reconcile > maximum/2 {
return maximum
}
extra := 2 * reconcile
if cfg.GitHub.RequestTimeout.Duration > maximum-extra {
return maximum
}
return cfg.GitHub.RequestTimeout.Duration + extra
return saturatingFreshnessDuration(
cfg.GitHub.RequestTimeout.Duration,
maxJitteredBackoff(cfg),
cfg.Controller.ReconcileInterval.Duration,
saturatingMulInt(
max(cfg.GitHub.Retry.MaxAttempts, 1),
listenerAcknowledgementConvergenceLegs,
),
)
}

func validPhase(phase model.Phase) bool {
Expand All @@ -204,28 +241,30 @@ func observedFreshnessLimit(cfg config.Config) time.Duration {
cfg.GitHub.RequestTimeout.Duration,
cfg.GitHub.Retry.Maximum.Duration,
cfg.Controller.ReconcileInterval.Duration,
cfg.GitHub.Retry.MaxAttempts,
len(cfg.GitHub.Targets),
saturatingMulInt(
max(cfg.GitHub.Retry.MaxAttempts, 1),
max(len(cfg.GitHub.Targets), 1),
),
)
}

func saturatingFreshnessDuration(request, retryMaximum, reconcile time.Duration, attempts, targets int) time.Duration {
// saturatingFreshnessDuration bounds retryUnits attempts of a retryable GitHub
// request -- each costing request plus one retryBackoff wait -- plus the two
// reconcile intervals a caller needs to observe the result, clamping to the
// largest representable time.Duration instead of overflowing. Callers compose
// retryUnits from their own attempt and repetition counts.
func saturatingFreshnessDuration(request, retryBackoff, reconcile time.Duration, retryUnits int) time.Duration {
const maximum = time.Duration(1<<63 - 1)
attempts = max(attempts, 1)
targets = max(targets, 1)
retryUnits = max(retryUnits, 1)
perAttempt := request
if retryMaximum > maximum-perAttempt {
return maximum
}
perAttempt += retryMaximum
if perAttempt > maximum/time.Duration(attempts) {
if retryBackoff > maximum-perAttempt {
return maximum
}
result := perAttempt * time.Duration(attempts)
if result > maximum/time.Duration(targets) {
perAttempt += retryBackoff
if perAttempt > maximum/time.Duration(retryUnits) {
return maximum
}
result *= time.Duration(targets)
result := perAttempt * time.Duration(retryUnits)
if reconcile > maximum/2 || result > maximum-2*reconcile {
return maximum
}
Expand Down
78 changes: 77 additions & 1 deletion internal/app/doctor_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -261,17 +261,93 @@ func TestObservedFreshnessLimitUsesConfiguredRequestsRetriesAndTargets(t *testin
}
}

func TestListenerAcknowledgementGraceBudgetsAFullRetryEnvelopePerConvergenceLeg(t *testing.T) {
t.Parallel()
cfg := doctorTestConfig()
got := listenerAcknowledgementGrace(cfg)
want := listenerAcknowledgementConvergenceLegs*6*(70*time.Second+time.Minute) + 2*5*time.Second
if got != want {
t.Fatalf("listener acknowledgement grace = %s, want %s", got, want)
}

// Every term of the retry policy has to move the window, because a poll that
// exhausts any of them is still legitimately retrying. Budgeting fewer
// attempts than are configured is what let a benign busy-fleet poll trip a
// hard fault.
for _, test := range []struct {
name string
mutate func(*config.Config)
}{
{name: "more-attempts", mutate: func(c *config.Config) { c.GitHub.Retry.MaxAttempts = 12 }},
{name: "larger-backoff-maximum", mutate: func(c *config.Config) {
c.GitHub.Retry.Maximum = config.Duration{Duration: 2 * time.Minute}
}},
// Jitter is applied after the backoff base is capped at Maximum, so a
// policy-compliant wait can exceed bare Maximum.
{name: "positive-jitter", mutate: func(c *config.Config) { c.GitHub.Retry.JitterRatio = 0.2 }},
{name: "longer-request-timeout", mutate: func(c *config.Config) {
c.GitHub.RequestTimeout = config.Duration{Duration: 2 * time.Minute}
}},
} {
t.Run(test.name, func(t *testing.T) {
t.Parallel()
wider := doctorTestConfig()
test.mutate(&wider)
if widened := listenerAcknowledgementGrace(wider); widened <= got {
t.Fatalf("grace = %s, want more than the baseline %s", widened, got)
}
})
}
}

// A wedged listener never acknowledges, so its lag grows without bound. Widening
// the window delays that verdict; it must not remove it.
func TestListenerAcknowledgementStaysAHardFaultForAWedgedListener(t *testing.T) {
t.Parallel()
now := time.Date(2026, 7, 10, 12, 0, 0, 0, time.UTC)
grace := listenerAcknowledgementGrace(doctorTestConfig())

store := state.NewMemoryStore()
_ = store.SaveDesired(context.Background(), model.DesiredState{SchemaVersion: 1, Mode: model.ModeEnabled, UpdatedAt: now})
observed := healthyDoctorObserved(now, model.PhaseReady)
observed.Pools[0].CapacityAcknowledged = false
observed.Pools[0].UpdatedAt = now.Add(-10 * grace)
_ = store.SaveObserved(context.Background(), observed)

application, out, _ := newTestApplication(t, "", store, nil)
application.dependencies.Config = doctorTestConfig()
application.dependencies.Now = func() time.Time { return now }
application.dependencies.Control = doctorControlFake{status: control.Status{ProcessID: 42, Phase: model.PhaseReady, Version: "1.2.3"}}
application.dependencies.Gaming = fakeGamingHost{inventory: host.GamingInventory{DesktopStatus: host.DesktopStatusRunning, DockerReachable: true}}
application.dependencies.Doctor = &doctorInspectorFake{checks: []DoctorCheck{{Name: "environment", Healthy: true, Detail: "verified"}}}

if code := application.Run(context.Background(), []string{"host", "doctor"}); code != ExitDegraded {
t.Fatalf("doctor exit code = %d, want %d (sustained non-acknowledgement must stay a hard fault)\n%s", code, ExitDegraded, out.String())
}
if !strings.Contains(out.String(), "[FAIL] github-listener/organization") {
t.Fatalf("doctor output missing the listener failure:\n%s", out.String())
}
}

func TestDoctorAllowsOnlyBoundedListenerAcknowledgementTransition(t *testing.T) {
t.Parallel()
now := time.Date(2026, 7, 10, 12, 0, 0, 0, time.UTC)
grace := listenerAcknowledgementGrace(doctorTestConfig())
for _, test := range []struct {
name string
transition time.Time
wantCode int
wantMarker string
}{
{name: "within-grace", transition: now.Add(-15 * time.Second), wantCode: ExitOK, wantMarker: "[PASS] github-listener/organization"},
{name: "past-grace", transition: now.Add(-81 * time.Second), wantCode: ExitDegraded, wantMarker: "[FAIL] github-listener/organization"},
// The one benign busy-fleet acknowledgement lag on record (ci-runner
// alignment audit, D4). It exceeded the old window and degraded the exit
// code; containing it is the whole point of the widened derivation, so it
// is pinned as an absolute case rather than left implied by the boundary
// below.
{name: "benign-busy-fleet-lag", transition: now.Add(-129 * time.Second), wantCode: ExitOK, wantMarker: "[PASS] github-listener/organization"},
{name: "at-grace", transition: now.Add(-grace), wantCode: ExitOK, wantMarker: "[PASS] github-listener/organization"},
{name: "past-grace", transition: now.Add(-grace - time.Second), wantCode: ExitDegraded, wantMarker: "[FAIL] github-listener/organization"},
} {
t.Run(test.name, func(t *testing.T) {
t.Parallel()
Expand Down
Loading