Skip to content

fix(agent): stop heartbeat watchdog from firing every heartbeat on slow links (#2386) - #2392

Merged
ToddHebebrand merged 2 commits into
mainfrom
fix/2386-heartbeat-watchdog-dump
Jul 13, 2026
Merged

fix(agent): stop heartbeat watchdog from firing every heartbeat on slow links (#2386)#2392
ToddHebebrand merged 2 commits into
mainfrom
fix/2386-heartbeat-watchdog-dump

Conversation

@ToddHebebrand

Copy link
Copy Markdown
Collaborator

Closes #2386

Problem

The heartbeat watchdog armed a 15s timer around the whole runHeartbeat() — metrics collection, the primary POST (one 30s-capped context around the retry loop), and after consecutive failures a second full backup-probe POST (another 30s cap). Legitimate worst case is ~60-65s, so on any slow/flapping uplink the watchdog fired on every heartbeat (observed live: every 60s for 2+ days on a macOS device). Each fire did a stop-the-world runtime.Stack(buf, true), allocated 1MiB, and logged a 100KB WARN entry the shipper uploads — which the API rejects (fields > 32,000 stringified chars), 400ing the entire batch and discarding every legitimate log entry shipped with it.

Fix

  1. Timeout 15s → 90s. The watchdog was added in Agent: desktop helper reconnect loop storms logs on headless Windows Server (Session 0 only) #387 to catch broker-mutex starvation — an indefinite block that exceeds any finite bound. 90s clears the ~60-65s legitimate worst case (30s primary POST + 30s backup probe + collection overhead) while fully preserving the starvation diagnostic. I chose raising the bound over re-scoping what's timed: re-scoping would require threading the watchdog through sendHeartbeat's internals and would stop covering the metrics-collection hang class the whole-call watchdog currently catches for free.
  2. Rate-limit dumps: at most one per 10 minutes, across invocations. Suppressed fires log a cheap one-line WARN with a running suppressed_dumps counter; the next emitted dump reports suppressed_dumps_since_last. Concurrent/overlapping fires race for the slot via CAS.
  3. Cap the dump at 8KB raw, cut at a goroutine boundary, with goroutine_count as a separate field. JSON escaping roughly doubles a stack dump, so 8KB leaves comfortable headroom under the API's 32,000-char fields ceiling (worst-case-escaping test included).
  4. Shipper hardening: Enqueue now pre-caps any entry's fields at 31,000 JSON bytes (mirroring the API limit, byte-count is conservative vs. JS string length), replacing oversized fields with a small fields_dropped marker — so no single bloated entry can burn a whole batch again, whatever produces it. No per-entry retry protocol; the guard is purely local and pre-buffer.

Tests

  • Existing watchdog tests (fires-when-blocked, no-fire-fast-path, cancels-on-panic) still pass; harness now resets the cross-invocation rate-limit state.
  • New: rate-limit within interval (1 dump + suppressed-counter WARN), dump-again-after-interval (reports suppressed count), truncateGoroutineDump boundary/marker behavior, worst-case-escaped dump fits the 32,000-char API limit, capFields pass-through/replacement, and Enqueue capping an oversized entry while preserving the message.
  • cd agent && go test -race ./internal/heartbeat/... ./internal/logging/... — green. gofmt clean on touched files, go vet clean.

🤖 Generated with Claude Code

…ow links (#2386)

The heartbeat watchdog (15s) timed the whole runHeartbeat() — metrics
collection plus a 30s-capped primary POST plus, after consecutive
failures, a second 30s-capped backup-probe POST — so on any degraded
uplink it fired on every single heartbeat, doing a stop-the-world
runtime.Stack over all goroutines and emitting a 100KB WARN entry the
API's 32,000-char fields limit rejects, burning the whole shipped log
batch with it.

- Raise the watchdog timeout default to 90s, above the ~60-65s
  legitimate worst case. The watchdog targets indefinite broker-mutex
  starvation (#387), which exceeds any finite bound, so the diagnostic
  is preserved while routine slow sends never trip it.
- Rate-limit goroutine dumps to one per 10 minutes across invocations;
  suppressed fires log a cheap one-line WARN with a running counter,
  and the next dump reports how many fires were suppressed.
- Cap the raw dump at 8KB (cut at a goroutine boundary) so the shipped
  entry fits the API's 32,000-stringified-char fields ceiling with
  JSON-escaping headroom; add goroutine_count alongside.
- Shipper: pre-cap any entry's fields at 31,000 JSON bytes before
  buffering, replacing oversized fields with a small marker so one
  bloated entry can no longer 400 the entire batch.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
@cloudflare-workers-and-pages

cloudflare-workers-and-pages Bot commented Jul 12, 2026

Copy link
Copy Markdown

Deploying breeze with  Cloudflare Pages  Cloudflare Pages

Latest commit: 0ebe700
Status: ✅  Deploy successful!
Preview URL: https://d9450258.breeze-9te.pages.dev
Branch Preview URL: https://fix-2386-heartbeat-watchdog.breeze-9te.pages.dev

View logs

…alvage, deterministic tests

- capFields: an unmarshalable value (NaN/Inf) no longer passes through to
  poison the whole-batch marshal in shipBatch (which drops every co-batched
  entry) — it is dropped by name like an oversized field.
- capFields: salvage small correlating fields (ids, durations) instead of
  discarding everything, and name each dropped key with its size in the
  fields_dropped marker.
- Raise the watchdog dump cap 8KB -> 12KB (still <32,000 chars at worst-case
  2x escaping); note the capFields backstop for pathological <>&-heavy dumps.
- Comment precision: backup probe fires only past backupProbeThreshold;
  typical JSON inflation is a few percent (cap sized for worst case);
  byte>=char claim scoped to strings; note the rate-limit slot is consumed
  even if the WARN is dropped at enqueue.
- Tests: replace sleep-racy blocked-heartbeat helper with an observe-then-
  release pattern; add deterministic CAS concurrency + interval-boundary
  tests, production-defaults pin, NaN capFields test, salvage assertions.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
@ToddHebebrand

Copy link
Copy Markdown
Collaborator Author

Review run: /pr-review-toolkit:review-pr (code-reviewer, pr-test-analyzer, silent-failure-hunter, comment-analyzer), plus a focused code-reviewer re-pass on the follow-up commit.

Findings: 10 raised across the four agents → all addressed in 0ebe700; 0 outstanding.

  • HIGH — capFields marshal-error path passed unmarshalable fields through, guaranteeing a whole-batch drop in shipBatch (the marshal-failure flavor of the [Agent] Heartbeat watchdog fires on every heartbeat over a slow link, shipping 100KB goroutine dumps the API rejects #2386 bug) → now dropped by name via the same marker path.
  • MEDIUM — oversized-fields marker discarded all co-resident fields → small correlating scalars (ids, durations) are now salvaged under a per-field 1KB cap and a half-limit running budget; dropped keys are named with sizes.
  • MEDIUM — 8KB dump cap trimmed the local copy too → raised to 12KB (still <32,000 chars at worst-case 2x escaping, with the capFields backstop for pathological <>&-heavy dumps).
  • Test quality — sleep-racy blocked-heartbeat helper replaced with observe-the-fire-then-release; added deterministic CAS-concurrency, interval-boundary, and production-defaults tests plus a NaN capFields test.
  • Comment precision — backup-probe threshold, JSON-inflation phrasing, byte-vs-char claim scoping, rate-limit-slot note.

Not addressed (pre-existing, out of scope): shipper batches up to 500 entries while the API caps logs at 200 per request — the same burn-the-batch class, but present before this PR; worth its own issue.

Tests: cd agent && go test -race -count=2 ./internal/heartbeat/... ./internal/logging/... green (includes the three pre-existing watchdog tests, updated); go vet clean; touched files gofmt-clean. No TS changes, so no tsc run.

Status: review-clean, awaiting maintainer merge.

@ToddHebebrand

Copy link
Copy Markdown
Collaborator Author

Independent re-review of follow-up commit 0ebe700: clean — go vet clean, internal/heartbeat + internal/logging pass go test -race -count=3. Budget arithmetic in capFields verified sound against escaping-heavy values (value-side expansion is counted post-marshal). One theoretical gap noted, not reachable in this codebase: used counts raw key length, not escaped — dynamic keys containing <>& could re-breach the cap, but slog field keys here are always short ASCII literals. Optional belt-and-suspenders if ever desired: a final json.Marshal re-check after the salvage loop. Not blocking.

@ToddHebebrand
ToddHebebrand merged commit 44d343b into main Jul 13, 2026
41 checks passed
@ToddHebebrand
ToddHebebrand deleted the fix/2386-heartbeat-watchdog-dump branch July 13, 2026 01:07
ToddHebebrand added a commit that referenced this pull request Jul 13, 2026
…cap (#2397) (#2402)

Closes #2397

## Problem

The agent log shipper accumulates up to 500 entries per flush
(`defaultMaxBatchSize`) but shipped them all in one HTTP request. The
API's logs endpoint caps `logs` at 200 entries per request
(`apps/api/src/routes/agents/logs.ts`, `z.array(...).max(200)`) and 400s
the whole request when exceeded — and the shipper never retries 4xx. A
full batch was therefore guaranteed lost wholesale, precisely under
bursty logging when logs matter most. Same burn-the-batch class as
#2386.

## Fix (agent-side only)

- New named constant `maxEntriesPerShipRequest = 200` in
`agent/internal/logging/shipper.go`, with a comment pointing at the
API-side cap (Go and TS can't share code — the comment is the sync
mechanism, and the value must stay <= the oldest supported API cap since
self-hosted versions vary).
- `shipBatch` now splits each flush into <=200-entry chunks; the
500-entry accumulation buffer is unchanged.
- New `shipChunk` carries one HTTP request with the existing retry loop:
- **Non-auth 4xx** — chunk-local: drops only that chunk's entries; the
batch's remaining chunks still ship.
- **429/5xx/network errors** — retried per chunk (`shipRetryCount`,
Retry-After honored as before).
- **Terminal failures abort the batch's remaining chunks** with a
counted drop: network error or 429/5xx after exhausting retries (server
unreachable — each further chunk would burn another full retry cycle
while blocking the ship loop), and **401** (token dead for every chunk
alike; also keeps `RecordAuthFailure` at one per flush, matching the
pre-chunking rate the auth monitor's skip threshold was tuned for). Net
drop count in these cases matches the old single-request behavior.
- Server cap untouched.

## Tests (`agent/internal/logging/shipper_test.go`)

- 500-entry flush produces exactly 3 requests of 200/200/100, in order,
none lost or duplicated.
- <=200-entry batch still goes out as a single request.
- A 400 on chunk 2 drops only that chunk (300 entries delivered,
`DroppedLogCount == 200`, chunk 3 verified shipped).
- A transient 500 on chunk 2 is retried per-chunk; all 500 entries
delivered.
- Dead server: only chunk 1's retry cycle runs (3 requests), remaining
chunks abort with counted drops.
- 401: exactly 1 request, exactly 1 `RecordAuthFailure`, all 500 dropped
with count.
- Pin test asserting `maxEntriesPerShipRequest == 200` against the API
contract.

## Verification

- `cd agent && go test -race ./internal/logging/...` — ok (7.5s)
- `gofmt -l` clean, `go vet` clean, `go build ./...` ok

## Note for the merger

Open PR #2392 (#2386) also touches `shipper.go` (adds `capFields` in
`Enqueue`). This change is confined to the flush/ship path, so overlap
is minimal, but whichever merges second may need a trivial rebase. This
PR is based on `origin/main`, not on #2392's branch.

🤖 Generated with [Claude Code](https://claude.com/claude-code)

---------

Co-authored-by: Todd Hebebrand <todd@lanternops.io>
Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
ToddHebebrand added a commit that referenced this pull request Jul 13, 2026
…hrottle (#2422) (#2453)

## Summary

Fixes both gaps in the `capture_pprof` diagnostic command (#2394/#2408
seam):

1. **Wedge gauges were always 0/0.** `handleCapturePprof` discarded its
`*Heartbeat` receiver and embedded `collectors.CollectRuntimeStats()`
directly, which never populates `commandsInFlight`/`commandsOverdue`.
The snapshot now goes through `h.collectAgentRuntime(now)` — the wrapper
that wires in `inFlightCommandStats` — so a capture taken while chasing
an overdue-commands heartbeat trend reflects the real pool state.

2. **No throttle on GC-forcing captures.** Heap/all captures
unconditionally ran `runtime.GC()`; as a server-queued command (10
concurrent / 100 queued), a burst could force back-to-back
stop-the-world GCs. Added a 30s minimum interval between admitted
captures using the same atomic CAS slot pattern as the heartbeat
watchdog dump throttle (#2392). Throttled captures fail with an explicit
`rate-limited` error. Payload validation runs before the throttle so
malformed requests don't consume the slot.

All changes are confined to `handlers_diag.go` / `handlers_diag_test.go`
— `heartbeat.go` is untouched.

## Tests

- New: `TestHandleCapturePprofIncludesWedgeGauges` (tracked overdue
command shows up as 1/1 in the snapshot),
`TestHandleCapturePprofThrottled` (second capture rejected, slot frees
after interval), `TestHandleCapturePprofValidationDoesNotConsumeSlot`.
- Existing diag tests updated to use a zero-value `*Heartbeat` +
per-test throttle reset.
- `cd agent && go test -race ./internal/heartbeat/...` — ok (41s); `go
build ./...` clean; `go vet` clean.

Closes #2422

🤖 Generated with [Claude Code](https://claude.com/claude-code)

---------

Co-authored-by: Todd Hebebrand <todd@lanternops.io>
Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

[Agent] Heartbeat watchdog fires on every heartbeat over a slow link, shipping 100KB goroutine dumps the API rejects

1 participant