activator: say once when the guard holds a host awake
The guard is silent. When it keeps a host resident for an imminent tick the only evidence is the ABSENCE of a hibernate line, which makes "confirm the window change did what we expected" an argument from silence — precisely the check the 15m -> 90s change will need to make positively. One line per host per spell of residency, on the transition rather than every sweep: a held host trips the guard on every pass (every 30s at the default window, every 22s at 90s) and a line per pass would bury what an operator actually reads.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01NbP6qc2gf7BFZkQ8QLcm4C
2 files changed,
+57
−0
internal/activator/activator.go+19 −0internal/activator/activator_test.go+38 −0
CI passed — run details
diff --git a/internal/activator/activator.go b/internal/activator/activator.go| index 426b8c5e9..f4a40eca7 100644 |
| --- a/internal/activator/activator.go |
| +++ b/internal/activator/activator.go |
| @@ -266,6 +266,15 @@ type actEntry struct { |
| inflight int |
| lastActive time.Time |
| + // heldForTick is "the guard is currently keeping this host resident", |
| + // carried across sweeps for one reason: so the log line fires on the |
| + // TRANSITION rather than on every sweep. A held host trips the guard on |
| + // every pass — every 30s at the 15m window, every 22s at 90s — and a line |
| + // per pass per host would bury the events an operator actually reads. |
| + // It is only ever cleared by the entry going away, because the sweep's |
| + // only exit from "held" is the hibernate below it. |
| + heldForTick bool |
| + |
| rep Rep |
| proc Proc |
| @@ -979,6 +988,16 @@ func (a *Service) sweepOnce() { |
| a.beginStopLocked(e) |
| continue |
| } |
| + // Say so, once, when the guard first takes hold. Without this the |
| + // only evidence that the guard is working is the ABSENCE of a |
| + // hibernate line, which makes "confirm the window change did what |
| + // we expected" an argument from silence. One line per host per |
| + // spell of residency is enough to answer it positively. |
| + if !e.heldForTick { |
| + e.heldForTick = true |
| + log.Printf("activator: %s held awake — next scheduled delivery at %s, inside the %s idle window", |
| + e.host, time.Unix(next, 0).UTC().Format(time.RFC3339), a.cfg.Idle) |
| + } |
| // Fall through to the convergence check below: a host held awake |
| // for its schedule never reaches a "next wake" to converge on, so |
| // it is now one of the always-awake hosts that arm was written |
diff --git a/internal/activator/activator_test.go b/internal/activator/activator_test.go| index 5893ae761..019315536 100644 |
| --- a/internal/activator/activator_test.go |
| +++ b/internal/activator/activator_test.go |
| @@ -10,11 +10,13 @@ package activator |
| // dependency must point edge→activator only. |
| import ( |
| + "bytes" |
| "context" |
| "database/sql" |
| "errors" |
| "fmt" |
| "io" |
| + "log" |
| "net" |
| "net/http" |
| "net/http/httptest" |
| @@ -3995,3 +3997,39 @@ func TestChildProcStopClosesTheControlSocketWhenTheChildIsAlreadyGone(t *testing |
| t.Fatalf("control socket after Stop on an exited child: stat err = %v, want it unlinked", err) |
| } |
| } |
| + |
| +// The guard's log line fires on the TRANSITION into "held", not on every |
| +// sweep. A held host trips the guard on every pass — every 30s at the default |
| +// window — so a line per pass would bury the events an operator reads. This |
| +// pins the once-ness, which is the whole reason the entry carries a bool. |
| +func TestGuardLogsHeldOnceNotEverySweep(t *testing.T) { |
| + const host = "chatty.bab.oncarlos.com" |
| + a, _, clk, reg := testActivator(t, 15*time.Minute) |
| + rt := testRoute(host) |
| + arrangeAwake(t, a, rt) |
| + armTimer(t, reg, host, clk.now().Add(21*time.Minute)) |
| + clk.advance(16 * time.Minute) // idle past the window; tick still 5m out |
| + |
| + var buf bytes.Buffer |
| + old := log.Writer() |
| + log.SetOutput(&buf) |
| + defer log.SetOutput(old) |
| + |
| + a.sweepOnce() |
| + a.sweepOnce() |
| + a.sweepOnce() |
| + |
| + if n := strings.Count(buf.String(), "held awake"); n != 1 { |
| + t.Errorf("logged %d held-awake lines over three sweeps, want exactly 1:\n%s", n, buf.String()) |
| + } |
| + a.mu.Lock() |
| + held := a.entries[host] != nil && a.entries[host].heldForTick |
| + a.mu.Unlock() |
| + if !held { |
| + t.Error("entry does not record that it is being held for a tick") |
| + } |
| + // And the host is still resident: the guard did its job, quietly. |
| + if buf.String() != "" && strings.Contains(buf.String(), "hibernating") { |
| + t.Errorf("host hibernated while held:\n%s", buf.String()) |
| + } |
| +} |