fix(mac_unified_logging): supervise log stream, shed on stall, fix shutdown#295
fix(mac_unified_logging): supervise log stream, shed on stall, fix shutdown#295maximelb wants to merge 2 commits into
Conversation
…utdown The adapter could not recover from any subprocess-level disruption without a full process restart, and a prolonged downstream stall (e.g. the USP output blocked for a long time) could leave it permanently degraded: - The decoder fed an UNBUFFERED channel, so a stalled consumer backed the stall up through the stdout pipe into the `log stream` process itself (logd drops, and the long-lived subprocess can stay degraded after the stall clears). - The `log stream` subprocess was never supervised: no Wait(), no exit detection, no restart. If it died or degraded, the adapter shipped nothing (or less) forever while keeping a healthy-looking connection. - json.Decoder errors spun in a tight loop forever (a Decoder does not resync after garbage) instead of restarting the subprocess. - Any stderr output tore down gathering and then called panic() on a nil error; the channel was never closed, leaving the sender goroutine blocked on range forever: process up, connection up, zero events. - Close() called Done() on a WaitGroup that was never Add()ed (panic), and the sender goroutine never released wgSenders, so chStopped could never fire. Rework: - Buffered channel (4096) decouples the subprocess from the network; when the consumer stalls past the buffer, SHED and count, reporting the shed count every minute — never block the logd pipe silently. - Supervisor loop restarts `log stream` (5s backoff) on exit or decode desync, reaping the subprocess properly (Kill, drain stderr, Wait). - stderr lines are surfaced as warnings (log stream emits informational notices there) instead of killing gathering. - Clean shutdown: StopGathering is idempotent, kills the subprocess to unblock a parked decoder, closes the channel so the sender exits, and Close() waits on the right WaitGroup. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Self-review of the resilience rework found a deadlock and some rough edges: - Close() deadlock: it waited on the sender goroutine (wgSenders.Wait) BEFORE closing the uspClient. If handleEvents was parked in the infinite Ship(_, 0) retry (full buffer during an uplink stall — the exact condition this PR targets), nothing released it: the wait hung and uspClient.Close() was never reached. Reordered to stop the gatherer, Drain + Close the client (which unblocks a parked Ship), THEN wait — matching the bounded shutdown idiom used by the stdin and syslog adapters. A new isRunning flag makes handleEvents drain the channel without re-shipping (and without error spam) once closing. - Quiet the spurious "decode failed, restarting subprocess" warning on a clean stop (the decode error there is just our own kill). - Make the `log stream` command injectable (streamCommand var) and restartBackoff a var, so the supervisor/shed/stop/restart logic is testable without a real macOS `log` binary. log.go has no build constraint, so these tests run on Linux CI. - Add log_test.go: header drop + ordered delivery, restart-on-exit, shed-when-consumer-stalls (with shed-count reporting), and idempotent StopGathering closing the channel. Passes under -race. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
|
Self-review pass — found and fixed one real deadlock plus smaller issues (commit b15a204): Deadlock in Smaller fixes:
Added Verified: One thing I deliberately did NOT add: process-group kill. |
2 participants
Problem
The macOS Unified Logging adapter cannot recover from any subprocess-level disruption without a full process restart, and a prolonged downstream stall (USP output blocked for an extended period — e.g. a long server-side disruption) can leave it permanently degraded at a fraction of its real event rate while looking perfectly healthy (process up, websocket connected, keepalives flowing).
Specific defects in the previous implementation:
logd. The decoder fed an unbuffered channel; a stalledShip()(which retries with an infinite timeout onErrorBufferFull) froze the decoder, filled the 64KB stdout pipe, and blocked thelog streamprocess itself for the duration of the stall. Besides guaranteed data loss, a long-livedlog streamleft in that state can remain degraded after the stall clears.cmd.Start()with noWait(), exit detection, or restart — a dead or degradedlog streamsilently meant fewer/no events forever.json.Decoderdoes not resync after garbage; the loop printed to stdout and retried the same error indefinitely.log streamwrites informational notices, including under pressure) tore down gathering and calledpanic()on a capturednilerror; the channel was never closed, so the sender goroutine blocked onrangeforever — connected and mute.Close()calledDone()on a never-Add()ed WaitGroup (panic), and the sender never releasedwgSenders, so the stopped-channel could never fire.Fix
logdpipe is always drained.log stream(5s backoff) on subprocess exit or decoder desync, reaping it correctly (Kill → drain stderr to EOF → Wait, respecting the os/exec pipe rules).StopGatheringis idempotent, kills the subprocess to unblock a parked decoder, closes the channel so the sender exits, andClose()waits on the correct WaitGroup.Verification
GOOS=darwin go build ./mac_unified_logging/andGOOS=darwin go vet ./mac_unified_logging/clean (linux noop build unchanged).NewLogs/StartGatheringare package-scoped usage only); the adapter's public constructor/Close signatures are unchanged.log stream-death before merge, since CI cannot exercise darwin subprocess behavior.🤖 Generated with Claude Code