diff --git a/packages/cli/src/serve/auth/deviceFlow.test.ts b/packages/cli/src/serve/auth/deviceFlow.test.ts index a1ac9448a1e..6c298170cae 100644 --- a/packages/cli/src/serve/auth/deviceFlow.test.ts +++ b/packages/cli/src/serve/auth/deviceFlow.test.ts @@ -16,8 +16,10 @@ import { DEVICE_FLOW_MAX_EXPIRES_IN_SEC, DEVICE_FLOW_MAX_INTERVAL_MS, DEVICE_FLOW_PERSIST_TIMEOUT_MS, + DEVICE_FLOW_POLL_TIMEOUT_MS, DEVICE_FLOW_SLOW_DOWN_BUMP_MS, DEVICE_FLOW_START_TIMEOUT_MS, + DeviceFlowPollTimeoutError, DEVICE_FLOW_TERMINAL_GRACE_MS, DeviceFlowRegistry, TooManyActiveDeviceFlowsError, @@ -122,6 +124,13 @@ class FakeProvider implements DeviceFlowProvider { * `DeviceFlowProvider.poll()` `@remarks` sanitization contract by * throwing raw IdP detail. PR #4255 fold-in 8 #1. */ pollThrowsWith: Error | undefined; + /** Test hook: when `true`, `poll()` returns a Promise that NEVER + * resolves and ignores the supplied `signal`. Models a misbehaving + * provider whose underlying I/O isn't abortable — registry's + * authoritative `Promise.race` against `DEVICE_FLOW_POLL_TIMEOUT_MS` + * is the only thing that can rescue the await. PR #4255 follow-up + * review thread (deepseek-v4-pro). */ + pollHangs = false; /** Most recent `opts.signal` observed by `poll`. Test hook for the * abort-mid-poll assertion: after `registry.cancel(...)`, this * signal MUST report `.aborted === true` so the upstream HTTP @@ -168,6 +177,12 @@ class FakeProvider implements DeviceFlowProvider { this.pollThrowsWith = undefined; throw err; } + if (this.pollHangs) { + // Never resolves, ignores `signal`. Registry's Promise.race + // timeout is the only path out. + await new Promise(() => {}); + throw new Error('unreachable'); + } if (opts.signal.aborted) return { kind: 'pending' }; if (this.pollScript.length === 0) { return { kind: 'pending' }; @@ -667,6 +682,305 @@ describe('DeviceFlowRegistry — authoritative timeouts (fold-in 7)', () => { } }); + it('poll() that hangs past POLL_TIMEOUT_MS surfaces as upstream_error and aborts the entry signal (follow-up review)', async () => { + // PR #4255 follow-up review thread (deepseek-v4-pro): runPollTick + // now races provider.poll() against DEVICE_FLOW_POLL_TIMEOUT_MS so + // a non-abortable provider can no longer pin the per-providerId + // singleton waiting for sweeper-level expiry. Aborts the signal + // first so cooperative providers tear down cleanly; reject + // surfaces in the catch as the bounded `upstream_error` hint. + const provider = new FakeProvider(); + provider.pollHangs = true; + const built = buildRegistry(provider); + const { registry, env, events, auditLines } = built; + try { + const { view } = await registry.start({ providerId: 'qwen-oauth' }); + // Trigger the first poll tick. + env.clock.tick(DEVICE_FLOW_DEFAULT_INTERVAL_MS + 1); + env.scheduler.flushDue(env.clock.now); + // Let runPollTick reach the await. + await flushAsync(); + expect(provider.pollCount).toBe(1); + // Race timer hasn't fired yet — entry is still pending. + expect(registry.get(view.deviceFlowId)?.status).toBe('pending'); + // Advance clock past POLL_TIMEOUT_MS; race timer fires, aborts + // the entry signal, and rejects the wrapper promise. + env.clock.tick(DEVICE_FLOW_POLL_TIMEOUT_MS + 1); + env.scheduler.flushDue(env.clock.now); + await flushAsync(); + // Signal must be aborted so cooperative providers can abandon + // their in-flight fetch. + expect(provider.lastPollSignal?.aborted).toBe(true); + // The catch block surfaces a bounded upstream_error to SSE. + const failed = events.find( + (e) => + e.emission.type === 'failed' && + e.emission.data.deviceFlowId === view.deviceFlowId, + ); + expect(failed).toBeDefined(); + if (failed && failed.emission.type === 'failed') { + expect(failed.emission.data.errorKind).toBe('upstream_error'); + // PR #4291 follow-up review (qwen-latest, #2): the SSE/HTTP + // hint must distinguish a registry-side timeout from a + // provider throw. At 3 AM, on-call reading "provider.poll() + // threw" would grep the provider source for a non-existent + // throw site — when the actual issue is a hung IdP. + expect(failed.emission.data.hint).toContain('timed out after'); + expect(failed.emission.data.hint).toContain('check IdP connectivity'); + // Negative assertion: the misleading provider-throw hint + // MUST NOT appear on the timeout path. + expect(failed.emission.data.hint).not.toContain( + 'see daemon audit log for details', + ); + } + // Audit captures the timeout for the operator. Critically, the + // audit hint MUST NOT route through the `provider.poll() threw + // (raw)` template — that's reserved for actual provider throws + // and would mis-direct triage. On the timeout path the hint + // field is omitted entirely (rawProviderError stays undefined). + const auditFailure = auditLines.find( + (line) => + line['status'] === 'failed' && line['errorKind'] === 'upstream_error', + ); + expect(auditFailure).toBeDefined(); + const auditHint = auditFailure?.['hint'] as string | undefined; + if (auditHint !== undefined) { + expect(auditHint).not.toContain('provider.poll() threw (raw)'); + } + // PR #4291 follow-up review (Qwen Code review summary): + // poll-tick must NOT reschedule itself after a timeout-driven + // upstream_error (the entry has already transitioned to error + // state; another poll would be a `entry.status !== 'pending'` + // no-op at best, log noise at worst). Pin the invariant. + expect(provider.pollCount).toBe(1); + } finally { + registry.dispose(); + } + }); + + it('records lost_late_poll_after_timeout when provider.poll() resolves AFTER the registry race timeout (follow-up review #5)', async () => { + // PR #4291 follow-up review (qwen-latest, #5): symmetric with + // `lost_success_after_timeout` on the persist path. A flaky IdP + // that responds 1s past the 30s ceiling should leave an audit + // breadcrumb saying "IdP IS responsive, just slow" — without + // this, the daemon and the operator get the same observability + // as a fully unresponsive IdP. The fix attaches a passive + // observer to the original `provider.poll()` promise. + const provider = new FakeProvider(); + let resolveLate!: (r: DeviceFlowPollResult) => void; + const latePollPromise = new Promise((resolve) => { + resolveLate = resolve; + }); + // Custom hook: poll returns the controllable promise, ignoring signal. + provider.poll = async () => { + provider.pollCount += 1; + return latePollPromise; + }; + const built = buildRegistry(provider); + const { registry, env, auditLines } = built; + try { + const { view } = await registry.start({ providerId: 'qwen-oauth' }); + env.clock.tick(DEVICE_FLOW_DEFAULT_INTERVAL_MS + 1); + env.scheduler.flushDue(env.clock.now); + await flushAsync(); + expect(provider.pollCount).toBe(1); + // Fire the registry race timer. + env.clock.tick(DEVICE_FLOW_POLL_TIMEOUT_MS + 1); + env.scheduler.flushDue(env.clock.now); + await flushAsync(); + // Outer wrapper rejected; entry transitioned to error/upstream_error. + const snapshot = registry.get(view.deviceFlowId); + expect(snapshot?.status).toBe('error'); + // No `lost_late_poll_after_timeout` line YET — the original + // promise hasn't resolved. + expect( + auditLines.some((line) => + (line['hint'] as string | undefined)?.includes( + 'lost_late_poll_after_timeout', + ), + ), + ).toBe(false); + // Now the IdP belatedly responds. + resolveLate({ kind: 'pending' }); + await flushAsync(); + // The passive observer must have recorded an audit line. + const lateAudit = auditLines.find((line) => + (line['hint'] as string | undefined)?.includes( + 'lost_late_poll_after_timeout', + ), + ); + expect(lateAudit).toBeDefined(); + expect(lateAudit?.['errorKind']).toBe('upstream_error'); + expect(lateAudit?.['hint']).toContain('kind=pending'); + expect(lateAudit?.['hint']).toContain( + `${DEVICE_FLOW_POLL_TIMEOUT_MS}ms ceiling`, + ); + // PR #4291 follow-up review (qwen-latest, N1): kind=pending is a + // real late response (the IdP eventually responded), so the + // "responsive but slow" hint is appropriate here. The negative + // is the kind === 'error' branch (separately tested below). + expect(lateAudit?.['hint']).toContain('IdP is responsive but slow'); + expect(lateAudit?.['hint']).not.toContain('abort-driven'); + } finally { + registry.dispose(); + } + }); + + it('records lost_late_poll_after_timeout with abort-driven hint when late resolution is kind=error (qwen-latest review N1)', async () => { + // PR #4291 follow-up review (qwen-latest, N1): when the registry + // race timer aborts `entry.cancelController.signal`, a cooperative + // provider's `pollDeviceToken({signal})` typically throws + // AbortError; the provider's catch then resolves to + // `{kind: 'error', errorKind: 'upstream_error'}`. This success + // handler fires with `latePollResult.kind === 'error'`. Earlier + // shape would have audited "IdP is responsive but slow" — but the + // IdP could be totally down; the "response" is just the provider's + // abort cooperation. Pin the corrected attribution. + const provider = new FakeProvider(); + let resolveLate!: (r: DeviceFlowPollResult) => void; + const latePollPromise = new Promise((resolve) => { + resolveLate = resolve; + }); + provider.poll = async () => { + provider.pollCount += 1; + return latePollPromise; + }; + const built = buildRegistry(provider); + const { registry, env, auditLines } = built; + try { + const { view } = await registry.start({ providerId: 'qwen-oauth' }); + env.clock.tick(DEVICE_FLOW_DEFAULT_INTERVAL_MS + 1); + env.scheduler.flushDue(env.clock.now); + await flushAsync(); + env.clock.tick(DEVICE_FLOW_POLL_TIMEOUT_MS + 1); + env.scheduler.flushDue(env.clock.now); + await flushAsync(); + // Cooperative abort path: provider resolves to error AFTER the + // race timer fired. + resolveLate({ + kind: 'error', + errorKind: 'upstream_error', + hint: 'aborted by signal', + }); + await flushAsync(); + const lateAudit = auditLines.find((line) => + (line['hint'] as string | undefined)?.includes( + 'lost_late_poll_after_timeout', + ), + ); + expect(lateAudit).toBeDefined(); + expect(lateAudit?.['hint']).toContain('kind=error'); + // The corrected hint MUST NOT claim the IdP is responsive. + expect(lateAudit?.['hint']).not.toContain('IdP is responsive but slow'); + expect(lateAudit?.['hint']).toContain('abort-driven cooperation'); + expect(lateAudit?.['hint']).toContain('IdP responsiveness unknown'); + // dispose the entry to keep the test isolated. + void view; + } finally { + registry.dispose(); + } + }); + + it('records lost_late_poll_after_timeout when provider.poll() REJECTS after the race timeout (qwen-latest review N2)', async () => { + // PR #4291 follow-up review (qwen-latest, N2): the late observer + // also has an `onRejected` branch covering three sub-paths that + // were previously zero-tested: + // 1. `if (lateErr instanceof DeviceFlowPollTimeoutError) return;` + // (don't double-audit our own race-timer rejection) + // 2. The `detail.length > 256` truncation tail + // 3. The audit record for the rejection itself + // Late rejection is realistic: TCP RST or proxy 502 arriving 1s + // past the 30s ceiling. + const provider = new FakeProvider(); + let rejectLate!: (e: Error) => void; + const latePollPromise = new Promise( + (_resolve, reject) => { + rejectLate = reject; + }, + ); + provider.poll = async () => { + provider.pollCount += 1; + return latePollPromise; + }; + const built = buildRegistry(provider); + const { registry, env, auditLines } = built; + try { + await registry.start({ providerId: 'qwen-oauth' }); + env.clock.tick(DEVICE_FLOW_DEFAULT_INTERVAL_MS + 1); + env.scheduler.flushDue(env.clock.now); + await flushAsync(); + env.clock.tick(DEVICE_FLOW_POLL_TIMEOUT_MS + 1); + env.scheduler.flushDue(env.clock.now); + await flushAsync(); + // Late upstream failure (NOT our own DeviceFlowPollTimeoutError). + // Use a long-enough message to exercise the truncation tail. + const longDetail = `connection reset by peer ${'x'.repeat(400)}`; + rejectLate(new Error(longDetail)); + await flushAsync(); + const lateAudit = auditLines.find((line) => + (line['hint'] as string | undefined)?.includes( + 'lost_late_poll_after_timeout', + ), + ); + expect(lateAudit).toBeDefined(); + expect(lateAudit?.['errorKind']).toBe('upstream_error'); + expect(lateAudit?.['hint']).toContain('rejected after'); + expect(lateAudit?.['hint']).toContain( + `${DEVICE_FLOW_POLL_TIMEOUT_MS}ms ceiling`, + ); + expect(lateAudit?.['hint']).toContain('connection reset by peer'); + // Truncation tail must appear (long detail > 256 bytes). + expect(lateAudit?.['hint']).toContain('bytes]'); + } finally { + registry.dispose(); + } + }); + + it("does NOT double-audit when late rejection is the registry's own DeviceFlowPollTimeoutError (qwen-latest review N2 guard)", async () => { + // PR #4291 follow-up review (qwen-latest, N2): the late-rejection + // observer must filter out our own timer rejection — otherwise a + // single timeout would produce two audit lines (one from the + // wrapper catch, one from the late-rejection observer). The + // guard is `if (lateErr instanceof DeviceFlowPollTimeoutError) + // return;`. Pin it. + const provider = new FakeProvider(); + let rejectLate!: (e: Error) => void; + const latePollPromise = new Promise( + (_resolve, reject) => { + rejectLate = reject; + }, + ); + provider.poll = async () => { + provider.pollCount += 1; + return latePollPromise; + }; + const built = buildRegistry(provider); + const { registry, env, auditLines } = built; + try { + await registry.start({ providerId: 'qwen-oauth' }); + env.clock.tick(DEVICE_FLOW_DEFAULT_INTERVAL_MS + 1); + env.scheduler.flushDue(env.clock.now); + await flushAsync(); + env.clock.tick(DEVICE_FLOW_POLL_TIMEOUT_MS + 1); + env.scheduler.flushDue(env.clock.now); + await flushAsync(); + // Reject with the SAME sentinel the registry uses internally. + // The original wrapper catch already recorded a failed audit + // (the "real" failure for this entry). The late observer must + // NOT add a `lost_late_poll_after_timeout` line. + rejectLate(new DeviceFlowPollTimeoutError(DEVICE_FLOW_POLL_TIMEOUT_MS)); + await flushAsync(); + const lateAudits = auditLines.filter((line) => + (line['hint'] as string | undefined)?.includes( + 'lost_late_poll_after_timeout', + ), + ); + expect(lateAudits).toHaveLength(0); + } finally { + registry.dispose(); + } + }); + it('persist() that hangs past PERSIST_TIMEOUT_MS maps to persist_failed (#2)', async () => { const provider = new FakeProvider(); // Single poll tick returns success whose persist() never resolves. @@ -940,6 +1254,123 @@ describe('DeviceFlowRegistry — persist failure paths (fold-in 10 #1)', () => { } }); + it('cancellerClientId is first-writer-wins across concurrent cancel() calls during persist', async () => { + // PR #4255 follow-up review thread (deepseek-v4-pro): two SDK + // clients racing `cancel()` on the same persist-in-flight entry + // must NOT silently overwrite attribution. The first cancel that + // observes `persistInFlight` is the one that drove the transition; + // the persist-resolution event should be attributed to it. The + // second cancel is functionally a no-op on the entry (it's already + // marked `cancelRequestedDuringPersist`); its caller still appears + // in the audit trail through the `audit.record(...)` path but + // does not overwrite the SSE event's `originatorClientId`. + const provider = new FakeProvider(); + let rejectPersist!: (err: Error) => void; + const persistPromise = new Promise<{ expiresAt?: number }>( + (_resolve, reject) => { + rejectPersist = reject; + }, + ); + provider.pollScript = [ + { + kind: 'success', + persist: () => persistPromise, + }, + ]; + const built = buildRegistry(provider); + const { registry, env, events } = built; + try { + const { view } = await registry.start({ providerId: 'qwen-oauth' }); + env.clock.tick(DEVICE_FLOW_DEFAULT_INTERVAL_MS + 1); + env.scheduler.flushDue(env.clock.now); + await flushAsync(); + // First canceller wins. + const first = registry.cancel(view.deviceFlowId, 'sdk-A'); + expect(first).toEqual({ alreadyTerminal: false }); + // Second canceller observes `persistInFlight` already set; the + // entry is still marked `cancelRequestedDuringPersist`. Its id + // MUST NOT overwrite the first-writer's attribution. + const second = registry.cancel(view.deviceFlowId, 'sdk-B'); + expect(second).toEqual({ alreadyTerminal: false }); + // Persist now fails — the registry emits `cancelled` with + // `originatorClientId = entry.cancellerClientId` (sdk-A). + rejectPersist(new Error('aborted: cancel during persist')); + await flushAsync(); + const snapshot = registry.get(view.deviceFlowId); + expect(snapshot?.status).toBe('cancelled'); + const cancelledEvent = events.find( + (e) => + e.emission.type === 'cancelled' && + e.emission.data.deviceFlowId === view.deviceFlowId, + ); + expect(cancelledEvent).toBeDefined(); + // First-writer-wins: sdk-A drove the transition. + expect(cancelledEvent?.clientId).toBe('sdk-A'); + } finally { + registry.dispose(); + } + }); + + it('cancellerClientId is first-writer-wins even when the first canceller is anonymous (no clientId)', async () => { + // PR #4291 follow-up review (Copilot): the first version of the + // first-writer-wins guard used `entry.cancellerClientId === undefined` + // as the gate, which silently broke when the first canceller was + // anonymous: `cancel(id, undefined)` left the field undefined, and + // a later `cancel(id, 'sdk-B')` saw the gate as still open and + // overwrote attribution. The fix decouples the "have we recorded a + // canceller" question (`cancellerRecorded` flag) from the "do we + // have a clientId" question. An anonymous first canceller still + // flips the flag, blocking any later writer. + const provider = new FakeProvider(); + let rejectPersist!: (err: Error) => void; + const persistPromise = new Promise<{ expiresAt?: number }>( + (_resolve, reject) => { + rejectPersist = reject; + }, + ); + provider.pollScript = [ + { + kind: 'success', + persist: () => persistPromise, + }, + ]; + const built = buildRegistry(provider); + const { registry, env, events } = built; + try { + const { view } = await registry.start({ providerId: 'qwen-oauth' }); + env.clock.tick(DEVICE_FLOW_DEFAULT_INTERVAL_MS + 1); + env.scheduler.flushDue(env.clock.now); + await flushAsync(); + // First (anonymous) canceller wins. cancellerClientId stays + // undefined; cancellerRecorded is now true. + const first = registry.cancel(view.deviceFlowId); + expect(first).toEqual({ alreadyTerminal: false }); + // Second canceller IS identified — but the first-writer-wins + // gate must reject the overwrite. + const second = registry.cancel(view.deviceFlowId, 'sdk-B'); + expect(second).toEqual({ alreadyTerminal: false }); + rejectPersist(new Error('aborted: cancel during persist')); + await flushAsync(); + const snapshot = registry.get(view.deviceFlowId); + expect(snapshot?.status).toBe('cancelled'); + const cancelledEvent = events.find( + (e) => + e.emission.type === 'cancelled' && + e.emission.data.deviceFlowId === view.deviceFlowId, + ); + expect(cancelledEvent).toBeDefined(); + // The deferred SSE event must NOT carry sdk-B as originator — + // the anonymous first writer wins, so `entry.cancellerClientId` + // stays undefined, and the runPollTick deferred-cancel branch + // falls back to `entry.initiatorClientId` (which is also + // undefined here because `start()` itself was anonymous). The + // critical assertion: sdk-B did NOT silently take credit. + expect(cancelledEvent?.clientId).not.toBe('sdk-B'); + } finally { + registry.dispose(); + } + }); + it('records lost_success_after_timeout when persist resolves AFTER the registry timeout (round-12 #8)', async () => { // PR #4255 round-12 #8 (Cy_ZH): pins the split-brain detector // for non-conforming providers. fold-in 9 #7 added an diff --git a/packages/cli/src/serve/auth/deviceFlow.ts b/packages/cli/src/serve/auth/deviceFlow.ts index 104d76c7b2a..7e06ecda553 100644 --- a/packages/cli/src/serve/auth/deviceFlow.ts +++ b/packages/cli/src/serve/auth/deviceFlow.ts @@ -50,6 +50,21 @@ export const DEVICE_FLOW_PERSIST_TIMEOUT_MS = 30_000; * PR #4255 review fold-in 3 (#2). */ export const DEVICE_FLOW_START_TIMEOUT_MS = 30_000; +/** + * Hard ceiling on a single `provider.poll()` tick. Symmetric with + * `DEVICE_FLOW_START_TIMEOUT_MS` and `DEVICE_FLOW_PERSIST_TIMEOUT_MS`, + * which already bound their respective phases. PR #4255 follow-up + * review thread (deepseek-v4-pro): a hung IdP token endpoint (TCP + * established, no response) without this would block the registry's + * poll-tick promise indefinitely. The entry's `cancelController.signal` + * is the cooperative path; this race makes the timeout authoritative + * regardless of provider cooperation. The sweeper would still evict + * the entry once `expiresAt` is past, but until then the per-provider + * singleton stays occupied with no other recovery short of daemon + * restart. 30s is the same generosity the start/persist phases use + * and is well over a healthy IdP's polling round-trip. + */ +export const DEVICE_FLOW_POLL_TIMEOUT_MS = 30_000; /** * Operator-safe upper bound on the IdP-provided `expires_in`. RFC * 8628 §6.1 calls 5–30 minutes "reasonable"; 1 hour is the practical @@ -503,6 +518,18 @@ interface DeviceFlowEntry { * 9 review thread #5. */ cancellerClientId?: string; + /** + * First-writer-wins flag. Set the moment ANY `cancel()` call drives + * this entry into `cancelRequestedDuringPersist` — including the + * anonymous case where `cancellerClientId` stays `undefined`. The + * flag is decoupled from `cancellerClientId` because the latter + * being `undefined` is BOTH "no canceller has driven the transition + * yet" AND "an anonymous canceller drove the transition" — using it + * as the gate would let a later identified canceller silently + * overwrite an earlier anonymous one. PR #4255 follow-up review + * (Copilot on #4291): closes the anonymous-first canceller bug. + */ + cancellerRecorded?: boolean; } export interface DeviceFlowRegistryDeps { @@ -583,6 +610,26 @@ export class UpstreamDeviceFlowError extends Error { } } +/** + * Sentinel error raised by `runPollTick`'s own `Promise.race` timer when + * `provider.poll()` exceeds `DEVICE_FLOW_POLL_TIMEOUT_MS`. PR #4291 + * follow-up review (qwen-latest): the catch block previously routed + * this through the same `provider.poll() threw (raw): ...` audit path + * as a real provider throw, mis-leading on-call into investigating + * provider code when the actual issue is a hung IdP / network + * partition. The sentinel lets the catch differentiate the two and + * emit a timeout-specific audit + hint. + */ +export class DeviceFlowPollTimeoutError extends Error { + readonly code = 'poll_timeout'; + readonly timeoutMs: number; + constructor(timeoutMs: number) { + super(`device-flow poll timeout after ${timeoutMs}ms`); + this.name = 'DeviceFlowPollTimeoutError'; + this.timeoutMs = timeoutMs; + } +} + /** * Typed accessors for parking the `DeviceFlowRegistry` on * `express.Application['locals']`. The string key is shared between @@ -916,8 +963,29 @@ export class DeviceFlowRegistry { // `originatorClientId` was always `entry.initiatorClientId`, // which broke any SSE consumer that suppresses self-emitted // events to avoid double-handling. - if (cancellerClientId) { - entry.cancellerClientId = cancellerClientId; + // PR #4255 follow-up review thread (deepseek-v4-pro): first-writer- + // wins. Two SDK clients racing `cancel()` on the same persist-in- + // flight entry must NOT silently overwrite attribution — the second + // caller's `cancel()` is functionally a no-op (the entry is already + // marked `cancelRequestedDuringPersist`), so the persist-resolution + // event should be attributed to whoever actually drove the + // transition first. Subsequent callers stay in the audit trail + // through their own `audit.record(...)` line below. + // + // PR #4291 follow-up review (Copilot): the gate is `cancellerRecorded` + // (a separate flag), NOT `cancellerClientId === undefined`. The earlier + // shape silently broke when the first canceller was anonymous: their + // `cancel(id, undefined)` left `cancellerClientId` undefined, so the + // next identified `cancel(id, 'sdk-B')` saw the gate as still open + // and overwrote the attribution. Decoupling the "have we recorded a + // canceller" question from the "do we have a clientId" question fixes + // it: an anonymous first canceller still flips the flag, blocking + // any later writer. + if (!entry.cancellerRecorded) { + entry.cancellerRecorded = true; + if (cancellerClientId) { + entry.cancellerClientId = cancellerClientId; + } } try { entry.cancelController.abort(new Error('cancel during persist')); @@ -1011,14 +1079,50 @@ export class DeviceFlowRegistry { entry.lastPolledAt = now; let result: DeviceFlowPollResult; let rawProviderError: string | undefined; + let pollTimedOut = false; + // PR #4255 follow-up review thread (deepseek-v4-pro): bound + // `provider.poll()` with the same `Promise.race` shape used by + // `doStart` / persist. The cooperative `entry.cancelController.signal` + // path covers well-behaved providers; this race makes the timeout + // authoritative even when a provider ignores `signal`. A hung IdP + // token endpoint without this would otherwise block the poll-tick + // promise indefinitely (occupying the per-provider singleton until + // sweeper / daemon restart). The rejecting timer aborts the signal + // first so cooperative providers can still tear down cleanly. + // + // PR #4291 follow-up review (qwen-latest, #5): keep a reference to + // the original `provider.poll()` promise so we can detect a LATE + // success/error after our race timer already settled the wrapper. + // Without this, a flaky IdP that responds 1s past the 30s timeout + // would silently no-op (the second `.then(resolve, ...)` lands on + // an already-settled outer promise) — operator has no signal that + // the IdP is in fact responsive (just slow). Symmetric with the + // `lost_success_after_timeout` audit on the persist path (fold-in + // 9 #7 of #4255). + let pollTimer: ReturnType | undefined; + let providerPollPromise: Promise | undefined; try { - result = await provider.poll( - { - deviceCode: entry.deviceCode, - pkceVerifier: entry.pkceVerifier, - }, - { signal: entry.cancelController.signal }, - ); + result = await new Promise((resolve, reject) => { + pollTimer = this.schedule(DEVICE_FLOW_POLL_TIMEOUT_MS, () => { + pollTimedOut = true; + try { + entry.cancelController.abort( + new DeviceFlowPollTimeoutError(DEVICE_FLOW_POLL_TIMEOUT_MS), + ); + } catch { + // best-effort + } + reject(new DeviceFlowPollTimeoutError(DEVICE_FLOW_POLL_TIMEOUT_MS)); + }); + providerPollPromise = provider.poll( + { + deviceCode: entry.deviceCode!, + pkceVerifier: entry.pkceVerifier, + }, + { signal: entry.cancelController.signal }, + ); + providerPollPromise.then(resolve, reject); + }); } catch (err: unknown) { // PR #4255 fold-in 9 review thread #1 (refines fold-in 8 #1): // a non-conforming provider that violates the `@remarks` @@ -1031,12 +1135,89 @@ export class DeviceFlowRegistry { // outermost defense layer; the full raw `err.message` flows // through the audit channel (whose backing impl writes to // stderr) for operator visibility. - rawProviderError = err instanceof Error ? err.message : String(err); - result = { - kind: 'error', - errorKind: 'upstream_error', - hint: 'provider.poll() failed; see daemon audit log for details', - }; + // + // PR #4291 follow-up review (qwen-latest, #2): the previous + // shape routed our own race-timer rejection through the same + // `provider.poll() threw (raw): ...` audit path as a real + // provider throw — at 3 AM, on-call would mis-triage as + // "provider bug" and waste time investigating provider code. + // Branch on `DeviceFlowPollTimeoutError` to use a dedicated + // hint + suppress the misleading "raw" audit path. + if (err instanceof DeviceFlowPollTimeoutError) { + result = { + kind: 'error', + errorKind: 'upstream_error', + hint: `provider.poll() timed out after ${err.timeoutMs}ms; check IdP connectivity`, + }; + // rawProviderError stays undefined — the audit branch reads + // that to decide whether to emit the misleading "threw (raw)" + // line. Timeout is not a provider throw. + } else { + rawProviderError = err instanceof Error ? err.message : String(err); + result = { + kind: 'error', + errorKind: 'upstream_error', + hint: 'provider.poll() failed; see daemon audit log for details', + }; + } + } finally { + if (pollTimer !== undefined) this.clearScheduled(pollTimer); + } + // PR #4291 follow-up review (qwen-latest, #5): if our race timer + // settled the wrapper as a timeout, attach a passive observer on + // the original `provider.poll()` promise so a late resolution + // (IdP eventually responded after the 30s ceiling) leaves an + // operator audit breadcrumb. Without this, a flaky-but-responsive + // IdP looks identical to a fully unresponsive one. Mirrors the + // `lost_success_after_timeout` pattern on the persist path. + if (pollTimedOut && providerPollPromise !== undefined) { + const tracked = providerPollPromise; + // Detached on purpose; the catch on the ORIGINAL promise has + // already happened (via the wrapper) — the observer below + // sees the eventual settlement of the same promise. Both + // success and error branches go through audit only. + void tracked.then( + (latePollResult) => { + this.deps.audit?.record({ + deviceFlowId: entry.deviceFlowId, + providerId: entry.providerId, + clientId: entry.initiatorClientId, + status: 'failed', + errorKind: 'upstream_error', + // PR #4291 follow-up review (qwen-latest, N1): the late- + // poll resolve branch fires when `provider.poll()` returns + // a result AFTER our race timer settled the wrapper. For a + // cooperative provider whose abort path resolves to + // `{kind: 'error', errorKind: 'upstream_error'}` (the Qwen + // implementation does this in response to AbortError), the + // "response" is just the abort-cooperation path — the IdP + // could be completely down. Don't assert "responsive but + // slow" on the error kind: route operators correctly by + // distinguishing "real late response" (pending / slow_down / + // success) from "provider's abort cooperation" (error). + hint: + latePollResult.kind === 'error' + ? `lost_late_poll_after_timeout: provider.poll() resolved kind=error after ${DEVICE_FLOW_POLL_TIMEOUT_MS}ms ceiling — likely abort-driven cooperation; IdP responsiveness unknown` + : `lost_late_poll_after_timeout: provider.poll() resolved kind=${latePollResult.kind} after ${DEVICE_FLOW_POLL_TIMEOUT_MS}ms ceiling — IdP is responsive but slow; consider raising the operator-side IdP latency alert threshold`, + }); + }, + (lateErr: unknown) => { + // Late rejection from the same provider promise. Don't + // double-audit if the wrapper already saw this same error + // (we'd be double-counting the same I/O failure). + if (lateErr instanceof DeviceFlowPollTimeoutError) return; + const detail = + lateErr instanceof Error ? lateErr.message : String(lateErr); + this.deps.audit?.record({ + deviceFlowId: entry.deviceFlowId, + providerId: entry.providerId, + clientId: entry.initiatorClientId, + status: 'failed', + errorKind: 'upstream_error', + hint: `lost_late_poll_after_timeout: provider.poll() rejected after ${DEVICE_FLOW_POLL_TIMEOUT_MS}ms ceiling: ${detail.length > 256 ? `${detail.slice(0, 256)}…[+${detail.length - 256} bytes]` : detail}`, + }); + }, + ); } // PR #4255 round-12 #1 (gpt-5.5 review CzSpN): also re-check // `this.disposed` after the await. `dispose()` clears diff --git a/packages/cli/src/serve/auth/qwenDeviceFlowProvider.test.ts b/packages/cli/src/serve/auth/qwenDeviceFlowProvider.test.ts new file mode 100644 index 00000000000..499b906ce62 --- /dev/null +++ b/packages/cli/src/serve/auth/qwenDeviceFlowProvider.test.ts @@ -0,0 +1,345 @@ +/** + * @license + * Copyright 2025 Qwen Team + * SPDX-License-Identifier: Apache-2.0 + */ + +/** + * Unit tests for `QwenOAuthDeviceFlowProvider`'s stderr audit path. + * + * PR #4291 follow-up review (qwen-latest, #1): the catch block in + * `poll()` adds 4 distinct branches (AbortError skip, structured + * `QwenOAuthPollError`, generic `Error` with name+length redaction, + * non-Error throw) that drive what — if anything — lands in the + * operator audit. The security-critical pieces are: + * + * - `device_code` + PKCE verifier are POSTed to the IdP per RFC 8628 + * §3.4. A WAF / reverse proxy that echoes the request body in its + * error response would put both into stderr if we naively logged + * `err.message` — violating the BrandedSecret-style "secrets never + * appear in logs" contract the registry depends on. + * - The cancel/dispose lifecycle MUST stay quiet — emitting a "poll + * failed" line on every normal cancellation pollutes the audit. + * + * These tests pin all four branches against a stub `IQwenOAuth2Client` + * so a future refactor that drops the redaction shows up in CI. + */ + +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; +import { + QwenOAuthPollError, + type IQwenOAuth2Client, +} from '@qwen-code/qwen-code-core'; +import { QwenOAuthDeviceFlowProvider } from './qwenDeviceFlowProvider.js'; +import { brandSecret } from './deviceFlow.js'; + +function fakeClient( + overrides: Partial = {}, +): IQwenOAuth2Client { + return { + setCredentials: () => {}, + getCredentials: () => + ({}) as ReturnType, + getAccessToken: async () => ({}), + requestDeviceAuthorization: async () => + ({}) as Awaited< + ReturnType + >, + pollDeviceToken: async () => + ({}) as Awaited>, + refreshAccessToken: async () => + ({}) as Awaited>, + ...overrides, + }; +} + +describe('QwenOAuthDeviceFlowProvider.poll() — stderr audit branches', () => { + let stderrLines: string[]; + let stderrSpy: ReturnType; + let originalWrite: typeof process.stderr.write; + + beforeEach(() => { + stderrLines = []; + originalWrite = process.stderr.write.bind(process.stderr); + stderrSpy = vi.fn((chunk: string | Uint8Array) => { + stderrLines.push(typeof chunk === 'string' ? chunk : chunk.toString()); + return true; + }); + // process.stderr.write has overloaded signatures; cast to align with + // the chunk-only call shape used by writeStderrLine. + (process.stderr as { write: unknown }).write = stderrSpy; + }); + + afterEach(() => { + (process.stderr as { write: typeof originalWrite }).write = originalWrite; + }); + + function makeState() { + return { + deviceCode: brandSecret('device-code-secret-AAAA1111'), + pkceVerifier: brandSecret('pkce-verifier-secret-BBBB2222'), + }; + } + + it('skips stderr audit when caller aborted before poll started (signal.aborted check)', async () => { + // The early `opts.signal.aborted` short-circuit returns `pending` + // without invoking `pollDeviceToken` at all — no fetch, no catch, + // no audit. Pin the negative case so a future refactor that + // accidentally writes a stderr line on this path fails CI. + const provider = new QwenOAuthDeviceFlowProvider(fakeClient()); + const controller = new AbortController(); + controller.abort(); + const result = await provider.poll(makeState(), { + signal: controller.signal, + }); + expect(result.kind).toBe('pending'); + expect(stderrLines).toHaveLength(0); + }); + + it('skips stderr audit when AbortError is thrown AND the registry-owned signal is aborted (cancel/dispose lifecycle)', async () => { + // `cancel()` / `dispose()` aborts the AbortController and the + // underlying fetch throws an `AbortError`-like exception. This + // is normal lifecycle. The post-await `opts.signal.aborted` + // check is what proves WE caused the abort — that's the gate, + // not the error name itself. + const abortErr = new Error('The operation was aborted.'); + abortErr.name = 'AbortError'; + const controller = new AbortController(); + const provider = new QwenOAuthDeviceFlowProvider( + fakeClient({ + pollDeviceToken: async () => { + controller.abort(); + throw abortErr; + }, + }), + ); + const result = await provider.poll(makeState(), { + signal: controller.signal, + }); + expect(result.kind).toBe('error'); + if (result.kind === 'error') { + expect(result.errorKind).toBe('upstream_error'); + } + expect(stderrLines).toHaveLength(0); + }); + + it('LOGS unexpected AbortError when the registry-owned signal is NOT aborted (transport / proxy / undici)', async () => { + // PR #4291 follow-up review (gpt-5.5, #1): an `AbortError` can + // come from sources we did NOT initiate — upstream IdP TCP RST, + // proxy timeout, undici/node-fetch wrapping unrelated transport + // failures as AbortError. Earlier shape silently dropped these + // because of the `err.name === 'AbortError'` skip; now we only + // skip when WE caused the abort. Unexpected AbortError must + // still produce a stderr breadcrumb. + const abortErr = new Error('The operation was aborted.'); + abortErr.name = 'AbortError'; + const provider = new QwenOAuthDeviceFlowProvider( + fakeClient({ + pollDeviceToken: async () => { + throw abortErr; + }, + }), + ); + const result = await provider.poll(makeState(), { + // Signal NOT aborted — the abort came from an upstream source. + signal: new AbortController().signal, + }); + expect(result.kind).toBe('error'); + if (result.kind === 'error') { + expect(result.errorKind).toBe('upstream_error'); + } + expect(stderrLines).toHaveLength(1); + const line = stderrLines[0]; + // Routes through the non-OAuth Error path (name + length). + expect(line).toContain('AbortError'); + expect(line).toContain('raw suppressed'); + // Negative: the raw message is NOT echoed. + expect(line).not.toContain('The operation was aborted.'); + }); + + it('skips stderr audit when signal.aborted is set after the throw, even for non-AbortError errors', async () => { + // The other half of the abort guard: a cooperative provider + // notices the signal is aborted post-fetch and throws something + // generic. We still treat the post-await `signal.aborted` as + // proof this was a cancel, not a real failure. + const controller = new AbortController(); + const provider = new QwenOAuthDeviceFlowProvider( + fakeClient({ + pollDeviceToken: async () => { + controller.abort(); + throw new Error('socket hangup'); + }, + }), + ); + const result = await provider.poll(makeState(), { + signal: controller.signal, + }); + expect(result.kind).toBe('error'); + expect(stderrLines).toHaveLength(0); + }); + + it('logs only the structured oauthError field on QwenOAuthPollError (no raw body, no device_code/PKCE leak)', async () => { + // Critical security path: even when the upstream RESPONSE includes + // the request body verbatim (WAF echo, hostile reverse proxy), the + // QwenOAuthPollError carries only the structured `oauthError` / + // `description` fields. Logging those is safe; logging + // `err.message` would re-introduce the leak vector. + const provider = new QwenOAuthDeviceFlowProvider( + fakeClient({ + pollDeviceToken: async () => { + throw new QwenOAuthPollError({ + oauthError: 'slow_down', + description: 'Polling too fast', + status: 400, + }); + }, + }), + ); + const result = await provider.poll(makeState(), { + signal: new AbortController().signal, + }); + expect(result.kind).toBe('error'); + expect(stderrLines).toHaveLength(1); + const line = stderrLines[0]; + expect(line).toContain('qwen device-flow poll failed'); + expect(line).toContain('oauthError=slow_down'); + // The raw default message ("Device token poll failed: slow_down - + // Polling too fast") MUST NOT appear — only the structured field. + expect(line).not.toContain('Device token poll failed:'); + expect(line).not.toContain('device-code-secret'); + expect(line).not.toContain('pkce-verifier-secret'); + }); + + it('logs only err.name + message length on generic Error (raw message is suppressed)', async () => { + // The catch block treats any non-OAuth Error as potentially + // tainted (a fetch wrapper that templated the request body into + // its message). Log just the constructor name + length so + // on-call gets a triage-able breadcrumb without the request body. + const longMessage = + 'HTTP 502 from qwen IdP: Forbidden — request body: device_code=device-code-secret-AAAA1111&code_verifier=pkce-verifier-secret-BBBB2222'; + const provider = new QwenOAuthDeviceFlowProvider( + fakeClient({ + pollDeviceToken: async () => { + throw new Error(longMessage); + }, + }), + ); + const result = await provider.poll(makeState(), { + signal: new AbortController().signal, + }); + expect(result.kind).toBe('error'); + if (result.kind === 'error') { + expect(result.errorKind).toBe('upstream_error'); + } + expect(stderrLines).toHaveLength(1); + const line = stderrLines[0]; + expect(line).toContain('Error'); + expect(line).toContain(`message ${longMessage.length} bytes`); + expect(line).toContain('raw suppressed'); + // Hard assertions: NEITHER the raw message NOR the templated + // device-flow secrets may appear in stderr. + expect(line).not.toContain('HTTP 502 from qwen'); + expect(line).not.toContain('device-code-secret'); + expect(line).not.toContain('pkce-verifier-secret'); + }); + + it('logs placeholder when a non-Error value is thrown', async () => { + // `throw 'string'` is bad practice but fetch wrappers sometimes + // do it (or `throw { code: 'X' }`). The catch block writes a + // typeof-bound placeholder and gives up on extracting more — + // the typed return shape (`upstream_error`) carries enough for + // the SSE consumer. + // The catch in poll() must handle non-Error throws. We wrap the + // raw throw inside a sync function called from the async path so + // the lint rule against literal throws can stay enabled — the + // reject value is what we're testing, not the throw idiom. + const nonErrorThrower = (): never => { + const value: unknown = 'this is not an Error instance'; + throw value as Error; + }; + const provider = new QwenOAuthDeviceFlowProvider( + fakeClient({ + pollDeviceToken: async () => nonErrorThrower(), + }), + ); + const result = await provider.poll(makeState(), { + signal: new AbortController().signal, + }); + expect(result.kind).toBe('error'); + expect(stderrLines).toHaveLength(1); + const line = stderrLines[0]; + expect(line).toContain(''); + // The raw thrown string is NOT echoed. + expect(line).not.toContain('this is not an Error instance'); + }); + + it('reports the resolved errorKind on every emitted stderr line so triage can branch on it', async () => { + // Mapping check: the `errorKind` field in the typed return AND + // the stderr breadcrumb must agree. A mis-mapping here would + // route the SSE consumer one way and the operator another. + const provider = new QwenOAuthDeviceFlowProvider( + fakeClient({ + pollDeviceToken: async () => { + throw new QwenOAuthPollError({ + oauthError: 'access_denied', + description: 'user declined', + status: 400, + }); + }, + }), + ); + const result = await provider.poll(makeState(), { + signal: new AbortController().signal, + }); + expect(result.kind).toBe('error'); + if (result.kind === 'error') { + expect(result.errorKind).toBe('access_denied'); + } + expect(stderrLines).toHaveLength(1); + expect(stderrLines[0]).toContain('errorKind=access_denied'); + expect(stderrLines[0]).toContain('oauthError=access_denied'); + }); + + it('sanitizes control characters and ANSI escapes in attacker-controlled oauthError before stderr interpolation', async () => { + // PR #4291 follow-up review (gpt-5.5, #2): the OAuth `error` field + // comes directly from the upstream JSON. A compromised IdP / WAF + // / proxy can return a value containing newlines, terminal control + // characters, or ANSI escape sequences — interpolating that + // verbatim into a stderr line would forge additional log entries + // or inject color/cursor-movement sequences into operator + // terminals. `sanitizeForStderr` strips C0/C1 controls + DEL. + const malicious = + 'slow_down\n[serve] FORGED LOG ENTRY 2026-01-01\x1b[31mRED\x1b[0m'; + const provider = new QwenOAuthDeviceFlowProvider( + fakeClient({ + pollDeviceToken: async () => { + throw new QwenOAuthPollError({ + oauthError: malicious, + description: 'attacker-supplied', + status: 400, + }); + }, + }), + ); + const result = await provider.poll(makeState(), { + signal: new AbortController().signal, + }); + expect(result.kind).toBe('error'); + expect(stderrLines).toHaveLength(1); + const line = stderrLines[0]; + // The forged log line text MUST NOT appear as a real second line. + // Implementation replaces \n with `?`, so the body is on a single + // line and the second `[serve]` no longer leads a line. + expect(line.split('\n').length).toBe(2); // single content line + trailing newline + // ANSI escape \x1b is gone. + expect(line).not.toContain('\x1b[31m'); + expect(line).not.toContain('\x1b[0m'); + // Newline inside the value is gone. + expect(line).not.toMatch(/\n\[serve\] FORGED/); + // The literal text after the controls is preserved (operator can + // still see what the IdP claimed) — only the harmful bytes are + // replaced. + expect(line).toContain('FORGED LOG ENTRY'); + expect(line).toContain('RED'); + }); +}); diff --git a/packages/cli/src/serve/auth/qwenDeviceFlowProvider.ts b/packages/cli/src/serve/auth/qwenDeviceFlowProvider.ts index ed86236cbd2..4b35417dd85 100644 --- a/packages/cli/src/serve/auth/qwenDeviceFlowProvider.ts +++ b/packages/cli/src/serve/auth/qwenDeviceFlowProvider.ts @@ -52,6 +52,25 @@ function truncateForStderr(detail: string): string { return `${detail.slice(0, STDERR_DETAIL_MAX)}…[+${dropped} bytes truncated]`; } +/** + * Strip / replace bytes that could forge log lines or inject terminal + * control sequences when interpolated into a stderr breadcrumb. PR #4291 + * follow-up review (gpt-5.5, #2): `QwenOAuthPollError.oauthError` comes + * directly from the upstream JSON `error` field — attacker-controlled + * if the IdP, a reverse proxy, or a WAF is hostile / compromised. A + * value like `slow_down\n[serve] FAKE LOG LINE 2026-...` would otherwise + * forge an extra log line; a value containing `\x1b[…m` could inject + * ANSI color or cursor-movement sequences into operator terminals. + * + * Strips C0 controls (0x00–0x1f), DEL (0x7f), and C1 controls (0x80–0x9f). + * Replaces each with `?` so the operator can still see SOMETHING was + * present at that index (length-preserving) instead of silently dropping. + */ +function sanitizeForStderr(value: string): string { + // eslint-disable-next-line no-control-regex + return value.replace(/[\x00-\x1f\x7f-\x9f]/g, '?'); +} + /** * Qwen-OAuth implementation of `DeviceFlowProvider` for `qwen serve`. * @@ -199,6 +218,66 @@ export class QwenOAuthDeviceFlowProvider implements DeviceFlowProvider { err instanceof QwenOAuthPollError ? mapRfc8628OAuthCode(err.oauthError) : 'upstream_error'; + // PR #4255 follow-up review thread (deepseek-v4-pro): mirror the + // `start()` path's stderr audit so on-call can distinguish WAF + // block from network reset from malformed JSON at 3 AM. + // + // Three follow-up tightenings: + // + // 1. **Skip ONLY when the registry-owned signal aborted (#4291, + // follow-up gpt-5.5 review).** Earlier shape also skipped + // when `err.name === 'AbortError'`, but `AbortError` can + // come from sources WE didn't initiate — upstream IdP TCP + // RST, proxy timeout, undici/node-fetch wrapping unrelated + // transport failures as AbortError. Those are real failures + // that the operator needs visibility into; silently dropping + // them was a signal-loss bug. Now we skip iff `opts.signal` + // was driven aborted by `cancel()` / `dispose()` — anything + // else, including unexpected `AbortError`, falls through to + // the sanitized breadcrumb path with `signalAborted=false`. + // + // 2. **Don't echo raw `err.message`** (Copilot review on + // #4291). `pollDeviceToken` POSTs `device_code` + + // `code_verifier` (PKCE) per RFC 8628 §3.4. A WAF / reverse + // proxy that echoes the request body in its error response + // would put those bearer-equivalent values into daemon + // stderr — violating the BrandedSecret-style "secrets never + // appear in logs" contract the registry depends on. Log + // STRUCTURED diagnostics only: `QwenOAuthPollError.oauthError` + // (RFC 8628 §3.5 enum), or for non-OAuth errors, just the + // constructor name + a bounded message length so the + // on-call still gets a breadcrumb without the request-body + // echo path. + // + // 3. **Sanitize `oauthError` before interpolation (#4291, + // follow-up gpt-5.5 review).** The OAuth error code field + // is attacker-controlled JSON from the IdP / proxy / WAF. + // A value like `slow_down\n[serve] FAKE LOG ENTRY ...` would + // forge additional log lines; a value with `\x1b[31m` could + // inject ANSI control sequences into operator terminals. + // Strip C0/C1 controls before interpolation. + const aborted = opts.signal.aborted; + if (!aborted) { + let safeDetail: string; + if (err instanceof QwenOAuthPollError) { + // Structured upstream OAuth error envelope — no raw body, + // but the `oauthError` field IS attacker-controlled, so + // sanitize C0/C1 controls before interpolating. + const rawOauthError = err.oauthError ?? '(missing)'; + safeDetail = `oauthError=${sanitizeForStderr(rawOauthError)}`; + } else if (err instanceof Error) { + // Non-OAuth (network / parse / unexpected upstream shape / + // unexpected AbortError). The constructor name + length is + // enough for triage; the raw message MAY contain WAF-echoed + // request body fields. + safeDetail = `${err.name} (message ${err.message.length} bytes; raw suppressed to avoid echoing device_code/PKCE)`; + } else { + safeDetail = ``; + } + writeStderrLine( + `[serve] qwen device-flow poll failed (errorKind=${errorKind}): ${truncateForStderr(safeDetail)}`, + ); + } return { kind: 'error', errorKind, diff --git a/packages/cli/src/serve/server.test.ts b/packages/cli/src/serve/server.test.ts index 01b3d9c778b..79c9dba0a5d 100644 --- a/packages/cli/src/serve/server.test.ts +++ b/packages/cli/src/serve/server.test.ts @@ -4156,6 +4156,102 @@ describe('auth device-flow routes', () => { expect(fakeProvider.startCount()).toBe(1); }); + it('POST take-over only echoes userCode/verificationUri/initiatorClientId to caller matching the initiator (#4291 follow-up review)', async () => { + // PR #4291 follow-up review (gpt-5.5, #3): policy consistency. + // The closed-out GET redaction (don't echo userCode to non- + // initiator callers) was bypassable via POST take-over — + // any bearer-token holder POSTing the same `providerId` got + // `attached: true` AND the original starter's verification + // material. Now the same caller-clientId gate applies. Fresh + // starts naturally pass (caller IS initiator); take-overs by + // a different clientId see only the public envelope. + const { app } = buildApp({ token: 'tkn' }); + // Starter identifies as sdk-A. + const first = await request(app) + .post('/workspace/auth/device-flow') + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .set('X-Qwen-Client-Id', 'sdk-A') + .send({ providerId: 'qwen-oauth' }); + expect(first.status).toBe(201); + // Fresh starter MUST see the verification material — they ARE + // the initiator. + expect(first.body.userCode).toBe('USER-1'); + expect(first.body.verificationUri).toBe('https://idp.example/verify'); + expect(first.body.initiatorClientId).toBe('sdk-A'); + + // Different SDK take-over — must NOT see verification fields. + const takeoverDifferent = await request(app) + .post('/workspace/auth/device-flow') + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .set('X-Qwen-Client-Id', 'sdk-B') + .send({ providerId: 'qwen-oauth' }); + expect(takeoverDifferent.status).toBe(200); + expect(takeoverDifferent.body.attached).toBe(true); + expect(takeoverDifferent.body.deviceFlowId).toBe(first.body.deviceFlowId); + expect(takeoverDifferent.body).not.toHaveProperty('userCode'); + expect(takeoverDifferent.body).not.toHaveProperty('verificationUri'); + expect(takeoverDifferent.body).not.toHaveProperty( + 'verificationUriComplete', + ); + expect(takeoverDifferent.body).not.toHaveProperty('initiatorClientId'); + + // Anonymous take-over against an identified-start — must NOT see + // verification fields either (mismatched: identified vs anonymous). + const takeoverAnon = await request(app) + .post('/workspace/auth/device-flow') + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .send({ providerId: 'qwen-oauth' }); + expect(takeoverAnon.status).toBe(200); + expect(takeoverAnon.body.attached).toBe(true); + expect(takeoverAnon.body).not.toHaveProperty('userCode'); + + // Same-id take-over (sdk-A again) — DOES see the material. + const takeoverSame = await request(app) + .post('/workspace/auth/device-flow') + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .set('X-Qwen-Client-Id', 'sdk-A') + .send({ providerId: 'qwen-oauth' }); + expect(takeoverSame.status).toBe(200); + expect(takeoverSame.body.attached).toBe(true); + expect(takeoverSame.body.userCode).toBe('USER-1'); + expect(takeoverSame.body.initiatorClientId).toBe('sdk-A'); + }); + + it('POST take-over preserves the anonymous-start → anonymous-reattach use case', async () => { + // PR #4291 follow-up review (gpt-5.5, #3): the both-undefined + // branch of `callerIsInitiator` keeps the legitimate "anonymous + // start, anonymous re-attach (e.g., process restart, no + // persisted clientId)" use case working. Without this, every + // anonymous re-attach would silently lose the userCode. + const { app } = buildApp({ token: 'tkn' }); + const first = await request(app) + .post('/workspace/auth/device-flow') + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .send({ providerId: 'qwen-oauth' }); + expect(first.status).toBe(201); + expect(first.body.userCode).toBe('USER-1'); + + const reattach = await request(app) + .post('/workspace/auth/device-flow') + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .send({ providerId: 'qwen-oauth' }); + expect(reattach.status).toBe(200); + expect(reattach.body.attached).toBe(true); + expect(reattach.body.deviceFlowId).toBe(first.body.deviceFlowId); + // Both-undefined: anonymous initiator, anonymous re-attach → same + // caller. Verification fields ARE returned. + expect(reattach.body.userCode).toBe('USER-1'); + expect(reattach.body.verificationUri).toBe('https://idp.example/verify'); + // No initiatorClientId echoed (none was set originally). + expect(reattach.body).not.toHaveProperty('initiatorClientId'); + }); + it('GET /workspace/auth/device-flow/:id returns 200 for known + 404 for unknown', async () => { const { app } = buildApp({ token: 'tkn' }); const post = await request(app) @@ -4415,10 +4511,10 @@ describe('auth device-flow routes', () => { it('GET /workspace/auth/device-flow/:id is strict-gated; GET /workspace/auth/status is read-only', async () => { // The two GETs have ASYMMETRIC auth posture by design: // - `GET /workspace/auth/device-flow/:id` returns `userCode` for - // pending entries, which is shoulder-surf-able if a peer process - // on the same host can read it. fold-in (round-4 #1) added - // `mutate({strict:true})` to close the info-disclosure - // asymmetry vs. the strict POST/DELETE. + // pending entries (only when caller's clientId matches the + // initiator — see follow-up review thread test below). fold-in + // (round-4 #1) added `mutate({strict:true})` to close the + // info-disclosure asymmetry vs. the strict POST/DELETE. // - `GET /workspace/auth/status` intentionally redacts userCode // (lists only deviceFlowId/providerId/expiresAt) so it stays // bearer-only (passthrough on loopback no-token default). @@ -4434,4 +4530,137 @@ describe('auth device-flow routes', () => { .set('Host', `127.0.0.1:${baseOpts.port}`); expect(status.status).toBe(200); }); + + it('GET /workspace/auth/device-flow/:id only echoes userCode/verificationUri/initiatorClientId to caller matching the initiator', async () => { + // PR #4255 follow-up review thread (deepseek-v4-pro): the GET + // response shape is symmetrized with the POST take-over response. + // An anonymous caller, or a caller identifying as a different + // client, only sees the public envelope (status/timestamps/error + // fields) — never the verification code or the initiator id. + const { app } = buildApp({ token: 'tkn' }); + const post = await request(app) + .post('/workspace/auth/device-flow') + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .set('X-Qwen-Client-Id', 'sdk-A') + .send({ providerId: 'qwen-oauth' }); + const id = post.body.deviceFlowId as string; + expect(typeof id).toBe('string'); + + const matchingCaller = await request(app) + .get(`/workspace/auth/device-flow/${id}`) + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .set('X-Qwen-Client-Id', 'sdk-A'); + expect(matchingCaller.status).toBe(200); + expect(matchingCaller.body.deviceFlowId).toBe(id); + expect(matchingCaller.body.userCode).toBe('USER-1'); + expect(matchingCaller.body.verificationUri).toBe( + 'https://idp.example/verify', + ); + expect(matchingCaller.body.initiatorClientId).toBe('sdk-A'); + + const anonymousCaller = await request(app) + .get(`/workspace/auth/device-flow/${id}`) + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`); + expect(anonymousCaller.status).toBe(200); + expect(anonymousCaller.body.deviceFlowId).toBe(id); + expect(anonymousCaller.body).not.toHaveProperty('userCode'); + expect(anonymousCaller.body).not.toHaveProperty('verificationUri'); + expect(anonymousCaller.body).not.toHaveProperty('verificationUriComplete'); + expect(anonymousCaller.body).not.toHaveProperty('initiatorClientId'); + + const differentCaller = await request(app) + .get(`/workspace/auth/device-flow/${id}`) + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .set('X-Qwen-Client-Id', 'sdk-B'); + expect(differentCaller.status).toBe(200); + expect(differentCaller.body.deviceFlowId).toBe(id); + expect(differentCaller.body).not.toHaveProperty('userCode'); + expect(differentCaller.body).not.toHaveProperty('verificationUri'); + expect(differentCaller.body).not.toHaveProperty('verificationUriComplete'); + expect(differentCaller.body).not.toHaveProperty('initiatorClientId'); + }); + + it('GET /workspace/auth/device-flow/:id returns 400 invalid_client_id when X-Qwen-Client-Id is malformed (qwen-latest review N3)', async () => { + // PR #4291 follow-up review (qwen-latest, N3): the GET handler's + // strict-clientId behavior — added in this PR to drive the + // `callerIsInitiator` gate — was documented in JSDoc but not + // pinned in CI. A future refactor that removes or reorders the + // `parseClientIdHeader` call would silently revert the contract + // change. Pin: a malformed header (>128 chars or invalid chars) + // returns 400 `invalid_client_id` from THIS specific GET route. + const { app } = buildApp({ token: 'tkn' }); + const post = await request(app) + .post('/workspace/auth/device-flow') + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .send({ providerId: 'qwen-oauth' }); + const id = post.body.deviceFlowId as string; + + // Over-length: 129 chars. + const tooLong = 'a'.repeat(129); + const tooLongRes = await request(app) + .get(`/workspace/auth/device-flow/${id}`) + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .set('X-Qwen-Client-Id', tooLong); + expect(tooLongRes.status).toBe(400); + expect(tooLongRes.body.code).toBe('invalid_client_id'); + + // Invalid characters (spaces / quotes — anything outside the + // allowed token charset). + const badChars = await request(app) + .get(`/workspace/auth/device-flow/${id}`) + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .set('X-Qwen-Client-Id', 'has spaces and "quotes"'); + expect(badChars.status).toBe(400); + expect(badChars.body.code).toBe('invalid_client_id'); + }); + + it('GET /workspace/auth/device-flow/:id returns userCode for an anonymously-started flow when the GET caller is also anonymous', async () => { + // PR #4291 follow-up review (qwen-latest, #3): the original + // gate required both `initiatorClientId` AND `callerClientId` + // to be defined and equal — which silently locked anonymous- + // started flows out of their own data (the SDK that didn't + // pass `X-Qwen-Client-Id` on POST also doesn't pass it on + // GET, but the response body switched from "useful" to + // "redacted public envelope" with HTTP 200 and no error). Fix: + // also accept `both undefined` as the same caller. The gate's + // purpose is to prevent CROSS-client reads, not to lock + // anonymous flows out of themselves. + const { app } = buildApp({ token: 'tkn' }); + // Start anonymously (no X-Qwen-Client-Id header). + const post = await request(app) + .post('/workspace/auth/device-flow') + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .send({ providerId: 'qwen-oauth' }); + const id = post.body.deviceFlowId as string; + expect(typeof id).toBe('string'); + // Anonymous GET — must still see the verification fields. + const anonGet = await request(app) + .get(`/workspace/auth/device-flow/${id}`) + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`); + expect(anonGet.status).toBe(200); + expect(anonGet.body.deviceFlowId).toBe(id); + expect(anonGet.body.userCode).toBe('USER-1'); + expect(anonGet.body.verificationUri).toBe('https://idp.example/verify'); + // No initiatorClientId — there wasn't one (anonymous start). + expect(anonGet.body).not.toHaveProperty('initiatorClientId'); + // An IDENTIFIED caller, however, is NOT the same caller — + // they don't get the verification fields. + const identified = await request(app) + .get(`/workspace/auth/device-flow/${id}`) + .set('Authorization', 'Bearer tkn') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .set('X-Qwen-Client-Id', 'sdk-X'); + expect(identified.status).toBe(200); + expect(identified.body).not.toHaveProperty('userCode'); + expect(identified.body).not.toHaveProperty('verificationUri'); + }); }); diff --git a/packages/cli/src/serve/server.ts b/packages/cli/src/serve/server.ts index b6f1258ef47..8147c629df0 100644 --- a/packages/cli/src/serve/server.ts +++ b/packages/cli/src/serve/server.ts @@ -716,6 +716,16 @@ export function createServeApp( // information-disclosure asymmetry (the sibling // `GET /workspace/auth/status` stays bearer-only because its // pendingDeviceFlows entries intentionally omit `userCode`). + // + // PR #4291 follow-up review (qwen-latest, #4): GET now also runs + // `parseClientIdHeader` to drive the `callerIsInitiator` gate in + // `toDeviceFlowStateBody`. INTENTIONAL contract change: a malformed + // `X-Qwen-Client-Id` (>128 chars or invalid characters) returns + // `400 invalid_client_id` instead of the previous 200, matching the + // POST/DELETE behavior. SDK clients that send the header on POST + // should send a valid value on GET too. Anonymous callers (header + // absent) are unaffected and continue to work as pre-PR-4291 — the + // both-undefined branch in `callerIsInitiator` covers them. app.get( '/workspace/auth/device-flow/:id', mutate({ strict: true }), @@ -736,7 +746,37 @@ export function createServeApp( }); return; } - res.status(200).json(toDeviceFlowStateBody(view)); + const clientId = parseClientIdHeader(req, res); + if (clientId === null) return; + // PR #4291 follow-up review (qwen-latest, N4): when the + // `callerIsInitiator` gate redacts the verification fields, + // operators triaging "SDK got HTTP 200 but no userCode" have + // zero signal in daemon stderr / audit. The redaction happens + // INSIDE the body shaper which doesn't have an audit sink, so + // the route handler is the right layer to record it. Use + // QWEN_SERVE_DEBUG-gated stderr (rather than unconditional + // audit) — multi-SDK setups sharing a bearer token will cause + // legitimate "different caller GETs same flow" traffic that + // would otherwise flood production logs. Operators who hit + // the symptom can flip QWEN_SERVE_DEBUG=1 and get the + // breadcrumb on the next reproduction. + const callerIsInitiator = + (view.initiatorClientId === undefined && clientId === undefined) || + (view.initiatorClientId !== undefined && + clientId !== undefined && + clientId === view.initiatorClientId); + if ( + !callerIsInitiator && + process.env['QWEN_SERVE_DEBUG'] && + !['0', 'false', 'off', 'no'].includes( + (process.env['QWEN_SERVE_DEBUG'] ?? '').trim().toLowerCase(), + ) + ) { + writeStderrLine( + `qwen serve debug: GET /workspace/auth/device-flow/${id} redacted verification fields — caller-clientId mismatch (initiator=${view.initiatorClientId ?? 'anonymous'}, caller=${clientId ?? 'anonymous'})`, + ); + } + res.status(200).json(toDeviceFlowStateBody(view, clientId)); }, ); @@ -1732,14 +1772,34 @@ function toDeviceFlowStartResponseBody( deviceFlowId: view.deviceFlowId, providerId: view.providerId, status: view.status, - userCode: view.userCode ?? '', - verificationUri: view.verificationUri ?? '', expiresAt: view.expiresAt ?? 0, intervalMs: view.intervalMs ?? 0, attached, }; - if (view.verificationUriComplete) { - body['verificationUriComplete'] = view.verificationUriComplete; + // PR #4291 follow-up review (gpt-5.5, #3): policy consistency with + // `toDeviceFlowStateBody` — only the original starter sees the + // verification material. Earlier shape unconditionally returned + // `userCode` / `verificationUri` / `verificationUriComplete` on + // every POST, including the `attached: true` take-over case, so any + // bearer-token holder that POSTed `providerId: ` got the + // verification code another client started. That bypassed the + // closed-out GET redaction completely. Apply the same gate here. + // Fresh starts naturally pass the gate because `view.initiatorClientId` + // was set from the same `callerClientId` on this very request. + // Take-over callers that don't match the initiator now see the + // public envelope only. The both-undefined branch preserves the + // anonymous-start → anonymous-reattach use case. + const callerIsInitiator = + (view.initiatorClientId === undefined && callerClientId === undefined) || + (view.initiatorClientId !== undefined && + callerClientId !== undefined && + callerClientId === view.initiatorClientId); + if (callerIsInitiator) { + body['userCode'] = view.userCode ?? ''; + body['verificationUri'] = view.verificationUri ?? ''; + if (view.verificationUriComplete) { + body['verificationUriComplete'] = view.verificationUriComplete; + } } // PR #4255 round-12 #6 (gpt-5.5 review CzHOK): minor info-leak // close-out — only echo `initiatorClientId` back to a take-over @@ -1763,6 +1823,7 @@ function toDeviceFlowStartResponseBody( function toDeviceFlowStateBody( view: DeviceFlowPublicView, + callerClientId?: string, ): Record { const body: Record = { deviceFlowId: view.deviceFlowId, @@ -1772,16 +1833,55 @@ function toDeviceFlowStateBody( }; if (view.errorKind) body['errorKind'] = view.errorKind; if (view.hint) body['hint'] = view.hint; - if (view.userCode) body['userCode'] = view.userCode; - if (view.verificationUri) body['verificationUri'] = view.verificationUri; - if (view.verificationUriComplete) { - body['verificationUriComplete'] = view.verificationUriComplete; - } if (view.expiresAt !== undefined) body['expiresAt'] = view.expiresAt; if (view.intervalMs !== undefined) body['intervalMs'] = view.intervalMs; if (view.lastPolledAt !== undefined) body['lastPolledAt'] = view.lastPolledAt; - if (view.initiatorClientId) { - body['initiatorClientId'] = view.initiatorClientId; + // PR #4255 follow-up review thread (deepseek-v4-pro): symmetrize with + // the POST take-over response shape — only echo `userCode` / + // `verificationUri` / `verificationUriComplete` / `initiatorClientId` + // back to the original starter (matched by `X-Qwen-Client-Id`). An + // anonymous GET caller, or a caller identifying as a different client, + // sees only the public envelope (`status` / `errorKind` / `hint` / + // timestamps). Bearer-token gated already (the route uses + // `mutate({ strict: true })`), so the blast radius was small, but + // multi-client setups sharing a single daemon token could otherwise + // enumerate other clients' verification codes. + // + // **Threat model (PR #4291 follow-up review by Copilot):** this gate + // is BEST-EFFORT ATTRIBUTION, not authentication. `X-Qwen-Client-Id` + // is a syntactic header, not bound to a server-validated identity — + // anyone holding the bearer token can spoof it. The bearer token IS + // the auth boundary; this gate exists to prevent ACCIDENTAL + // cross-client reads in well-behaved multi-SDK setups (and to keep + // GET symmetric with the POST take-over shape closed out in + // round-12 #6 of #4255). A determined attacker who has compromised + // the daemon bearer token already wins; locking down GET further + // would require binding identity into bearer-token issuance, which + // is a separate architectural change. + // PR #4291 follow-up review (qwen-latest, #3): the gate must accept + // the both-undefined case too, otherwise an anonymously-started flow + // (POST without `X-Qwen-Client-Id` → `initiatorClientId === undefined`) + // becomes silently unreadable: even the same anonymous caller GETting + // the same id can no longer retrieve `userCode`/`verificationUri` — + // the body switches from "what they got from POST" to a redacted + // public envelope, with HTTP 200, no error. Pre-PR-4291 GET returned + // these fields to anyone with the bearer; this gate's purpose is to + // prevent CROSS-client reads, not to lock anonymous flows out of + // their own data. + const callerIsInitiator = + (view.initiatorClientId === undefined && callerClientId === undefined) || + (view.initiatorClientId !== undefined && + callerClientId !== undefined && + callerClientId === view.initiatorClientId); + if (callerIsInitiator) { + if (view.userCode) body['userCode'] = view.userCode; + if (view.verificationUri) body['verificationUri'] = view.verificationUri; + if (view.verificationUriComplete) { + body['verificationUriComplete'] = view.verificationUriComplete; + } + if (view.initiatorClientId) { + body['initiatorClientId'] = view.initiatorClientId; + } } return body; } diff --git a/packages/sdk-typescript/src/daemon/events.ts b/packages/sdk-typescript/src/daemon/events.ts index 02548240846..12fc98e8781 100644 --- a/packages/sdk-typescript/src/daemon/events.ts +++ b/packages/sdk-typescript/src/daemon/events.ts @@ -199,6 +199,16 @@ export type DaemonAuthDeviceFlowErrorKind = * exchange succeeded but the daemon couldn't durably store credentials * (EACCES, EROFS, ENOSPC, etc.). Distinct from `upstream_error`. */ | 'persist_failed' + /** SDK-synthesized when the daemon's GET returns 404 inside + * `DaemonAuthFlow.awaitCompletion`. Surfaced from `getDeviceFlowOrSynthetic404` + * rather than the daemon — three reachable causes: (a) the flow expired + * past the 5-min terminal grace window and the sweeper reaped it, (b) the + * daemon was restarted and lost the in-memory registry, (c) the + * `deviceFlowId` was wrong / spoofed. PR #4255 follow-up review thread + * (deepseek-v4-pro): added to the typed union so SDK consumers' exhaustive + * switches narrow it as a known literal instead of falling into the + * `(string & {})` fallback arm. */ + | 'not_found_or_evicted' | (string & {}); export interface DaemonAuthDeviceFlowStartedData {