From 3dbb804f3e477b60ca82d4fa4e3df713dd986a82 Mon Sep 17 00:00:00 2001 From: Neil <4138956+nwparker@users.noreply.github.com> Date: Sun, 18 Oct 2026 14:25:39 -0700 Subject: [PATCH] fix(macos): the TCC prompt watcher's log stream dies with Orca, and old orphans are reclaimed (#30148) * fix(macos): the TCC prompt watcher's log stream dies with Orca log stream only writes when its predicate matches (about never), so it never gets SIGPIPE when Orca dies without running stop() (crash, SIGKILL, e2e teardown, force-quit dev builds) and lived on under launchd. One dev machine had 126 orphans holding 566 MB and ~40% CPU. A /bin/sh wrapper now holds a never-written stdin pipe from Orca and kills log stream on EOF. * fix(macos): reclaim TCC log streams that older builds orphaned The wrapper stops new leaks, but users upgrading still have every log stream an earlier crash or force-quit left under launchd. Ten seconds after launch, once per process, Orca terminates launchd-parented processes running exactly the watcher's old command line. A live watcher's log stream is parented by its wrapper, so it never matches. * test(macos): document the fake log stream cast * fix(macos): arm log stream wrapper trap before fork; verify orphan executable * fix(macos): re-read orphan identity before SIGTERM; disable inherited errexit in wrapper --- src/main/macos-tcc-log-stream-orphans.test.ts | 85 +++++++++++++++++++ src/main/macos-tcc-log-stream-orphans.ts | 82 ++++++++++++++++++ src/main/macos-tcc-prompt-notice.test.ts | 3 + src/main/macos-tcc-prompt-notice.ts | 10 +++ src/main/macos-tcc-prompt-watch.test.ts | 23 ++++- src/main/macos-tcc-prompt-watch.ts | 41 +++++++-- 6 files changed, 233 insertions(+), 11 deletions(-) create mode 100644 src/main/macos-tcc-log-stream-orphans.test.ts create mode 100644 src/main/macos-tcc-log-stream-orphans.ts diff --git a/src/main/macos-tcc-log-stream-orphans.test.ts b/src/main/macos-tcc-log-stream-orphans.test.ts new file mode 100644 index 00000000000..a5c8f2ab7fd --- /dev/null +++ b/src/main/macos-tcc-log-stream-orphans.test.ts @@ -0,0 +1,85 @@ +import { describe, expect, it, vi } from 'vitest' +import { + findOrphanedTccLogStreams, + reclaimOrphanedTccLogStreams +} from './macos-tcc-log-stream-orphans' +import { parsePsArgsLine, type ProcessIdentityRow } from './opencode/opencode-client-sweep' + +// Captured from `ps -eo pid=,ppid=,etime=,args=` on a Mac holding leaked watchers. +const LEGACY_ARGS = + '/usr/bin/log stream --predicate subsystem == "com.apple.TCC" AND eventMessage CONTAINS "AUTHREQ_PROMPTING" --info --style compact' + +function row( + pid: number, + ppid: number, + args = LEGACY_ARGS, + executable = '/usr/bin/log' +): ProcessIdentityRow { + const parsed = parsePsArgsLine(`${pid} ${ppid} 01:00 ${args}`, Date.now()) + if (!parsed) { + throw new Error('unparseable fixture') + } + return { ...parsed, executable } +} + +describe('findOrphanedTccLogStreams', () => { + it('matches only launchd-parented copies of the exact watcher command', () => { + expect( + findOrphanedTccLogStreams([ + row(10, 1), + row(11, 4321), + row(12, 1, '/usr/bin/log stream --predicate subsystem == "com.apple.TCC" --style compact'), + row(13, 1, '/usr/bin/log show --last 1m'), + // A pid recycled between the args and comm sweeps, or an unreadable comm. + row(14, 1, LEGACY_ARGS, '/usr/bin/yes'), + row(15, 1, LEGACY_ARGS, '') + ]).map((match) => match.pid) + ).toEqual([10]) + }) +}) + +describe('reclaimOrphanedTccLogStreams', () => { + it('terminates each orphan and tolerates ones that already exited', async () => { + const kill = vi.fn((pid: number) => { + if (pid === 21) { + throw new Error('ESRCH') + } + }) + const reclaimed = await reclaimOrphanedTccLogStreams({ + platform: 'darwin', + sweep: async () => [row(20, 1), row(21, 1), row(22, 99)], + readProcess: async (pid) => row(pid, 1), + kill + }) + expect(kill.mock.calls).toEqual([ + [20, 'SIGTERM'], + [21, 'SIGTERM'] + ]) + expect(reclaimed).toBe(1) + }) + + it('skips a pid whose identity changed or cannot be re-read before signalling', async () => { + const kill = vi.fn() + const restarted = { ...row(42, 1), startedAtMs: Date.now() + 60_000 } + const current = new Map([ + [40, null], + [41, row(41, 1, '/usr/bin/log stream --style compact')], + [42, restarted], + [43, row(43, 777)] + ]) + const reclaimed = await reclaimOrphanedTccLogStreams({ + platform: 'darwin', + sweep: async () => [row(40, 1), row(41, 1), row(42, 1), row(43, 1)], + readProcess: async (pid) => current.get(pid) ?? null, + kill + }) + expect(kill).not.toHaveBeenCalled() + expect(reclaimed).toBe(0) + }) + + it('never sweeps off macOS', async () => { + const sweep = vi.fn(async () => [row(30, 1)]) + expect(await reclaimOrphanedTccLogStreams({ platform: 'linux', sweep })).toBe(0) + expect(sweep).not.toHaveBeenCalled() + }) +}) diff --git a/src/main/macos-tcc-log-stream-orphans.ts b/src/main/macos-tcc-log-stream-orphans.ts new file mode 100644 index 00000000000..8503fab6354 --- /dev/null +++ b/src/main/macos-tcc-log-stream-orphans.ts @@ -0,0 +1,82 @@ +import { runProcess } from '@orca/process-host' +import { + parsePsArgsLine, + splitCommandLineArgv, + sweepProcessIdentities, + type ProcessIdentityRow +} from './opencode/opencode-client-sweep' +import { LOG_PREDICATE } from './macos-tcc-prompt-watch' + +/** The exact argv that Orca builds before the sh wrapper spawned `log stream` directly. */ +const LEGACY_LOG_STREAM_COMMAND = splitCommandLineArgv( + ['/usr/bin/log', 'stream', '--predicate', LOG_PREDICATE, '--info', '--style', 'compact'].join(' ') +).join(' ') + +// Why: `etime` has 1 s resolution and two reads of it can straddle a tick. +const START_TIME_TOLERANCE_MS = 2_000 + +function isLegacyOrphan(row: ProcessIdentityRow): boolean { + return row.ppid === 1 && row.argv.join(' ') === LEGACY_LOG_STREAM_COMMAND +} + +/** + * Why: older builds left this `log stream` running under launchd whenever Orca died + * uncleanly, and those orphans outlive every later launch. A live watcher's + * `log stream` is parented by its wrapper, so only launchd's children (ppid 1) match. + * `executable` comes from a later `ps` than argv, so a pid recycled between them fails. + */ +export function findOrphanedTccLogStreams( + rows: readonly ProcessIdentityRow[] +): ProcessIdentityRow[] { + return rows.filter((row) => row.executable === '/usr/bin/log' && isLegacyOrphan(row)) +} + +/** One-snapshot re-read of a single pid, so its ppid, start time and argv agree. */ +async function readProcessIdentity(pid: number): Promise { + const result = await runProcess({ + program: 'ps', + args: ['-o', 'pid=,ppid=,etime=,args=', '-p', String(pid)], + timeoutMs: 5_000 + }) + return result.code === 0 && !result.timedOut ? parsePsArgsLine(result.stdout, Date.now()) : null +} + +export async function reclaimOrphanedTccLogStreams( + deps: { + platform?: NodeJS.Platform + sweep?: () => Promise + readProcess?: (pid: number) => Promise + kill?: (pid: number, signal: NodeJS.Signals) => void + } = {} +): Promise { + if ((deps.platform ?? process.platform) !== 'darwin') { + return 0 + } + const readProcess = deps.readProcess ?? readProcessIdentity + const kill = deps.kill ?? ((pid, signal) => process.kill(pid, signal)) + let reclaimed = 0 + for (const candidate of findOrphanedTccLogStreams( + await (deps.sweep ?? sweepProcessIdentities)() + )) { + try { + // Why: the sweep joins two `ps` snapshots, so re-read right before signalling + // and skip anything whose identity changed or can no longer be confirmed. + const current = await readProcess(candidate.pid) + if ( + !current || + !isLegacyOrphan(current) || + Math.abs(current.startedAtMs - candidate.startedAtMs) > START_TIME_TOLERANCE_MS + ) { + continue + } + kill(candidate.pid, 'SIGTERM') + reclaimed++ + } catch { + // Already gone, or another user's process. + } + } + if (reclaimed > 0) { + console.info(`[tcc-prompt-watch] reclaimed ${reclaimed} orphaned log stream process(es)`) + } + return reclaimed +} diff --git a/src/main/macos-tcc-prompt-notice.test.ts b/src/main/macos-tcc-prompt-notice.test.ts index e8745b67c61..2190f13211b 100644 --- a/src/main/macos-tcc-prompt-notice.test.ts +++ b/src/main/macos-tcc-prompt-notice.test.ts @@ -10,6 +10,9 @@ vi.mock('./codex-accounts/fs-utils', () => ({ writeFileAtomically: (...args: unknown[]) => writeFileAtomically(...args) })) vi.mock('./persistence', () => ({ getCanonicalUserDataPath: () => '/tmp/orca-tcc-notice-test' })) +vi.mock('./macos-tcc-log-stream-orphans', () => ({ + reclaimOrphanedTccLogStreams: vi.fn(async () => 0) +})) vi.mock('./macos-tcc-prompt-watch', () => ({ MacosTccPromptWatch: class { constructor(options: { onPrompt: () => void }) { diff --git a/src/main/macos-tcc-prompt-notice.ts b/src/main/macos-tcc-prompt-notice.ts index c51367d8c6a..595b8fe9363 100644 --- a/src/main/macos-tcc-prompt-notice.ts +++ b/src/main/macos-tcc-prompt-notice.ts @@ -4,6 +4,7 @@ import type { BrowserWindow } from 'electron' import { writeFileAtomically } from './codex-accounts/fs-utils' import { getCanonicalUserDataPath } from './persistence' import { MacosTccPromptWatch } from './macos-tcc-prompt-watch' +import { reclaimOrphanedTccLogStreams } from './macos-tcc-log-stream-orphans' /** * Surfaces Full Disk Access guidance only to users macOS is actually prompting @@ -53,6 +54,7 @@ let nextClaimId = 0 let pendingClaim: { claimId: number; ownerToken: number } | null = null let deferredWatchStartTimer: ReturnType | null = null let deferredWatchStartGeneration = 0 +let orphanReclaimScheduled = false function tallyPath(): string { return join(getCanonicalUserDataPath(), 'macos-tcc-prompt-tally.json') @@ -223,6 +225,14 @@ export function initTccPromptNotice( if (process.platform !== 'darwin') { return } + if (!orphanReclaimScheduled) { + orphanReclaimScheduled = true + // Why: runs even after the notice is dismissed, since older builds' orphans are still alive. + setTimeout( + () => void reclaimOrphanedTccLogStreams(), + TCC_PROMPT_WATCH_START_FALLBACK_MS + ).unref() + } if (watch) { trackMainWindow(mainWindow) startWatchAfterFirstVisibleProgress( diff --git a/src/main/macos-tcc-prompt-watch.test.ts b/src/main/macos-tcc-prompt-watch.test.ts index a0e9d9370a6..025cbc843f4 100644 --- a/src/main/macos-tcc-prompt-watch.test.ts +++ b/src/main/macos-tcc-prompt-watch.test.ts @@ -91,12 +91,16 @@ describe('isOrcaAttributedPrompt', () => { function createFakeLogStream(): { child: LogStreamChild + stdin: PassThrough stdout: PassThrough killed: string[] } { + const stdin = new PassThrough() const stdout = new PassThrough() const killed: string[] = [] + // oxlint-disable-next-line typescript/consistent-type-assertions -- SAFETY: the watcher only touches stdin/stdout/kill and EventEmitter events, all provided here. const child = Object.assign(new EventEmitter(), { + stdin, stdout, stderr: new PassThrough(), kill: (signal?: string) => { @@ -104,7 +108,7 @@ function createFakeLogStream(): { return true } }) as unknown as LogStreamChild - return { child, stdout, killed } + return { child, stdin, stdout, killed } } // Why: the watcher is darwin-gated, so CI (Linux) would silently no-op every @@ -158,11 +162,26 @@ describe('MacosTccPromptWatch', () => { }) it('kills the child on stop so it cannot outlive app quit', () => { - const { child, killed } = createFakeLogStream() + const { child, stdin, killed } = createFakeLogStream() const watch = new MacosTccPromptWatch({ onPrompt: vi.fn(), spawnLogStream: () => child }) watch.start() watch.stop() expect(killed).toEqual(['SIGTERM']) + // Why: closing the parent-death pipe is the backstop if the wrapper missed the signal. + expect(stdin.destroyed).toBe(true) + }) + + it('closes the parent-death pipe of a child that terminated on its own', () => { + const { child, stdin } = createFakeLogStream() + const watch = new MacosTccPromptWatch({ + onPrompt: vi.fn(), + spawnLogStream: () => child, + restartDelayMs: 60_000 + }) + watch.start() + child.emit('exit', 1) + expect(stdin.destroyed).toBe(true) + watch.stop() }) it('restarts once after an unexpected termination without creating a retry loop', async () => { diff --git a/src/main/macos-tcc-prompt-watch.ts b/src/main/macos-tcc-prompt-watch.ts index acff095a82b..95d65a99e31 100644 --- a/src/main/macos-tcc-prompt-watch.ts +++ b/src/main/macos-tcc-prompt-watch.ts @@ -1,9 +1,9 @@ import { spawn, type ChildProcessByStdio } from 'node:child_process' import { createInterface, type Interface } from 'node:readline' -import type { Readable } from 'node:stream' +import type { Readable, Writable } from 'node:stream' -/** Why: stdin is 'ignore', so this is narrower than ChildProcessWithoutNullStreams. */ -export type LogStreamChild = ChildProcessByStdio +/** Why: stdin is a never-written pipe whose EOF tells the wrapper that Orca died. */ +export type LogStreamChild = ChildProcessByStdio /** * Counts the macOS TCC consent dialogs that name Orca as the responsible @@ -36,7 +36,8 @@ const WATCHED_SERVICES = new Set([ 'kTCCServiceSystemPolicyDownloadsFolder' ]) -const LOG_PREDICATE = 'subsystem == "com.apple.TCC" AND eventMessage CONTAINS "AUTHREQ_PROMPTING"' +export const LOG_PREDICATE = + 'subsystem == "com.apple.TCC" AND eventMessage CONTAINS "AUTHREQ_PROMPTING"' export type TccPromptEvent = { /** TCC service the dialog was raised for, e.g. `kTCCServiceSystemPolicyAppData`. */ @@ -88,14 +89,33 @@ export type TccPromptWatchOptions = { restartDelayMs?: number } +// Why: `log stream` never notices its parent dying (it only writes on a rare +// match), so a crashed or SIGKILLed Orca orphaned it forever. The wrapper kills +// it when our stdin pipe hits EOF, and exits when it exits. fd 3 is needed +// because async lists in a non-interactive sh get stdin=/dev/null. The trap is +// armed before the fork; `term` covers a signal that lands before `log_pid` is set. +// `set +eu` because an inherited SHELLOPTS=errexit would end the reader on read's EOF status. +const LOG_STREAM_WRAPPER_SCRIPT = `set +eu +exec 3<&0 +log_pid= +term= +trap 'term=1; [ -n "$log_pid" ] && kill "$log_pid" 2>/dev/null' TERM INT HUP +/usr/bin/log stream --predicate "$1" --info --style compact /dev/null +{ read -r _ <&3; kill "$log_pid" 2>/dev/null; } & +reader_pid=$! +wait "$log_pid" +status=$? +kill "$reader_pid" 2>/dev/null +exit "$status"` + function spawnDefaultLogStream(): LogStreamChild { // Why: the predicate is evaluated inside the logging system, so this delivers // ~1 line per real dialog instead of the ~30/s the TCC subsystem emits raw. - return spawn( - '/usr/bin/log', - ['stream', '--predicate', LOG_PREDICATE, '--info', '--style', 'compact'], - { stdio: ['ignore', 'pipe', 'pipe'] } - ) + return spawn('/bin/sh', ['-c', LOG_STREAM_WRAPPER_SCRIPT, 'sh', LOG_PREDICATE], { + stdio: ['pipe', 'pipe', 'pipe'] + }) } /** @@ -138,6 +158,8 @@ export class MacosTccPromptWatch { this.reader?.close() this.reader = null this.child = null + // Why: EOF on stdin makes any surviving wrapper reader kill its log stream. + child.stdin.destroy() if (this.stopped || this.restartAttempted) { return } @@ -167,6 +189,7 @@ export class MacosTccPromptWatch { this.reader = null // Why: log stream ignores a closed stdout, so the child needs an explicit kill or it outlives quit. this.child?.kill('SIGTERM') + this.child?.stdin.destroy() this.child = null } }