Skip to content

fix(telemetry): flush a final heartbeat on graceful shutdown - #1037

Merged
github-actions[bot] merged 3 commits into
mainfrom
fix/telemetry-shutdown-flush
Aug 25, 2026
Merged

github-actions[bot] merged 3 commits into
mainfrom
fix/telemetry-shutdown-flush

Conversation

@Dumbris

@Dumbris Dumbris commented Aug 24, 2026 •

Copy link
Copy Markdown
Member

What

Telemetry counters live in memory and are reset only after an accepted (2xx) send. There was no send on shutdown, so everything recorded after the 5-minute first heartbeat was discarded unless the process survived to the 24h tick — which most desktop sessions don't. Deferred follow-up from #1029.

Service.Stop() now performs one final heartbeat, after it has joined the heartbeat loop.

Key decisions

  • Reuse the exact send+reset path. The flush calls the same sendHeartbeat body, so the counter contract is untouched: a failed or timed-out flush resets nothing (counts survive to the next run), and an accepted flush can't double-count with a later start.
  • Flush after the join, not from a second goroutine. At that point the loop has provably exited, so there is exactly one sender and no interleaving with a tick. It still happens inside Runtime.Close before the shutdown marker resolves and the BBolt handle closes, which is where buildHeartbeat's funnel writes are legal.
  • Fresh context, hard 4s bound. Runtime.Close cancels the app context before Stop, so a derived context would abort instantly; and a dead endpoint must never delay a quit.
  • Skipped when disabled by env/config, non-semver build, opted out, or nothing recorded since the last accepted send (new CounterRegistry.HasPendingCounters, inspecting exactly the set Reset zeroes).
  • No build-time one-shots on this path (consumeOneShots=false). Two side effects are consumed when the payload is built rather than when it is accepted: the 365-day anonymous-id rotation (which rewrites the whole config file) and the installer_heartbeat_pending flag. Spending either for a send that may never land would destroy state a normal run still has, so the flush skips both and the next start performs them. Every other build-time touch (activationStore.Load, the diagnostics/preflight snapshots) is a db.View, and funnelStore.RecordActivity is idempotent day-marking.
  • Delivery is at-least-once, deliberately. A send cut off after the endpoint accepted it but before the client saw the response leaves the counters pending, so the flush re-sends them. That is undecidable client-side; the alternative is dropping the window entirely, which is the bug this fixes. Documented in docs/features/telemetry.md — receivers dedup per (anonymous_id, timestamp).
  • Threaded through the concurrency mechanisms feat(telemetry): heartbeat v9 — TPA gate/prompt scan counters + trust_mode distribution #1029 added (liveConfig() snapshot, persistConfig liveness guard, atomic rotation under s.mu); no races reintroduced.

Drive-by: two unlocked reads of state NotifyConfigChanged writes

NotifyConfigChanged rewrites both s.endpoint and s.config under s.mu, and it is one call away from the beacon goroutine it launches.

  • s.endpoint was read unlocked by the heartbeat, feedback, and opt-out-beacon paths — a race the flush widens, since it now sends from whichever goroutine called Stop. All four reads go through a new liveEndpoint().
  • s.config.GetAnonymousID() was read unlocked by both opt-out-beacon eligibility gates, two lines above that endpoint read. Snapshotting the pointer would not have sufficed: GetAnonymousID dereferences cfg.Telemetry, which ensureAnonymousIDOnce / advanceUpgradeFunnelOnce also install under s.mu, so the whole read has to be inside the critical section — exactly as telemetryEnabledLive documents. New liveAnonymousID().

No unlocked s.config read remains outside a locked region.

Tests

internal/telemetry/shutdown_flush_test.go: sent-once + counters reset, post-first-heartbeat activity captured (the regression), flush timeout leaves shutdown unblocked and counters retained, opted-out and disabled installs send nothing, the flush skips after an already-accepted tick, it joins + re-sends an unconfirmed one, and the anonymous-id read is locked (fails under -race without liveAnonymousID, flagging both call sites against optout.go:215). activation_test.go additionally pins that a non-consuming resolve leaves installer_heartbeat_pending armed.

go test -race passes for ./internal/telemetry/..., ./internal/runtime/..., ./internal/httpapi/..., ./internal/server/ (CI skip regex), ./internal/config|storage|index|upstream/...; the flush tests survive -count=200 -race. golangci-lint v2 with .github/.golangci.yml reports 0 issues. (TestScanForPII_V7FieldViolations fails at -count=2 on this machine on origin/main too — the local username is literally user, a blocked value that leaks into the second pass via PopulateBlockedValues; verified pre-existing, not a regression.)

Live verification against a real binary (-ldflags semver, isolated --config/--data-dir, telemetry endpoint pointed at a local sink, port 18088):

  • 11 REST calls, then SIGTERM → nothing before shutdown (the loop is parked in the 5-minute initial delay), then exactly one POST /heartbeat carrying surface_requests.unknown: 11 — the session that used to be dropped. launch_source came back as the runtime-detected unknown, not a consumed one-shot.
  • Same run with DO_NOT_TRACK=1 → sink stays empty; the log shows Telemetry disabled by environment variable, and the flush is never armed.

CI note

The first Unit Tests (ubuntu-latest, 1.25) run failed on TestFastPathDoesNotOvertakeAQueue (internal/upstream/limiter/limiter_test.go:635, "FIFO violated") — a package this PR does not touch at all. Verified pre-existing: it reproduces on a clean origin/main worktree at go test ./internal/upstream/limiter/ -run TestFastPathDoesNotOvertakeAQueue -count=400. Rerun requested; worth a real fix on main, since the assertion demands strict FIFO from a fast path that only usually loses the race.

Cross-model review

Reviewed with the opencode CLI (gpt-5.6-sol). Round 1 and round 2 both returned CHANGES REQUIRED; every finding below was verified against the code before being acted on.

Round 1 — three genuine defects, all fixed:

  1. A failed flush spent the installer one-shot. resolveLaunchSource clears installer_heartbeat_pending at build time; on the shutdown path an offline/timed-out flush destroyed an attribution that previously survived into the next run.
  2. TestFlushOnStopNoDoubleSendWithPeriodicTick was flaky — reproduced locally at -count=300 (got 4, want 2). Its premise ("exactly once whatever the interleaving") was simply not what the design guarantees. Split into two deterministic tests plus the at-least-once documentation.
  3. TestFlushOnStopSkippedWhenOptedOut raced the opt-out beacon, which POSTs to the same /heartbeat ingest path (the test comment claimed /opt-out). Verified empirically. The recorder now classifies beacons by their event field and the test waits for the beacon before asserting.

Round 2 — one genuine defect, fixed: the unlocked GetAnonymousID reads described under Drive-by above, reproduced under -race before the fix.

Round 3 — CLEAN. "No new correctness or security defects found. Applied fixes are complete and consistent with shutdown ordering."

Rejected, with rebuttals:

  • Pin the heartbeat URL through validateTelemetryURL. Pre-existing sink; the endpoint is a local config value documented as a testing aid. Worth its own PR, not this one.
  • buildHeartbeat is not bounded by flushTimeout. The pre-existing joined tick has the identical exposure, and Runtime.Close has no hard deadline (upstream shutdown alone budgets 45s+15s ahead of it).
  • TOCTOU between the pre-transmit optedOut check and client.Do (raised twice). Pre-existing on the periodic sender and unchanged in character here; the flush's telemetryEnabledLive() closes the window the round-1 report described. The proposed fix — an emission mutex held across the HTTP send — would make NotifyConfigChanged block the config-save path on up to 10s of network I/O, breaking the "never blocks the caller" invariant that goroutine exists to uphold.
  • The flush can double-send a heartbeat whose response was lost. Deliberate at-least-once, undecidable client-side, now documented rather than papered over.

Telemetry counters are in-memory and reset only after an accepted (2xx)
send, so everything recorded after the 5-minute first heartbeat was lost
unless the process survived to the 24h tick — which most desktop sessions
do not. Deferred follow-up from #1029.

Stop() now performs ONE final heartbeat after joining the loop:

- It reuses sendHeartbeat's send+reset path verbatim, so the counter
  contract is unchanged — a failed/timed-out flush drops nothing, an
  accepted flush cannot double-count with the next start.
- It runs AFTER the loop is joined rather than from a second goroutine,
  so there is provably no concurrent sender and the flush cannot
  interleave with a tick.
- It uses a fresh context hard-bounded to 4s (Runtime.Close cancels the
  app context before Stop, and a dead endpoint must never hang a quit).
- It is skipped when telemetry is disabled by env/config, the build is
  non-semver, the user opted out, or nothing was recorded since the last
  accepted send (new CounterRegistry.HasPendingCounters).
- Anonymous-id rotation is suppressed on this path: rotation rewrites the
  whole config file, and shutdown is the wrong moment for that.

Also closes a pre-existing data race the flush widens: s.endpoint is
rewritten under s.mu by NotifyConfigChanged but was read unlocked by the
heartbeat, feedback, and opt-out-beacon paths. All four now read it
through liveEndpoint(), matching liveConfig().
@cloudflare-workers-and-pages

cloudflare-workers-and-pages Bot commented Aug 24, 2026 •

Copy link
Copy Markdown

Deploying mcpproxy-docs with  Cloudflare Pages  Cloudflare Pages

Latest commit: a854ee7
Status: ✅  Deploy successful!
Preview URL: https://68e624f0.mcpproxy-docs.pages.dev
Branch Preview URL: https://fix-telemetry-shutdown-flush.mcpproxy-docs.pages.dev

View logs

@codecov-commenter

codecov-commenter commented Aug 24, 2026 •

Copy link
Copy Markdown

⚠️ Please install the 'codecov app svg image' to ensure uploads and comments are reliably processed by Codecov.

Codecov Report

❌ Patch coverage is 75.00000% with 17 lines in your changes missing coverage. Please review.

Files with missing lines Patch % Lines
internal/telemetry/registry.go 45.00% 6 Missing and 5 partials ⚠️
internal/telemetry/telemetry.go 86.36% 3 Missing and 3 partials ⚠️

📢 Thoughts on this report? Let us know!

Cross-model review round 1 (opencode / gpt-5.6-sol) found three real defects
in the graceful-shutdown flush.

1. A failed flush destroyed the installer attribution. resolveLaunchSource
   clears installer_heartbeat_pending at BUILD time, before the send is known
   to have landed — a deliberate trade for the long-running loop, but it
   inverts on the flush: the process is exiting, so an offline or timed-out
   flush spent a one-shot that previously survived into the next run. The
   flush now leaves the flag armed and reports the runtime-detected source;
   the next start still claims "installer" exactly once. Generalized the
   rotate flag into consumeOneShots, which now gates both the 365-day
   anonymous-id rotation and the installer flag (send/buildHeartbeat*
   renamed accordingly).

2. TestFlushOnStopNoDoubleSendWithPeriodicTick was flaky — reproduced at
   -count=300 (got 4, want 2). Its premise was wrong: a tick aborted after
   the endpoint accepted it leaves counters pending, so the flush re-sends
   them. Delivery is at-least-once (undecidable client-side), which is the
   deliberate trade against dropping the window entirely. Split into two
   deterministic tests: the flush skips after an ACCEPTED tick, and joins +
   re-sends an unconfirmed one. Documented the semantics in code and docs.

3. TestFlushOnStopSkippedWhenOptedOut raced the opt-out beacon, which POSTs
   to the same /heartbeat ingest path (its comment claimed /opt-out). The
   recorder now classifies beacons by their `event` field and the test waits
   for the beacon before asserting no usage heartbeat followed.

Rejected as pre-existing/undecidable, with rebuttals: heartbeat-URL
validateTelemetryURL pinning (pre-existing sink, local config value),
buildHeartbeat not bounded by flushTimeout (the joined tick already had the
same exposure), and the opt-out latch race (the flush's telemetryEnabledLive
plus the pre-transmit optedOut re-check already close the described window).
@github-actions

github-actions Bot commented Aug 24, 2026 •

Copy link
Copy Markdown
Contributor

📦 Build Artifacts

Workflow Run: View Run
Branch: fix/telemetry-shutdown-flush

Available Artifacts

  • archive-darwin-amd64 (29 MB)
  • archive-darwin-arm64 (26 MB)
  • archive-linux-amd64 (17 MB)
  • archive-linux-arm64 (15 MB)
  • archive-windows-amd64 (29 MB)
  • archive-windows-arm64 (25 MB)
  • frontend-dist-pr (0 MB)
  • installer-dmg-darwin-amd64 (23 MB)
  • installer-dmg-darwin-arm64 (20 MB)

How to Download

Option 1: GitHub Web UI (easiest)

  1. Go to the workflow run page linked above
  2. Scroll to the bottom "Artifacts" section
  3. Click on the artifact you want to download

Option 2: GitHub CLI

gh run download 32765967430 --repo smart-mcp-proxy/mcpproxy-go

Note: Artifacts expire in 14 days.

Cross-model review round 2 (opencode / gpt-5.6-sol). One genuine finding: the
second half of this PR's own s.endpoint drive-by was left undone.

EmitOptOutBeacon and SendOptOutBeacon both gate on s.config.GetAnonymousID()
read WITHOUT s.mu, two lines above the endpoint read that now takes it.
NotifyConfigChanged swaps s.config under s.mu, and GetAnonymousID dereferences
cfg.Telemetry — a pointer ensureAnonymousIDOnce / advanceUpgradeFunnelOnce also
install under s.mu — so snapshotting the pointer would not have been enough
either; the whole read has to be inside the critical section, exactly as
telemetryEnabledLive documents. NotifyConfigChanged itself launches the beacon
goroutine, so the writer and the reader are one call apart.

Added liveAnonymousID() alongside liveConfig()/liveEndpoint() and routed both
gates through it. TestOptOutBeaconReadsAnonymousIDUnderLock reproduces the
race first (the detector flags both sites against optout.go:215) and passes
after. No unlocked s.config read remains outside a locked region.

Also re-raised and rejected again: the opt-out TOCTOU between the pre-transmit
optedOut check and client.Do. It is pre-existing on the periodic sender and
unchanged in character here, and the proposed fix — an emission mutex held
across the HTTP send — would make NotifyConfigChanged block the config-save
path on up to 10s of network I/O, breaking the "never blocks the caller"
invariant that goroutine exists to uphold.

@github-actions github-actions Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Approved (Model B): Paperclip review verdicts = ACCEPT and qa-gate green at this head SHA. Arming auto-merge; GitHub merges when all required checks pass.

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.

2 participants