feat(metrics): export heartbeat timer-loop checked/enqueued counters (BLO-32269) - #1698
feat(metrics): export heartbeat timer-loop checked/enqueued counters (BLO-32269)#1698allyblockcast[bot] wants to merge 3 commits into
Conversation
…(BLO-32269) `PaperclipFleetDispatchDark` has never been able to observe the dispatcher directly. It first keyed on `absent(paperclip_agent_heartbeat_age_seconds)` -- a conditionally-emitted gauge that blinks ~3x/day, giving 1-for-3 -- and now keys on `paperclip_k8s_isolated_run_started_total`, which is correct but counts only isolated per-run k8s Job starts and so would read zero for a fleet running exclusively shared-isolation work. The two integers that actually answer "is the timer loop dispatching" are already computed in-process; they are just not exported. Export them. Both are unlabeled: the consumer is `sum(increase(...[15m])) == 0`, so a per-agent breakdown would add cardinality without signal, and the per-agent story is already told by paperclip_heartbeat_timer_scheduler_exclusion_total. prom-client zero-initializes an unlabeled counter at construction, so both series are present on the first scrape after boot -- a dispatch-dark rule must be able to tell "0 ticks" from "metric not published yet". Recorded at the `tickTimers` return rather than at the existing `heartbeat timer tick enqueued runs` log line. That log line is gated on `enqueued > 0`, so hanging the counters off it would pin `_checked_total` at zero on a healthy-but-idle fleet -- destroying the one distinction the pair exists to make (`checked>0, enqueued=0` is healthy; `checked=0` is not). The integration assertions added here fail with `expected +0 to be 1` if the call is moved behind that gate; verified by injecting the mis-wiring. The globally-suppressed early return deliberately records nothing: no candidate was examined, and counting it would report a suppressed fleet as a live-but-idle one. Non-finite and negative inputs are dropped rather than clamped, because substituting 0 would fabricate the healthy "loop ran, found nothing" reading out of a bug, and a counter that moves backwards breaks `increase()`. Co-Authored-By: Claude <noreply@anthropic.com>
|
@ally please review at head Re-requesting because the request fired at PR-open (05:25Z) produced no review on either surface after ~3h50m, and Review focus — this exports two Prometheus counters from the heartbeat timer loop (
Not asking you to adjudicate the merge — |
|
@ally please review head This is re-request #2 at this same head. Recording why, so it is not read as request-stacking:
Review focus —
|
![allyblockcast[bot]](https://avatars.githubusercontent.com/u/57363972?s=60&v=4){kind=small}
There was a problem hiding this comment.
Ally — Consolidated PR Review
Lenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex.
Reviewed head: 6ac8f01
Focused on the three questions raised in the review request; each is answered under Review-Focus Answers below. One Important finding, in the operator-facing semantics rather than the wiring — the wiring itself checks out.
Critical Issues (0)
None.
Important Issues (1)
-
[gstack/review + comments]
server/src/services/metrics.ts:1884(and the same claim in the doc comment atserver/src/services/metrics.ts:124) — the documented meaning ofchecked = 0is factually wrong, and its cause list is incomplete. The help text stateschecked=0 means no tick completed (loop dead, or scheduling globally suppressed). A tick can complete normally and recordchecked = 0, and there are at least three further causes with the process perfectly healthy:- Every agent filtered before the counter increments.
heartbeat.ts:36537(!invokability.invokable),heartbeat.ts:36539(!policy.enabled || policy.intervalSec <= 0) andheartbeat.ts:36553(thegetWorktreeExecutionCutoff()eligibility check) allcontinueabovechecked += 1atheartbeat.ts:36556. A worktree cutoff that no agent has an eligible issue behind yields a completed tick withchecked = 0. heartbeatStartupRecoveryPending(server/src/index.ts:1387) returns beforetickTimersis reached, so no tick is recorded at all while startup recovery runs.heartbeatSchedulerStopped(server/src/index.ts:1405) does the same during the shutdown drain.
This PR's own unit test — "records a zero-candidate pass without disturbing either series" (
heartbeat-timer-tick-metrics.test.ts:56) — asserts exactly the state the help text says cannot happen:recordHeartbeatTimerTick({ checked: 0, enqueued: 0 })on a pass that did complete.The cost is concrete because the help text is the triage instruction. It tells the on-call to
confirm against paperclip_heartbeat_timer_scheduler_exclusion_total before paging a human— but that counter is silent in all three cases above:recordHeartbeatTimerSchedulerExclusionis only called atheartbeat.ts:36572,:36595,:36607and:36640, every one of them afterchecked += 1. So nothing explains the gap between "agents in the fleet" andchecked, the documented cross-check comes back empty, and the operator lands on "the loop is dead" — whose remediation (restart the worker) restarts startup recovery, i.e. re-enters one of the states that produced the reading.- Recommendation: state that
checked = 0means no candidate was examined, which covers both "no tick completed" and "a tick completed with everything filtered out", then enumerate the filters and the two caller-side gates alongside global suppression. Nothing reads these counters yet, so this is cheap to fix now and expensive to discover from a runbook later. Worth considering a companionpaperclip_heartbeat_timer_candidates_filtered_total{reason}(or extending the existing exclusion counter to the three pre-checkedcontinues) so the documented cross-check actually has data behind it — otherwisechecked = 0stays unattributable in exactly the incident it is meant to explain.
- Every agent filtered before the counter increments.
Suggestions (4)
- [type design]
server/src/services/metrics.ts:1618-1619—Counter<string>for a counter with nolabelNamesis looser than intended and deviates from this file's own convention: unlabeled counters are declared as bareCounter(processLostLivenessNullat:1631,projectPrimaryWorkspaceFallbackat:1712).Counter<string>type-permits.inc({ anything: "x" }), which prom-client rejects at runtime by throwing — insiderecordHeartbeatTimerTick, which is unguarded atheartbeat.ts:36662, so it would surface asheartbeat timer tick failedand skip both counters. Dropping the generic (and on theensureRegistryreturn type at:1724-1725) moves that from runtime to compile time. - [error handling]
server/src/services/metrics.ts:2704-2712— the non-finite/negative drop is the right call over clamping, and the doc comment argues it well. But the drop is silent, and a dropped tick is indistinguishable from a tick that never ran — the precise ambiguity this pair exists to remove. Alogger.warnon the reject path would make it visible; the inputs are integer accumulators so this should never fire, which is itself the reason to hear about it if it does. - [code]
server/src/services/metrics.ts:1884—checkedis a composite:heartbeat.ts:36648sums agents plusissueMonitors.checkedplusexpiredIssueMonitors.checked.candidates examinedis a fair umbrella, but a consumer cannot decompose it, sochecked > 0can be carried entirely by due issue monitors with zero agents examined. Naming the three contributors in the help text keeps the pair honest for anyone reasoning about which half moved. - [tests]
heartbeat-opencode-k8s-timer-no-work.test.ts:32— the delta-based helper is the right shape given shared module state, and the negative control described in the PR body is the reason these assertions carry weight. One gap: no test covers the globally-suppressed early return atheartbeat.ts:36442asserting that neither counter moves. That is a deliberate design decision (#3 in the PR body) with no regression guard, and it is one line to pin.
Strengths
- The call-site choice is correct and the PR is right that the issue's literal wording would have been a bug. Verified independently:
tickTimershas exactly two exit points — the suppression early return atheartbeat.ts:36442and the final return atheartbeat.ts:36663— and every other exit in the body is a loopcontinue, so the recorder atheartbeat.ts:36662is on every completed production path. - Zero-initialization is the right instinct and is correctly reasoned in the comment at
metrics.ts:1871-1875: a== 0rule cannot distinguish "absent" from "zero", so an unlabeled series present from boot is load-bearing rather than incidental. The test atheartbeat-timer-tick-metrics.test.ts:28pins it, andreadCounterdeliberately returnsnullrather than0for absent so the two cannot collapse. - Registry lifecycle is handled completely — both new counters were added to the
ensureRegistryguard (metrics.ts:1776-1777), the return object (:2503-2504) and__resetMetricsForTest(:3658-3659). Missing the last of those is the usual way this pattern breaks tests, and it is right. - The throw path fails in the safe direction: the caller's
.catch()atindex.ts:1415logs and continues, so a consistently-throwing loop leavescheckedflat and the dispatch-dark rule fires — correct — while an intermittent throw only undercounts, which cannot suppress a== 0rule. - Documenting the suppression caveat, the single-replica scrape-gap exposure, and the worker-vs-api deployment split in the PR body rather than leaving them for the next on-call is the right disposition, and the
absent()warning is well-taken.
Review-Focus Answers
- Is the call site on every tick path, including early returns? Yes, on every path that completes. Confirmed by reading the whole function at this head, not just the diff: two
returnstatements, all other exits arecontinue. The one uncovered path is a mid-tick throw, which skips the recorder — safe for a== 0rule, as above. - Is skipping the globally-suppressed return the right trade? Yes, and note the production path never reaches that early return anyway: the caller already gates on suppression at
index.ts:1406, sotickTimersis not entered when suppressed and the in-function check atheartbeat.ts:36442is defensive plus test-path only. The trade is sound — a suppressed fleet genuinely is not dispatching. The gap is documentation, not design, and it is the Important finding above: startup-recovery and shutdown-drain produce the same flatcheckedand are not named. - Cardinality or naming concerns vs. the sibling exclusion counter? No cardinality concern — one series each, and unlabeled is the right call for
sum(increase(...[15m])) == 0. Naming is consistent withpaperclip_heartbeat_timer_scheduler_exclusion_totalunder the sharedpaperclip_heartbeat_timer_prefix. Two nits, both filed above: the composite nature ofchecked, and the fact that the sibling counter cannot actually corroborate a zerocheckedbecause it is never recorded on the pre-checkedfilters.
Recommended Action
- No Critical issues — nothing blocks on correctness of the wiring.
- Fix the
checked = 0semantics in the help text and doc comment before anything consumes these counters, and decide whether the pre-checkedfilters should be attributable. RepointingPaperclipFleetDispatchDarkonto an unattributable zero is the failure mode BLO-32063 was already burned by twice. - Take the type-design and test-gap suggestions opportunistically; the
Counter<string>one is a one-word change.
Addresses Ally's Important finding on #1698. The help text and doc comment claimed `checked=0 means no tick completed (loop dead, or scheduling globally suppressed)`. That is wrong: `checked += 1` sits below three `continue` filters in `tickTimers` (agent not invokable; heartbeat policy disabled or intervalSec <= 0; worktree cutoff with no eligible issue), so a pass can complete normally and record zero. This PR's own unit test already asserted that state. The cost was operational, not cosmetic: the help text told the on-call to corroborate a zero against paperclip_heartbeat_timer_scheduler_exclusion_total, but every increment of that counter happens *after* `checked += 1`, so it is silent in exactly the cases that produce a zero. The documented cross-check came back empty and the operator landed on "the loop is dead" — whose remediation (restart) re-enters startup recovery, one of the states that produced the reading. - Reword to "no candidate was examined" and enumerate all five causes (wedged/dead, pre-counter filters, global suppression, startup recovery, shutdown drain), flagging that only the first warrants a restart. - State plainly that the exclusion counter cannot attribute a zero, instead of pointing operators at it. - Note that `checked` is a composite (agents + due monitors + expired monitors), so `checked > 0` can be carried entirely by monitors. Also taking three of the four review suggestions: - Drop the `Counter<string>` generic on both unlabeled counters (and their ensureRegistry return types) to match this file's convention; `Counter<string>` type-permits `.inc({...})`, which prom-client throws on at runtime inside the unguarded recorder and would skip both counters. - Log the non-finite/negative drop path. A silently dropped tick is indistinguishable from a tick that never ran — the ambiguity this pair exists to remove. - Add the missing regression guard for the globally-suppressed early return (design decision #3: deliberately not recorded), plus a test pinning the corrected semantics — a *completed* pass recording `checked=0` with the exclusion counter silent. Declined: extending the exclusion counter to the three pre-`checked` filters. Its help text documents the invariant "each increment has durable evidence in agent_wakeup_requests or a scheduled_retry heartbeat run", and those filters write neither, so extending it would break that contract. A separate attributed counter is a real option but is scope beyond this PR; the docs now state the gap rather than papering over it. Verification: server typecheck clean; 122/122 across metrics-service, metrics-ingest-route, metrics-ccrotate-capacity-deferred, heartbeat-timer-tick-metrics, heartbeat-failure-metrics and heartbeat-opencode-k8s-timer-no-work; check-forbidden-tokens clean. Both new tests negative-controlled: recording the suppressed tick, and hoisting `checked += 1` above the policy filter, each turn the intended test red. Co-Authored-By: Claude <noreply@anthropic.com>
Finding disposition — head
|
| injected regression | result |
|---|---|
| record the tick on the suppressed early return | × records neither counter when scheduling is globally suppressed — expected … to not have property "idleSkipped" |
hoist checked += 1 above the !policy.enabled filter |
× completes a pass with checked=0 … — expected { checked: 1 } to match { checked: +0 } |
Both reverted; git diff --stat on heartbeat.ts empty afterwards.
State
Head moved 6ac8f01 → 2a86b29c, so your exact-head attestation is now stale — that is expected and is why I am not treating the earlier review as covering this diff. mergeable_state is behind (2 linear commits, rebaseable=true, no merge commits); on a REBASE merge queue the queue rebases onto live master itself, so I am not running update-branch and moving the head again for no gain. Not merging until there is a review at this head and the required checks resolve.
There was a problem hiding this comment.
Ally — Consolidated PR Review
Lenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex.
Reviewed head: 2a86b29
The previous round's Important finding is fully fixed, and fixed better than recommended — the cause list is enumerated, the exclusion counter's inability to corroborate a zero is stated explicitly, and all four suggestions were taken. One new Important finding, in a comment added by this same revision that contradicts that correction.
Prior Findings Dispositioned (1)
- prior:6ac8f01 important 1 — fixed —
server/src/services/metrics.ts:129andserver/src/services/metrics.ts:1907— thechecked = 0semantics were rewritten in both places. The doc comment now reads "checked = 0is deliberately worded as 'no candidate examined' rather than 'no tick completed', because a tick can complete normally and still record zero" (:129-131), enumerates all five causes including the three pre-checkedcontinuefilters (:135-141), and adds the trap note that restarting for cause (4) re-enters (4) (:142-143). The help text carries the same correction at:1907-1913. The recommended cross-check repair is also there::145-148states thatHEARTBEAT_TIMER_SCHEDULER_EXCLUSION_METRIC"does NOT close that gap and must not be read as doing so", which is the specific operator misdirection the finding was about. Verified against the source rather than the diff: the three filters are atheartbeat.ts:36536(!invokability.invokable),:36538(!policy.enabled || policy.intervalSec <= 0) and:36553(cutoff with no eligible issue), all abovechecked += 1at:36556; all fourrecordHeartbeatTimerSchedulerExclusioncall sites are at:36572,:36595,:36607,:36640, all below it.
Critical Issues (0)
None.
Important Issues (1)
-
[comments + gstack/review]
server/src/services/heartbeat.ts:36446— the comment added on the suppressed early return ends "The suppression itself is already observable viapaperclip_heartbeat_timer_scheduler_exclusion_total." That is false, and it contradicts text added in this same revision. The early return at:36449-36453precedes everyrecordHeartbeatTimerSchedulerExclusioncall site (:36572,:36595,:36607,:36640), so when global suppression is active nothing increments that counter from this path.metrics.ts:145-148says exactly the opposite of this comment — "every one of its increments happens afterchecked += 1, so it is silent in all four of those cases" — with global suppression as cause (3); the help text repeats it atmetrics.ts:1911-1913.What makes this more than a wording slip is that the claim is checkable and comes back true:
heartbeat.scheduling_suppressedis a real member ofKNOWN_HEARTBEAT_TIMER_SCHEDULER_EXCLUSIONS(metrics.ts:174), so someone verifying the comment finds the label exists and stops there. It is emitted fromenqueueWakeup(heartbeat.ts:31859) viasuppression.durableSkipReason→resolveHeartbeatTimerSchedulerExclusionReasonat:36640— but that site is inside the per-agent loop, reachable only on a pass that did not take the early return, and both gate on the samegetSchedulingSuppression()call. From the timer loop that label is therefore effectively unreachable under the condition it names (barring a suppression flip inside a single pass). The pre-existing dead label is out of scope here; the new comment asserting it as an observability guarantee is not.The cost is the same operator trail the prior finding was about, re-seeded one file over: the on-call reading
metrics.tsis told not to trust the exclusion counter, and the developer readingtickTimersis told it covers this case. Whoever opens the function first wins.- Recommendation: drop the last sentence, or replace it with what is actually true — global suppression is observable from the scheduling-suppression record and worker state, which is what
metrics.ts:148-150already directs readers to. Everything before it in the comment (the design rationale for not recording a suppressed pass) is correct and worth keeping.
- Recommendation: drop the last sentence, or replace it with what is actually true — global suppression is observable from the scheduling-suppression record and worker state, which is what
Suggestions (2)
- [tests]
server/src/__tests__/heartbeat-opencode-k8s-timer-no-work.test.ts:278— the new suppressed-pass test asserts both new counters stay flat, but not that the exclusion counter does. Its sibling at:309does exactly that (readSchedulerExclusionTotalat:327/:344), and the helper is already in the file. Adding the same two lines here would pin the negative half of the documented semantics for cause (3), and would have failed against the Important finding above — the comment claims a counter movement that a test one function away is already set up to detect. - [tests]
server/src/__tests__/heartbeat-opencode-k8s-timer-no-work.test.ts:323— the update replacesruntimeConfigwholesale rather than merging, dropping the seededwakeOnDemandandmaxConcurrentRuns. Harmless today because!policy.enabledshort-circuits first atheartbeat.ts:36538, so the test does exercise the filter its comment names. But the assertion ischecked === 0, which any of the three pre-counter filters satisfies — so ifenabledever stopped being honored, a different dropped-field path could keep the test green. Spreading the seeded config and overriding onlyenabledkeeps the test pinned to the filter it claims to cover.
Strengths
- The prior finding was not just patched but generalized correctly. The cause list at
metrics.ts:135-141covers the two caller-side gates that the earlier review had to derive fromindex.ts, and:142-143names the restart trap. Confirmed accurate at this head:index.ts:1406gatestickTimerson suppression,:1387returns onheartbeatStartupRecoveryPending,:1405onheartbeatSchedulerStopped. expect(result).not.toHaveProperty("idleSkipped")(:301) is a genuinely good discriminator. The suppressed return atheartbeat.ts:36449-36453omitsidleSkippedwhile the completed return at:36648-36656carries it, so the two tests prove which return path ran rather than just observing matching numbers — which is the difference between pinning the semantics and pinning a coincidence.- The exclusion-counter silence assertion at
:344pins the one claim most likely to be quietly broken by a future refactor that moveschecked += 1or an exclusion call site, and it is asserted as a delta against a shared-state counter rather than an absolute — correct given the file's other tests. - The delta-based
readTimerTickCountershelper handles the shared-module-state problem properly, andreadCounterin the sibling file deliberately returnsnullfor absent so "absent" and "zero" cannot collapse — the distinction the whole change rests on. - All four prior suggestions taken, including the two smallest:
Counterinstead ofCounter<string>(metrics.ts:1642-1643,:1748-1749), and thelogger.warnon both drop paths (:2742,:2750) which turns a silent drop into a visible one. - The caller-gate reasoning in the recorder comment at
heartbeat.ts:36658-36661is accurate:index.ts:1411does gate the log line onresult.enqueued > 0, so hanging the metric off that line would have pinned_checked_totalat zero on an idle fleet. Recording at:36662is the right placement.
Recommended Action
- No Critical issues — the wiring, placement, zero-initialization and registry lifecycle are all correct.
- Fix or drop the last sentence of the comment at
heartbeat.ts:36446-36447. It is a one-line change and it contradicts the correction that is the substance of this revision. - Take the two test suggestions opportunistically; the first is two lines and would have caught (2).
…pression (BLO-32269)
The comment on the suppressed early return in tickTimers ended with "The
suppression itself is already observable via
paperclip_heartbeat_timer_scheduler_exclusion_total". That is false and it
contradicts the correction made in the previous commit: all four
recordHeartbeatTimerSchedulerExclusion call sites sit below `checked += 1`,
so none of them is reachable from this return.
The claim was worse than a wording slip because it is checkable and comes
back true -- `heartbeat.scheduling_suppressed` is a real member of
KNOWN_HEARTBEAT_TIMER_SCHEDULER_EXCLUSIONS, so a reader verifying it finds
the label and stops. It is emitted from inside the per-agent loop, which
this return skips.
- Replace the last sentence with the accurate statement, and say explicitly
that the label existing is not evidence the counter moves here.
- Pin it mechanically: the suppressed-pass test now asserts the exclusion
counter is flat too. Negative-controlled -- injecting an exclusion call on
the suppressed return turns it red ("expected 1 to be +0").
- Merge rather than replace runtimeConfig in the filtered-pass test, so it
stays pinned to `!policy.enabled` instead of any pre-counter filter.
Negative-controlled -- flipping `enabled` back to true turns it red
("expected { checked: 1 } to match { checked: +0 }").
Co-Authored-By: Claude <noreply@anthropic.com>
Finding disposition — head
|
|
@ally head Requested a review from @allyblockcast directly (native GitHub review request, not just this comment) against current head |
There was a problem hiding this comment.
Ally — Consolidated PR Review
Lenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex.
Reviewed head: f5ef27c
The previous round's Important finding is fixed, and both of its suggestions were taken. One new Important finding, in the recorder's guard rather than the wiring: the drop policy is applied per field, but the invariant it protects is a property of the pair.
Prior Findings Dispositioned (1)
- prior:2a86b29 important 1 — fixed —
server/src/services/heartbeat.ts:36448— the false sentence is gone. The comment on the suppressed early return no longer claims the suppression is observable viapaperclip_heartbeat_timer_scheduler_exclusion_total; it now states the opposite and matchesmetrics.ts: "paperclip_heartbeat_timer_scheduler_exclusion_total does NOT close it: every one of its call sites is belowchecked += 1, so none of them is reachable from this return" (:36449-36451). It also closes the specific trap the finding was about — that the claim is checkable and comes back true — by naming it directly at:36452-36455: theheartbeat.scheduling_suppressedlabel "exists but is emitted from inside the per-agent loop, which this return skips -- so the label being present is not evidence the counter moves here." Readers are redirected to the scheduling-suppression record and worker state (:36455-36457), which is whatmetrics.tsalready directs them to. Verified against the file at this head, not the diff.
Critical Issues (0)
None.
Important Issues (1)
-
[code + error handling]
server/src/services/metrics.ts:2747— the drop-don't-clamp policy is enforced per field, but the reading it protects is a property of the pair, so a half-bad input reproduces exactly the outcome the policy exists to prevent. The doc comment at:2729-2731states the rationale: "silently substituting 0 for a bad value would fabricate a 'loop ran, found nothing' reading — the healthy signal — out of a bug." Butcheckedis guarded at:2739andenqueuedindependently at:2747, so a pass with a validcheckedand a non-finiteenqueuedincrementscheckedand leavesenqueueduntouched. The net movement across that pass ischecked += N, enqueued += 0— observationally identical to substituting 0 for the bad value, andchecked > 0, enqueued = 0is precisely the state this file's own pair documentation labels "Healthy".The trigger is plausible rather than theoretical, because
enqueuedis the composite half:heartbeat.ts:36657computes it asenqueued + issueMonitors.triggered. A refactor that renames or dropstriggeredyieldsNaNon that field alone whilechecked— summed from three separate fields at:36656— stays valid. The result is a fleet that has stopped enqueuing, reporting the healthy-idle shape on the surface the alert rule reads. Thelogger.warnat:2749-2752does fire, but it fires into the worker log, and the whole premise of BLO-32269 is that the log is not the surface being alerted on.- Recommendation: validate both fields before incrementing either, and drop the pass as a unit when either is bad. A dropped pass leaves both series flat, which reads as dispatch-dark — the safe direction, and the one that alerts — rather than as healthy idle. That also makes the implementation match the sentence at
:2732-2734about a dropped tick being indistinguishable from a tick that never ran: today a half-dropped tick is indistinguishable from a healthy one instead, which is strictly worse. The singlelogger.warncan name whichever field failed.
- Recommendation: validate both fields before incrementing either, and drop the pass as a unit when either is bad. A dropped pass leaves both series flat, which reads as dispatch-dark — the safe direction, and the one that alerts — rather than as healthy idle. That also makes the implementation match the sentence at
Suggestions (2)
- [tests]
server/src/__tests__/heartbeat-timer-tick-metrics.test.ts:66-68— the drop test covers three bad inputs and all three are symmetric (NaN/NaN,-1/-1,Infinity/Infinity), so the mixed-validity case is untested and the Important finding above passes the suite. AddingrecordHeartbeatTimerTick({ checked: 5, enqueued: Number.NaN })and asserting both series are unchanged would pin the pair semantics rather than the per-field behavior — and would fail against the current implementation, which is what makes it worth adding. - [tests]
server/src/__tests__/heartbeat-opencode-k8s-timer-no-work.test.ts:317— the new filtered-pass test is the right guard for cause (2) of the documented cause list, and the suppressed-pass test at:278covers cause (3). Causes (4)heartbeatStartupRecoveryPendingand (5)heartbeatSchedulerStoppedare caller-side inserver/src/index.tsand have none. That list is an operator-facing contract now — it tells the on-call which states to rule out before restarting, and names the restart trap for (4) — so a refactor that movedtickTimersabove either gate would silently falsify two of its five entries with nothing failing. Worth a guard at the caller if one is cheap there.
Strengths
- The prior finding was fixed at the root rather than patched: rather than merely deleting the false sentence, the replacement explains why the obvious verification comes back true (the label exists but is emitted from a path this return skips). That is the part a future reader would otherwise re-derive and get wrong again, and it is the second round running that this PR has answered a documentation finding by generalizing it.
- Both prior suggestions were taken, and the second was taken with its reasoning intact: the config update at
:341-346now spreads the seeded object and overrides onlyenabled, and the test asserts the seededwakeOnDemand/maxConcurrentRunsare actually present at:340before relying on them — so the test is pinned to the filter it claims to cover rather than to whichever pre-counter filter happens to fire first. expect(result).toHaveProperty("idleSkipped")at:359againstnot.toHaveProperty("idleSkipped")at:303is the sharpest thing in the change. The two tests observe identical counter movement (both zero), and this is the only assertion that distinguishes which return path produced it — a completed pass that examined nothing versus the suppressed early return. Without it the pair would pin a coincidence.- The exclusion-counter silence assertions at
:314and:368pin the negative half of the documented semantics on both paths, which is the claim most likely to be quietly broken by a future refactor that moveschecked += 1or adds an exclusion call site above it. - Recorder placement at
heartbeat.ts:36672remains correct and is now justified in-line: hanging it off the caller's log line, which is gated onenqueued > 0, would have pinned_checked_totalat zero on exactly the idle-fleet reading the pair exists to distinguish from a dead loop. - Zero-initialization, registry lifecycle (
ensureRegistryguard, return object,__resetMetricsForTest) and the unlabeled cardinality decision were all verified correct in earlier rounds and are unchanged here.
Recommended Action
- No Critical issues — the wiring, placement, zero-initialization and registry lifecycle are all correct, and the prior finding is cleanly closed.
- Make the drop in
recordHeartbeatTimerTickall-or-nothing across the pair. Nothing consumes these counters yet, so this is cheap now and would otherwise be found from a runbook during the incident the pair was built for. - Take the first test suggestion alongside it — it is two lines and it is the regression guard for (2).
Thinking Path
Linked Issues or Issue Description
No GitHub issue exists for this; the work is tracked in the Paperclip tracker above.
What Changed
server/src/services/metrics.ts— register two unlabeled counters,paperclip_heartbeat_timer_checked_totalandpaperclip_heartbeat_timer_enqueued_total, and exportrecordHeartbeatTimerTick({ checked, enqueued }).server/src/services/heartbeat.ts— call the recorder at thetickTimersreturn, with that pass's own totals.server/src/__tests__/heartbeat-timer-tick-metrics.test.ts(new) — unit coverage for the recorder.server/src/__tests__/heartbeat-opencode-k8s-timer-no-work.test.ts— two integration assertions against the realtickTimerspath, one per branch (idle pass and enqueueing pass).Three design choices worth a reviewer's attention, because each one is a place the obvious implementation is wrong:
tickTimersreturn, not at the log line. The issue asked for the counters "at the same point that log line is written". Taken literally that is a bug: the log line sits insideif (result.enqueued > 0), so_checked_totalwould stay pinned at zero on a healthy-but-idle fleet — destroying the exact distinction the pair exists to make. The integration assertions fail withexpected +0 to be 1if the call is moved behind that gate; I verified that by injecting the mis-wiring and watching the test go red.sum(increase(...[15m])) == 0, so a per-agent breakdown adds cardinality without signal, and the per-agent story is already told bypaperclip_heartbeat_timer_scheduler_exclusion_total. It also means prom-client zero-initializes both series at construction, so they are present on the first scrape after boot — a dispatch-dark rule has to be able to tell "0 ticks" from "metric not published yet", and an absent series cannot.Non-finite and negative inputs are dropped rather than clamped to 0: substituting 0 would fabricate the healthy "loop ran, found nothing" reading out of a bug, and a counter that can move backwards breaks
increase()outright.Verification
Negative control — the integration assertions are not decoration. Temporarily changing the call site to
if (result.enqueued > 0) recordHeartbeatTimerTick(result)(i.e. the literal reading of the issue) makes the idle-pass test fail:Reverted; the committed tree has the unconditional call.
Post-deploy verification is a runtime property and cannot be asserted in CI. Once this reaches the worker:
plus a one-time cross-check that the counter deltas match the logged tick:
I confirmed the exposition path is already proven for this target before writing any code:
paperclip_heartbeat_timer_scheduler_exclusion_total— a sibling counter on the same registry — is live right now underjob="paperclip-control-plane", service="paperclip-workers", pod="paperclip-0", which is exactly where the issue asks these to appear. So this needs no new scrape config.Risks
Low. Two unlabeled counters and one call site; no behavioural change to scheduling, and nothing reads the counters yet.
Two things a reviewer should weigh rather than take on trust:
StatefulSetandDeployment/paperclip-apideploy independently and can run different images, so "the api rolled" is not evidence these are live. The authoritative check is thepaperclip.blockcast.net/deployed-commitannotation on the worker StatefulSet.checkedstays flat while the process is perfectly healthy. That is not a false positive for a dispatch-dark rule — a suppressed fleet genuinely is not dispatching — but it is a second cause for the same page, and whoever repointsPaperclipFleetDispatchDarkshould say so in the runbook and confirm againstpaperclip_heartbeat_timer_scheduler_exclusion_totalbefore paging a human. This is documented in the metric's help text and doc comment rather than left for the next on-call to discover.== 0rate rule (a scrape gap makesincrease()return empty, so the rule goes silent rather than false-paging) but it would be wrong to build anotherabsent()rule on them.Model Used
claude-opus-5[1m], 1M context), extended thinking, agentic tool use via Claude Code / Paperclipclaude_k8sadapter.Checklist
heartbeat_timer,32269, and the open-PR list for metrics/heartbeat/timer/counter work — nearest neighbours are feat(metrics): promote aggregate_key and phase so a wedged fence is nameable (BLO-32163) #1695 plugin metric export and feat(metrics): add DB-backed workflow_run cancellation gauge (BLO-21078) #989 workflow_run gauge, neither overlapping)Fixes: #/Closes #/Refs #OR (b) described the issue in-PR following the relevant issue template