Skip to content

mac_unified_logging: fix infinite json.Decoder error loop (sustained ~113% CPU, silent collection stall)#305

Open
amrik-lc wants to merge 1 commit into
masterfrom
fix-mac-unified-logging-decode-loop
Open

mac_unified_logging: fix infinite json.Decoder error loop (sustained ~113% CPU, silent collection stall)#305
amrik-lc wants to merge 1 commit into
masterfrom
fix-mac-unified-logging-decode-loop

Conversation

@amrik-lc

@amrik-lc amrik-lc commented Jul 7, 2026

Copy link
Copy Markdown

Fixes a bug in the mac_unified_logging adapter observed in the field as sustained ~113% CPU on macOS — with the worse side effect that the adapter had silently stopped collecting logs entirely. Tracked in refractionPOINT/tracking#4458.

Root cause

StartGathering dropped the first line of log stream --style=ndjson output using a throwaway bufio.Reader, which buffers (and then discards) up to 64KB beyond that first line. Depending on startup timing, the json.Decoder created afterwards starts reading mid-JSON-object and returns a SyntaxError. Go's json.Decoder never advances its input past a syntax error, so the read loop degenerated into a permanent hot loop:

  • failed Decode + two fmt.Println per iteration, forever → ~1 core pegged (plus GC churn)
  • the stdout pipe is never read again → it fills → log stream blocks forever in write()zero events ingested until the process is restarted

Diagnosed from a process sample (all on-CPU time under StartGathering.func1fmt.Fprintln/encoding/json.(*SyntaxError).Error) and a spindump showing the log child's output thread blocked in write() since the moment it was forked, days earlier.

Fix

  • Parse the ndjson output line by line with a bufio.Scanner (4MB max line) and json.Unmarshal each line, skipping lines that fail to parse. The non-JSON "Filtering the log data..." header is skipped naturally, so the racy drop-first-line hack is gone. A bad line can now never wedge the stream.
  • Close logs.Channel when the stream ends, so the adapter terminates (and can be restarted by its supervisor) instead of hanging silently if log stream dies.
  • Make StopGathering close-based (sync.Once + close(exit)): idempotent and non-blocking, where the old unbuffered send could block forever if the gatherer wasn't at the select. A watcher goroutine kills the subprocess on stop so a reader blocked in Scan() unblocks.
  • Check cmd.Start()'s error and return it from StartGathering (was previously ignored inside the goroutine).
  • stderr watcher: panic with the actual stderr line instead of panic(err) on a stale nil error from the enclosing scope (which produced a meaningless panic(nil)).
  • client.go: buffer the signal.Notify channel (pre-existing go vet finding; unbuffered signal channels can drop the signal).

Verification

  • gofmt -l clean; go build and go vet pass for GOOS=darwin GOARCH=arm64 and GOOS=linux on the package.
  • Behavior change on decode errors: instead of looping on the same error, the adapter skips the offending line and continues with the next one; if the stream itself ends, the adapter exits instead of spinning.

🤖 Generated with Claude Code

The gatherer dropped the first line of `log stream` output via a
throwaway bufio.Reader, which could buffer and discard up to 64KB
beyond that line. The json.Decoder then started mid-object and hit a
SyntaxError, which json.Decoder never advances past: the loop spun
forever printing the same error (sustained ~113% CPU) while the stdout
pipe filled and `log stream` blocked permanently, so no logs were
collected at all until restart.

Parse the ndjson output line by line with a bufio.Scanner instead and
skip lines that fail to parse (including the non-JSON header line, so
the drop-first-line hack is no longer needed). A bad line can now never
wedge the stream.

Also:
- Close logs.Channel when the stream ends so the adapter shuts down
  instead of hanging silently if `log stream` dies.
- Make StopGathering close-based (idempotent, non-blocking) and kill
  the subprocess so a reader blocked in Scan() unblocks.
- Report the actual stderr line instead of panicking with a stale nil
  err from the enclosing scope.
- Buffer the signal.Notify channel (pre-existing go vet finding).

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.

1 participant