Skip to content

fix(agent): collapse macOS log show fan-out, stream-bound output, back off event-log cadence (#2390) - #2393

Merged
ToddHebebrand merged 4 commits into
mainfrom
fix/2390-macos-log-show-subprocess-storm
Jul 13, 2026
Merged

fix(agent): collapse macOS log show fan-out, stream-bound output, back off event-log cadence (#2390)#2393
ToddHebebrand merged 4 commits into
mainfrom
fix/2390-macos-log-show-subprocess-storm

Conversation

@ToddHebebrand

Copy link
Copy Markdown
Collaborator

Closes #2390

Problem

On an idle macOS device the agent spawned 81,683 subprocesses in ~2 days. The dominant cost: log show --predicate ... --style json runs twice in parallel (security + hardware predicates) every ~5 minutes, plus again from the ReliabilityCollector's own EventLogCollector — and each invocation burns ~3.8s of CPU even when it returns 2 bytes. Secondary: the log show path used runCollectorOutput, which buffers the entire output before checking the 4 MiB cap.

Changes

1. One log show instead of two (eventlogs_darwin.go, new eventlogs_unifiedlog.go)
The security and hardware sub-collectors are collapsed into a single invocation with an OR-merged predicate, still wrapped in AND (messageType >= error) so macOS filters at the source. Entries are re-categorized in Go by mirroring the security predicate clauses (com.apple.opendirectoryd / com.apple.TCC subsystems or an "authentication" message → security; everything else the merged predicate can match → hardware). Per-category enable flags are respected: with only one category enabled, the query uses just that category's predicate and stamps it unconditionally. Helpers live in a platform-neutral file (no build tag) so they're unit-testable on Linux CI, following the crashReportKind precedent.

2. Streaming-bounded runner (command_limits.go)
New runCollectorBoundedOutput streams stdout through io.LimitReader(limit+1) so the 4 MiB cap is enforced before buffering (the old post-hoc check let a 100 MB output cost ~200 MB peak). Unlike runCollectorLimitedOutput it does not silently truncate or swallow errors: over-limit output, read failures, and non-zero exits all surface. Kept --style json (not ndjson) — a truncated JSON array fails parse loudly, and incremental parse wasn't needed once the cap is stream-enforced.

3. Window math: --start <timestamp> instead of floor-truncated --last Nm
The old --last window was floored to whole minutes and computed from a lastCollectTime stamped at the end of the previous pass — consecutive windows gapped, silently dropping events. Now the query passes an explicit --start (format YYYY-MM-DD HH:MM:SS±ZZZZ, verified live against log(1)), clamped to [now-60m, now], and lastCollectTime is stamped at pass start. Windows now tile exactly; the only residual overlap is the sub-second sliver of a pass in flight, which can at worst duplicate one event — preferable to dropping (no dedup exists downstream, noted in code).

4. Default cadence 5m → 15m (all four sibling defaults: agent NewEventLogCollector, shared eventLogInlineSettingsSchema, API EVENT_LOG_DEFAULTS, web EventLogTab)
Justification: every pass fans out subprocess work on all platforms, and the collected data is error-level events feeding retention/alerting — not something needing 5-minute freshness. 15m cuts the macOS steady-state unified-log CPU by ~6x combined with the query merge (2 queries/5min → 1 query/15min). Server-side configurability (1–60) is untouched — any partner who wants 5m back sets it in the event-log policy. ⚠️ Note: the zod default change means existing policies whose stored settings omit collectionIntervalMinutes will re-parse to 15m on all platforms.

5. Reliability collector (reliability.go)
Kept its own daily pass (sharing the heartbeat collector's instance would make the two consumers steal each other's events — each event is consumed once per instance). Found and documented a silent pre-existing bug: its intended 24h first-run lookback was already defeated for the unified log by the 60m clamp — only the DiagnosticReports crash-file scan (the authoritative long-window crash signal) truly looks back 24h. That clamp is now explicit and intentional (unifiedLogMaxLookback): scanning 24h of unified log would cost minutes of CPU (extrapolating from 3.8s/5m) and mostly time out, for marginal signal.

Verification

  • cd agent && go test -race ./internal/collectors/...ok (darwin build tags compile natively on macOS)
  • New tests: merged/single-category predicate construction, re-categorization mapping (8 cases), --start clamp math, 15m default, and 4 runCollectorBoundedOutput tests (over-limit rejection, exact-limit pass, exit-code surfacing, timeout)
  • Live end-to-end on a real Mac: single merged log show --start over a 10m window returned 2,181 entries in 5.9s, TCC entries correctly re-categorized security
  • gofmt clean on all touched files; GOOS=windows, GOOS=linux, GOOS=darwin go build ./... all pass
  • vitest run green: packages/shared inline-settings (51), apps/api agents/eventlogs (2), apps/web EventLogTab (4)
  • tsc --noEmit clean in packages/shared, apps/api, apps/web

🤖 Generated with Claude Code

…k off event-log cadence (#2390)

An idle macOS agent spawned 81,683 subprocesses in 2 days; each `log show`
burns ~3.8s CPU to return 2 bytes. Four changes:

- Merge the security + hardware unified-log sub-collectors into ONE
  `log show` invocation with an OR-merged predicate (respecting per-category
  enable flags) and Go-side re-categorization that mirrors the security
  predicate clauses.
- Switch the unified-log path to a new streaming-bounded runner
  (runCollectorBoundedOutput) that enforces the 4 MiB cap through an
  io.LimitReader BEFORE buffering, and surfaces exit/read errors instead of
  silently truncating.
- Replace floor-truncated `--last Nm` with an explicit `--start <timestamp>`
  (clamped to [now-60m, now]) and stamp lastCollectTime at pass START,
  closing the window-gap that silently dropped events between passes.
- Back off the default collection cadence 5m -> 15m across all four sibling
  defaults (agent, shared zod validator, API resolver, web UI), keeping the
  1-60m server-side configurability intact.

The ReliabilityCollector keeps its own daily pass, but its 24h first-run
lookback is now explicitly documented as applying to DiagnosticReports crash
files only — the unified-log window is intentionally clamped to 60m because
scanning 24h of unified log costs far more than the marginal signal.

Closes #2390

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: 4dc7c92
Status: ✅  Deploy successful!
Preview URL: https://a35a22bc.breeze-9te.pages.dev
Branch Preview URL: https://fix-2390-macos-log-show-subp.breeze-9te.pages.dev

View logs

- Capture capped (4KB) stderr in runCollectorBoundedOutput and include it in
  failure errors so fleet-wide `log show` failures are diagnosable from agent
  Warn logs; add cmd.WaitDelay insurance against an orphaned descendant
  holding the stdout pipe past the timeout.
- Only advance the event-log watermark when every sub-collector succeeded:
  a transient `log show` failure now retries the same window next pass
  (bounded by the 60m clamp; server-side onConflictDoNothing absorbs
  re-collected duplicates) instead of silently dropping both merged
  categories.
- Complete the 5m->15m sibling-default sweep: DB column default (with
  idempotent migration) and the AI-tool event_log example shape.
- Move unifiedLogStartFormat into the platform-neutral file so Linux CI
  compiles it, and pin the exact log(1) --start format in a test.
- Add drift-guard test: EVENT_LOG_DEFAULTS === eventLogInlineSettingsSchema
  defaults (the route test mocks the constant wholesale and would never
  catch divergence).
- Tests for stderr surfacing and the capped stderr buffer.

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, silent-failure-hunter, pr-test-analyzer (parallel), plus a targeted re-check of the fix-up commit.

Findings: 6 raised → all addressed in 1e974d5; 0 outstanding.

  • code-reviewer (important): 5→15 sweep missed the DB column default (configurationPolicies.ts) → fixed + idempotent migration 2026-07-12-event-log-interval-default.sql; (minor) stale collectionIntervalMinutes: 5 in the AI-tool event_log example shape → fixed.
  • silent-failure-hunter (medium): runCollectorBoundedOutput discarded stderr, making log show failures undiagnosable from agent logs → now captures capped 4KB stderr into the failure error; watermark advanced past failed windows, silently dropping both merged categories on transient failure → watermark now only advances when every sub-collector succeeded (retry bounded by the 60m clamp; re-collected duplicates absorbed by device_event_logs_dedup_idx + onConflictDoNothing, verified). (low, taken) cmd.WaitDelay added as orphaned-descendant insurance. (low, declined) ctx-race spurious-timeout and readErr-masks-waitErr orderings are exact parity with the pre-existing runner family and never silent — left as-is.
  • pr-test-analyzer (important): EVENT_LOG_DEFAULTS had no drift guard (route test mocks it wholesale) → added helpers.eventLogDefaults.test.ts pinning it to eventLogInlineSettingsSchema.parse({}); unifiedLogStartFormat lived in the darwin-only file so Linux CI never compiled the one stringly-typed log(1) contract → moved to the platform-neutral file + exact-format test.

Tests: cd agent && go test -race ./internal/collectors/... green (darwin-native, includes all new predicate/classify/clamp/format/bounded-runner tests); GOOS=windows|linux|darwin go build ./... all pass; gofmt clean on touched files. Vitest green: shared inline-settings (51), api agents/eventlogs (2) + new eventLogDefaults (2), web EventLogTab (4). tsc --noEmit clean in shared/api/web. Migration SQL dry-run verified against real Postgres (BEGIN/ROLLBACK). Live end-to-end on a real Mac: one merged log show --start over 10m returned 2,181 entries in 5.9s with correct re-categorization.

Status: review-clean, CI running on the latest push, awaiting maintainer merge. Note the local db:check-drift red is environmental (dev DB hasn't applied pending migrations from main); CI's Check Migrations runs against a fresh DB.

… actual inserts (#2393 round-2 review)

GAP 2 (HIGH): the round-1 all-or-nothing watermark introduced a starvation
coupling — a persistently failing unified-log query froze `since` for the
crash-report and power sub-collectors too. Their windows (unclamped) grew
unboundedly from the frozen seed, and after the maxEvents cap the oldest
(already-sent, server-deduped) events won every pass, silently starving NEW
crash/power events. Fixed with per-source watermarks: each sub-collector
advances only when IT succeeds, so a failing source retries its own bounded
window while healthy sources keep flowing. The fan-out core moved to the
platform-neutral file with a CI-run test proving crash/power events still
flow while unified-log fails persistently.

GAP 1 (MEDIUM): agent retry passes deliberately re-submit windows, and the
API absorbed duplicates via device_event_logs_dedup_idx + onConflictDoNothing
— but enqueueLogForwarding still forwarded the full submitted list, so every
retry re-forwarded duplicates to the org's SIEM. Insert now uses .returning()
and forwarding is gated on the rows that actually inserted; response count /
audit insertedCount now report actual inserts. Test added for the
all-conflicts path.

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

Copy link
Copy Markdown
Collaborator Author

Review addendum — round-2 silent-failure re-review of 1e974d5: 3 findings raised → 2 fixed in d185fcd, 1 declined.

  • GAP 2 (high, fixed): the round-1 all-or-nothing watermark introduced a starvation coupling — a persistently failing unified-log query froze since for the crash-report/power sub-collectors, whose (unclamped) windows then grew unboundedly; after the maxEvents cap the oldest already-sent events won every pass, silently starving NEW crash/power events. Fixed with per-source watermarks: each sub-collector advances only when it succeeds (sourceWatermarks / runEventLogSubCollectors, moved to the platform-neutral file). New CI-run test TestRunEventLogSubCollectorsIsolatesFailingSource proves healthy sources keep advancing and their events keep flowing across passes while a sibling fails persistently; TestSourceWatermarkFallsBackToSeed pins the reliability-collector seeding.
  • GAP 1 (medium, fixed): agent retry passes re-submit windows and the DB absorbed duplicates (device_event_logs_dedup_idx + onConflictDoNothing), but enqueueLogForwarding still forwarded the full submitted list — every retry re-forwarded duplicates to the org's SIEM. Insert now uses .returning() and forwarding is gated on rows that actually inserted; count/audit insertedCount now report actual inserts (the agent ignores the response body — verified sendInventoryData is fire-and-forget). Test added for the all-conflicts path (no forwarding call, count 0).
  • Low (declined): cappedBuffer keeps the first 4KB of stderr rather than prefix+suffix — CLI failure banners front-load the diagnostic; not worth the extra machinery.

Tests after round 2: go test -race ./internal/collectors/... green (incl. the two new watermark tests); GOOS=windows|linux go build ./... pass; gofmt clean. vitest run src/routes/agents/eventlogs.test.ts 3/3 green; tsc --noEmit clean in apps/api.

Status: review-clean at d185fcd, CI running, awaiting maintainer merge.

…nt-log default

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
@ToddHebebrand
ToddHebebrand merged commit 95bd92d into main Jul 13, 2026
43 checks passed
@ToddHebebrand
ToddHebebrand deleted the fix/2390-macos-log-show-subprocess-storm branch July 13, 2026 01:44
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] macOS agent spawned 81,683 subprocesses in 2 days; each 'log show' burns ~3.8s CPU

1 participant