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
This commit is contained in:
Tam Nhu Tran
2026-05-10 15:12:40 -04:00
parent 3af2cf68d4
commit 641d492cd6
13 changed files with 1457 additions and 3 deletions
@@ -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> = {}): 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);
});
});
@@ -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');
});
});
@@ -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<string, unknown>;
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<Record<string, unknown>>;
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<Record<string, unknown>>;
const inner = (batches[0]['tokens'] as Array<Record<string, unknown>>)[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);
});
});
@@ -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> = {}): 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']);
});
});
+95 -3
View File
@@ -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<AccountInfo | null> {
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<Accou
// H7: Mutable ref for stdin keepalive interval (set later, needed in cleanup)
let stdinKeepalive: ReturnType<typeof setInterval> | 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<Accou
cancelManualCallbackPrompt: null,
};
// OAuth trace recorder — opt-in file sink via CCS_OAUTH_LOG_FILE=1
const fileSink =
process.env['CCS_OAUTH_LOG_FILE'] === '1'
? createFileSink({ dir: path.join(getCcsDir(), 'logs') })
: undefined;
const trace = createOAuthTraceRecorder({
sessionId: state.sessionId,
provider,
verbose,
fileSink,
});
traceRef = trace; // wire late-binding ref for cleanup/handleCancel
trace.record(OAuthTracePhase.BinarySpawn, {
callbackPort,
headless,
manualCallback: !!options.manualCallback,
flowType,
});
// Register session for cancellation support
registerAuthSession(state.sessionId, provider);
attachProcessToSession(state.sessionId, authProcess);
@@ -732,6 +786,14 @@ export function executeOAuthProcess(options: OAuthProcessOptions): Promise<Accou
const handleCancel = (cancelledSessionId: string) => {
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<Accou
}
authProcess.stdout?.on('data', async (data: Buffer) => {
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<Accou
authSessionEvents.removeListener('session:cancelled', handleCancel);
unregisterAuthSession(state.sessionId);
cancelProjectSelection(state.sessionId);
trace.record(OAuthTracePhase.Timeout, { timeoutMs });
void trace.flush();
killWithEscalation(authProcess);
console.log('');
console.log(fail(`OAuth timed out after ${timeoutMs / 60000} minutes`));
@@ -849,6 +930,10 @@ export function executeOAuthProcess(options: OAuthProcessOptions): Promise<Accou
unregisterAuthSession(state.sessionId);
cancelProjectSelection(state.sessionId);
const elapsed = ((Date.now() - startTime) / 1000).toFixed(1);
trace.record(OAuthTracePhase.BinaryExit, {
code,
stderrTail: redactString(state.stderrData.trim().split('\n').pop() ?? ''),
});
if (code === 0) {
const exitAnalysis = analyzeSuccessfulAuthExit({
@@ -861,6 +946,8 @@ export function executeOAuthProcess(options: OAuthProcessOptions): Promise<Accou
});
if (exitAnalysis.tokenSnapshot) {
trace.record(OAuthTracePhase.TokenFileAppeared, {});
await trace.flush();
console.log('');
console.log(ok(`Authentication successful (${elapsed}s)`));
@@ -881,6 +968,8 @@ export function executeOAuthProcess(options: OAuthProcessOptions): Promise<Accou
});
}
trace.record(OAuthTracePhase.TokenFileMissing, {});
await trace.flush();
// Try auto-import for Kiro, show error for others
const account = await handleTokenNotFound(
provider,
@@ -889,7 +978,8 @@ export function executeOAuthProcess(options: OAuthProcessOptions): Promise<Accou
nickname,
expectedAccountId,
verbose,
exitAnalysis.failureReason || undefined
exitAnalysis.failureReason || undefined,
trace
);
resolve(account);
}
@@ -918,6 +1008,8 @@ export function executeOAuthProcess(options: OAuthProcessOptions): Promise<Accou
authSessionEvents.removeListener('session:cancelled', handleCancel);
unregisterAuthSession(state.sessionId);
cancelProjectSelection(state.sessionId);
trace.record(OAuthTracePhase.Error, {}, error);
void trace.flush();
console.log('');
console.log(fail(`Failed to start auth process: ${error.message}`));
resolve(null);
@@ -0,0 +1,214 @@
import { OAuthTraceEvent, OAuthTracePhase } from './trace-events';
export type FailureBranchId =
| 'URL_NOT_DISPLAYED'
| 'BROWSER_NOT_OPENED'
| 'CALLBACK_NEVER_OBSERVED'
| 'BINARY_ERROR_EXIT'
| 'TOKEN_FILE_MISSING_POST_EXIT'
| 'TIMEOUT'
| 'SESSION_CANCELLED'
| 'TOKEN_EXCHANGE_REJECTED'
| 'PASTE_INVALID'
| 'GEMINI_PLUS_MISSING_CRED'
| 'AGY_RESPONSIBILITY_DECLINED'
| 'UNKNOWN';
export interface DiagnosisResult {
branchId: FailureBranchId;
data: Record<string, unknown>;
}
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;
}
+13
View File
@@ -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';
+119
View File
@@ -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<string, unknown>): Record<string, unknown> {
const out: Record<string, unknown> = {};
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<string, unknown>)
: item
);
} else if (value && typeof value === 'object') {
out[key] = redactJsonShallow(value as Record<string, unknown>);
} 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;
@@ -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;
},
};
}
@@ -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;
},
};
}
@@ -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]';
}
}
@@ -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<string, unknown>;
error?: { code?: string; message: string };
}
/** Sink interface — accept events that have already been redacted. */
export interface OAuthTraceSink {
write(event: OAuthTraceEvent): void;
flush?(): Promise<void>;
}
@@ -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<string, unknown>,
error?: { code?: string; message: string } | Error
): void;
snapshot(): OAuthTraceEvent[];
summary(): {
totalMs: number;
phaseCounts: Record<string, number>;
lastPhase?: OAuthTracePhase;
};
flush(): Promise<void>;
}
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<string, number> = {};
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
}
}
}
},
};
}