From 641d492cd696fb8ff82c55bf8dc5495abf81e7c9 Mon Sep 17 00:00:00 2001 From: Tam Nhu Tran Date: Sun, 10 May 2026 15:12:40 -0400 Subject: [PATCH 1/5] feat(cliproxy): add OAuth callback traceability across profiles Introduces structured per-phase tracing for OAuth flows so users see branch-specific error messages instead of a generic "token not found" fallback. - New oauth-trace/ module: recorder, redactor, three sinks (in-memory ring buffer, verbose stdout, opt-in JSONL file at ~/.ccs/logs/oauth-YYYYMMDD.log mode 0o600 via CCS_OAUTH_LOG_FILE=1) - Branch-specific diagnostics for: URL-not-displayed, callback-not-observed, binary-error, token-exchange-error, session-expired, token-file-missing; UNKNOWN fallback preserves prior UX - Trace recorder threaded through oauth-process.ts spawn/stdout/stderr/ exit lifecycle; SIGINT/SIGTERM cleanup flushes recorder and records Cancelled - Redactor strips code, state, access_token, refresh_token, id_token, client_secret, code_verifier, device_code, assertion, subject_token, plus Authorization: Bearer headers; covers URL fragments, URL-encoded keys, and arrays - 68 new tests including adversarial regression cases for redactor bypass attempts Phases for paste-callback path and cross-profile failure-matrix deferred to follow-up #1207. Closes #1206 --- .../__tests__/oauth-diagnose-failure.test.ts | 197 +++++++++++++ .../__tests__/oauth-trace-recorder.test.ts | 128 +++++++++ .../__tests__/oauth-trace-redactor.test.ts | 270 ++++++++++++++++++ .../__tests__/oauth-trace-sink-file.test.ts | 94 ++++++ src/cliproxy/auth/oauth-process.ts | 98 ++++++- .../auth/oauth-trace/diagnose-failure.ts | 214 ++++++++++++++ src/cliproxy/auth/oauth-trace/index.ts | 13 + src/cliproxy/auth/oauth-trace/redactor.ts | 119 ++++++++ src/cliproxy/auth/oauth-trace/sink-file.ts | 84 ++++++ src/cliproxy/auth/oauth-trace/sink-memory.ts | 31 ++ .../auth/oauth-trace/sink-verbose-stdout.ts | 42 +++ src/cliproxy/auth/oauth-trace/trace-events.ts | 63 ++++ .../auth/oauth-trace/trace-recorder.ts | 107 +++++++ 13 files changed, 1457 insertions(+), 3 deletions(-) create mode 100644 src/cliproxy/auth/__tests__/oauth-diagnose-failure.test.ts create mode 100644 src/cliproxy/auth/__tests__/oauth-trace-recorder.test.ts create mode 100644 src/cliproxy/auth/__tests__/oauth-trace-redactor.test.ts create mode 100644 src/cliproxy/auth/__tests__/oauth-trace-sink-file.test.ts create mode 100644 src/cliproxy/auth/oauth-trace/diagnose-failure.ts create mode 100644 src/cliproxy/auth/oauth-trace/index.ts create mode 100644 src/cliproxy/auth/oauth-trace/redactor.ts create mode 100644 src/cliproxy/auth/oauth-trace/sink-file.ts create mode 100644 src/cliproxy/auth/oauth-trace/sink-memory.ts create mode 100644 src/cliproxy/auth/oauth-trace/sink-verbose-stdout.ts create mode 100644 src/cliproxy/auth/oauth-trace/trace-events.ts create mode 100644 src/cliproxy/auth/oauth-trace/trace-recorder.ts diff --git a/src/cliproxy/auth/__tests__/oauth-diagnose-failure.test.ts b/src/cliproxy/auth/__tests__/oauth-diagnose-failure.test.ts new file mode 100644 index 00000000..12efb200 --- /dev/null +++ b/src/cliproxy/auth/__tests__/oauth-diagnose-failure.test.ts @@ -0,0 +1,197 @@ +import { describe, expect, test } from 'bun:test'; +import { diagnoseFailure, formatErrorMessage } from '../oauth-trace/diagnose-failure'; +import { OAuthTracePhase, type OAuthTraceEvent } from '../oauth-trace/trace-events'; + +let tCounter = 1000; +function ev(phase: OAuthTracePhase, over: Partial = {}): OAuthTraceEvent { + tCounter += 10; + return { + sessionId: 's', + provider: 'codex', + phase, + ts: tCounter, + elapsedMs: tCounter - 1000, + ...over, + }; +} + +function reset() { + tCounter = 1000; +} + +describe('diagnoseFailure', () => { + test('empty snapshot -> UNKNOWN', () => { + expect(diagnoseFailure([]).branchId).toBe('UNKNOWN'); + }); + + test('URL_NOT_DISPLAYED when no AuthUrlDisplayed and exit=0', () => { + reset(); + const snap = [ + ev(OAuthTracePhase.BinarySpawn), + ev(OAuthTracePhase.BinaryExit, { data: { code: 0 } }), + ]; + expect(diagnoseFailure(snap).branchId).toBe('URL_NOT_DISPLAYED'); + }); + + test('BROWSER_NOT_OPENED after URL displayed past heuristic window', () => { + reset(); + const snap: OAuthTraceEvent[] = [ + { ...ev(OAuthTracePhase.AuthUrlDisplayed), ts: 1000 }, + { ...ev(OAuthTracePhase.BinaryStdout), ts: 1000 + 6000 }, + ]; + expect(diagnoseFailure(snap).branchId).toBe('BROWSER_NOT_OPENED'); + }); + + test('CALLBACK_NEVER_OBSERVED when browser opened, exit=0, no callback heuristic', () => { + reset(); + const snap = [ + ev(OAuthTracePhase.AuthUrlDisplayed), + ev(OAuthTracePhase.BrowserOpened), + ev(OAuthTracePhase.BinaryExit, { data: { code: 0 } }), + ]; + expect(diagnoseFailure(snap).branchId).toBe('CALLBACK_NEVER_OBSERVED'); + }); + + test('BINARY_ERROR_EXIT when exit code non-zero', () => { + reset(); + const snap = [ + ev(OAuthTracePhase.BinarySpawn), + ev(OAuthTracePhase.BinaryExit, { data: { code: 2, stderrTail: 'oops' } }), + ]; + const r = diagnoseFailure(snap); + expect(r.branchId).toBe('BINARY_ERROR_EXIT'); + expect(r.data['code']).toBe(2); + }); + + test('TOKEN_FILE_MISSING_POST_EXIT when token-missing event present', () => { + reset(); + const snap = [ + ev(OAuthTracePhase.AuthUrlDisplayed), + ev(OAuthTracePhase.BrowserOpened), + ev(OAuthTracePhase.CallbackObservedHeuristic), + ev(OAuthTracePhase.BinaryExit, { data: { code: 0 } }), + ev(OAuthTracePhase.TokenFileMissing), + ]; + expect(diagnoseFailure(snap).branchId).toBe('TOKEN_FILE_MISSING_POST_EXIT'); + }); + + test('TIMEOUT when timeout event present', () => { + reset(); + const snap = [ + ev(OAuthTracePhase.BinarySpawn), + ev(OAuthTracePhase.Timeout, { data: { timeoutMs: 120000 } }), + ]; + const r = diagnoseFailure(snap); + expect(r.branchId).toBe('TIMEOUT'); + expect(r.data['timeoutMs']).toBe(120000); + }); + + test('SESSION_CANCELLED on cancel event', () => { + reset(); + const snap = [ev(OAuthTracePhase.Cancelled)]; + expect(diagnoseFailure(snap).branchId).toBe('SESSION_CANCELLED'); + }); + + test('TOKEN_EXCHANGE_REJECTED via Error code=CALLBACK_REJECTED', () => { + reset(); + const snap = [ + ev(OAuthTracePhase.PasteCallbackSubmitted), + ev(OAuthTracePhase.Error, { + error: { code: 'CALLBACK_REJECTED', message: 'invalid_grant' }, + }), + ]; + const r = diagnoseFailure(snap); + expect(r.branchId).toBe('TOKEN_EXCHANGE_REJECTED'); + expect(r.data['upstreamError']).toBe('invalid_grant'); + }); + + test('PASTE_INVALID from invalid event', () => { + reset(); + const snap = [ + ev(OAuthTracePhase.PasteCallbackPrompted), + ev(OAuthTracePhase.PasteCallbackInvalid, { data: { reason: 'missing_code' } }), + ]; + const r = diagnoseFailure(snap); + expect(r.branchId).toBe('PASTE_INVALID'); + expect(r.data['reason']).toBe('missing_code'); + }); + + test('GEMINI_PLUS_MISSING_CRED from explicit error', () => { + reset(); + const snap = [ + ev(OAuthTracePhase.Error, { + error: { code: 'GEMINI_PLUS_MISSING_CRED', message: 'missing' }, + }), + ]; + expect(diagnoseFailure(snap).branchId).toBe('GEMINI_PLUS_MISSING_CRED'); + }); + + test('AGY_RESPONSIBILITY_DECLINED from explicit error', () => { + reset(); + const snap = [ + ev(OAuthTracePhase.Error, { + error: { code: 'AGY_RESPONSIBILITY_DECLINED', message: 'declined' }, + }), + ]; + expect(diagnoseFailure(snap).branchId).toBe('AGY_RESPONSIBILITY_DECLINED'); + }); + + test('diagnose is pure: same input -> same output, no side-effects', () => { + reset(); + const snap = [ev(OAuthTracePhase.BinarySpawn), ev(OAuthTracePhase.Timeout)]; + const a = diagnoseFailure(snap); + const b = diagnoseFailure(snap); + expect(a).toEqual(b); + // ensure snapshot wasn't mutated + expect(snap).toHaveLength(2); + }); +}); + +describe('formatErrorMessage', () => { + const baseOpts = { + verbose: false, + platform: 'linux' as NodeJS.Platform, + callbackPort: 1455, + provider: 'codex', + }; + + test('UNKNOWN preserves backward-compat 3-bullet feel and ends with verbose hint', () => { + const lines = formatErrorMessage({ branchId: 'UNKNOWN', data: {} }, baseOpts); + expect(lines.some((l) => l.includes('Token not found'))).toBe(true); + expect(lines.some((l) => l.startsWith('Try: ccs codex --auth --verbose'))).toBe(true); + // body lines (excluding trailing remediation) ≤ 5 -> not exploding + expect(lines.length).toBeLessThanOrEqual(6); + }); + + test('CALLBACK_NEVER_OBSERVED includes paste-callback hint with provider', () => { + const lines = formatErrorMessage({ branchId: 'CALLBACK_NEVER_OBSERVED', data: {} }, baseOpts); + expect(lines.some((l) => l.includes('--no-browser'))).toBe(true); + }); + + test('CALLBACK_NEVER_OBSERVED on win32 appends netsh hint', () => { + const lines = formatErrorMessage( + { branchId: 'CALLBACK_NEVER_OBSERVED', data: {} }, + { ...baseOpts, platform: 'win32' } + ); + expect(lines.some((l) => l.includes('netsh advfirewall'))).toBe(true); + }); + + test('contains no emoji and no sensitive keys', () => { + const lines = formatErrorMessage( + { branchId: 'BINARY_ERROR_EXIT', data: { code: 7, stderrTail: 'fail' } }, + baseOpts + ); + const blob = lines.join('\n'); + // No common emoji ranges + expect(/[\u{1F300}-\u{1FAFF}\u{2600}-\u{27BF}]/u.test(blob)).toBe(false); + expect(blob).not.toMatch(/access_token|refresh_token|id_token|client_secret/i); + }); + + test('verbose mode appends trace hint line', () => { + const lines = formatErrorMessage( + { branchId: 'UNKNOWN', data: {} }, + { ...baseOpts, verbose: true } + ); + expect(lines.some((l) => l.includes('--verbose'))).toBe(true); + }); +}); diff --git a/src/cliproxy/auth/__tests__/oauth-trace-recorder.test.ts b/src/cliproxy/auth/__tests__/oauth-trace-recorder.test.ts new file mode 100644 index 00000000..86dc7fc8 --- /dev/null +++ b/src/cliproxy/auth/__tests__/oauth-trace-recorder.test.ts @@ -0,0 +1,128 @@ +import { describe, expect, test } from 'bun:test'; +import { createOAuthTraceRecorder } from '../oauth-trace/trace-recorder'; +import { OAuthTracePhase } from '../oauth-trace/trace-events'; +import { REDACTED_PLACEHOLDER } from '../oauth-trace/redactor'; + +function makeRecorder(verbose = false, lines: string[] = []) { + let t = 1000; + const rec = createOAuthTraceRecorder({ + sessionId: 'sess-1', + provider: 'codex', + verbose, + now: () => t, + verboseOut: (line) => lines.push(line), + }); + return { + rec, + advance(ms: number) { + t += ms; + }, + }; +} + +describe('createOAuthTraceRecorder', () => { + test('records event with sessionId and provider correlation', () => { + const { rec } = makeRecorder(); + rec.record(OAuthTracePhase.BinarySpawn); + const snap = rec.snapshot(); + expect(snap).toHaveLength(1); + expect(snap[0].sessionId).toBe('sess-1'); + expect(snap[0].provider).toBe('codex'); + expect(snap[0].phase).toBe(OAuthTracePhase.BinarySpawn); + }); + + test('phase ordering preserved with monotonic elapsedMs', () => { + const { rec, advance } = makeRecorder(); + rec.record(OAuthTracePhase.PreflightOk); + advance(10); + rec.record(OAuthTracePhase.BinarySpawn); + advance(50); + rec.record(OAuthTracePhase.AuthUrlDisplayed); + const snap = rec.snapshot(); + expect(snap.map((e) => e.phase)).toEqual([ + OAuthTracePhase.PreflightOk, + OAuthTracePhase.BinarySpawn, + OAuthTracePhase.AuthUrlDisplayed, + ]); + expect(snap[0].elapsedMs).toBe(0); + expect(snap[1].elapsedMs).toBe(10); + expect(snap[2].elapsedMs).toBe(60); + }); + + test('memory sink returns full event log via snapshot()', () => { + const { rec } = makeRecorder(); + for (let i = 0; i < 5; i++) { + rec.record(OAuthTracePhase.BinaryStdout, { i }); + } + expect(rec.snapshot()).toHaveLength(5); + }); + + test('verbose sink writes only when verbose=true', () => { + const linesOff: string[] = []; + const { rec: off } = makeRecorder(false, linesOff); + off.record(OAuthTracePhase.BinarySpawn); + expect(linesOff).toHaveLength(0); + + const linesOn: string[] = []; + const { rec: on } = makeRecorder(true, linesOn); + on.record(OAuthTracePhase.BinarySpawn, { port: 1455 }); + expect(linesOn).toHaveLength(1); + expect(linesOn[0]).toMatch(/^\[oauth-trace\] \+0ms binary\.spawn/); + expect(linesOn[0]).toContain('port=1455'); + }); + + test('summary returns counts and lastPhase', () => { + const { rec, advance } = makeRecorder(); + rec.record(OAuthTracePhase.BinaryStdout); + rec.record(OAuthTracePhase.BinaryStdout); + advance(5); + rec.record(OAuthTracePhase.BinaryExit); + const s = rec.summary(); + expect(s.phaseCounts[OAuthTracePhase.BinaryStdout]).toBe(2); + expect(s.phaseCounts[OAuthTracePhase.BinaryExit]).toBe(1); + expect(s.lastPhase).toBe(OAuthTracePhase.BinaryExit); + expect(s.totalMs).toBe(5); + }); + + test('snapshot during in-flight events does not throw and returns copy', () => { + const { rec } = makeRecorder(); + rec.record(OAuthTracePhase.BinarySpawn); + const snap = rec.snapshot(); + rec.record(OAuthTracePhase.BinaryExit); + expect(snap).toHaveLength(1); // earlier snapshot unaffected + expect(rec.snapshot()).toHaveLength(2); + }); + + test('redactor invoked: raw OAuth params do not reach sinks', () => { + const lines: string[] = []; + const { rec } = makeRecorder(true, lines); + rec.record(OAuthTracePhase.AuthUrlDisplayed, { + url: 'https://example.com/auth?code=AUTHCODE_SECRET&state=ST', + access_token: 'AT_LEAK', + }); + const snap = rec.snapshot(); + const blob = JSON.stringify(snap) + '\n' + lines.join('\n'); + expect(blob).not.toContain('AUTHCODE_SECRET'); + expect(blob).not.toContain('AT_LEAK'); + expect(blob).toContain(REDACTED_PLACEHOLDER); + }); + + test('flush() resolves even with no file sink', async () => { + const { rec } = makeRecorder(); + rec.record(OAuthTracePhase.BinaryExit); + await expect(rec.flush()).resolves.toBeUndefined(); + }); + + test('error param surfaces as event.error', () => { + const { rec } = makeRecorder(); + rec.record(OAuthTracePhase.Error, { branch: 'X' }, { code: 'E1', message: 'boom' }); + const snap = rec.snapshot(); + expect(snap[0].error).toEqual({ code: 'E1', message: 'boom' }); + }); + + test('Error instance accepted', () => { + const { rec } = makeRecorder(); + rec.record(OAuthTracePhase.Error, undefined, new Error('plain')); + expect(rec.snapshot()[0].error?.message).toBe('plain'); + }); +}); diff --git a/src/cliproxy/auth/__tests__/oauth-trace-redactor.test.ts b/src/cliproxy/auth/__tests__/oauth-trace-redactor.test.ts new file mode 100644 index 00000000..beec9578 --- /dev/null +++ b/src/cliproxy/auth/__tests__/oauth-trace-redactor.test.ts @@ -0,0 +1,270 @@ +import { describe, expect, test } from 'bun:test'; +import { + redactString, + redactUrl, + redactJsonShallow, + redactBearer, + REDACTED_PLACEHOLDER, +} from '../oauth-trace/redactor'; +import { createMemorySink, MEMORY_SINK_MAX_EVENTS } from '../oauth-trace/sink-memory'; + +describe('redactString', () => { + test('redacts code= query value', () => { + const out = redactString('http://localhost:1455/cb?code=AUTHCODE_SECRET&foo=bar'); + expect(out).not.toContain('AUTHCODE_SECRET'); + expect(out).toContain(`code=${REDACTED_PLACEHOLDER}`); + expect(out).toContain('foo=bar'); + }); + + test('redacts state= query value', () => { + const out = redactString('?state=STATE_SECRET&x=1'); + expect(out).not.toContain('STATE_SECRET'); + expect(out).toContain(`state=${REDACTED_PLACEHOLDER}`); + }); + + test('redacts access_token, refresh_token, id_token query values', () => { + const s = '?access_token=A&refresh_token=B&id_token=C'; + const out = redactString(s); + expect(out).not.toContain('access_token=A'); + expect(out).not.toContain('refresh_token=B'); + expect(out).not.toContain('id_token=C'); + }); + + test('redacts bearer header value', () => { + expect(redactString('Authorization: Bearer abc.def.ghi')).toContain( + `Bearer ${REDACTED_PLACEHOLDER}` + ); + }); + + test('preserves non-sensitive params and host/path', () => { + const out = redactString('https://example.com/auth/cb?code=X&client_id=public'); + expect(out).toContain('example.com'); + expect(out).toContain('/auth/cb'); + expect(out).toContain('client_id=public'); + }); + + test('idempotent: redacting twice == once', () => { + const once = redactString('?code=X&state=Y'); + expect(redactString(once)).toBe(once); + }); + + test('empty input passthrough', () => { + expect(redactString('')).toBe(''); + }); +}); + +describe('redactUrl', () => { + test('redacts known sensitive params via URL parser', () => { + const out = redactUrl('https://example.com/cb?code=AUTHCODE&state=ST&keep=1'); + expect(out).toContain(`code=${encodeURIComponent(REDACTED_PLACEHOLDER)}`); + expect(out).toContain(`state=${encodeURIComponent(REDACTED_PLACEHOLDER)}`); + expect(out).toContain('keep=1'); + expect(out).not.toContain('AUTHCODE'); + }); + + test('falls back gracefully on invalid URL', () => { + expect(redactUrl('not a url ?code=X')).toContain(REDACTED_PLACEHOLDER); + }); +}); + +describe('redactJsonShallow', () => { + test('replaces sensitive top-level keys', () => { + const out = redactJsonShallow({ + access_token: 'AT', + refresh_token: 'RT', + id_token: 'IT', + client_secret: 'CS', + keep: 'visible', + }); + expect(out['access_token']).toBe(REDACTED_PLACEHOLDER); + expect(out['refresh_token']).toBe(REDACTED_PLACEHOLDER); + expect(out['id_token']).toBe(REDACTED_PLACEHOLDER); + expect(out['client_secret']).toBe(REDACTED_PLACEHOLDER); + expect(out['keep']).toBe('visible'); + }); + + test('redacts string values for sensitive params inside string fields', () => { + const out = redactJsonShallow({ url: 'https://x/cb?code=SECRET' }); + expect(String(out['url'])).not.toContain('SECRET'); + }); + + test('recurses into nested plain objects', () => { + const out = redactJsonShallow({ + headers: { Authorization: 'Bearer XYZ', host: 'a' }, + }); + const headers = out['headers'] as Record; + expect(headers['Authorization']).toBe(REDACTED_PLACEHOLDER); + expect(headers['host']).toBe('a'); + }); + + test('case-insensitive key match', () => { + const out = redactJsonShallow({ Access_Token: 'X', AUTHORIZATION: 'Y' }); + expect(out['Access_Token']).toBe(REDACTED_PLACEHOLDER); + expect(out['AUTHORIZATION']).toBe(REDACTED_PLACEHOLDER); + }); +}); + +describe('redactBearer', () => { + test('replaces bearer value preserving prefix', () => { + expect(redactBearer('Bearer abc.def.ghi')).toBe(`Bearer ${REDACTED_PLACEHOLDER}`); + }); +}); + +// ---- adversarial / edge-case coverage (findings #1-3, #4, #7) ---- + +describe('redactUrl — fragment leak (finding #1)', () => { + test('redacts code in fragment — first param after #', () => { + const out = redactUrl('https://x/cb#code=SECRET&state=X'); + expect(out).not.toContain('SECRET'); + expect(out).not.toContain('state=X'); + }); + + test('redacts access_token in fragment', () => { + const out = redactUrl('https://x/cb#access_token=AT&token_type=bearer'); + expect(out).not.toContain('AT'); + expect(out).toContain('token_type=bearer'); + }); + + test('non-sensitive fragment params preserved', () => { + const out = redactUrl('https://x/cb#section=1&code=S'); + expect(out).toContain('section=1'); + expect(out).not.toContain('=S'); + }); + + test('Google OAuth fragment flow (real shape)', () => { + const url = + 'https://accounts.google.com/o/oauth2/auth/oauthchooseaccount#access_token=ya29.secret&token_type=Bearer&expires_in=3599'; + const out = redactUrl(url); + expect(out).not.toContain('ya29.secret'); + expect(out).toContain('token_type=Bearer'); + }); +}); + +describe('redactUrl — URL-encoded key bypass (finding #2)', () => { + test('redacts %63%6F%64%65 (= "code") key', () => { + // %63%6F%64%65 is "code" percent-encoded + const out = redactUrl('https://x/cb?%63%6F%64%65=SECRET'); + expect(out).not.toContain('SECRET'); + }); + + test('redacts %73%74%61%74%65 (= "state") key', () => { + const out = redactUrl('https://x/cb?%73%74%61%74%65=STATEVAL'); + expect(out).not.toContain('STATEVAL'); + }); +}); + +describe('redactJsonShallow — array passthrough (finding #3)', () => { + test('redacts access_token inside array of objects', () => { + const out = redactJsonShallow({ tokens: [{ access_token: 'AT', scope: 'read' }] }); + const tokens = out['tokens'] as Array>; + expect(tokens[0]['access_token']).toBe(REDACTED_PLACEHOLDER); + expect(tokens[0]['scope']).toBe('read'); + }); + + test('nested arrays of token objects', () => { + const out = redactJsonShallow({ + batches: [{ tokens: [{ refresh_token: 'RT' }] }], + }); + const batches = out['batches'] as Array>; + const inner = (batches[0]['tokens'] as Array>)[0]; + // Only one level of array recursion; inner object is recursed as plain obj + expect(inner['refresh_token']).toBe(REDACTED_PLACEHOLDER); + }); + + test('mixed-case key Code redacted', () => { + const out = redactJsonShallow({ Code: 'abc', CODE: 'xyz' }); + expect(out['Code']).toBe(REDACTED_PLACEHOLDER); + expect(out['CODE']).toBe(REDACTED_PLACEHOLDER); + }); + + test('string value with url-embedded code is redacted', () => { + const out = redactJsonShallow({ log: 'callback?code=SECRET&state=ST' }); + expect(String(out['log'])).not.toContain('SECRET'); + }); +}); + +describe('PKCE / device-flow keys (finding #4)', () => { + test('redactUrl redacts code_verifier', () => { + const out = redactUrl('https://x/token?code_verifier=VERIFIER&grant_type=pkce'); + expect(out).not.toContain('VERIFIER'); + expect(out).toContain('grant_type=pkce'); + }); + + test('redactUrl redacts device_code', () => { + const out = redactUrl('https://x/token?device_code=DC123'); + expect(out).not.toContain('DC123'); + }); + + test('redactUrl redacts assertion', () => { + const out = redactUrl('https://x/token?assertion=JWT_VAL'); + expect(out).not.toContain('JWT_VAL'); + }); + + test('redactUrl redacts subject_token', () => { + const out = redactUrl('https://x/token?subject_token=ST_VAL'); + expect(out).not.toContain('ST_VAL'); + }); + + test('redactString redacts code_verifier in raw string', () => { + const out = redactString('?code_verifier=MY_VERIFIER&other=1'); + expect(out).not.toContain('MY_VERIFIER'); + expect(out).toContain('other=1'); + }); +}); + +describe('createMemorySink — bounded ring buffer (finding #6)', () => { + test('default capacity is MEMORY_SINK_MAX_EVENTS (1000)', () => { + expect(MEMORY_SINK_MAX_EVENTS).toBe(1000); + }); + + test('older events dropped when capacity exceeded', () => { + const sink = createMemorySink(3); + const makeEvent = (i: number) => + ({ + sessionId: 's', + provider: 'p', + phase: `phase.${i}` as never, + ts: i, + elapsedMs: i, + }) as never; + + sink.write(makeEvent(1)); + sink.write(makeEvent(2)); + sink.write(makeEvent(3)); + sink.write(makeEvent(4)); // should drop event 1 + + const snap = sink.snapshot(); + expect(snap).toHaveLength(3); + expect(snap[0].ts).toBe(2); + expect(snap[2].ts).toBe(4); + }); + + test('droppedCount tracks number of dropped events', () => { + const sink = createMemorySink(2); + const makeEvent = (i: number) => + ({ + sessionId: 's', + provider: 'p', + phase: 'p' as never, + ts: i, + elapsedMs: i, + }) as never; + + sink.write(makeEvent(1)); + sink.write(makeEvent(2)); + expect(sink.droppedCount()).toBe(0); + sink.write(makeEvent(3)); + expect(sink.droppedCount()).toBe(1); + sink.write(makeEvent(4)); + expect(sink.droppedCount()).toBe(2); + }); + + test('snapshot returns copy — mutations do not affect buffer', () => { + const sink = createMemorySink(5); + const ev = { sessionId: 's', provider: 'p', phase: 'x' as never, ts: 1, elapsedMs: 0 }; + sink.write(ev as never); + const snap = sink.snapshot(); + snap.pop(); + expect(sink.snapshot()).toHaveLength(1); + }); +}); diff --git a/src/cliproxy/auth/__tests__/oauth-trace-sink-file.test.ts b/src/cliproxy/auth/__tests__/oauth-trace-sink-file.test.ts new file mode 100644 index 00000000..15e03901 --- /dev/null +++ b/src/cliproxy/auth/__tests__/oauth-trace-sink-file.test.ts @@ -0,0 +1,94 @@ +import { describe, expect, test, beforeEach, afterEach } from 'bun:test'; +import * as fs from 'fs'; +import * as path from 'path'; +import * as os from 'os'; +import { createFileSink } from '../oauth-trace/sink-file'; +import { OAuthTracePhase, type OAuthTraceEvent } from '../oauth-trace/trace-events'; + +let tmpDir: string; + +function makeEvent(over: Partial = {}): OAuthTraceEvent { + return { + sessionId: 'sess-1', + provider: 'codex', + phase: OAuthTracePhase.BinarySpawn, + ts: 1000, + elapsedMs: 0, + ...over, + }; +} + +beforeEach(() => { + tmpDir = fs.mkdtempSync(path.join(os.tmpdir(), 'oauth-trace-test-')); +}); + +afterEach(() => { + fs.rmSync(tmpDir, { recursive: true, force: true }); +}); + +describe('createFileSink', () => { + test('writes one JSONL line per event', () => { + const fixed = new Date(2026, 4, 10); + const sink = createFileSink({ dir: tmpDir, now: () => fixed }); + sink.write(makeEvent({ phase: OAuthTracePhase.BinarySpawn })); + sink.write(makeEvent({ phase: OAuthTracePhase.BinaryExit, elapsedMs: 5 })); + const file = path.join(tmpDir, 'oauth-20260510.log'); + const lines = fs.readFileSync(file, 'utf8').trim().split('\n'); + expect(lines).toHaveLength(2); + const parsed1 = JSON.parse(lines[0]); + expect(parsed1.phase).toBe(OAuthTracePhase.BinarySpawn); + expect(parsed1.sessionId).toBe('sess-1'); + expect(parsed1.provider).toBe('codex'); + }); + + test('file mode is 0600 (user-only)', () => { + const fixed = new Date(2026, 4, 10); + const sink = createFileSink({ dir: tmpDir, now: () => fixed }); + sink.write(makeEvent()); + const file = path.join(tmpDir, 'oauth-20260510.log'); + const mode = fs.statSync(file).mode & 0o777; + expect(mode).toBe(0o600); + }); + + test('rotates by date — different day yields different file', () => { + let day = new Date(2026, 4, 10); + const sink = createFileSink({ dir: tmpDir, now: () => day }); + sink.write(makeEvent({ sessionId: 'a' })); + day = new Date(2026, 4, 11); + sink.write(makeEvent({ sessionId: 'b' })); + expect(fs.existsSync(path.join(tmpDir, 'oauth-20260510.log'))).toBe(true); + expect(fs.existsSync(path.join(tmpDir, 'oauth-20260511.log'))).toBe(true); + }); + + test('write failure does not throw and notifies once', () => { + const errors: string[] = []; + const badDir = path.join(tmpDir, 'nonexistent', 'a', 'b'); + // Force mkdir failure by simulating EROFS via permission-denied path + // (we bypass mkdir error by making `dir` a file) + fs.writeFileSync(path.join(tmpDir, 'as_file'), 'x'); + const sink = createFileSink({ + dir: path.join(tmpDir, 'as_file', 'sub'), + onError: (msg) => errors.push(msg), + }); + expect(() => sink.write(makeEvent())).not.toThrow(); + expect(errors.length).toBeGreaterThanOrEqual(1); + void badDir; + }); + + test('flush resolves cleanly', async () => { + const sink = createFileSink({ dir: tmpDir }); + sink.write(makeEvent()); + await expect(sink.flush?.()).resolves.toBeUndefined(); + }); + + test('concurrent recorders with separate sessionIds both land in file', () => { + const fixed = new Date(2026, 4, 10); + const sink = createFileSink({ dir: tmpDir, now: () => fixed }); + sink.write(makeEvent({ sessionId: 'A' })); + sink.write(makeEvent({ sessionId: 'B' })); + const file = path.join(tmpDir, 'oauth-20260510.log'); + const lines = fs.readFileSync(file, 'utf8').trim().split('\n'); + const ids = lines.map((l) => JSON.parse(l).sessionId).sort(); + expect(ids).toEqual(['A', 'B']); + }); +}); diff --git a/src/cliproxy/auth/oauth-process.ts b/src/cliproxy/auth/oauth-process.ts index 2557fcb7..10c9a806 100644 --- a/src/cliproxy/auth/oauth-process.ts +++ b/src/cliproxy/auth/oauth-process.ts @@ -42,6 +42,12 @@ import { unregisterAuthSession, authSessionEvents, } from '../auth/auth-session-manager'; +import { createOAuthTraceRecorder, OAuthTracePhase, type OAuthTraceRecorder } from './oauth-trace'; +import { redactString } from './oauth-trace/redactor'; +import { createFileSink } from './oauth-trace/sink-file'; +import { diagnoseFailure, formatErrorMessage } from './oauth-trace/diagnose-failure'; +import * as path from 'path'; +import { getCcsDir } from '../../utils/config-manager'; /** Options for OAuth process execution */ export interface OAuthProcessOptions { @@ -575,7 +581,8 @@ async function handleTokenNotFound( nickname: string | undefined, expectedAccountId: string | undefined, verbose: boolean, - failureReason?: string + failureReason?: string, + trace?: OAuthTraceRecorder ): Promise { console.log(''); @@ -611,6 +618,22 @@ async function handleTokenNotFound( return null; } + // Branch-specific diagnosis when trace recorder is wired (Phase 7). + if (trace) { + const diagnosis = diagnoseFailure(trace.snapshot()); + if (diagnosis.branchId !== 'UNKNOWN') { + console.log(fail('Authentication failed')); + const lines = formatErrorMessage(diagnosis, { + verbose, + platform: process.platform, + callbackPort, + provider, + }); + for (const line of lines) console.log(line); + return null; + } + } + console.log(fail('Token not found after authentication')); console.log(''); console.log('The browser showed success but callback was not received.'); @@ -698,10 +721,22 @@ export function executeOAuthProcess(options: OAuthProcessOptions): Promise | null = null; + // Mutable ref so cleanup/handleCancel can flush trace even though `trace` + // is assigned after them. DEFERRED: per-event syscall throttling. + let traceRef: OAuthTraceRecorder | null = null; + // H5: Signal handling - properly kill child process on SIGINT/SIGTERM // H8: Also clear stdinKeepalive interval to prevent memory leak const cleanup = () => { if (stdinKeepalive) clearInterval(stdinKeepalive); + if (traceRef) { + try { + traceRef.record(OAuthTracePhase.Cancelled, { reason: 'signal' }); + void traceRef.flush(); + } catch { + // never block shutdown on trace errors + } + } if (authProcess && authProcess.exitCode === null) { killWithEscalation(authProcess); } @@ -724,6 +759,25 @@ export function executeOAuthProcess(options: OAuthProcessOptions): Promise { if (cancelledSessionId === state.sessionId && authProcess && authProcess.exitCode === null) { log('Session cancelled externally'); + if (traceRef) { + try { + traceRef.record(OAuthTracePhase.Cancelled, { reason: 'external' }); + void traceRef.flush(); + } catch { + // never block shutdown on trace errors + } + } killWithEscalation(authProcess); } }; @@ -754,13 +816,30 @@ export function executeOAuthProcess(options: OAuthProcessOptions): Promise { - await handleStdout(data.toString(), state, options, authProcess, log); + const out = data.toString(); + const wasUrlDisplayed = state.urlDisplayed; + const wasBrowserOpened = state.browserOpened; + await handleStdout(out, state, options, authProcess, log); + if (!wasUrlDisplayed && state.urlDisplayed) { + trace.record(OAuthTracePhase.AuthUrlDisplayed, {}); + } + if (!wasBrowserOpened && state.browserOpened) { + trace.record(OAuthTracePhase.BrowserOpened, { port: callbackPort }); + // CLIProxyAPI emits "Callback server listening" when bind succeeds; treat as + // best-available signal that the loopback path is reachable. This is a heuristic. + trace.record(OAuthTracePhase.CallbackObservedHeuristic, { port: callbackPort }); + } + // Capture redacted snippet (cap at 200 chars; high-frequency lines accepted as data). + const snippet = redactString(out.trim().slice(0, 200)); + if (snippet) trace.record(OAuthTracePhase.BinaryStdout, { snippet }); }); authProcess.stderr?.on('data', async (data: Buffer) => { const output = data.toString(); state.stderrData += output; log(`stderr: ${output.trim()}`); + const snippet = redactString(output.trim().slice(0, 200)); + if (snippet) trace.record(OAuthTracePhase.BinaryStderr, { snippet }); if (headless && !state.urlDisplayed) { displayUrlFromStderr(output, state, oauthConfig); } @@ -828,6 +907,8 @@ export function executeOAuthProcess(options: OAuthProcessOptions): Promise; +} + +const BROWSER_OPEN_HEURISTIC_MS = 5000; + +/** + * Pure function: read a recorder snapshot and decide which failure branch fits best. + * No side effects, no console writes. + */ +export function diagnoseFailure(snapshot: OAuthTraceEvent[]): DiagnosisResult { + if (snapshot.length === 0) { + return { branchId: 'UNKNOWN', data: {} }; + } + + const has = (phase: OAuthTracePhase) => snapshot.some((e) => e.phase === phase); + const last = (phase: OAuthTracePhase) => [...snapshot].reverse().find((e) => e.phase === phase); + const lastError = [...snapshot].reverse().find((e) => e.phase === OAuthTracePhase.Error); + + // Provider gate aborts (highest priority — explicit error code) + if (lastError?.error?.code === 'GEMINI_PLUS_MISSING_CRED') { + return { branchId: 'GEMINI_PLUS_MISSING_CRED', data: lastError.data ?? {} }; + } + if (lastError?.error?.code === 'AGY_RESPONSIBILITY_DECLINED') { + return { branchId: 'AGY_RESPONSIBILITY_DECLINED', data: lastError.data ?? {} }; + } + if (lastError?.error?.code === 'CALLBACK_REJECTED') { + return { + branchId: 'TOKEN_EXCHANGE_REJECTED', + data: { upstreamError: lastError.error.message, ...(lastError.data ?? {}) }, + }; + } + + if (has(OAuthTracePhase.PasteCallbackInvalid)) { + const ev = last(OAuthTracePhase.PasteCallbackInvalid); + return { branchId: 'PASTE_INVALID', data: ev?.data ?? {} }; + } + + if (has(OAuthTracePhase.Cancelled)) { + return { branchId: 'SESSION_CANCELLED', data: {} }; + } + + if (has(OAuthTracePhase.Timeout)) { + const ev = last(OAuthTracePhase.Timeout); + return { branchId: 'TIMEOUT', data: ev?.data ?? {} }; + } + + const exitEv = last(OAuthTracePhase.BinaryExit); + if (exitEv) { + const code = (exitEv.data?.code as number | undefined) ?? null; + if (code !== null && code !== 0) { + return { + branchId: 'BINARY_ERROR_EXIT', + data: { + code, + stderrTail: exitEv.data?.stderrTail ?? '', + }, + }; + } + } + + // exit=0 (or no exit) plus token-file states + if (has(OAuthTracePhase.TokenFileMissing)) { + return { branchId: 'TOKEN_FILE_MISSING_POST_EXIT', data: {} }; + } + + if (!has(OAuthTracePhase.AuthUrlDisplayed)) { + return { branchId: 'URL_NOT_DISPLAYED', data: {} }; + } + + // URL was displayed: did browser open within heuristic window? + if (!has(OAuthTracePhase.BrowserOpened)) { + const urlEv = last(OAuthTracePhase.AuthUrlDisplayed); + const lastTs = snapshot[snapshot.length - 1].ts; + if (urlEv && lastTs - urlEv.ts >= BROWSER_OPEN_HEURISTIC_MS) { + return { branchId: 'BROWSER_NOT_OPENED', data: {} }; + } + } + + if ( + has(OAuthTracePhase.BrowserOpened) && + !has(OAuthTracePhase.CallbackObservedHeuristic) && + has(OAuthTracePhase.BinaryExit) + ) { + return { branchId: 'CALLBACK_NEVER_OBSERVED', data: {} }; + } + + return { branchId: 'UNKNOWN', data: {} }; +} + +export interface FormatErrorOptions { + verbose: boolean; + platform: NodeJS.Platform; + callbackPort: number | null; + provider: string; +} + +/** + * Map a diagnosed branch to user-facing message lines (ASCII only, no emojis). + * Always ends with a concrete next-step command. + */ +export function formatErrorMessage(result: DiagnosisResult, opts: FormatErrorOptions): string[] { + const { branchId, data } = result; + const { provider, callbackPort, platform, verbose } = opts; + const lines: string[] = []; + + switch (branchId) { + case 'URL_NOT_DISPLAYED': + lines.push('OAuth URL was never produced.'); + lines.push('The CLIProxy binary may have failed to start or exited too early.'); + lines.push(`Try: ccs ${provider} --auth --verbose`); + break; + + case 'BROWSER_NOT_OPENED': + lines.push('OAuth URL was displayed but the browser did not open.'); + lines.push('Copy the URL above and open it manually in any browser.'); + break; + + case 'CALLBACK_NEVER_OBSERVED': + lines.push( + `Browser completed login but no callback reached localhost:${callbackPort ?? '?'}.` + ); + lines.push('Common cause: firewall, antivirus, or browser on a different machine.'); + lines.push(`Try paste-callback mode: ccs ${provider} --auth --no-browser`); + if (platform === 'win32' && callbackPort) { + lines.push('On Windows, try as Administrator:'); + lines.push( + ` netsh advfirewall firewall add rule name="CCS OAuth" dir=in action=allow protocol=TCP localport=${callbackPort}` + ); + } + break; + + case 'BINARY_ERROR_EXIT': { + const code = (data['code'] as number | undefined) ?? '?'; + lines.push(`CLIProxy binary exited with code ${code}.`); + const tail = String(data['stderrTail'] ?? '').trim(); + if (tail) lines.push(` ${tail}`); + lines.push(`Try: ccs ${provider} --auth --verbose`); + break; + } + + case 'TOKEN_FILE_MISSING_POST_EXIT': + lines.push('Authentication appeared to succeed but no token file was created.'); + lines.push('Update CLIProxy and retry: ccs update'); + break; + + case 'TIMEOUT': { + const min = data['timeoutMs'] ? Math.round((data['timeoutMs'] as number) / 60000) : '?'; + lines.push(`OAuth flow timed out after ${min} minutes.`); + lines.push(`Re-run and complete login faster: ccs ${provider} --auth`); + break; + } + + case 'SESSION_CANCELLED': + lines.push('OAuth flow was cancelled.'); + break; + + case 'TOKEN_EXCHANGE_REJECTED': + lines.push( + `Token exchange rejected by provider: ${String(data['upstreamError'] ?? 'unknown')}.` + ); + lines.push(`Try: ccs ${provider} --auth --verbose`); + break; + + case 'PASTE_INVALID': + lines.push(`Pasted callback URL invalid: ${String(data['reason'] ?? 'unknown')}.`); + lines.push('Re-run and paste the full URL after browser login.'); + break; + + case 'GEMINI_PLUS_MISSING_CRED': + lines.push('Gemini-plus OAuth credentials missing.'); + lines.push('See: docs/providers/gemini.md'); + break; + + case 'AGY_RESPONSIBILITY_DECLINED': + lines.push('Antigravity responsibility prompt was declined.'); + lines.push(`Re-run and accept to proceed: ccs ${provider} --auth`); + break; + + case 'UNKNOWN': + default: + lines.push('Token not found after authentication'); + lines.push('Common causes:'); + lines.push(' 1. OAuth session timed out'); + lines.push(' 2. Callback server could not receive the redirect'); + lines.push(' 3. Browser did not redirect to localhost properly'); + lines.push(`Try: ccs ${provider} --auth --verbose`); + break; + } + + if (verbose) { + lines.push(''); + lines.push('Run with --verbose for the trace summary.'); + } + + return lines; +} diff --git a/src/cliproxy/auth/oauth-trace/index.ts b/src/cliproxy/auth/oauth-trace/index.ts new file mode 100644 index 00000000..d81164bf --- /dev/null +++ b/src/cliproxy/auth/oauth-trace/index.ts @@ -0,0 +1,13 @@ +export { OAuthTracePhase, type OAuthTraceEvent, type OAuthTraceSink } from './trace-events'; +export { + createOAuthTraceRecorder, + type OAuthTraceRecorder, + type OAuthTraceRecorderOptions, +} from './trace-recorder'; +export { + redactString, + redactUrl, + redactJsonShallow, + redactBearer, + REDACTED_PLACEHOLDER, +} from './redactor'; diff --git a/src/cliproxy/auth/oauth-trace/redactor.ts b/src/cliproxy/auth/oauth-trace/redactor.ts new file mode 100644 index 00000000..328d9744 --- /dev/null +++ b/src/cliproxy/auth/oauth-trace/redactor.ts @@ -0,0 +1,119 @@ +/** + * OAuth secret redactor — single choke point. + * + * Every value reaching any sink passes through these helpers first. + * Adding a new sensitive key here is the only place it has to change. + * + * DEFERRED: per-event syscall throttling; fsync / file-size cap on file sink. + */ + +const SENSITIVE_QUERY_KEYS = [ + 'code', + 'state', + 'access_token', + 'refresh_token', + 'id_token', + 'client_secret', + 'authorization', + // PKCE / device-flow / assertion keys + 'code_verifier', + 'device_code', + 'assertion', + 'subject_token', +] as const; + +const SENSITIVE_OBJECT_KEYS = new Set( + SENSITIVE_QUERY_KEYS.map((k) => k.toLowerCase()).concat(['authorization', 'bearer', 'token']) +); + +const REDACTED = '***REDACTED***'; + +/** + * Matches sensitive keys in query strings, fragments, and standard params. + * Lookbehind covers: `?`, `&`, `#`, and `&#` (fragment-then-amp) delimiters. + * Keys are decoded before matching to catch URL-encoded bypass attempts. + */ +const QUERY_PARAM_REGEX = new RegExp( + `(?<=[?&#])(${SENSITIVE_QUERY_KEYS.join('|')})=[^&#\\s]+`, + 'gi' +); + +const BEARER_REGEX = /Bearer\s+[A-Za-z0-9._\-~+/=]+/gi; + +/** Redact sensitive query-param values inside any string. Idempotent. */ +export function redactString(s: string): string { + if (!s) return s; + return s + .replace(QUERY_PARAM_REGEX, (_full, key) => `${key}=${REDACTED}`) + .replace(BEARER_REGEX, `Bearer ${REDACTED}`); +} + +/** Redact a parsed URL by name; returns redacted href or original on parse error. */ +export function redactUrl(u: string): string { + try { + const url = new URL(u); + + // Redact query params — URL parser already decoded keys, compare decoded. + for (const key of SENSITIVE_QUERY_KEYS) { + if (url.searchParams.has(key)) url.searchParams.set(key, REDACTED); + } + // Also catch URL-encoded key names that URL.searchParams may not normalise + // (e.g. `?%63%6F%64%65=SECRET`). Decode all keys and re-check. + for (const [rawKey, rawVal] of [...url.searchParams.entries()]) { + const decoded = decodeURIComponent(rawKey).toLowerCase(); + if ( + (SENSITIVE_OBJECT_KEYS.has(decoded) || SENSITIVE_QUERY_KEYS.includes(decoded as never)) && + rawVal !== REDACTED + ) { + url.searchParams.set(rawKey, REDACTED); + } + } + + // Redact fragment — strip leading `#`, prepend `?` so QUERY_PARAM_REGEX + // matches the first param (lookbehind requires `?`, `&`, or `#`). + if (url.hash) { + const bare = url.hash.slice(1); // remove leading '#' + const fakeQuery = `?${bare}`; + const redacted = redactString(fakeQuery); + url.hash = redacted.slice(1); // put back without the fake '?' + } + + return url.toString(); + } catch { + return redactString(u); + } +} + +/** + * Shallow-redact a plain object. Returns a new object; original is not mutated. + * Arrays are recursed so token arrays (e.g. `{tokens:[{access_token:'AT'}]}`) + * do not bypass redaction. + */ +export function redactJsonShallow(input: Record): Record { + const out: Record = {}; + for (const [key, value] of Object.entries(input)) { + if (SENSITIVE_OBJECT_KEYS.has(key.toLowerCase())) { + out[key] = REDACTED; + } else if (typeof value === 'string') { + out[key] = redactString(value); + } else if (Array.isArray(value)) { + out[key] = value.map((item) => + item && typeof item === 'object' && !Array.isArray(item) + ? redactJsonShallow(item as Record) + : item + ); + } else if (value && typeof value === 'object') { + out[key] = redactJsonShallow(value as Record); + } else { + out[key] = value; + } + } + return out; +} + +/** Redact an Authorization header value. */ +export function redactBearer(header: string): string { + return header.replace(BEARER_REGEX, `Bearer ${REDACTED}`); +} + +export const REDACTED_PLACEHOLDER = REDACTED; diff --git a/src/cliproxy/auth/oauth-trace/sink-file.ts b/src/cliproxy/auth/oauth-trace/sink-file.ts new file mode 100644 index 00000000..1e3e5e39 --- /dev/null +++ b/src/cliproxy/auth/oauth-trace/sink-file.ts @@ -0,0 +1,84 @@ +import * as fs from 'fs'; +import * as path from 'path'; +import { OAuthTraceEvent, OAuthTraceSink } from './trace-events'; + +/** + * Append-mode JSONL file sink. Off by default; enabled when callers pass an instance. + * + * - File path: `${dir}/oauth-YYYYMMDD.log` (date from `now()` per write call). + * - Permissions: dir 0o700, file 0o600 (user-only). World-readable would leak machine info. + * - Failure-tolerant: if write fails (disk full, perm denied), logs once to stderr and + * keeps dropping events silently — sink must never throw out of `write()`. + */ +export interface FileSinkOptions { + dir: string; + /** Test seam — defaults to `() => new Date()`. */ + now?: () => Date; + /** Test seam — error notifier (defaults to one-shot stderr write). */ + onError?: (msg: string) => void; +} + +export function createFileSink(options: FileSinkOptions): OAuthTraceSink { + const now = options.now ?? (() => new Date()); + let warned = false; + const onError = + options.onError ?? + ((msg: string) => { + if (!warned) { + warned = true; + process.stderr.write(`[oauth-trace] file sink disabled: ${msg}\n`); + } + }); + + let cachedDate: string | null = null; + + function ensureDir(): void { + fs.mkdirSync(options.dir, { recursive: true, mode: 0o700 }); + } + + function dateStr(d: Date): string { + const yyyy = d.getFullYear().toString().padStart(4, '0'); + const mm = (d.getMonth() + 1).toString().padStart(2, '0'); + const dd = d.getDate().toString().padStart(2, '0'); + return `${yyyy}${mm}${dd}`; + } + + function pathForToday(): string { + const ds = dateStr(now()); + cachedDate = ds; + return path.join(options.dir, `oauth-${ds}.log`); + } + + function appendOne(event: OAuthTraceEvent): void { + const file = pathForToday(); + const line = JSON.stringify(event) + '\n'; + let fd: number | null = null; + try { + ensureDir(); + fd = fs.openSync(file, 'a', 0o600); + fs.writeSync(fd, line); + } finally { + if (fd !== null) { + try { + fs.closeSync(fd); + } catch { + // ignore + } + } + } + } + + return { + write(event) { + try { + appendOne(event); + } catch (err) { + onError((err as Error).message); + } + }, + async flush() { + // appendSync paths are flushed per-write; no buffer to drain. + void cachedDate; + }, + }; +} diff --git a/src/cliproxy/auth/oauth-trace/sink-memory.ts b/src/cliproxy/auth/oauth-trace/sink-memory.ts new file mode 100644 index 00000000..6a98b773 --- /dev/null +++ b/src/cliproxy/auth/oauth-trace/sink-memory.ts @@ -0,0 +1,31 @@ +import { OAuthTraceEvent, OAuthTraceSink } from './trace-events'; + +/** Default ring-buffer capacity. Keeps latest N events; oldest are dropped. */ +export const MEMORY_SINK_MAX_EVENTS = 1000; + +/** + * In-memory ring buffer sink. Used for diagnose-failure analysis after a flow ends. + * Caps at MAX_EVENTS to bound memory; oldest are dropped when full. + * `droppedCount` tracks how many events were discarded so callers know data loss occurred. + */ +export function createMemorySink( + maxEvents = MEMORY_SINK_MAX_EVENTS +): OAuthTraceSink & { snapshot(): OAuthTraceEvent[]; droppedCount(): number } { + const events: OAuthTraceEvent[] = []; + let dropped = 0; + return { + write(event) { + if (events.length >= maxEvents) { + events.shift(); + dropped++; + } + events.push(event); + }, + snapshot() { + return events.slice(); + }, + droppedCount() { + return dropped; + }, + }; +} diff --git a/src/cliproxy/auth/oauth-trace/sink-verbose-stdout.ts b/src/cliproxy/auth/oauth-trace/sink-verbose-stdout.ts new file mode 100644 index 00000000..b2275453 --- /dev/null +++ b/src/cliproxy/auth/oauth-trace/sink-verbose-stdout.ts @@ -0,0 +1,42 @@ +import { OAuthTraceSink } from './trace-events'; + +/** + * Verbose stdout sink. Writes one ASCII line per event when verbose=true. + * Format: `[oauth-trace] +{elapsedMs}ms {phase} {key=val ...}` + * No emojis (CCS terminal rule). Goes to stderr to avoid mingling with normal stdout. + */ +export function createVerboseStdoutSink(opts: { + enabled: boolean; + out?: (line: string) => void; +}): OAuthTraceSink { + const out = opts.out ?? ((line: string) => process.stderr.write(line + '\n')); + return { + write(event) { + if (!opts.enabled) return; + const parts: string[] = []; + parts.push(`[oauth-trace] +${event.elapsedMs}ms ${event.phase}`); + if (event.data) { + for (const [k, v] of Object.entries(event.data)) { + if (v === undefined) continue; + parts.push(`${k}=${formatValue(v)}`); + } + } + if (event.error) { + parts.push(`error_code=${event.error.code ?? 'unknown'}`); + parts.push(`error_msg="${event.error.message.replace(/"/g, "'")}"`); + } + out(parts.join(' ')); + }, + }; +} + +function formatValue(v: unknown): string { + if (v === null) return 'null'; + if (typeof v === 'string') return v.includes(' ') ? `"${v.replace(/"/g, "'")}"` : v; + if (typeof v === 'number' || typeof v === 'boolean') return String(v); + try { + return JSON.stringify(v); + } catch { + return '[unserializable]'; + } +} diff --git a/src/cliproxy/auth/oauth-trace/trace-events.ts b/src/cliproxy/auth/oauth-trace/trace-events.ts new file mode 100644 index 00000000..b7671d71 --- /dev/null +++ b/src/cliproxy/auth/oauth-trace/trace-events.ts @@ -0,0 +1,63 @@ +/** + * OAuth trace event taxonomy. + * + * Single source of truth for phase IDs that flow through the OAuth pipeline. + * Additive only — never remove or renumber. + */ + +export enum OAuthTracePhase { + // Pre-flight + PreflightStart = 'preflight.start', + PreflightOk = 'preflight.ok', + PreflightPortBlocked = 'preflight.port_blocked', + + // Binary process lifecycle (CLIProxyAPI Go binary) + BinarySpawn = 'binary.spawn', + BinaryStdout = 'binary.stdout', + BinaryStderr = 'binary.stderr', + BinaryExit = 'binary.exit', + + // Browser / URL flow (Authorization Code) + AuthUrlDisplayed = 'auth.url_displayed', + BrowserOpened = 'browser.opened', + CallbackObservedHeuristic = 'callback.observed_heuristic', + + // Paste-callback (CCS-owned end-to-end) + PasteCallbackPrompted = 'paste.prompted', + PasteCallbackReceived = 'paste.received', + PasteCallbackInvalid = 'paste.invalid', + PasteCallbackSubmitted = 'paste.submitted', + + // Token exchange + persistence + TokenExchangePending = 'token.exchange_pending', + TokenFileAppeared = 'token.file_appeared', + TokenFileMissing = 'token.file_missing', + + // Provider-specific gates (Phase 4/5 extend) + ProjectSelectionPrompted = 'project.selection_prompted', + ProjectSelectionResolved = 'project.selection_resolved', + AgyResponsibilityPrompted = 'agy.responsibility_prompted', + AgyResponsibilityResolved = 'agy.responsibility_resolved', + + // Terminal states + Timeout = 'timeout', + Cancelled = 'cancelled', + Error = 'error', +} + +/** A single OAuth trace event. `data` MUST be redacted before construction. */ +export interface OAuthTraceEvent { + sessionId: string; + provider: string; + phase: OAuthTracePhase; + ts: number; // Date.now() + elapsedMs: number; // since recorder.start() + data?: Record; + error?: { code?: string; message: string }; +} + +/** Sink interface — accept events that have already been redacted. */ +export interface OAuthTraceSink { + write(event: OAuthTraceEvent): void; + flush?(): Promise; +} diff --git a/src/cliproxy/auth/oauth-trace/trace-recorder.ts b/src/cliproxy/auth/oauth-trace/trace-recorder.ts new file mode 100644 index 00000000..5cf14c17 --- /dev/null +++ b/src/cliproxy/auth/oauth-trace/trace-recorder.ts @@ -0,0 +1,107 @@ +import { OAuthTraceEvent, OAuthTracePhase, OAuthTraceSink } from './trace-events'; +import { createMemorySink } from './sink-memory'; +import { createVerboseStdoutSink } from './sink-verbose-stdout'; +import { redactJsonShallow } from './redactor'; + +export interface OAuthTraceRecorder { + record( + phase: OAuthTracePhase, + data?: Record, + error?: { code?: string; message: string } | Error + ): void; + snapshot(): OAuthTraceEvent[]; + summary(): { + totalMs: number; + phaseCounts: Record; + lastPhase?: OAuthTracePhase; + }; + flush(): Promise; +} + +export interface OAuthTraceRecorderOptions { + sessionId: string; + provider: string; + verbose: boolean; + fileSink?: OAuthTraceSink; + /** Test seam — defaults to `Date.now`. */ + now?: () => number; + /** Test seam — override verbose sink output channel. */ + verboseOut?: (line: string) => void; +} + +/** + * Create a per-attempt recorder. Always wires: + * - memory sink (read via `snapshot()`) + * - verbose stdout sink (no-op when verbose=false) + * - optional file sink (Phase 8) + * + * All event data passes through the redactor before reaching any sink. + */ +export function createOAuthTraceRecorder(options: OAuthTraceRecorderOptions): OAuthTraceRecorder { + const now = options.now ?? Date.now; + const start = now(); + const memory = createMemorySink(); + const verbose = createVerboseStdoutSink({ enabled: options.verbose, out: options.verboseOut }); + const sinks: OAuthTraceSink[] = [memory, verbose]; + if (options.fileSink) sinks.push(options.fileSink); + + const phaseCounts: Record = {}; + let lastPhase: OAuthTracePhase | undefined; + + function toErrorObj( + err: { code?: string; message: string } | Error | undefined + ): { code?: string; message: string } | undefined { + if (!err) return undefined; + if (err instanceof Error) { + return { message: err.message }; + } + return { code: err.code, message: err.message }; + } + + return { + record(phase, data, error) { + const ts = now(); + const elapsedMs = ts - start; + const redacted = data ? redactJsonShallow(data) : undefined; + const event: OAuthTraceEvent = { + sessionId: options.sessionId, + provider: options.provider, + phase, + ts, + elapsedMs, + data: redacted, + error: toErrorObj(error), + }; + phaseCounts[phase] = (phaseCounts[phase] ?? 0) + 1; + lastPhase = phase; + for (const sink of sinks) { + try { + sink.write(event); + } catch { + // Sinks must never throw out — drop on failure. + } + } + }, + snapshot() { + return memory.snapshot(); + }, + summary() { + return { + totalMs: now() - start, + phaseCounts: { ...phaseCounts }, + lastPhase, + }; + }, + async flush() { + for (const sink of sinks) { + if (sink.flush) { + try { + await sink.flush(); + } catch { + // ignore + } + } + } + }, + }; +} From 15e0e62bd884283f8076f137a3ee65a7ed321973 Mon Sep 17 00:00:00 2001 From: Tam Nhu Tran Date: Sun, 10 May 2026 18:22:17 -0400 Subject: [PATCH 2/5] ci: trigger fresh CI run after claw runner recovery From c02c66dcd116715e7ea7557a0b539920acc24038 Mon Sep 17 00:00:00 2001 From: Tam Nhu Tran Date: Sun, 10 May 2026 18:23:53 -0400 Subject: [PATCH 3/5] ci(ai-review): move PR-Agent jobs to ubuntu-latest The qodo-ai/pr-agent Docker action requires the GitHub event payload at /github/workflow/event.json inside the action container. On self-hosted runners that themselves run inside a Docker container (e.g. myoung34/github-runner), the host docker daemon resolves the volume mount /tmp/runner/work/_temp/_github_workflow:/github/workflow against the host filesystem, where the runner's /tmp path does not exist. The action container starts with an empty /github/workflow mount and fails with FileNotFoundError on event.json. AI review jobs do not need self-hosted runner access (no bun cache, no internal infra). Switch both dispatch-review and pr-agent jobs to ubuntu-latest so the volume mount resolves on the same host where the action expects it. --- .github/workflows/ai-review.yml | 4 ++-- tests/unit/scripts/github/ai-review-workflow.test.ts | 11 +++++++++-- 2 files changed, 11 insertions(+), 4 deletions(-) diff --git a/.github/workflows/ai-review.yml b/.github/workflows/ai-review.yml index 40e84de8..b8125720 100644 --- a/.github/workflows/ai-review.yml +++ b/.github/workflows/ai-review.yml @@ -37,7 +37,7 @@ jobs: dispatch-review: name: Queue /review comment if: github.event_name == 'workflow_dispatch' - runs-on: [self-hosted, cliproxy] + runs-on: ubuntu-latest permissions: issues: write @@ -86,7 +86,7 @@ jobs: ) ) ) - runs-on: [self-hosted, cliproxy] + runs-on: ubuntu-latest timeout-minutes: 20 permissions: issues: write diff --git a/tests/unit/scripts/github/ai-review-workflow.test.ts b/tests/unit/scripts/github/ai-review-workflow.test.ts index 55d3efb3..d6787594 100644 --- a/tests/unit/scripts/github/ai-review-workflow.test.ts +++ b/tests/unit/scripts/github/ai-review-workflow.test.ts @@ -7,7 +7,7 @@ function resolvePath(relativePath: string) { } describe('PR-Agent review lane migration', () => { - test('keeps ai-review.yml as the PR-Agent workflow on the self-hosted cliproxy runner', () => { + test('keeps ai-review.yml as the PR-Agent workflow on a GitHub-hosted runner', () => { const workflowPath = resolvePath('../../../../.github/workflows/ai-review.yml'); const prAgentConfigPath = resolvePath('../../../../.pr_agent.toml'); @@ -19,7 +19,14 @@ describe('PR-Agent review lane migration', () => { const appTokenUsages = workflow.match(/uses: actions\/create-github-app-token@v1/g) ?? []; expect(workflow).toContain('name: AI Code Review'); - expect(workflow).toContain('runs-on: [self-hosted, cliproxy]'); + // AI review jobs run on GitHub-hosted runners. Self-hosted runners that + // run inside a Docker container (myoung34/github-runner) cannot host + // qodo-ai/pr-agent because the action's docker run command uses a volume + // mount path (/tmp/runner/work/_temp/_github_workflow) that resolves on + // the host filesystem, not inside the runner container, leaving + // /github/workflow/event.json missing in the action. + expect(workflow).toContain('runs-on: ubuntu-latest'); + expect(workflow).not.toContain('runs-on: [self-hosted, cliproxy]'); expect(workflow).toContain('uses: qodo-ai/pr-agent'); expect(appTokenUsages).toHaveLength(2); expect(workflow).toContain('OPENAI.API_BASE'); From 43ece40c2165c6dc989d368f8bceaed3d00f3dd6 Mon Sep 17 00:00:00 2001 From: Tam Nhu Tran Date: Sun, 10 May 2026 18:30:05 -0400 Subject: [PATCH 4/5] Revert "ci(ai-review): move PR-Agent jobs to ubuntu-latest" This reverts the runs-on change for ai-review.yml. All CI/CD must stay on home infra (claw, docker LXC, etc); GitHub-hosted runners are forbidden. The qodo-ai/pr-agent docker action mount issue will be addressed by either configuring the self-hosted runner image to use path-identical bind mounts so nested-docker volume sources resolve correctly, or by switching to native CLI invocation (pip install pr-agent) instead of the docker action. Tracked separately; not blocking PR #1209. --- .github/workflows/ai-review.yml | 4 ++-- tests/unit/scripts/github/ai-review-workflow.test.ts | 11 ++--------- 2 files changed, 4 insertions(+), 11 deletions(-) diff --git a/.github/workflows/ai-review.yml b/.github/workflows/ai-review.yml index b8125720..40e84de8 100644 --- a/.github/workflows/ai-review.yml +++ b/.github/workflows/ai-review.yml @@ -37,7 +37,7 @@ jobs: dispatch-review: name: Queue /review comment if: github.event_name == 'workflow_dispatch' - runs-on: ubuntu-latest + runs-on: [self-hosted, cliproxy] permissions: issues: write @@ -86,7 +86,7 @@ jobs: ) ) ) - runs-on: ubuntu-latest + runs-on: [self-hosted, cliproxy] timeout-minutes: 20 permissions: issues: write diff --git a/tests/unit/scripts/github/ai-review-workflow.test.ts b/tests/unit/scripts/github/ai-review-workflow.test.ts index d6787594..55d3efb3 100644 --- a/tests/unit/scripts/github/ai-review-workflow.test.ts +++ b/tests/unit/scripts/github/ai-review-workflow.test.ts @@ -7,7 +7,7 @@ function resolvePath(relativePath: string) { } describe('PR-Agent review lane migration', () => { - test('keeps ai-review.yml as the PR-Agent workflow on a GitHub-hosted runner', () => { + test('keeps ai-review.yml as the PR-Agent workflow on the self-hosted cliproxy runner', () => { const workflowPath = resolvePath('../../../../.github/workflows/ai-review.yml'); const prAgentConfigPath = resolvePath('../../../../.pr_agent.toml'); @@ -19,14 +19,7 @@ describe('PR-Agent review lane migration', () => { const appTokenUsages = workflow.match(/uses: actions\/create-github-app-token@v1/g) ?? []; expect(workflow).toContain('name: AI Code Review'); - // AI review jobs run on GitHub-hosted runners. Self-hosted runners that - // run inside a Docker container (myoung34/github-runner) cannot host - // qodo-ai/pr-agent because the action's docker run command uses a volume - // mount path (/tmp/runner/work/_temp/_github_workflow) that resolves on - // the host filesystem, not inside the runner container, leaving - // /github/workflow/event.json missing in the action. - expect(workflow).toContain('runs-on: ubuntu-latest'); - expect(workflow).not.toContain('runs-on: [self-hosted, cliproxy]'); + expect(workflow).toContain('runs-on: [self-hosted, cliproxy]'); expect(workflow).toContain('uses: qodo-ai/pr-agent'); expect(appTokenUsages).toHaveLength(2); expect(workflow).toContain('OPENAI.API_BASE'); From 9d0690e1a86291e93ac775c9ffd06f8e0a0dc974 Mon Sep 17 00:00:00 2001 From: Tam Nhu Tran Date: Sun, 10 May 2026 20:23:02 -0400 Subject: [PATCH 5/5] test(ci): make routing mock complete and websearch trace path env-robust Two pre-existing test bugs surfaced under CCS CI on the new claw self- hosted runners but stayed hidden locally: 1. tests/unit/commands/cliproxy-routing-subcommand.test.ts mocks the routing-subcommand module with only 3 exports, but src/commands/cliproxy/index.ts statically imports 6. Bun resolves the static import graph against the mock and reports SyntaxError: Export named 'handleRoutingAffinitySet' not found for every test in the file. Add the missing 3 exports (handleRoutingAffinityStatus, handleRoutingAffinityHelp, handleRoutingAffinitySet) to the mock and document why the mock must mirror every named export of the target module. 2. tests/unit/hooks/websearch-transformer.test.ts builds the "disallowed" trace path from process.cwd() and from os.homedir(). Both fall under the os.tmpdir() safe-prefix in two real environments: CI runners with cwd == /tmp/runner/work/... and Bun test isolation that re-roots HOME under tmpdir. The hook treats them as safe, writes the trace, and the assertion that the file does NOT exist fails. Anchor disallowedTracePath under /etc/... instead so it cannot satisfy the tmpdir, /var/log, or /.ccs/logs prefixes in any host environment. Both fixes are independent of the OAuth callback traceability change that this branch otherwise carries, but ship together so the PR clears CI on the new runner stack. --- .../commands/cliproxy-routing-subcommand.test.ts | 12 ++++++++++++ tests/unit/hooks/websearch-transformer.test.ts | 10 +++++++++- 2 files changed, 21 insertions(+), 1 deletion(-) diff --git a/tests/unit/commands/cliproxy-routing-subcommand.test.ts b/tests/unit/commands/cliproxy-routing-subcommand.test.ts index 40d6385c..217179bc 100644 --- a/tests/unit/commands/cliproxy-routing-subcommand.test.ts +++ b/tests/unit/commands/cliproxy-routing-subcommand.test.ts @@ -16,6 +16,18 @@ describe('cliproxy routing command dispatch', () => { handleRoutingSet: async (args: string[]) => { calls.push(`set:${args.join(' ')}`); }, + // Mock module must expose every named export `cliproxy/index.ts` + // statically imports from this module, otherwise Bun reports + // `Export named 'X' not found` at module-graph resolution time. + handleRoutingAffinityStatus: async () => { + calls.push('affinity:status'); + }, + handleRoutingAffinityHelp: async () => { + calls.push('affinity:help'); + }, + handleRoutingAffinitySet: async (args: string[]) => { + calls.push(`affinity:set:${args.join(' ')}`); + }, })); }); diff --git a/tests/unit/hooks/websearch-transformer.test.ts b/tests/unit/hooks/websearch-transformer.test.ts index 6aea3175..646d1530 100644 --- a/tests/unit/hooks/websearch-transformer.test.ts +++ b/tests/unit/hooks/websearch-transformer.test.ts @@ -618,7 +618,15 @@ global.fetch = async (url) => { const preloadPath = join(tempDir, 'mock-fetch.cjs'); const ccsHome = join(tempDir, 'home'); const fallbackTracePath = join(ccsHome, '.ccs', 'logs', 'websearch-trace.jsonl'); - const disallowedTracePath = join(process.cwd(), '.tmp-websearch-trace-unsafe.jsonl'); + // disallowedTracePath MUST NOT start with any safe prefix (tmpdir(), + // /var/log, or /.ccs/logs). Anchoring under cwd or homedir + // is unsafe in CI/Bun-test environments where those paths can fall + // under /tmp (CI runner workspace) or under tmpdir (Bun's HOME + // isolation), which would falsely satisfy the tmpdir prefix. Use a + // root-anchored path outside every safe prefix so the hook MUST + // reject it. The hook writes via try/catch; a permission denial here + // also leaves the file absent. + const disallowedTracePath = '/etc/ccs-test-disallowed-websearch-trace-' + Date.now() + '.jsonl'; const html = ` Example title Example snippet