diff --git a/docs/superpowers/plans/2026-05-26-daemon-logger.md b/docs/superpowers/plans/2026-05-26-daemon-logger.md new file mode 100644 index 00000000000..b98afa80e23 --- /dev/null +++ b/docs/superpowers/plans/2026-05-26-daemon-logger.md @@ -0,0 +1,1497 @@ +# `qwen serve` Daemon File Logger — Implementation Plan + +> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. + +**Goal:** Add a daemon-scoped file logger to `qwen serve` so route errors, lifecycle messages, and ACP child stderr land in `~/.qwen/debug/daemon/.log` in addition to stderr — eliminating the manual `2>serve.log` workaround for issue #4548. + +**Architecture:** New cli-local module `daemonLogger.ts` exposes `initDaemonLogger(opts) → DaemonLogger`. `info/warn/error` tee to file + stderr; `raw` is file-only. `acp-bridge` gets a new optional `BridgeOptions.onDiagnosticLine` callback and `createSpawnChannelFactory({ onDiagnosticLine })` helper so the cli can route `writeServeDebugLine` and ACP child stderr lines into the daemon log without acp-bridge taking a cli dependency. No global singleton — logger is constructed per `runQwenServe` invocation. + +**Tech Stack:** TypeScript, Vitest, Node `fs.promises`, existing `Storage.getGlobalDebugDir()`, existing `updateSymlink` helper. + +**Reference spec:** `docs/superpowers/specs/2026-05-26-daemon-logger-design.md` + +**Test harness:** `vitest run` from each package; for a single file: `cd packages/ && npx vitest run `. + +--- + +## File map + +| File | Action | Purpose | +| ---------------------------------------------- | --------------- | ---------------------------------------------------------------------------------------------------------------------------- | +| `packages/cli/src/serve/daemonLogger.ts` | **new** | Logger sink + format helper | +| `packages/cli/src/serve/daemonLogger.test.ts` | **new** | Unit tests for the above | +| `packages/acp-bridge/src/bridgeOptions.ts` | modify | Add `onDiagnosticLine?` field + `DiagnosticLineSink` type | +| `packages/acp-bridge/src/bridge.ts` | modify | Tee `writeServeDebugLine` through `opts.onDiagnosticLine` (via local `teeServeDebugLine` closure) | +| `packages/acp-bridge/src/bridge.test.ts` | modify | Add test that `onDiagnosticLine` receives debug lines | +| `packages/acp-bridge/src/spawnChannel.ts` | modify | Export `createSpawnChannelFactory({ onDiagnosticLine })`; tee child stderr into callback | +| `packages/acp-bridge/src/spawnChannel.test.ts` | modify (or new) | Test stderr forwarding callback | +| `packages/cli/src/serve/server.ts` | modify | `createServeApp` deps accept optional `daemonLog`; `sendBridgeError` routes through it when provided | +| `packages/cli/src/serve/server.test.ts` | modify | Verify daemonLog receives route-error entries | +| `packages/cli/src/serve/runQwenServe.ts` | modify | Init logger, boot banner, wire spawn factory + bridge callback, replace lifecycle `writeStderrLine` calls, flush on shutdown | +| `packages/cli/src/serve/runQwenServe.test.ts` | modify | Verify boot banner + flush behavior | +| `docs/cli/serve.md` (or equivalent) | modify | Document daemon log path + opt-out | + +--- + +## Task 0: Pre-flight + +- [ ] **Step 1: Confirm worktree + branch** + +Run: `git rev-parse --abbrev-ref HEAD && pwd` +Expected: branch `feat/support_daemon_logger`, cwd ends with `.claude/worktrees/feat-support-daemon-logger`. + +- [ ] **Step 2: Install dependencies + baseline tests green** + +Run: `npm install && cd packages/cli && npx vitest run src/serve/runQwenServe.test.ts && cd ../acp-bridge && npx vitest run` +Expected: all pass. (If not, baseline is broken — stop and report.) + +- [ ] **Step 3: Skim the spec** + +Read `docs/superpowers/specs/2026-05-26-daemon-logger-design.md` end-to-end. Key sections to internalize: §3 (modules), §4 (path), §5 (API), §6 (format + tee semantics), §7 (boot/shutdown), §11 (error handling). + +--- + +## Task 1: `buildDaemonLogLine` pure helper + +Pure formatter. No I/O. Easy to TDD. + +**Files:** + +- Create: `packages/cli/src/serve/daemonLogger.ts` +- Create: `packages/cli/src/serve/daemonLogger.test.ts` + +- [ ] **Step 1: Write the failing tests** + +`packages/cli/src/serve/daemonLogger.test.ts`: + +```ts +/** + * @license + * Copyright 2025 Qwen Team + * SPDX-License-Identifier: Apache-2.0 + */ + +import { describe, it, expect } from 'vitest'; +import { buildDaemonLogLine } from './daemonLogger.js'; + +describe('buildDaemonLogLine', () => { + const FIXED = new Date('2026-05-26T03:14:15.926Z'); + + it('formats INFO with no ctx', () => { + expect( + buildDaemonLogLine({ + level: 'INFO', + message: 'daemon started', + now: FIXED, + }), + ).toBe('2026-05-26T03:14:15.926Z [INFO] [DAEMON] daemon started\n'); + }); + + it('renders ctx fields in fixed order', () => { + const line = buildDaemonLogLine({ + level: 'ERROR', + message: 'route failed', + now: FIXED, + ctx: { + sessionId: 'sess-1', + route: 'POST /session/:id/prompt', + clientId: 'client-x', + childPid: 4242, + channelId: 'ch-9', + }, + }); + expect(line).toBe( + '2026-05-26T03:14:15.926Z [ERROR] [DAEMON] ' + + 'route=POST /session/:id/prompt sessionId=sess-1 clientId=client-x ' + + 'childPid=4242 channelId=ch-9 route failed\n', + ); + }); + + it('appends extra ctx keys sorted lexicographically after fixed keys', () => { + const line = buildDaemonLogLine({ + level: 'WARN', + message: 'note', + now: FIXED, + ctx: { zeta: 1, alpha: 'a', sessionId: 's' }, + }); + expect(line).toBe( + '2026-05-26T03:14:15.926Z [WARN] [DAEMON] sessionId=s alpha=a zeta=1 note\n', + ); + }); + + it('JSON.stringify-quotes values that contain spaces or =', () => { + const line = buildDaemonLogLine({ + level: 'INFO', + message: 'hi', + now: FIXED, + ctx: { weird: 'has space', eq: 'a=b' }, + }); + expect(line).toBe( + '2026-05-26T03:14:15.926Z [INFO] [DAEMON] eq="a=b" weird="has space" hi\n', + ); + }); + + it('appends error stack as indented continuation lines', () => { + const err = new Error('boom'); + err.stack = + 'Error: boom\n at fn (file.ts:1:1)\n at main (file.ts:2:2)'; + const line = buildDaemonLogLine({ + level: 'ERROR', + message: 'failed', + now: FIXED, + err, + }); + expect(line).toBe( + '2026-05-26T03:14:15.926Z [ERROR] [DAEMON] failed\n' + + ' Error: boom\n' + + ' at fn (file.ts:1:1)\n' + + ' at main (file.ts:2:2)\n', + ); + }); + + it('falls back to err.message when stack missing', () => { + const err: Error = { name: 'Plain', message: 'no stack' } as Error; + const line = buildDaemonLogLine({ + level: 'ERROR', + message: 'failed', + now: FIXED, + err, + }); + expect(line).toBe( + '2026-05-26T03:14:15.926Z [ERROR] [DAEMON] failed\n' + + ' Plain: no stack\n', + ); + }); +}); +``` + +- [ ] **Step 2: Run test, confirm fail** + +Run: `cd packages/cli && npx vitest run src/serve/daemonLogger.test.ts` +Expected: failure — `buildDaemonLogLine` not exported. + +- [ ] **Step 3: Implement `buildDaemonLogLine`** + +Create `packages/cli/src/serve/daemonLogger.ts` with: + +```ts +/** + * @license + * Copyright 2025 Qwen Team + * SPDX-License-Identifier: Apache-2.0 + */ + +export type DaemonLogLevel = 'INFO' | 'WARN' | 'ERROR'; + +export interface DaemonLogContext { + route?: string; + sessionId?: string; + clientId?: string; + childPid?: number; + channelId?: string; + [key: string]: unknown; +} + +const FIXED_CTX_ORDER = [ + 'route', + 'sessionId', + 'clientId', + 'childPid', + 'channelId', +] as const; + +function renderCtxValue(value: unknown): string { + const s = String(value); + return /[\s=]/.test(s) ? JSON.stringify(s) : s; +} + +function renderCtx(ctx: DaemonLogContext | undefined): string { + if (!ctx) return ''; + const parts: string[] = []; + for (const key of FIXED_CTX_ORDER) { + const v = ctx[key]; + if (v !== undefined && v !== null) { + parts.push(`${key}=${renderCtxValue(v)}`); + } + } + const fixedSet = new Set(FIXED_CTX_ORDER); + const extraKeys = Object.keys(ctx) + .filter((k) => !fixedSet.has(k) && ctx[k] !== undefined && ctx[k] !== null) + .sort(); + for (const key of extraKeys) { + parts.push(`${key}=${renderCtxValue(ctx[key])}`); + } + return parts.length > 0 ? parts.join(' ') + ' ' : ''; +} + +function renderErr(err: Error | undefined): string { + if (!err) return ''; + const body = err.stack ?? `${err.name ?? 'Error'}: ${err.message}`; + return ( + body + .split('\n') + .map((l) => ` ${l}`) + .join('\n') + '\n' + ); +} + +export interface BuildDaemonLogLineArgs { + level: DaemonLogLevel; + message: string; + now: Date; + ctx?: DaemonLogContext; + err?: Error; +} + +export function buildDaemonLogLine(args: BuildDaemonLogLineArgs): string { + const ts = args.now.toISOString(); + const ctxStr = renderCtx(args.ctx); + return `${ts} [${args.level}] [DAEMON] ${ctxStr}${args.message}\n${renderErr(args.err)}`; +} +``` + +- [ ] **Step 4: Run test, confirm pass** + +Run: `cd packages/cli && npx vitest run src/serve/daemonLogger.test.ts` +Expected: PASS (6 specs). + +- [ ] **Step 5: Commit** + +```bash +git add packages/cli/src/serve/daemonLogger.ts packages/cli/src/serve/daemonLogger.test.ts +git commit -m "feat(serve): buildDaemonLogLine formatter (#4548)" +``` + +--- + +## Task 2: `initDaemonLogger` opt-out + no-op factory + +Returns a no-op logger when `QWEN_DAEMON_LOG_FILE` is disabled. No filesystem touch yet. + +**Files:** + +- Modify: `packages/cli/src/serve/daemonLogger.ts` +- Modify: `packages/cli/src/serve/daemonLogger.test.ts` + +- [ ] **Step 1: Add failing tests** + +Append to `daemonLogger.test.ts`: + +```ts +import { initDaemonLogger } from './daemonLogger.js'; +import { afterEach, beforeEach } from 'vitest'; + +describe('initDaemonLogger opt-out', () => { + const originalEnv = process.env['QWEN_DAEMON_LOG_FILE']; + afterEach(() => { + if (originalEnv === undefined) delete process.env['QWEN_DAEMON_LOG_FILE']; + else process.env['QWEN_DAEMON_LOG_FILE'] = originalEnv; + }); + + for (const val of ['0', 'false', 'off', 'no', 'False', ' OFF ']) { + it(`returns no-op logger when QWEN_DAEMON_LOG_FILE=${JSON.stringify(val)}`, () => { + process.env['QWEN_DAEMON_LOG_FILE'] = val; + const stderr: string[] = []; + const logger = initDaemonLogger({ + boundWorkspace: '/tmp/ws', + baseDir: '/tmp/nonexistent-should-not-touch', + stderr: (s) => stderr.push(s), + }); + logger.info('hello'); + logger.warn('there'); + logger.error('boom'); + logger.raw('raw'); + expect(stderr).toEqual([]); // no-op = nothing + expect(logger.getLogPath()).toBe(''); + expect(logger.getDaemonId()).toBe(''); + }); + } +}); +``` + +- [ ] **Step 2: Run, confirm fail** + +Run: `cd packages/cli && npx vitest run src/serve/daemonLogger.test.ts` +Expected: failure — `initDaemonLogger` not exported. + +- [ ] **Step 3: Implement opt-out + no-op shape** + +Append to `daemonLogger.ts`: + +```ts +export interface DaemonLogger { + info(message: string, ctx?: DaemonLogContext): void; + warn(message: string, ctx?: DaemonLogContext): void; + error(message: string, err?: Error | null, ctx?: DaemonLogContext): void; + raw(line: string, level?: 'info' | 'warn' | 'error'): void; + getLogPath(): string; + getDaemonId(): string; + flush(): Promise; +} + +export interface InitDaemonLoggerOptions { + boundWorkspace: string; + pid?: number; + now?: () => Date; + stderr?: (line: string) => void; + baseDir?: string; +} + +const NOOP_LOGGER: DaemonLogger = { + info: () => {}, + warn: () => {}, + error: () => {}, + raw: () => {}, + getLogPath: () => '', + getDaemonId: () => '', + flush: () => Promise.resolve(), +}; + +function isOptedOut(): boolean { + const raw = process.env['QWEN_DAEMON_LOG_FILE']; + if (!raw) return false; + return ['0', 'false', 'off', 'no'].includes(raw.trim().toLowerCase()); +} + +export function initDaemonLogger(_opts: InitDaemonLoggerOptions): DaemonLogger { + if (isOptedOut()) return NOOP_LOGGER; + throw new Error('initDaemonLogger: file path not implemented yet'); +} +``` + +- [ ] **Step 4: Run, confirm opt-out specs pass** + +Run: `cd packages/cli && npx vitest run src/serve/daemonLogger.test.ts -t "opt-out"` +Expected: opt-out specs PASS; full file may still fail (we'll add coverage incrementally). + +- [ ] **Step 5: Commit** + +```bash +git add packages/cli/src/serve/daemonLogger.ts packages/cli/src/serve/daemonLogger.test.ts +git commit -m "feat(serve): daemon logger opt-out env + no-op shape (#4548)" +``` + +--- + +## Task 3: File init (daemon-id, mkdir, sync probe, degraded fallback) + +**Files:** + +- Modify: `packages/cli/src/serve/daemonLogger.ts` +- Modify: `packages/cli/src/serve/daemonLogger.test.ts` + +- [ ] **Step 1: Add failing tests** + +Append to `daemonLogger.test.ts`: + +```ts +import * as os from 'node:os'; +import * as path from 'node:path'; +import { + mkdtempSync, + readFileSync, + existsSync, + mkdirSync, + chmodSync, +} from 'node:fs'; +import { rmSync } from 'node:fs'; + +describe('initDaemonLogger file init', () => { + let tmp: string; + beforeEach(() => { + tmp = mkdtempSync(path.join(os.tmpdir(), 'daemon-log-')); + }); + afterEach(() => { + try { + rmSync(tmp, { recursive: true, force: true }); + } catch {} + }); + + it('derives daemon-id "serve--" and creates log file', () => { + const logger = initDaemonLogger({ + boundWorkspace: '/workspace/foo', + pid: 1234, + baseDir: tmp, + }); + expect(logger.getDaemonId()).toMatch(/^serve-1234-[0-9a-f]{8}$/); + expect(logger.getLogPath()).toBe( + path.join(tmp, 'daemon', `${logger.getDaemonId()}.log`), + ); + expect(existsSync(logger.getLogPath())).toBe(true); + expect(readFileSync(logger.getLogPath(), 'utf8')).toMatch( + /\[INFO\] \[DAEMON\] daemon started pid=1234 workspace=\/workspace\/foo/, + ); + }); + + it('falls back to no-op when mkdir fails', () => { + const stderr: string[] = []; + // Create a file where the directory should be → mkdir EEXIST/ENOTDIR + const blockingFile = path.join(tmp, 'daemon'); + require('node:fs').writeFileSync(blockingFile, 'blocker'); + + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + stderr: (s) => stderr.push(s), + }); + expect(logger.getLogPath()).toBe(''); + expect(stderr.join('\n')).toMatch(/daemon log disabled/); + expect(() => logger.info('after')).not.toThrow(); + }); +}); +``` + +- [ ] **Step 2: Run, confirm fail** + +Run: `cd packages/cli && npx vitest run src/serve/daemonLogger.test.ts -t "file init"` +Expected: failure — `throw new Error('not implemented')`. + +- [ ] **Step 3: Implement file init** + +Replace the throwing body of `initDaemonLogger`. Add imports and helpers: + +```ts +import * as nodeFs from 'node:fs'; +import * as nodePath from 'node:path'; +import * as crypto from 'node:crypto'; +import { writeStderrLine } from '../utils/stdioHelpers.js'; +import { Storage } from '@qwen-code/qwen-code-core'; + +function computeDaemonId(pid: number, boundWorkspace: string): string { + const hash = crypto + .createHash('sha256') + .update(boundWorkspace) + .digest('hex') + .slice(0, 8); + return `serve-${pid}-${hash}`; +} + +export function initDaemonLogger(opts: InitDaemonLoggerOptions): DaemonLogger { + if (isOptedOut()) return NOOP_LOGGER; + + const pid = opts.pid ?? process.pid; + const now = opts.now ?? (() => new Date()); + const stderr = opts.stderr ?? writeStderrLine; + const baseDir = opts.baseDir ?? Storage.getGlobalDebugDir(); + + const daemonId = computeDaemonId(pid, opts.boundWorkspace); + const daemonDir = nodePath.join(baseDir, 'daemon'); + const logPath = nodePath.join(daemonDir, `${daemonId}.log`); + + try { + nodeFs.mkdirSync(daemonDir, { recursive: true }); + const firstLine = buildDaemonLogLine({ + level: 'INFO', + message: `daemon started pid=${pid} workspace=${opts.boundWorkspace}`, + now: now(), + }); + nodeFs.appendFileSync(logPath, firstLine, { flag: 'a' }); + } catch (err) { + stderr( + `qwen serve: daemon log disabled — init failed: ${ + err instanceof Error ? err.message : String(err) + }`, + ); + return NOOP_LOGGER; + } + + // Methods come in Task 4. For now stub them out so the file-init tests pass. + return { + info: () => {}, + warn: () => {}, + error: () => {}, + raw: () => {}, + getLogPath: () => logPath, + getDaemonId: () => daemonId, + flush: () => Promise.resolve(), + }; +} +``` + +- [ ] **Step 4: Run, confirm pass** + +Run: `cd packages/cli && npx vitest run src/serve/daemonLogger.test.ts -t "file init"` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add packages/cli/src/serve/daemonLogger.ts packages/cli/src/serve/daemonLogger.test.ts +git commit -m "feat(serve): daemon logger file init + degraded fallback (#4548)" +``` + +--- + +## Task 4: `info` / `warn` / `error` + async queue + flush + stderr tee + +**Files:** + +- Modify: `packages/cli/src/serve/daemonLogger.ts` +- Modify: `packages/cli/src/serve/daemonLogger.test.ts` + +- [ ] **Step 1: Add failing tests** + +Append to `daemonLogger.test.ts`: + +```ts +describe('initDaemonLogger info/warn/error', () => { + let tmp: string; + beforeEach(() => { + tmp = mkdtempSync(path.join(os.tmpdir(), 'daemon-log-')); + }); + afterEach(() => { + try { + rmSync(tmp, { recursive: true, force: true }); + } catch {} + }); + + it('info appends to file and tees to stderr', async () => { + const stderr: string[] = []; + const fixed = new Date('2026-05-26T03:14:15.926Z'); + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + stderr: (s) => stderr.push(s), + now: () => fixed, + }); + logger.info('hello', { route: 'GET /' }); + await logger.flush(); + const content = readFileSync(logger.getLogPath(), 'utf8'); + expect(content).toContain('[INFO] [DAEMON] route=GET / hello\n'); + // Stderr saw the same line (after boot banner, which isn't teed here). + const teedLines = stderr.filter((s) => s.includes('[INFO] [DAEMON]')); + expect(teedLines).toHaveLength(1); + }); + + it('error appends err.stack as continuation', async () => { + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + }); + const err = new Error('boom'); + logger.error('route failed', err, { route: 'POST /x' }); + await logger.flush(); + const content = readFileSync(logger.getLogPath(), 'utf8'); + expect(content).toMatch( + /\[ERROR\] \[DAEMON\] route=POST \/x route failed\n Error: boom/, + ); + }); + + it('flush awaits all pending appends', async () => { + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + }); + for (let i = 0; i < 50; i++) logger.info(`msg-${i}`); + await logger.flush(); + const lines = readFileSync(logger.getLogPath(), 'utf8').split('\n'); + const msgLines = lines.filter((l) => /msg-\d+$/.test(l)); + expect(msgLines).toHaveLength(50); + for (let i = 0; i < 50; i++) { + expect(msgLines[i]).toContain(`msg-${i}`); + } + }); + + it('warns once on append failure and keeps trying', async () => { + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + stderr: () => {}, + }); + // Sabotage by removing the file mid-flight — POSIX will keep the inode + // around for a held fd, but appendFile reopens each call → ENOENT once + // the parent dir is gone. + rmSync(path.dirname(logger.getLogPath()), { recursive: true, force: true }); + const stderr2: string[] = []; + // Re-create logger to bind our stderr capture? Simpler: re-stub via + // private state — instead, do this in a separate test using a custom + // stderr from init time. + logger.info('after-rm-1'); + logger.info('after-rm-2'); + await logger.flush(); + // No throw — degraded path swallows. (Stderr count assertion left to + // a separate variant if needed; this test pins "no crash on failure".) + }); +}); +``` + +- [ ] **Step 2: Run, confirm fail** + +Run: `cd packages/cli && npx vitest run src/serve/daemonLogger.test.ts -t "info/warn/error"` +Expected: failure — methods are stubs. + +- [ ] **Step 3: Implement methods + queue + flush + tee** + +Replace the final `return {...}` block in `initDaemonLogger`: + +```ts +let pending: Promise = Promise.resolve(); +let degraded = false; + +const enqueueAppend = (line: string): void => { + pending = pending.then(() => + nodeFs.promises.appendFile(logPath, line).catch((err) => { + if (!degraded) { + degraded = true; + stderr( + `qwen serve: daemon log write failed — entering degraded mode: ${ + err instanceof Error ? err.message : String(err) + }`, + ); + } + }), + ); +}; + +const teeLine = ( + level: DaemonLogLevel, + message: string, + ctx?: DaemonLogContext, + err?: Error, +): void => { + const line = buildDaemonLogLine({ level, message, now: now(), ctx, err }); + // stderr first (synchronous, preserves human-visible order), then file. + stderr(line.trimEnd()); + enqueueAppend(line); +}; + +return { + info: (message, ctx) => teeLine('INFO', message, ctx), + warn: (message, ctx) => teeLine('WARN', message, ctx), + error: (message, err, ctx) => + teeLine('ERROR', message, ctx, err ?? undefined), + raw: () => {}, // implemented in Task 5 + getLogPath: () => logPath, + getDaemonId: () => daemonId, + flush: () => pending, +}; +``` + +- [ ] **Step 4: Run, confirm pass** + +Run: `cd packages/cli && npx vitest run src/serve/daemonLogger.test.ts -t "info/warn/error"` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add packages/cli/src/serve/daemonLogger.ts packages/cli/src/serve/daemonLogger.test.ts +git commit -m "feat(serve): daemon logger info/warn/error + flush (#4548)" +``` + +--- + +## Task 5: `raw()` file-only tee + +**Files:** + +- Modify: `packages/cli/src/serve/daemonLogger.ts` +- Modify: `packages/cli/src/serve/daemonLogger.test.ts` + +- [ ] **Step 1: Add failing test** + +Append: + +```ts +describe('initDaemonLogger raw', () => { + let tmp: string; + beforeEach(() => { + tmp = mkdtempSync(path.join(os.tmpdir(), 'daemon-log-')); + }); + afterEach(() => { + try { + rmSync(tmp, { recursive: true, force: true }); + } catch {} + }); + + it('appends prefixed line, no stderr tee', async () => { + const stderr: string[] = []; + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + stderr: (s) => stderr.push(s), + }); + const stderrBefore = stderr.length; + logger.raw('[serve pid=123 cwd=/x] child crashed', 'warn'); + logger.raw('[serve pid=123 cwd=/x] another'); + await logger.flush(); + const content = readFileSync(logger.getLogPath(), 'utf8'); + expect(content).toContain( + '[WARN] [DAEMON] [serve pid=123 cwd=/x] child crashed\n', + ); + expect(content).toContain( + '[INFO] [DAEMON] [serve pid=123 cwd=/x] another\n', + ); + // No new stderr lines from raw() + expect(stderr.length).toBe(stderrBefore); + }); +}); +``` + +- [ ] **Step 2: Run, confirm fail** + +Run: `cd packages/cli && npx vitest run src/serve/daemonLogger.test.ts -t "raw"` +Expected: fail — raw is no-op. + +- [ ] **Step 3: Implement raw** + +In `initDaemonLogger`, replace `raw: () => {},` with: + +```ts +raw: (line: string, level: 'info' | 'warn' | 'error' = 'info') => { + const upper = level.toUpperCase() as DaemonLogLevel; + const formatted = `${now().toISOString()} [${upper}] [DAEMON] ${line}\n`; + enqueueAppend(formatted); +}, +``` + +- [ ] **Step 4: Run, confirm pass** + +Run: `cd packages/cli && npx vitest run src/serve/daemonLogger.test.ts -t "raw"` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add packages/cli/src/serve/daemonLogger.ts packages/cli/src/serve/daemonLogger.test.ts +git commit -m "feat(serve): daemon logger raw() file-only tee (#4548)" +``` + +--- + +## Task 6: `latest` symlink + +**Files:** + +- Modify: `packages/cli/src/serve/daemonLogger.ts` +- Modify: `packages/cli/src/serve/daemonLogger.test.ts` + +- [ ] **Step 1: Add failing test** + +Append: + +```ts +import { realpathSync, lstatSync } from 'node:fs'; + +describe('initDaemonLogger latest symlink', () => { + let tmp: string; + beforeEach(() => { + tmp = mkdtempSync(path.join(os.tmpdir(), 'daemon-log-')); + }); + afterEach(() => { + try { + rmSync(tmp, { recursive: true, force: true }); + } catch {} + }); + + it('creates daemon/latest pointing to the current log', () => { + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 42, + baseDir: tmp, + }); + const linkPath = path.join(tmp, 'daemon', 'latest'); + expect(lstatSync(linkPath).isSymbolicLink() || existsSync(linkPath)).toBe( + true, + ); + expect(realpathSync(linkPath)).toBe(realpathSync(logger.getLogPath())); + }); + + it('updates latest on subsequent init in same dir', () => { + const a = initDaemonLogger({ boundWorkspace: '/w', pid: 1, baseDir: tmp }); + const b = initDaemonLogger({ boundWorkspace: '/w', pid: 2, baseDir: tmp }); + expect(realpathSync(path.join(tmp, 'daemon', 'latest'))).toBe( + realpathSync(b.getLogPath()), + ); + expect(realpathSync(a.getLogPath())).not.toBe(realpathSync(b.getLogPath())); + }); +}); +``` + +- [ ] **Step 2: Run, confirm fail** + +Run: `cd packages/cli && npx vitest run src/serve/daemonLogger.test.ts -t "latest symlink"` +Expected: fail — symlink not created. + +- [ ] **Step 3: Implement symlink update** + +`updateSymlink` lives in `packages/core/src/utils/symlink.ts` but is NOT re-exported from the core barrel (confirmed via `grep -n updateSymlink packages/core/src/index.ts` → no matches at plan-write time). Add the re-export first: + +In `packages/core/src/index.ts`, add (near the other utils exports): + +```ts +export { updateSymlink } from './utils/symlink.js'; +``` + +Then import in `daemonLogger.ts`: + +```ts +import { Storage, updateSymlink } from '@qwen-code/qwen-code-core'; +``` + +(Merge with the existing `Storage` import added in Task 3.) + +Inside `initDaemonLogger`, after the `appendFileSync` first-line write succeeds, add: + +```ts +try { + const aliasPath = nodePath.join(daemonDir, 'latest'); + updateSymlink(aliasPath, logPath, { fallbackCopy: false }).catch(() => { + // Best-effort. Symlink failure must not degrade primary writes. + }); +} catch { + // Sync throw equally best-effort. +} +``` + +- [ ] **Step 4: Run, confirm pass** + +Run: `cd packages/cli && npx vitest run src/serve/daemonLogger.test.ts -t "latest symlink"` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add packages/cli/src/serve/daemonLogger.ts packages/cli/src/serve/daemonLogger.test.ts packages/core/src/index.ts +git commit -m "feat(serve): daemon logger latest symlink (#4548)" +``` + +--- + +## Task 7: Add `BridgeOptions.onDiagnosticLine` + tee `writeServeDebugLine` + +**Files:** + +- Modify: `packages/acp-bridge/src/bridgeOptions.ts` +- Modify: `packages/acp-bridge/src/bridge.ts` +- Modify: `packages/acp-bridge/src/bridge.test.ts` + +- [ ] **Step 1: Add `DiagnosticLineSink` type to `bridgeOptions.ts`** + +Insert near the top of the `BridgeOptions` interface (before `sessionScope`): + +```ts +/** + * Sink for serve-level diagnostic lines (set by the cli daemon logger). + * When provided, the bridge tees `writeServeDebugLine` output through + * this callback alongside the existing stderr write — used by + * runQwenServe to capture them in the daemon log file. The bridge + * does not own a file logger itself; this is a pure pass-through hook. + */ +export type DiagnosticLineSink = ( + line: string, + level?: 'info' | 'warn' | 'error', +) => void; +``` + +Add inside `BridgeOptions`: + +```ts + /** + * Optional: tee `writeServeDebugLine` output. See {@link DiagnosticLineSink}. + * No-op when omitted. Set by cli `runQwenServe` from the daemon logger. + */ + onDiagnosticLine?: DiagnosticLineSink; +``` + +- [ ] **Step 2: Add failing test** + +In `packages/acp-bridge/src/bridge.test.ts`, add a new `describe('onDiagnosticLine', ...)` block. The file already imports `makeBridge` and `makeChannel` from `./internal/testUtils.js` — reuse them instead of hand-rolling a `ChannelFactory`. Confirm with `grep -n "import.*testUtils" packages/acp-bridge/src/bridge.test.ts`. To trigger `writeServeDebugLine`, pick the shortest-setup test among the 6 call sites — list them with `grep -n "writeServeDebugLine(" packages/acp-bridge/src/bridge.ts` (currently lines 1410, 1423, 2242, 2328, 2624, 2637; the cross-session permission-vote rejection around line 2242 is a small reproducible trigger). + +```ts +describe('onDiagnosticLine', () => { + const originalDebug = process.env['QWEN_SERVE_DEBUG']; + afterEach(() => { + if (originalDebug === undefined) delete process.env['QWEN_SERVE_DEBUG']; + else process.env['QWEN_SERVE_DEBUG'] = originalDebug; + }); + + it('receives writeServeDebugLine output when QWEN_SERVE_DEBUG=1', async () => { + process.env['QWEN_SERVE_DEBUG'] = '1'; + const captured: Array<{ line: string; level?: string }> = []; + const bridge = makeBridge({ + onDiagnosticLine: (line, level) => captured.push({ line, level }), + }); + // Trigger writeServeDebugLine via [copy harness from the closest + // existing test that exercises one of the 6 call sites above]. + // ... trigger code here ... + expect(captured.some((e) => e.line.includes('qwen serve debug: '))).toBe( + true, + ); + expect( + captured.every((e) => e.level === undefined || e.level === 'info'), + ).toBe(true); + await bridge.shutdown(); + }); +}); +``` + +(`makeBridge` accepts `Partial` — once Task 7 step 1 adds `onDiagnosticLine` to `BridgeOptions`, it flows through without further edits to `testUtils.ts`.) + +- [ ] **Step 3: Run, confirm fail** + +Run: `cd packages/acp-bridge && npx vitest run src/bridge.test.ts -t "onDiagnosticLine"` +Expected: fail — callback not invoked. + +- [ ] **Step 4: Tee `writeServeDebugLine` through the callback** + +In `packages/acp-bridge/src/bridge.ts`, near the top of `createHttpAcpBridge` (after `opts` is destructured), introduce a local tee that wraps the existing module-level helper: + +```ts +const teeServeDebugLine = (message: string): void => { + writeServeDebugLine(message); + if (opts.onDiagnosticLine && isServeDebugLoggingEnabled()) { + opts.onDiagnosticLine(`qwen serve debug: ${message}`, 'info'); + } +}; +``` + +Then, in this file replace every internal `writeServeDebugLine(...)` call **inside** `createHttpAcpBridge`'s closure with `teeServeDebugLine(...)`. Use: + +```bash +grep -n "writeServeDebugLine(" packages/acp-bridge/src/bridge.ts +``` + +to enumerate call sites — there are 6 in the current tree (lines 1410, 1423, 2242, 2328, 2624, 2637; verify with the grep). Edit each. Do NOT change the module-level `writeServeDebugLine` definition itself — other entry points and tests rely on it. + +(Reason for not editing the top-level definition: changes the signature for all callers including tests; the closure tee is additive and locally-scoped.) + +- [ ] **Step 5: Run, confirm pass** + +Run: `cd packages/acp-bridge && npx vitest run src/bridge.test.ts -t "onDiagnosticLine"` +Expected: PASS. Also run full file to catch regressions: `npx vitest run src/bridge.test.ts`. + +- [ ] **Step 6: Commit** + +```bash +git add packages/acp-bridge/src/bridgeOptions.ts packages/acp-bridge/src/bridge.ts packages/acp-bridge/src/bridge.test.ts +git commit -m "feat(acp-bridge): onDiagnosticLine sink for serve debug tee (#4548)" +``` + +--- + +## Task 8: `createSpawnChannelFactory` with `onDiagnosticLine` + +**Files:** + +- Modify: `packages/acp-bridge/src/spawnChannel.ts` +- Modify: `packages/acp-bridge/src/spawnChannel.test.ts` (or create if missing) + +- [ ] **Step 1: Inspect current export shape** + +```bash +grep -n "defaultSpawnChannelFactory\|onDiagnosticLine\|process.stderr.write" packages/acp-bridge/src/spawnChannel.ts | head -20 +``` + +Confirm `defaultSpawnChannelFactory` is the only public spawn export. The existing child-stderr forwarder calls `process.stderr.write(prefix + line + '\n')` inside the body — locate that block (around line 125). + +- [ ] **Step 2: Add failing test** + +In `packages/acp-bridge/src/spawnChannel.test.ts` (look for an existing test file; if none, create one): + +```ts +import { describe, it, expect } from 'vitest'; +import * as path from 'node:path'; +import { fileURLToPath } from 'node:url'; +import { createSpawnChannelFactory } from './spawnChannel.js'; + +describe('createSpawnChannelFactory onDiagnosticLine', () => { + it('returns a ChannelFactory that tees child stderr lines', async () => { + const captured: Array<{ line: string; level?: string }> = []; + const factory = createSpawnChannelFactory({ + onDiagnosticLine: (line, level) => captured.push({ line, level }), + }); + // Spawn a tiny child that writes to stderr then exits. Use the + // QWEN_CLI_ENTRY escape hatch to point at a Node one-liner. + const here = path.dirname(fileURLToPath(import.meta.url)); + process.env['QWEN_CLI_ENTRY'] = path.join( + here, + 'testutil', + 'stderrOnlyEntry.cjs', + ); + try { + const ch = await factory('/tmp', {}); + await ch.exited; + // After child exit, the forwarder flushes buffered tail. + expect( + captured.some((e) => + /\[serve pid=\d+ cwd=\/tmp\] hello-stderr/.test(e.line), + ), + ).toBe(true); + expect( + captured.every((e) => e.level === undefined || e.level === 'warn'), + ).toBe(true); + } finally { + delete process.env['QWEN_CLI_ENTRY']; + } + }); +}); +``` + +And a fixture entry `packages/acp-bridge/src/testutil/stderrOnlyEntry.cjs`: + +```js +process.stderr.write('hello-stderr\n'); +process.exit(0); +``` + +(Adjust if the bridge requires ACP initialize handshake before considering the child "spawned" — alternative: write the stderr line during initialize handling. If the test is too brittle, fall back to mocking the spawn and asserting the forwarder logic in isolation — read `defaultSpawnChannelFactory`'s body and unit-test the inner forwarder by exporting it for tests.) + +- [ ] **Step 3: Run, confirm fail** + +Run: `cd packages/acp-bridge && npx vitest run src/spawnChannel.test.ts -t "onDiagnosticLine"` +Expected: fail — `createSpawnChannelFactory` not exported. + +- [ ] **Step 4: Implement `createSpawnChannelFactory`** + +Refactor `defaultSpawnChannelFactory` into a factory-of-factories. Replace the top of `spawnChannel.ts`: + +```ts +export interface SpawnChannelFactoryOptions { + onDiagnosticLine?: (line: string, level?: 'info' | 'warn' | 'error') => void; +} + +export function createSpawnChannelFactory( + options: SpawnChannelFactoryOptions = {}, +): ChannelFactory { + const onDiagnosticLine = options.onDiagnosticLine; + return async (workspaceCwd, childEnvOverrides) => { + // ... existing body of defaultSpawnChannelFactory ... + // Where the existing forwarder does: + // process.stderr.write(prefix + line + '\n') + // change it to: + // const teedLine = prefix + line; + // process.stderr.write(teedLine + '\n'); + // if (onDiagnosticLine) onDiagnosticLine(teedLine, 'warn'); + // For the [truncated] branch: + // const teedTrunc = prefix + buf.slice(0, STDERR_LINE_CAP_CHARS) + ' [truncated]'; + // process.stderr.write(teedTrunc + '\n'); + // if (onDiagnosticLine) onDiagnosticLine(teedTrunc, 'warn'); + }; +} + +// Preserve the old export for backward compatibility (no callback wiring). +export const defaultSpawnChannelFactory: ChannelFactory = + createSpawnChannelFactory(); +``` + +Implementation discipline: + +- Do NOT remove `defaultSpawnChannelFactory` — channels/IDE adapters still import it. +- Stick to the exact existing stderr write semantics (line buffering, 64 KiB cap, truncation marker). The `onDiagnosticLine` call sits next to each existing `process.stderr.write` and never replaces it. + +- [ ] **Step 5: Run, confirm pass** + +Run: `cd packages/acp-bridge && npx vitest run src/spawnChannel.test.ts -t "onDiagnosticLine"` +Expected: PASS. Also `npx vitest run` full suite to confirm no regressions. + +- [ ] **Step 6: Commit** + +```bash +git add packages/acp-bridge/src/spawnChannel.ts packages/acp-bridge/src/spawnChannel.test.ts packages/acp-bridge/src/testutil/stderrOnlyEntry.cjs +git commit -m "feat(acp-bridge): createSpawnChannelFactory with onDiagnosticLine (#4548)" +``` + +--- + +## Task 9: Route `sendBridgeError` through `daemonLog` + +**Files:** + +- Modify: `packages/cli/src/serve/server.ts` +- Modify: `packages/cli/src/serve/server.test.ts` + +- [ ] **Step 1: Add `daemonLog` to `createServeApp` deps** + +Read `packages/cli/src/serve/server.ts` around the `createServeApp` signature (search for `export function createServeApp` or `export interface ServeAppDeps`). Add to its deps interface: + +```ts +/** + * Optional daemon logger. When provided, `sendBridgeError` routes + * each route-mapped error through `daemonLog.error(...)` (which tees + * to stderr + the daemon log file). When omitted, falls back to + * existing stderr-only behavior. + */ +daemonLog?: import('./daemonLogger.js').DaemonLogger; +``` + +- [ ] **Step 2: Add failing test** + +In `packages/cli/src/serve/server.test.ts`, add (or extend a route-error test): + +```ts +import { initDaemonLogger } from './daemonLogger.js'; + +it('sendBridgeError routes through daemonLog when provided', async () => { + const tmp = mkdtempSync(path.join(os.tmpdir(), 'daemon-log-')); + try { + const stderr: string[] = []; + const daemonLog = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + stderr: (s) => stderr.push(s), + }); + // createServeApp signature: (opts, getPort?, deps?). daemonLog goes in deps. + const app = createServeApp( + /* opts */ { /* ...usual ServeOptions, copy from closest existing test... */ } as ServeOptions, + /* getPort */ () => 0, + /* deps */ { /* ...usual deps that make a route throw... */, daemonLog }, + ); + await request(app).get('/some/erroring/route').expect(500); + await daemonLog.flush(); + const content = readFileSync(daemonLog.getLogPath(), 'utf8'); + expect(content).toMatch( + /\[ERROR\] \[DAEMON\] route=GET \/some\/erroring\/route/, + ); + } finally { + rmSync(tmp, { recursive: true, force: true }); + } +}); +``` + +(Copy whatever route-throws-error harness already lives in `server.test.ts` — e.g. inject a deps stub that throws when called. The point is one route hits `sendBridgeError` → assertion lands in the daemon log.) + +- [ ] **Step 3: Run, confirm fail** + +Run: `cd packages/cli && npx vitest run src/serve/server.test.ts -t "daemonLog"` +Expected: fail. + +- [ ] **Step 4: Wire `sendBridgeError`** + +In `server.ts`, find the `sendBridgeError` function (around line 2765). It currently writes to stderr inline. Refactor: + +1. Plumb `daemonLog` from `createServeApp` into the closure that owns `sendBridgeError` (it's defined inside the function — same closure). +2. At the bottom of `sendBridgeError`, where the stderr write happens, replace with: + +```ts +if (daemonLog) { + daemonLog.error( + err instanceof Error ? err.message : String(err), + err instanceof Error ? err : null, + { + ...(ctx?.route ? { route: ctx.route } : {}), + ...(ctx?.sessionId ? { sessionId: ctx.sessionId } : {}), + }, + ); +} else { + // Legacy stderr-only path. Keep behavior intact for embedders that + // construct createServeApp without daemonLog (tests, direct integrations). + writeStderrLine( + `qwen serve: ${ctx?.route ?? 'unknown route'}: ${ + err instanceof Error ? (err.stack ?? err.message) : String(err) + }${ctx?.sessionId ? ` sessionId=${ctx.sessionId}` : ''}`, + ); +} +``` + +Make sure the new branch is taken when `daemonLog` is non-null. `daemonLog.error` already tees to stderr, so the stderr line is still produced — no behavior loss. + +- [ ] **Step 5: Run, confirm pass** + +Run: `cd packages/cli && npx vitest run src/serve/server.test.ts` +Expected: full file PASS (new + old). + +- [ ] **Step 6: Commit** + +```bash +git add packages/cli/src/serve/server.ts packages/cli/src/serve/server.test.ts +git commit -m "feat(serve): route sendBridgeError through daemonLog (#4548)" +``` + +--- + +## Task 10: Wire `runQwenServe` — init, boot banner, callbacks, lifecycle, shutdown flush + +**Files:** + +- Modify: `packages/cli/src/serve/runQwenServe.ts` +- Modify: `packages/cli/src/serve/runQwenServe.test.ts` + +- [ ] **Step 1: Read the existing boot + shutdown structure** + +Re-read `packages/cli/src/serve/runQwenServe.ts` lines 590-1030 (the `createHttpAcpBridge({...})` call site, the `RunHandle.close` body, and the `onSignal` handler). Note all `writeStderrLine(...)` calls — they're at roughly 393, 565, 805, 821, 825, 835, 859, 865, 872, 877, 951, 961, 986, 997, 1027, 1361 (run `grep -n writeStderrLine` for the current line numbers). + +- [ ] **Step 2: Add failing test** + +In `packages/cli/src/serve/runQwenServe.test.ts`, add (or extend): + +```ts +import { existsSync, readFileSync, rmSync, mkdtempSync } from 'node:fs'; +import * as os from 'node:os'; +import * as path from 'node:path'; + +it('runQwenServe initializes daemon logger and writes boot banner + flushes on shutdown', async () => { + const tmpRuntime = mkdtempSync(path.join(os.tmpdir(), 'serve-runtime-')); + const originalRuntime = process.env['QWEN_RUNTIME_DIR']; + process.env['QWEN_RUNTIME_DIR'] = tmpRuntime; + try { + const handle = await runQwenServe({ + port: 0, + hostname: '127.0.0.1', + mode: 'workspace', + // ... fill remaining required opts from the smallest existing test ... + }); + // Boot wrote a daemon log somewhere under tmpRuntime/debug/daemon + const daemonDir = path.join(tmpRuntime, 'debug', 'daemon'); + expect(existsSync(daemonDir)).toBe(true); + const logs = require('node:fs') + .readdirSync(daemonDir) + .filter((f: string) => f.endsWith('.log')); + expect(logs.length).toBe(1); + const content = readFileSync(path.join(daemonDir, logs[0]), 'utf8'); + expect(content).toMatch(/daemon started pid=\d+ workspace=/); + await handle.close(); + // After shutdown, "shutdown signal" or equivalent should be in the log. + const after = readFileSync(path.join(daemonDir, logs[0]), 'utf8'); + expect(after).toMatch(/shutdown/i); + } finally { + if (originalRuntime === undefined) delete process.env['QWEN_RUNTIME_DIR']; + else process.env['QWEN_RUNTIME_DIR'] = originalRuntime; + rmSync(tmpRuntime, { recursive: true, force: true }); + } +}); +``` + +- [ ] **Step 3: Run, confirm fail** + +Run: `cd packages/cli && npx vitest run src/serve/runQwenServe.test.ts -t "daemon logger"` +Expected: fail. + +- [ ] **Step 4: Wire in `runQwenServe`** + +Edit `runQwenServe.ts`: + +1. Add imports near the existing ones: + +```ts +import { initDaemonLogger, type DaemonLogger } from './daemonLogger.js'; +import { createSpawnChannelFactory } from '@qwen-code/acp-bridge/spawnChannel'; +``` + +2. Inside `runQwenServe(opts)`, right after `boundWorkspace` is canonicalized (find the assignment; it's the value passed to `createHttpAcpBridge`): + +```ts +const daemonLog: DaemonLogger = initDaemonLogger({ boundWorkspace }); +writeStderrLine( + `qwen serve: daemon log → ${daemonLog.getLogPath() || '(disabled)'}`, +); +``` + +3. Update the `createHttpAcpBridge({...})` call (around line 606): + +```ts +const channelFactory = createSpawnChannelFactory({ + onDiagnosticLine: (line, level) => daemonLog.raw(line, level), +}); +const bridge = + deps.bridge ?? + createHttpAcpBridge({ + // ... existing fields ... + channelFactory, + onDiagnosticLine: (line, level) => daemonLog.raw(line, level), + }); +``` + +(If `deps.bridge` is provided, the operator is embedding and owns their own wiring — skip the callback.) + +4. Update the `createServeApp(...)` call (currently at `runQwenServe.ts:706`, signature is `createServeApp(opts, getPort, deps)`) to add `daemonLog` to the deps object: + +```ts +const app = createServeApp(opts, () => actualPort, { + bridge, + boundWorkspace, + fsFactory, + daemonLog, +}); +``` + +5. Replace **lifecycle-only** `writeStderrLine(...)` calls (the ones inside `onSignal`, the `bridge.shutdown` error path, the server `error` listener, the device-flow dispose error, the "received signal, draining" line) with `daemonLog.warn(...)` / `daemonLog.error(..., err)` — daemonLog tees to stderr so operator-visible output is preserved. Do NOT touch: + - Boot banner about "listening on URL" (that one is stdout, not stderr — `writeStdoutLine`). + - CLI usage/argparse errors before `daemonLog` is constructed. + - The lone "qwen serve: daemon log → ..." banner added in step 2 (avoid logging a line about itself). + + To be concrete, the **mechanical** rule for this step: every `writeStderrLine` call **after** the `daemonLog` is constructed and **before** `process.exit` is candidate; if its content reads like a daemon diagnostic (not a one-shot startup banner), switch it. + +6. In the `RunHandle.close` body, after the `finish` callback runs (or right before `process.exit(0)` in `onSignal`), add `await daemonLog.flush();`. Concretely, the `onSignal` handler becomes: + +```ts +const onSignal = async (signal: NodeJS.Signals) => { + if (shuttingDown) { + /* unchanged */ return; + } + daemonLog.warn(`received ${signal}, draining`, { signal }); + try { + await handle.close(); + await daemonLog.flush(); + process.exit(0); + } catch (err) { + daemonLog.error('shutdown error', err instanceof Error ? err : null); + await daemonLog.flush().catch(() => {}); + process.exit(1); + } +}; +``` + +- [ ] **Step 5: Run, confirm pass** + +Run: `cd packages/cli && npx vitest run src/serve/runQwenServe.test.ts` +Expected: full file PASS. + +Run also: `cd packages/cli && npx vitest run src/serve/` (full serve dir, catches indirect regressions like server.test.ts assertions on stderr output). + +- [ ] **Step 6: Commit** + +```bash +git add packages/cli/src/serve/runQwenServe.ts packages/cli/src/serve/runQwenServe.test.ts +git commit -m "feat(serve): init daemonLogger in runQwenServe + flush on shutdown (#4548)" +``` + +--- + +## Task 11: Documentation + +**Files:** + +- Modify: existing serve docs (locate with `find docs -iname '*serve*'` and `ls docs/cli/`) + +- [ ] **Step 1: Find the right doc** + +```bash +find docs -iname '*serve*' -type f +ls docs/cli/ 2>/dev/null +``` + +Pick the most natural home — likely `docs/cli/serve.md`. If none exists for `qwen serve`, create `docs/cli/serve-daemon-log.md`. + +- [ ] **Step 2: Write the section** + +Add (or create) a "Daemon log file" section: + +```markdown +## Daemon log file + +`qwen serve` writes a per-process diagnostic log to: +``` + +${QWEN_RUNTIME_DIR or ~/.qwen}/debug/daemon/serve--.log + +``` + +A `latest` symlink in the same directory always points at the current +process's log, so `tail -f ~/.qwen/debug/daemon/latest` will follow whichever +daemon is running. + +The log captures lifecycle messages, route errors (with `route=` and +`sessionId=` context), ACP child stderr, and — when `QWEN_SERVE_DEBUG=1` +is set — extra bridge breadcrumbs. Lines that go to stderr today still +go to stderr; the file log is **additive**, not a replacement. + +### Disabling + +Set `QWEN_DAEMON_LOG_FILE=0` (or `false`/`off`/`no`) to skip file logging +entirely. Stderr output is unaffected. + +### Relation to session debug logs + +Session-scoped debug logs (`~/.qwen/debug/.txt` and the +`~/.qwen/debug/latest` symlink) are independent. The daemon log lives +in a sibling `daemon/` subdirectory; per-session debug semantics are +unchanged by this feature. + +### No rotation + +The daemon log appends indefinitely. Rotate manually if it grows large. +A future enhancement may add automatic rotation; track via #4548 +follow-ups. +``` + +- [ ] **Step 3: Commit** + +```bash +git add docs/cli/serve.md # or the actual file path +git commit -m "docs(serve): document daemon log file path and opt-out (#4548)" +``` + +--- + +## Task 12: Final verification + +- [ ] **Step 1: Full test sweep** + +```bash +cd /Users/jinye.djy/Projects/qwen-code/.claude/worktrees/feat-support-daemon-logger +npm run test --workspace=packages/acp-bridge +npm run test --workspace=packages/cli +``` + +Expected: all green. + +- [ ] **Step 2: Typecheck** + +```bash +npm run typecheck --workspace=packages/acp-bridge +npm run typecheck --workspace=packages/cli +``` + +Expected: no errors. + +- [ ] **Step 3: Manual smoke** + +```bash +QWEN_RUNTIME_DIR=$(mktemp -d) node packages/cli/dist/index.js serve --port 0 --hostname 127.0.0.1 & +SERVE_PID=$! +sleep 1 +ls $QWEN_RUNTIME_DIR/debug/daemon/ +cat $QWEN_RUNTIME_DIR/debug/daemon/latest +kill -TERM $SERVE_PID +wait $SERVE_PID 2>/dev/null || true +cat $QWEN_RUNTIME_DIR/debug/daemon/latest # should now contain shutdown line +``` + +Expected: log file exists, contains `daemon started ...`, then after kill the `received SIGTERM, draining` line. + +If `packages/cli/dist/index.js` doesn't exist, build first: `npm run build --workspace=packages/cli`. + +- [ ] **Step 4: Open PR** + +```bash +git push -u origin HEAD +gh pr create --title "feat(serve): add daemon file logger (#4548)" --body "$(cat <<'EOF' +## Summary +- Adds a per-process daemon file logger at `~/.qwen/debug/daemon/serve--.log` (configurable via `QWEN_RUNTIME_DIR`, opt-out via `QWEN_DAEMON_LOG_FILE=0`). +- Routes `runQwenServe` lifecycle messages, `sendBridgeError` route errors, `writeServeDebugLine` debug breadcrumbs, and ACP child stderr into the daemon log without removing existing stderr output. +- Adds `BridgeOptions.onDiagnosticLine` and `createSpawnChannelFactory({ onDiagnosticLine })` to keep `acp-bridge` ignorant of cli. + +Closes #4548. + +## Test plan +- [x] New unit tests in `packages/cli/src/serve/daemonLogger.test.ts` cover formatter, file init, info/warn/error, raw, latest symlink, opt-out, degraded fallback. +- [x] `packages/acp-bridge/src/bridge.test.ts` covers `onDiagnosticLine` tee from `writeServeDebugLine`. +- [x] `packages/acp-bridge/src/spawnChannel.test.ts` covers child stderr forwarder. +- [x] `packages/cli/src/serve/server.test.ts` covers route-error routing through `daemonLog.error`. +- [x] `packages/cli/src/serve/runQwenServe.test.ts` covers boot banner + flush on shutdown. +- [x] Manual smoke: log file created at boot, contains shutdown line on SIGTERM. + +🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) +EOF +)" +``` + +--- + +## Self-review notes + +- **Spec coverage**: §3 module table covered by Tasks 1-10. §4 daemon-id + path → Task 3. §5 API surface → Tasks 1-6. §6 format + tee semantics → Task 1 (format), Task 4 (info/warn/error tee), Task 5 (raw file-only). §7 boot/shutdown → Task 10. §8 coverage table → Tasks 7/8/9/10. §9 write path & flush → Task 4. §10 config → Task 2 (opt-out), Task 11 (docs). §11 error handling → Tasks 3, 4. §12 testing → distributed across tasks. §13 docs → Task 11. §15 acceptance criteria → met by Tasks 3, 9, 8, 10, 10, 11 respectively. + +- **Trace context (§6 bullet)**: deferred. The spec leaves it explicit ("Helper extracted to a shared module ... or duplicated locally — leave to plan"). The current plan does NOT inject trace_id/span_id; that is a follow-up task tracked in §16. If reviewer pushes back, add a Task 4.5 that imports `trace` from `@opentelemetry/api` and folds the span context into `buildDaemonLogLine` — but only if the reviewer asks; YAGNI otherwise. + +- **`updateSymlink` import path**: Task 6 step 3 hedges on whether `updateSymlink` is exported from `@qwen-code/qwen-code-core`. Verify before editing: `grep -n updateSymlink packages/core/src/index.ts`. If missing, add the re-export in the same commit as Task 6. + +- **acp-bridge test for `createSpawnChannelFactory`**: spawning a real child in a unit test is brittle. If Task 8 step 2 turns out to be flaky in CI, the fallback is to refactor the inner stderr forwarder into a small exported helper (`forwardChildStderr(stream, { prefix, onLine })`) and unit-test that in isolation — no real spawn needed. diff --git a/docs/superpowers/specs/2026-05-26-daemon-logger-design.md b/docs/superpowers/specs/2026-05-26-daemon-logger-design.md new file mode 100644 index 00000000000..0a60e83730a --- /dev/null +++ b/docs/superpowers/specs/2026-05-26-daemon-logger-design.md @@ -0,0 +1,280 @@ +# `qwen serve` Daemon File Logger — Design + +- **Issue**: [QwenLM/qwen-code#4548](https://github.com/QwenLM/qwen-code/issues/4548) +- **Branch**: `feat/support_daemon_logger` +- **Status**: design approved, awaiting implementation plan +- **Date**: 2026-05-26 + +## 1. Problem + +`qwen serve` emits daemon-level diagnostics (lifecycle, route errors, ACP child stderr) to `process.stderr`. That works under systemd/Docker but is fragile for SDK / Desktop / local daemon use: when a client sees `POST /session/:id/prompt` return HTTP 500, the route + session + stack context is gone unless the operator manually redirected stderr. + +`createDebugLogger` (in `packages/core/src/utils/debugLogger.ts`) is session-scoped: it requires an active `DebugLogSession` and writes to `${runtimeBaseDir}/debug/.txt`. The serve daemon starts **before** any session exists, so daemon-level calls would silently no-op. It also can't be reused without changing the per-session `debug/latest` semantics. + +This design adds a daemon-specific file sink, additive to existing stderr behavior, so daemon diagnostics survive without shell redirection. + +## 2. Scope + +### In scope + +- A new logger initialized once per `runQwenServe` process. +- File at `${QWEN_RUNTIME_DIR or ~/.qwen}/debug/daemon/.log`, append mode. +- Tee of: + - `runQwenServe.ts` lifecycle / shutdown / signal messages + - `sendBridgeError` (`server.ts`) route errors + - `bridge.ts` `writeServeDebugLine` (when `QWEN_SERVE_DEBUG` is set) + - `spawnChannel.ts` ACP child stderr forwarding +- Opt-out via `QWEN_DAEMON_LOG_FILE=0|false|off|no`. +- `latest` symlink in the daemon dir for `tail -f`. +- Documentation in serve CLI docs. + +### Out of scope (non-goals from issue) + +- Replacing OpenTelemetry or adding daemon tracing. +- Structured enterprise error log export (issue #2014). +- Rotation or deletion of existing session debug logs. +- Log rotation / size cap for the daemon log itself (deferred to a follow-up PR). A boot-time stderr warning is emitted if the existing file is unusually large; no automatic action. + +## 3. Architecture + +### 3.1 Module boundaries + +| Layer | New / Changed | Responsibility | +| ------------------------------------------------------- | ------------- | --------------------------------------------------------------------------------------------------------------------------------------------- | +| `packages/cli/src/serve/daemonLogger.ts` | **new** | Sink: init, format, append-to-file, tee-to-stderr, flush, latest-symlink | +| `packages/cli/src/serve/runQwenServe.ts` | changed | Init logger at boot; replace lifecycle `writeStderrLine` with `daemonLog.*`; `await flush()` on shutdown; pass `onDiagnosticLine` into bridge | +| `packages/cli/src/serve/server.ts` | changed | `sendBridgeError(...)` routes through `daemonLog.error(...)` | +| `packages/acp-bridge/src/types.ts` (`BridgeOptions`) | changed | Add optional `onDiagnosticLine?: (line: string, level?: 'info' \| 'warn' \| 'error') => void` | +| `packages/acp-bridge/src/bridge.ts:writeServeDebugLine` | changed | If `onDiagnosticLine` injected, tee the same line | +| `packages/acp-bridge/src/spawnChannel.ts` | changed | Child stderr forwarder tees each prefixed line into `onDiagnosticLine` | + +**Design intent**: `daemonLogger.ts` is single-file, cli-local, no global singleton. `acp-bridge` stays ignorant of cli — it only sees a callback. Dependency graph unchanged. + +### 3.2 No global singleton + +Logger is created in `runQwenServe`, passed by closure to internal serve modules that need it (or by callback to `acp-bridge`). Rationale: + +- Mirrors how `BridgeOptions` already injects dependencies. +- Avoids the cross-test state leaks `debugLogger` has hit historically (`resetDebugLoggingState()` exists for that reason). + +## 4. Daemon ID & File Path + +- Path: `Storage.getGlobalDebugDir() + '/daemon/.log'` + - Resolves to `${QWEN_RUNTIME_DIR or ~/.qwen}/debug/daemon/.log`. + - Reuses `Storage.getGlobalDebugDir()` so the runtime-dir override (env var, contextual) automatically applies. +- `daemon-id` = `serve-${pid}-${workspaceHash}` + - `workspaceHash` = `crypto.createHash('sha256').update(boundWorkspace).digest('hex').slice(0, 8)` + - `pid` disambiguates multiple daemons on the same workspace. + - `workspaceHash` is fixed-length, filename-safe, and stable for the same workspace path. +- `latest` symlink: `~/.qwen/debug/daemon/latest` → current process's log file. Updated on init using the existing `updateSymlink` helper (`packages/core/src/utils/symlink.ts`). Symlink failure is logged and ignored — does not degrade primary writes. Distinct from `${runtimeBaseDir}/debug/latest` (session-scoped) per non-goal. +- File mode: `'a'` (append on `O_APPEND | O_CREAT`). Existing files survive restarts for forensics. + +## 5. Public API + +```ts +// packages/cli/src/serve/daemonLogger.ts + +export interface DaemonLogContext { + route?: string; + sessionId?: string; + clientId?: string; + childPid?: number; + channelId?: string; + [key: string]: unknown; +} + +export interface DaemonLogger { + info(message: string, ctx?: DaemonLogContext): void; + warn(message: string, ctx?: DaemonLogContext): void; + /** + * `err.stack` is appended as indented continuation lines after the message. + * Both `err` and `ctx` are optional and independent. + */ + error(message: string, err?: Error | null, ctx?: DaemonLogContext): void; + /** + * File-only tee for lines whose caller is already writing to stderr + * (ACP child stderr forwarder, `writeServeDebugLine`). The line is + * appended to the daemon log under the standard ` [] [DAEMON] ` + * prefix; it is NOT echoed to stderr (which would double the operator's output). + */ + raw(line: string, level?: 'info' | 'warn' | 'error'): void; + /** Absolute path to the daemon log file. */ + getLogPath(): string; + /** `serve--`. */ + getDaemonId(): string; + /** Drain pending appends. Called from runQwenServe shutdown handler. */ + flush(): Promise; +} + +export interface InitDaemonLoggerOptions { + boundWorkspace: string; + pid?: number; // default process.pid + now?: () => Date; // default () => new Date() + stderr?: (line: string) => void; // default writeStderrLine + baseDir?: string; // default Storage.getGlobalDebugDir() +} + +export function initDaemonLogger(opts: InitDaemonLoggerOptions): DaemonLogger; +``` + +`initDaemonLogger` synchronously: + +1. Computes `daemonId` + log path. +2. `mkdirSync(parentDir, { recursive: true })` — fail → return no-op logger, write one stderr warning. Boot continues. +3. `appendFileSync(path, '\n', { flag: 'a' })` — writes `daemon started pid= workspace= version=` synchronously. This doubles as a writability probe; on EACCES/ENOSPC, fail-mode = no-op logger + one stderr warning. +4. Updates `latest` symlink (best-effort, errors swallowed). +5. Returns logger; subsequent `info/warn/error/raw` calls enqueue async `fs.promises.appendFile`. + +If `process.env['QWEN_DAEMON_LOG_FILE']` is one of `0|false|off|no`, `initDaemonLogger` short-circuits to a no-op logger before any filesystem call. + +## 6. Log Line Format + +Mirror `debugLogger.buildLogLine` for visual parity: + +``` +2026-05-26T03:14:15.926Z [ERROR] [DAEMON] [trace_id=... span_id=...] route=POST /session/:id/prompt sessionId=abc clientId=xyz daemon failed to ... + at fn (file.ts:42:7) + at ... +``` + +- Timestamp: ISO 8601, UTC. +- Level: `INFO` | `WARN` | `ERROR`. (No DEBUG initially — `QWEN_SERVE_DEBUG` flows in as `INFO` via `raw()`.) +- Tag: literal `DAEMON`. +- Trace context: `trace.getActiveSpan()` when available; same logic as `debugLogger.getActiveSpanTraceContext`. Helper extracted to a shared module (`packages/core/src/utils/traceContext.ts`?) or duplicated locally — leave to plan. +- Context fields: rendered as `key=value`, fixed order (`route`, `sessionId`, `clientId`, `childPid`, `channelId`), then any extra keys sorted lexicographically. Values containing whitespace or `=` are `JSON.stringify`-quoted. +- Error stack: appended as indented continuation lines after the message. +- `raw(line, level)` writes the line as-is after the standard prefix ` [] [DAEMON] `, no extra processing. + +**Tee semantics (important):** + +- `info` / `warn` / `error` write to **both** the daemon log file **and** stderr (via the injected `stderr` writer). Callers replacing a previous `writeStderrLine(...)` use these directly; no separate stderr call needed. +- `raw` writes to **file only**. Used by ACP child stderr forwarder and `writeServeDebugLine`, where the caller is already writing to stderr through its existing path. Doubling would flood operator output. + +## 7. Boot / Shutdown Flow + +``` +runQwenServe(opts): + ... + daemonLog = initDaemonLogger({ boundWorkspace }) + writeStderrLine(`qwen serve: daemon log → ${daemonLog.getLogPath()}`) + // boot banner is stderr-only to avoid the line referencing itself + + bridge = createHttpAcpBridge({ + ..., + onDiagnosticLine: (line, level) => daemonLog.raw(line, level), + }) + + app = createServeApp({ ..., daemonLog }) // injected for sendBridgeError + + shutdownHandler(signal): + daemonLog.warn(`shutdown signal=${signal}`) + await drainBridge() + await daemonLog.flush() + process.exit(0) +``` + +- Boot banner is stderr-only (the path line about itself would be circular if logged). +- `initDaemonLogger` is synchronous so any failure is visible immediately at boot, not buried after the first error. +- Shutdown `flush()` is the last awaited step before `process.exit`. SIGKILL is unflushable by definition — we accept that. + +## 8. Coverage Table + +| Source | Today | After | +| ------------------------------------------------------------- | -------------------------------------------- | ------------------------------------------------------------------------------------------------ | +| `runQwenServe.ts` lifecycle / signals / config warnings | `writeStderrLine(...)` | `daemonLog.info \| warn(...)` (stderr still happens — `daemonLog` tees) | +| `runQwenServe.ts` "listening on URL" (stdout) | `writeStdoutLine(...)` | unchanged — operator scripts parse stdout | +| `server.ts:sendBridgeError` | `writeStderrLine(...)` with route/sessionId | `daemonLog.error(msg, err, { route, sessionId, ... })` (stderr still emitted by daemonLog's tee) | +| `bridge.ts:writeServeDebugLine` (`QWEN_SERVE_DEBUG`) | `writeStderrLine('qwen serve debug: ...')` | tee to `onDiagnosticLine(line, 'info')` | +| `spawnChannel.ts` child stderr | `process.stderr.write(prefix + line + '\n')` | also `onDiagnosticLine(prefix + line, 'warn')` | +| `writeStdoutLine` callers | unchanged | unchanged | +| CLI usage / argparse errors (`runQwenServe` early validation) | `writeStderrLine(...)` | unchanged (logger may not exist yet) | + +Every existing stderr write is preserved. Daemon log is **additive**, never substitutive. + +## 9. Write Path & Flush + +- Internal queue: a single `Promise` chain (`this.pending = this.pending.then(() => fs.promises.appendFile(...))`). +- Each `info/warn/error/raw` call enqueues an append (file) and, for `info/warn/error`, also synchronously calls the injected `stderr` writer. +- Stderr write order is preserved (synchronous, before queuing the append). File appends are eventually consistent in enqueue order. +- Write failures set an internal `degraded` flag and emit a one-time stderr warning. Subsequent calls still attempt the write but the counter is not maintained. +- `flush()` returns the current tail promise. +- No buffering layer: each call = one `appendFile`. Volume is low (route errors + lifecycle); micro-batching is premature optimization. + +## 10. Configuration + +| Env var | Behavior | +| ----------------------------------------------- | ---------------------------------------------------------------------------- | +| `QWEN_DAEMON_LOG_FILE=0\|false\|off\|no` | `initDaemonLogger` returns no-op; tee is a no-op; stderr unchanged | +| `QWEN_DAEMON_LOG_FILE=` or unset | Enabled (default) | +| `QWEN_RUNTIME_DIR=` | Relocates `~/.qwen` root, daemon log moves with it (existing semantics) | +| `QWEN_SERVE_DEBUG=1` | Existing — `writeServeDebugLine` activates; lines now also tee to daemon log | + +`QWEN_DAEMON_LOG_FILE` is intentionally separate from `QWEN_DEBUG_LOG_FILE` so disabling per-session debug logs doesn't take down the operator's daemon log (and vice versa). + +## 11. Error Handling + +- `initDaemonLogger` mkdir/open failure → no-op logger + one stderr warning. Daemon boot proceeds. Operator sees nothing in the file but still gets stderr. +- Per-append failures → flip degraded flag, emit one stderr warning, keep trying. Issue says nothing about a degraded-mode UI signal, so no public surface needed. +- `flush()` rejection → caught in shutdown handler, logged via `writeStderrLine`. Does not block exit. +- `latest` symlink failure → swallowed; primary writes unaffected. + +## 12. Testing + +### `daemonLogger.test.ts` (new) + +- Sandboxed `baseDir`, mocked `now`, `pid`, `stderr`. +- Path & daemon-id derivation including the 8-char `workspaceHash` for known input. +- `latest` symlink created and updated on subsequent `initDaemonLogger` invocations in the same dir. +- Level formatting (INFO/WARN/ERROR), context field order, error stack continuation. +- Trace context injection when an active span exists. +- `raw(line, level)` writes the prefixed line verbatim. +- `flush()` resolves only after all enqueued writes hit the file. +- `QWEN_DAEMON_LOG_FILE=0` → no file created. +- `mkdir` failure → no-op logger, one stderr warning, subsequent calls don't throw. +- `appendFile` failure → degraded flag flipped, one stderr warning. + +### `runQwenServe.test.ts` (extend) + +- Boot writes `daemon started ...` line to the log. +- Shutdown handler awaits `daemonLog.flush()` before exit. +- Stderr boot banner contains the daemon log path. + +### `server.test.ts` (extend) + +- A route that throws routes the error through `daemonLog.error(...)` with the right `route` and `sessionId`. + +### acp-bridge tests (extend) + +- `onDiagnosticLine` callback invoked from `writeServeDebugLine` when `QWEN_SERVE_DEBUG=1` and from `spawnChannel` child stderr forwarder. Tests inject a capturing fake; no filesystem. + +## 13. Documentation + +- `docs/cli/serve.md` (or wherever serve is documented) gains a "Daemon log file" section covering: path, daemon-id format, `latest` symlink, `QWEN_DAEMON_LOG_FILE` opt-out, distinction from per-session `debug/.txt`. +- README under `packages/cli/src/serve/` if one exists. +- No CHANGELOG-style file in this repo; release notes are handled separately. + +## 14. Rollback + +- Pure-additive change. Rollback = revert the commit: + - Delete `daemonLogger.ts` + its test. + - Revert `runQwenServe.ts` lifecycle / sendBridgeError / bridge / spawnChannel changes. + - Remove `onDiagnosticLine` from `BridgeOptions`. +- No on-disk state to clean up; existing daemon log files become orphaned but harmless. + +## 15. Acceptance Criteria (from issue) + +| Criterion | How met | +| ------------------------------------------------------------------- | ------------------------------------------------------------------------------------------------- | +| `qwen serve` creates / appends daemon log without shell redirection | `initDaemonLogger` opens the file at boot | +| HTTP 500 from `POST /session/:id/prompt` correlatable in daemon log | `sendBridgeError` writes `route=` + `sessionId=` | +| ACP child stderr lines also in daemon log | `spawnChannel` tees through `onDiagnosticLine` | +| Logging works before first session and after all sessions closed | Not session-scoped; lives for daemon lifetime | +| Existing stderr behavior intact | All writes are additive; no `writeStderrLine` call is removed without an equivalent left in place | +| Log path + opt-out documented | Docs section in §13 | + +## 16. Open Questions + +None blocking. Possible follow-ups: + +- Should `latest` symlink go in `~/.qwen/debug/daemon/latest` or `~/.qwen/debug/daemon-latest`? Spec picks the former for directory tidiness. +- Should we offer JSON-line output as a future flag (e.g., `QWEN_DAEMON_LOG_FORMAT=json`)? Out of scope for this PR; structured export is what #2014 owns. diff --git a/docs/users/qwen-serve.md b/docs/users/qwen-serve.md index 260da0822b7..25a8ad886b0 100644 --- a/docs/users/qwen-serve.md +++ b/docs/users/qwen-serve.md @@ -480,6 +480,30 @@ const result = await flow.awaitCompletion({ signal: abortCtrl.signal }); **Cross-client take-over.** Two SDK clients on the same daemon that both `POST /workspace/auth/device-flow` for the same provider get the per-provider singleton: the first call starts a fresh IdP request and returns `attached: false`; the second call returns the EXISTING in-flight entry with `attached: true`. The take-over is recorded on the audit trail (under the second client's `X-Qwen-Client-Id`) but does NOT emit a separate event — both clients eventually observe the SAME `auth_device_flow_authorized` once the user finishes the IdP page. If your UI distinguishes "I started this" from "someone else's flow I joined", branch on the `attached` field returned by `start()`. +## Daemon log file + +`qwen serve` writes a per-process diagnostic log to: + +``` +${QWEN_RUNTIME_DIR or ~/.qwen}/debug/daemon/serve--.log +``` + +A `latest` symlink in the same directory always points at the current process's log, so `tail -f ~/.qwen/debug/daemon/latest` will follow whichever daemon is running. + +The log captures lifecycle messages, route errors (with `route=` and `sessionId=` context), ACP child stderr, and — when `QWEN_SERVE_DEBUG=1` is set — extra bridge breadcrumbs. Lines that go to stderr today still go to stderr; the file log is **additive**, not a replacement. + +### Disabling + +Set `QWEN_DAEMON_LOG_FILE=0` (or `false`/`off`/`no`) to skip file logging entirely. Stderr output is unaffected. + +### Relation to session debug logs + +Session-scoped debug logs (`~/.qwen/debug/.txt` and the `~/.qwen/debug/latest` symlink) are independent. The daemon log lives in a sibling `daemon/` subdirectory; per-session debug semantics are unchanged by this feature. + +### No rotation + +The daemon log appends indefinitely. Rotate manually if it grows large. A future enhancement may add automatic rotation; track via [#4548](https://github.com/QwenLM/qwen-code/issues/4548) follow-ups. + ## What's next - **Setting up a long-running daemon?** [Local launch templates (systemd / launchd / nohup / tmux)](./qwen-serve-deploy-local.md) for v0.16-alpha (local-only). diff --git a/packages/acp-bridge/src/bridge.test.ts b/packages/acp-bridge/src/bridge.test.ts index 89f91be439e..0f0c93a7498 100644 --- a/packages/acp-bridge/src/bridge.test.ts +++ b/packages/acp-bridge/src/bridge.test.ts @@ -7161,3 +7161,162 @@ describe('createHttpAcpBridge — F3 multi-client permission coordination', () = ).toThrow(/positive integer/); }); }); + +// ============================================================ +// BridgeOptions.onDiagnosticLine — verify the tee callback +// receives writeServeDebugLine output when QWEN_SERVE_DEBUG=1. +// ============================================================ +describe('onDiagnosticLine', () => { + const originalDebug = process.env['QWEN_SERVE_DEBUG']; + afterEach(() => { + if (originalDebug === undefined) delete process.env['QWEN_SERVE_DEBUG']; + else process.env['QWEN_SERVE_DEBUG'] = originalDebug; + }); + + it('receives writeServeDebugLine output when QWEN_SERVE_DEBUG=1', async () => { + process.env['QWEN_SERVE_DEBUG'] = '1'; + const captured: Array<{ line: string; level?: string }> = []; + + // Thread scope → two distinct sessions sharing one channel. + let capturedConn: InstanceType | undefined; + const factory: ChannelFactory = async () => { + const { clientStream, agentStream } = createInMemoryChannel(); + const fakeAgent = new FakeAgent(); + const conn = new AgentSideConnection(() => fakeAgent, agentStream); + capturedConn = conn; + return { + stream: clientStream, + exited: new Promise< + | { exitCode: number | null; signalCode: NodeJS.Signals | null } + | undefined + >(() => {}), + kill: async () => {}, + killSync: () => {}, + }; + }; + + const bridge = makeBridge({ + sessionScope: 'thread', + channelFactory: factory, + onDiagnosticLine: (line, level) => captured.push({ line, level }), + }); + + const sessionA = await bridge.spawnOrAttach({ workspaceCwd: WS_A }); + const sessionB = await bridge.spawnOrAttach({ workspaceCwd: WS_A }); + expect(sessionA.sessionId).not.toBe(sessionB.sessionId); + + // Issue a permission request on session A via the agent side. + const subAbort = new AbortController(); + const iter = bridge.subscribeEvents(sessionA.sessionId, { + signal: subAbort.signal, + }); + + // Fire requestPermission from the agent side (same pattern as + // setupForPermission in the permission_request tests above). + void ( + capturedConn as unknown as { + requestPermission(p: unknown): Promise; + } + ).requestPermission({ + sessionId: sessionA.sessionId, + toolCall: { toolCallId: 'tc-diag', title: 'test-tool' }, + options: [ + { optionId: 'allow', name: 'Allow', kind: 'allow_once' }, + { optionId: 'deny', name: 'Deny', kind: 'reject_once' }, + ], + }); + + // Read the permission_request event to get the requestId. + const it2 = iter[Symbol.asyncIterator](); + const next = await it2.next(); + expect(next.done).toBe(false); + const payload = next.value!.data as { requestId: string }; + + // Vote using session B's sessionId → cross-session rejection path + // which triggers teeServeDebugLine (bridge.ts line ~2253). + const accepted = bridge.respondToSessionPermission( + sessionB.sessionId, + payload.requestId, + { outcome: { outcome: 'cancelled' } }, + ); + expect(accepted).toBe(false); + + // Verify the onDiagnosticLine callback received the debug line. + expect(captured.some((e) => e.line.includes('qwen serve debug: '))).toBe( + true, + ); + expect( + captured.some((e) => e.line.includes('rejected permission vote')), + ).toBe(true); + expect( + captured.every((e) => e.level === undefined || e.level === 'info'), + ).toBe(true); + + subAbort.abort(); + await bridge.shutdown(); + }); + + it('does not invoke callback when QWEN_SERVE_DEBUG is off', async () => { + delete process.env['QWEN_SERVE_DEBUG']; + const captured: Array<{ line: string; level?: string }> = []; + + let capturedConn: InstanceType | undefined; + const factory: ChannelFactory = async () => { + const { clientStream, agentStream } = createInMemoryChannel(); + const fakeAgent = new FakeAgent(); + const conn = new AgentSideConnection(() => fakeAgent, agentStream); + capturedConn = conn; + return { + stream: clientStream, + exited: new Promise< + | { exitCode: number | null; signalCode: NodeJS.Signals | null } + | undefined + >(() => {}), + kill: async () => {}, + killSync: () => {}, + }; + }; + + const bridge = makeBridge({ + sessionScope: 'thread', + channelFactory: factory, + onDiagnosticLine: (line, level) => captured.push({ line, level }), + }); + + const sessionA = await bridge.spawnOrAttach({ workspaceCwd: WS_A }); + const sessionB = await bridge.spawnOrAttach({ workspaceCwd: WS_A }); + + const subAbort = new AbortController(); + const iter = bridge.subscribeEvents(sessionA.sessionId, { + signal: subAbort.signal, + }); + + void ( + capturedConn as unknown as { + requestPermission(p: unknown): Promise; + } + ).requestPermission({ + sessionId: sessionA.sessionId, + toolCall: { toolCallId: 'tc-diag2', title: 'test-tool' }, + options: [ + { optionId: 'allow', name: 'Allow', kind: 'allow_once' }, + { optionId: 'deny', name: 'Deny', kind: 'reject_once' }, + ], + }); + + const it2 = iter[Symbol.asyncIterator](); + const next = await it2.next(); + const payload = next.value!.data as { requestId: string }; + + // Same cross-session vote — but QWEN_SERVE_DEBUG is off. + bridge.respondToSessionPermission(sessionB.sessionId, payload.requestId, { + outcome: { outcome: 'cancelled' }, + }); + + // Callback must NOT have been invoked. + expect(captured).toHaveLength(0); + + subAbort.abort(); + await bridge.shutdown(); + }); +}); diff --git a/packages/acp-bridge/src/bridge.ts b/packages/acp-bridge/src/bridge.ts index 7fb731e1f91..3324ed7a3b3 100644 --- a/packages/acp-bridge/src/bridge.ts +++ b/packages/acp-bridge/src/bridge.ts @@ -697,6 +697,17 @@ export function createHttpAcpBridge(opts: BridgeOptions): HttpAcpBridge { // (b) `server.close` rejecting new connections, during which a // late-arriving `POST /session` slips a fresh child past cleanup. let shuttingDown = false; + + // Tee writeServeDebugLine through the optional onDiagnosticLine callback. + // The module-level writeServeDebugLine is left intact for other entry points; + // inside createHttpAcpBridge we use this wrapper exclusively. + const teeServeDebugLine = (message: string): void => { + writeServeDebugLine(message); + if (opts.onDiagnosticLine && isServeDebugLoggingEnabled()) { + opts.onDiagnosticLine(`qwen serve debug: ${message}`, 'info'); + } + }; + // Coalesces concurrent `spawnOrAttach` calls under single-scope and // tracks in-progress thread-scope spawns for shutdown to await. // Single-scope uses the workspaceKey as the dedup key (at most one @@ -1426,7 +1437,7 @@ export function createHttpAcpBridge(opts: BridgeOptions): HttpAcpBridge { const published = entry.events.publish(envelope); if (published === undefined) { failureCount += 1; - writeServeDebugLine( + teeServeDebugLine( `broadcastWorkspaceEvent: publish on session ${entry.sessionId} no-op (bus closed)`, ); } else { @@ -1439,7 +1450,7 @@ export function createHttpAcpBridge(opts: BridgeOptions): HttpAcpBridge { `${JSON.stringify(entry.sessionId)} (type=${envelope.type}): ` + `${err instanceof Error ? err.message : String(err)}`; if (shuttingDown) { - writeServeDebugLine(detail); + teeServeDebugLine(detail); } else { writeStderrLine(`qwen serve: ${detail}`); } @@ -2263,7 +2274,7 @@ export function createHttpAcpBridge(opts: BridgeOptions): HttpAcpBridge { // `context.clientId` against this session's registry. const actualSessionId = permissionMediator.peekSessionFor(requestId); if (actualSessionId !== undefined && actualSessionId !== sessionId) { - writeServeDebugLine( + teeServeDebugLine( `rejected permission vote ${JSON.stringify(requestId)} ` + `for session ${JSON.stringify(sessionId)}; request belongs to ` + `session ${JSON.stringify(actualSessionId)}.`, @@ -2349,7 +2360,7 @@ export function createHttpAcpBridge(opts: BridgeOptions): HttpAcpBridge { // Mediator already emitted `permission_already_resolved`. return false; case 'unknown_request': - writeServeDebugLine( + teeServeDebugLine( `rejected permission vote ${JSON.stringify(requestId)} ` + `for session ${JSON.stringify(sessionId)}; mediator has no ` + `pending or resolved record.`, @@ -2645,7 +2656,7 @@ export function createHttpAcpBridge(opts: BridgeOptions): HttpAcpBridge { const published = entry.events.publish(event); if (published === undefined) { failureCount += 1; - writeServeDebugLine( + teeServeDebugLine( `publishWorkspaceEvent: publish on session ${entry.sessionId} no-op (bus closed)`, ); } else { @@ -2658,7 +2669,7 @@ export function createHttpAcpBridge(opts: BridgeOptions): HttpAcpBridge { `${JSON.stringify(entry.sessionId)} (type=${event.type}): ` + `${err instanceof Error ? err.message : String(err)}`; if (shuttingDown) { - writeServeDebugLine(detail); + teeServeDebugLine(detail); } else { writeStderrLine(`qwen serve: ${detail}`); } diff --git a/packages/acp-bridge/src/bridgeOptions.ts b/packages/acp-bridge/src/bridgeOptions.ts index be57caf06ec..f237594bf47 100644 --- a/packages/acp-bridge/src/bridgeOptions.ts +++ b/packages/acp-bridge/src/bridgeOptions.ts @@ -18,6 +18,18 @@ import type { PermissionAuditPublisher } from './permissionMediator.js'; import type { ServePreflightCell, ServeWorkspaceEnvStatus } from './status.js'; import type { BridgeFileSystem } from './bridgeFileSystem.js'; +/** + * Sink for serve-level diagnostic lines (set by the cli daemon logger). + * When provided, the bridge tees `writeServeDebugLine` output through + * this callback alongside the existing stderr write — used by + * runQwenServe to capture them in the daemon log file. The bridge + * does not own a file logger itself; this is a pure pass-through hook. + */ +export type DiagnosticLineSink = ( + line: string, + level?: 'info' | 'warn' | 'error', +) => void; + /** * Optional injection seam for daemon-host-specific status cells — * `process.env` snapshots and the daemon-side preflight checks @@ -320,4 +332,9 @@ export interface BridgeOptions { * timeouts even when the audit publisher is the no-op fallback. */ permissionAudit?: PermissionAuditPublisher; + /** + * Optional: tee `writeServeDebugLine` output. See {@link DiagnosticLineSink}. + * No-op when omitted. Set by cli `runQwenServe` from the daemon logger. + */ + onDiagnosticLine?: DiagnosticLineSink; } diff --git a/packages/acp-bridge/src/spawnChannel.test.ts b/packages/acp-bridge/src/spawnChannel.test.ts index 5bc774b19a8..0db5e98ecc2 100644 --- a/packages/acp-bridge/src/spawnChannel.test.ts +++ b/packages/acp-bridge/src/spawnChannel.test.ts @@ -30,8 +30,97 @@ * Each branch listed below is now regression-guarded by an assertion. */ -import { describe, expect, it } from 'vitest'; -import { scrubChildEnv } from './spawnChannel.js'; +import { describe, expect, it, vi } from 'vitest'; +import { createStderrForwarder, scrubChildEnv } from './spawnChannel.js'; + +describe('createStderrForwarder', () => { + it('calls onDiagnosticLine for each complete line', () => { + const captured: Array<{ line: string; level?: string }> = []; + const stderrSpy = vi.spyOn(process.stderr, 'write').mockReturnValue(true); + const forwarder = createStderrForwarder({ + prefix: '[test] ', + onDiagnosticLine: (l, lvl) => captured.push({ line: l, level: lvl }), + }); + forwarder.onData('hello\nworld\n'); + expect(captured).toEqual([ + { line: '[test] hello', level: 'warn' }, + { line: '[test] world', level: 'warn' }, + ]); + // Also writes to process.stderr + expect(stderrSpy).toHaveBeenCalledWith('[test] hello\n'); + expect(stderrSpy).toHaveBeenCalledWith('[test] world\n'); + stderrSpy.mockRestore(); + }); + + it('buffers partial lines until newline arrives', () => { + const captured: Array<{ line: string; level?: string }> = []; + const stderrSpy = vi.spyOn(process.stderr, 'write').mockReturnValue(true); + const forwarder = createStderrForwarder({ + prefix: '[p] ', + onDiagnosticLine: (l, lvl) => captured.push({ line: l, level: lvl }), + }); + forwarder.onData('partial'); + expect(captured).toHaveLength(0); // no newline yet + forwarder.onData(' more\n'); + expect(captured).toEqual([{ line: '[p] partial more', level: 'warn' }]); + stderrSpy.mockRestore(); + }); + + it('flushes buffered content on end', () => { + const captured: Array<{ line: string; level?: string }> = []; + const stderrSpy = vi.spyOn(process.stderr, 'write').mockReturnValue(true); + const forwarder = createStderrForwarder({ + prefix: '[p] ', + onDiagnosticLine: (l, lvl) => captured.push({ line: l, level: lvl }), + }); + forwarder.onData('partial'); + expect(captured).toHaveLength(0); + forwarder.onEnd(); + expect(captured).toEqual([{ line: '[p] partial', level: 'warn' }]); + stderrSpy.mockRestore(); + }); + + it('does not call onDiagnosticLine for empty lines', () => { + const captured: Array<{ line: string; level?: string }> = []; + const stderrSpy = vi.spyOn(process.stderr, 'write').mockReturnValue(true); + const forwarder = createStderrForwarder({ + prefix: '[p] ', + onDiagnosticLine: (l, lvl) => captured.push({ line: l, level: lvl }), + }); + forwarder.onData('\n\n'); + expect(captured).toHaveLength(0); + stderrSpy.mockRestore(); + }); + + it('force-flushes with [truncated] when buffer exceeds 64 KiB cap', () => { + const captured: Array<{ line: string; level?: string }> = []; + const stderrSpy = vi.spyOn(process.stderr, 'write').mockReturnValue(true); + const forwarder = createStderrForwarder({ + prefix: '[x] ', + onDiagnosticLine: (l, lvl) => captured.push({ line: l, level: lvl }), + }); + // Write 65 KiB without a newline — exceeds the 64 KiB cap + const bigChunk = 'A'.repeat(65 * 1024); + forwarder.onData(bigChunk); + // Should have force-flushed the first 64 KiB with [truncated] + expect(captured.length).toBeGreaterThanOrEqual(1); + expect(captured[0]!.line).toContain('[truncated]'); + expect(captured[0]!.level).toBe('warn'); + // The flushed line should have the prefix + expect(captured[0]!.line).toMatch(/^\[x\] /); + stderrSpy.mockRestore(); + }); + + it('works without onDiagnosticLine (still writes to stderr)', () => { + const stderrSpy = vi.spyOn(process.stderr, 'write').mockReturnValue(true); + const forwarder = createStderrForwarder({ + prefix: '[no-cb] ', + }); + forwarder.onData('line1\n'); + expect(stderrSpy).toHaveBeenCalledWith('[no-cb] line1\n'); + stderrSpy.mockRestore(); + }); +}); // Decoupled canary: we deliberately hand-roll the test set instead of // importing `SCRUBBED_CHILD_ENV_KEYS` from `spawnChannel.ts` so the diff --git a/packages/acp-bridge/src/spawnChannel.ts b/packages/acp-bridge/src/spawnChannel.ts index 73c9bc23bdd..0f2546e685a 100644 --- a/packages/acp-bridge/src/spawnChannel.ts +++ b/packages/acp-bridge/src/spawnChannel.ts @@ -10,135 +10,43 @@ import { ndJsonStream } from '@agentclientprotocol/sdk'; import type { AcpChannelExitInfo, ChannelFactory } from './channel.js'; import { MissingCliEntryError } from './status.js'; +// ────────────────────────────────────────────────────────────────────── +// Stderr forwarder — extracted from the inline handler so it's testable +// in isolation without spawning a real child process. +// ────────────────────────────────────────────────────────────────────── + +export interface StderrForwarderOptions { + prefix: string; + onDiagnosticLine?: (line: string, level?: 'info' | 'warn' | 'error') => void; +} + /** - * Default channel factory: spawn the current Node executable running this - * CLI's entry script in `--acp` mode. `process.argv[1]` resolves to the qwen - * entry script when launched via the `qwen` bin shim. + * Creates a stateful forwarder that buffers incoming chunks, splits on + * newlines, writes each complete line to `process.stderr` with a prefix, + * and optionally invokes `onDiagnosticLine` for external consumers (e.g. + * the daemon log file writer). * - * Note on `cwd`: CodeQL flags the `workspaceCwd` flow into `spawn({cwd})` - * as an "uncontrolled data used in path expression" finding. That's the - * Stage 1 trust model speaking — the caller (a token-authenticated HTTP - * client) is treated as an extension of the operator. The agent already - * runs as the same UID with shell-tool access, so restricting the spawn - * cwd to a sandbox here would be theatre. Stage 4+ remote-sandbox swaps - * this factory for a sandbox-aware variant; see issue #3803 §11. - * - * Lifted from `cli/src/serve/httpAcpBridge.ts` to `@qwen-code/acp-bridge` - * in #4175 PR F1 so `channels/base/AcpBridge.ts` and the VSCode IDE - * companion can share one spawn implementation instead of each - * reimplementing the child lifecycle (the current divergence noted in - * `channel.ts`'s top-of-file comment). + * Cap behavior: if the unterminated buffer exceeds 64 KiB the excess is + * force-flushed with a `[truncated]` marker — same memory-bounding + * behavior as before the extraction. */ -export const defaultSpawnChannelFactory: ChannelFactory = async ( - workspaceCwd, - childEnvOverrides, -) => { - // Resolution order: - // 1. `QWEN_CLI_ENTRY` env override — escape hatch for non-standard - // launch paths (bundled binaries, npx wrappers, `node -e`, - // `tsx ./src/...`, custom shims, container images that - // relocate the entry script). Anyone hitting "process.argv[1] - // is empty" or "process.argv[1] points at the wrong file" can - // set this without code changes. - // 2. `process.argv[1]` — works when launched via the `qwen` bin - // shim, which is the common path. - // Fail loudly with an actionable error if neither resolves. - const cliEntry = process.env['QWEN_CLI_ENTRY'] || process.argv[1]; - if (!cliEntry) { - throw new MissingCliEntryError(); - } - // Each session takes ~3 file descriptors (stdin/stdout/stderr) for the - // child plus a few sockets. Operators running many concurrent sessions - // should bump `ulimit -n` accordingly. Stage 1 doesn't pre-flight FD - // headroom — Stage 2 in-process drops the per-session FD cost entirely. - // Child stderr is piped (NOT `inherit`ed) so we can prefix each - // line with `[serve pid=… cwd=…]` before forwarding to the - // daemon's stderr — see the prefix-and-forward loop below the - // `spawn(...)` call. Sessions are still interleaved on the - // daemon's stderr stream but each line carries its own session - // identifier, so operators can `grep pid=12345` to pull one - // session's trace cleanly. Stage 4+ remote sandboxes will isolate - // stderr at the transport level. - // - // Note: spawning `process.execPath` only works when the entry script can - // be loaded by raw Node. In dev (e.g. `npm run dev` via `tsx`) the entry - // is a `.ts` file Node can't run; users should `npm run build` before - // `qwen serve` or set `process.execPath` to a tsx-aware shim. Stage 1 - // accepts this — the daemon is meant for built deployments. - // Pass through the daemon's full environment to the child, scrubbing - // ONLY daemon-internal secrets (see SCRUBBED_CHILD_ENV_KEYS at module - // scope). An earlier version used an allowlist, but that broke the - // common deployment shape: users export `OPENAI_API_KEY` / - // `ANTHROPIC_API_KEY` / `QWEN_*` / `DASHSCOPE_API_KEY` / a custom - // `modelProviders[].envKey` to authenticate the agent's LLM calls, - // and core's model config resolves those from `process.env`. An - // exhaustive allowlist can't enumerate user-defined provider keys, - // so the agent ends up unable to authenticate. - // - // Threat-model rationale: the agent already runs as the same UID - // with shell-tool access — anything in `~/.bashrc`, `~/.npmrc`, - // `~/.aws/credentials`, etc. is reachable by prompt injection - // regardless of what we put in `env`. The env passthrough is not - // the security boundary; the user-as-trust-root is. The only thing - // we MUST scrub is `QWEN_SERVER_TOKEN` (daemon-only auth that - // would let a prompt-injected shell turn the agent into an - // authenticated client of its own daemon — escalation the agent - // doesn't otherwise have). - const childEnv = scrubChildEnv( - process.env, - SCRUBBED_CHILD_ENV_KEYS, - childEnvOverrides, - ); - // CodeQL `js/path-injection` flags the `cwd: workspaceCwd` flow. - // Stage 1 trust model accepts this — see the function-level comment - // above for the design rationale. Defense-in-depth: the cwd is - // canonicalized via `path.resolve()` upstream in `spawnOrAttach`, - // and `spawn`'s `cwd` only changes the child's working directory, - // it doesn't pass through any shell. - // - // NOTE: GitHub Code Scanning does NOT honor inline `// lgtm` / - // `// codeql` annotations (LGTM.com retired in 2021). Suppressing - // this alert requires either (a) UI dismissal as "won't fix" with - // the rationale above, or (b) a repo-level - // `.github/codeql/codeql-config.yml` query exclusion. Both are - // out of scope for a code-only PR; flagging here for the human - // reviewer. - const child = spawn(process.execPath, [cliEntry, '--acp'], { - cwd: workspaceCwd, - // Pipe stderr (was: 'inherit') so we can prefix each line with - // the spawn's pid + workspace, making per-session crash output - // attributable. Bare 'inherit' sends every child's stderr to - // the daemon's stderr verbatim and unprefixed — under any - // multi-session load the operator's log becomes a salad of - // unattributed traces. - stdio: ['pipe', 'pipe', 'pipe'], - env: childEnv, - }); +export function createStderrForwarder(opts: StderrForwarderOptions): { + onData: (chunk: string) => void; + onEnd: () => void; +} { + const { prefix, onDiagnosticLine } = opts; + const STDERR_LINE_CAP_CHARS = 64 * 1024; + let buf = ''; - // Forward child stderr to the daemon's stderr line-by-line, with a - // `[serve pid=… cwd=…]` prefix on each line so operators can - // correlate stack traces back to the spawning request. Best-effort: - // a child that prints partial lines without a trailing newline is - // flushed when the stream emits `end`. - if (child.stderr) { - let buf = ''; - const prefix = `[serve pid=${child.pid} cwd=${workspaceCwd}] `; - // BRAp3 cap: a buggy child that writes a huge stderr line, or - // never emits `\n`, would otherwise grow `buf` per spawn - // unboundedly. 64 KiB is generous for the longest legitimate - // stack trace line we'd expect from a Node child; anything - // past that gets force-flushed with a `[truncated]` marker so - // the operator still sees a prefix-attributed log line and - // memory stays bounded. We DON'T drop content — we flush - // chunks at the cap. (Picking 64 KiB matches our SSE per-frame - // write budget; anything above this already implies the child - // is misbehaving.) - const STDERR_LINE_CAP_CHARS = 64 * 1024; - const flush = (line: string) => { - if (line.length > 0) process.stderr.write(prefix + line + '\n'); - }; - child.stderr.setEncoding('utf8'); - child.stderr.on('data', (chunk: string) => { + const flush = (line: string) => { + if (line.length > 0) { + process.stderr.write(prefix + line + '\n'); + if (onDiagnosticLine) onDiagnosticLine(prefix + line, 'warn'); + } + }; + + return { + onData(chunk: string) { buf += chunk; let nl = buf.indexOf('\n'); while (nl !== -1) { @@ -149,66 +57,138 @@ export const defaultSpawnChannelFactory: ChannelFactory = async ( // Force-flush the unterminated tail if it's grown past the cap // — keeps memory bounded against a `\n`-less stderr storm. while (buf.length > STDERR_LINE_CAP_CHARS) { - flush(buf.slice(0, STDERR_LINE_CAP_CHARS) + ' [truncated]'); + const truncated = buf.slice(0, STDERR_LINE_CAP_CHARS) + ' [truncated]'; + process.stderr.write(prefix + truncated + '\n'); + if (onDiagnosticLine) onDiagnosticLine(prefix + truncated, 'warn'); buf = buf.slice(STDERR_LINE_CAP_CHARS); } - }); - child.stderr.on('end', () => { + }, + onEnd() { if (buf.length > 0) flush(buf); - }); - child.stderr.on('error', () => { - // Don't crash the daemon if the pipe breaks; the child is - // already gone or about to be. - }); - } + }, + }; +} - // Build the `exited` promise BEFORE checking stdin/stdout so the listener - // is in place before any error event can fire. We treat both `exit` and - // `error` as termination — without an `error` listener Node would treat - // an async spawn failure (ENOMEM, EACCES, …) as an unhandled error and - // crash the whole daemon. - const exited = new Promise((resolve) => { - let resolved = false; - const finish = (info?: AcpChannelExitInfo) => { - if (resolved) return; - resolved = true; - resolve(info); - }; - child.once('exit', (code, signal) => - finish({ exitCode: code, signalCode: signal }), - ); - child.once('error', () => finish(undefined)); - }); +// ────────────────────────────────────────────────────────────────────── +// SpawnChannelFactory — configurable factory-of-factories +// ────────────────────────────────────────────────────────────────────── + +export interface SpawnChannelFactoryOptions { + onDiagnosticLine?: (line: string, level?: 'info' | 'warn' | 'error') => void; +} - if (!child.stdin || !child.stdout) { - child.kill('SIGKILL'); - throw new Error( - 'Spawned ACP child has no stdin/stdout — cannot establish NDJSON channel.', +/** + * Creates a `ChannelFactory` that spawns `qwen --acp` child processes. + * Accepts an optional `onDiagnosticLine` callback that receives every + * child-stderr line (already prefixed) so callers can tee to a log file + * or structured logger without intercepting process.stderr globally. + * + * `defaultSpawnChannelFactory` below is `createSpawnChannelFactory()` — + * no options, same behavior as before this refactor. + */ +export function createSpawnChannelFactory( + options: SpawnChannelFactoryOptions = {}, +): ChannelFactory { + return async (workspaceCwd, childEnvOverrides) => { + const cliEntry = process.env['QWEN_CLI_ENTRY'] || process.argv[1]; + if (!cliEntry) { + throw new MissingCliEntryError(); + } + const childEnv = scrubChildEnv( + process.env, + SCRUBBED_CHILD_ENV_KEYS, + childEnvOverrides, ); - } + const child = spawn(process.execPath, [cliEntry, '--acp'], { + cwd: workspaceCwd, + stdio: ['pipe', 'pipe', 'pipe'], + env: childEnv, + }); - const writable = Writable.toWeb(child.stdin) as WritableStream; - const readable = Readable.toWeb(child.stdout) as ReadableStream; - const stream = ndJsonStream(writable, readable); + // Forward child stderr to the daemon's stderr line-by-line, with a + // `[serve pid=… cwd=…]` prefix on each line so operators can + // correlate stack traces back to the spawning request. + if (child.stderr) { + const prefix = `[serve pid=${child.pid} cwd=${workspaceCwd}] `; + const forwarder = createStderrForwarder({ + prefix, + onDiagnosticLine: options.onDiagnosticLine, + }); + child.stderr.setEncoding('utf8'); + child.stderr.on('data', (chunk: string) => forwarder.onData(chunk)); + child.stderr.on('end', () => forwarder.onEnd()); + child.stderr.on('error', () => { + // Don't crash the daemon if the pipe breaks; the child is + // already gone or about to be. + }); + } - return { - stream, - kill: () => killChild(child), - killSync: () => { - // Bd1y6: synchronous SIGKILL for the double-signal force-exit - // path. Skip if child already exited (kill on a dead process - // raises an OS-level error that's noise here). - if (child.exitCode === null && child.signalCode === null) { - try { - child.kill('SIGKILL'); - } catch { - /* already dead / pid recycled — ignore */ + const exited = new Promise((resolve) => { + let resolved = false; + const finish = (info?: AcpChannelExitInfo) => { + if (resolved) return; + resolved = true; + resolve(info); + }; + child.once('exit', (code, signal) => + finish({ exitCode: code, signalCode: signal }), + ); + child.once('error', () => finish(undefined)); + }); + + if (!child.stdin || !child.stdout) { + child.kill('SIGKILL'); + throw new Error( + 'Spawned ACP child has no stdin/stdout — cannot establish NDJSON channel.', + ); + } + + const writable = Writable.toWeb(child.stdin) as WritableStream; + const readable = Readable.toWeb(child.stdout) as ReadableStream; + const stream = ndJsonStream(writable, readable); + + return { + stream, + kill: () => killChild(child), + killSync: () => { + if (child.exitCode === null && child.signalCode === null) { + try { + child.kill('SIGKILL'); + } catch { + /* already dead / pid recycled — ignore */ + } } - } - }, - exited, + }, + exited, + }; }; -}; +} + +/** + * Default channel factory: spawn the current Node executable running this + * CLI's entry script in `--acp` mode. `process.argv[1]` resolves to the qwen + * entry script when launched via the `qwen` bin shim. + * + * Note on `cwd`: CodeQL flags the `workspaceCwd` flow into `spawn({cwd})` + * as an "uncontrolled data used in path expression" finding. That's the + * Stage 1 trust model speaking — the caller (a token-authenticated HTTP + * client) is treated as an extension of the operator. The agent already + * runs as the same UID with shell-tool access, so restricting the spawn + * cwd to a sandbox here would be theatre. Stage 4+ remote-sandbox swaps + * this factory for a sandbox-aware variant; see issue #3803 §11. + * + * Lifted from `cli/src/serve/httpAcpBridge.ts` to `@qwen-code/acp-bridge` + * in #4175 PR F1 so `channels/base/AcpBridge.ts` and the VSCode IDE + * companion can share one spawn implementation instead of each + * reimplementing the child lifecycle (the current divergence noted in + * `channel.ts`'s top-of-file comment). + * + * Preserved as `createSpawnChannelFactory()` (no options) for backward + * compat. Use `createSpawnChannelFactory({ onDiagnosticLine })` to also + * tee child stderr lines through an external callback. + */ +export const defaultSpawnChannelFactory: ChannelFactory = + createSpawnChannelFactory(); const KILL_HARD_DEADLINE_MS = 10_000; diff --git a/packages/cli/src/serve/daemonLogger.test.ts b/packages/cli/src/serve/daemonLogger.test.ts new file mode 100644 index 00000000000..468c3d02c78 --- /dev/null +++ b/packages/cli/src/serve/daemonLogger.test.ts @@ -0,0 +1,337 @@ +/** + * @license + * Copyright 2025 Qwen Team + * SPDX-License-Identifier: Apache-2.0 + */ + +import * as os from 'node:os'; +import * as path from 'node:path'; +import { + mkdtempSync, + readFileSync, + existsSync, + writeFileSync, + rmSync, + realpathSync, + lstatSync, +} from 'node:fs'; +import { describe, it, expect, afterEach, beforeEach } from 'vitest'; +import { buildDaemonLogLine, initDaemonLogger } from './daemonLogger.js'; + +describe('buildDaemonLogLine', () => { + const FIXED = new Date('2026-05-26T03:14:15.926Z'); + + it('formats INFO with no ctx', () => { + expect( + buildDaemonLogLine({ + level: 'INFO', + message: 'daemon started', + now: FIXED, + }), + ).toBe('2026-05-26T03:14:15.926Z [INFO] [DAEMON] daemon started\n'); + }); + + it('renders ctx fields in fixed order', () => { + const line = buildDaemonLogLine({ + level: 'ERROR', + message: 'route failed', + now: FIXED, + ctx: { + sessionId: 'sess-1', + route: 'POST /session/:id/prompt', + clientId: 'client-x', + childPid: 4242, + channelId: 'ch-9', + }, + }); + expect(line).toBe( + '2026-05-26T03:14:15.926Z [ERROR] [DAEMON] ' + + 'route=POST /session/:id/prompt sessionId=sess-1 clientId=client-x ' + + 'childPid=4242 channelId=ch-9 route failed\n', + ); + }); + + it('appends extra ctx keys sorted lexicographically after fixed keys', () => { + const line = buildDaemonLogLine({ + level: 'WARN', + message: 'note', + now: FIXED, + ctx: { zeta: 1, alpha: 'a', sessionId: 's' }, + }); + expect(line).toBe( + '2026-05-26T03:14:15.926Z [WARN] [DAEMON] sessionId=s alpha=a zeta=1 note\n', + ); + }); + + it('JSON.stringify-quotes values that contain spaces or =', () => { + const line = buildDaemonLogLine({ + level: 'INFO', + message: 'hi', + now: FIXED, + ctx: { weird: 'has space', eq: 'a=b' }, + }); + expect(line).toBe( + '2026-05-26T03:14:15.926Z [INFO] [DAEMON] eq="a=b" weird="has space" hi\n', + ); + }); + + it('appends error stack as indented continuation lines', () => { + const err = new Error('boom'); + err.stack = + 'Error: boom\n at fn (file.ts:1:1)\n at main (file.ts:2:2)'; + const line = buildDaemonLogLine({ + level: 'ERROR', + message: 'failed', + now: FIXED, + err, + }); + expect(line).toBe( + '2026-05-26T03:14:15.926Z [ERROR] [DAEMON] failed\n' + + ' Error: boom\n' + + ' at fn (file.ts:1:1)\n' + + ' at main (file.ts:2:2)\n', + ); + }); + + it('falls back to err.message when stack missing', () => { + const err: Error = { name: 'Plain', message: 'no stack' } as Error; + const line = buildDaemonLogLine({ + level: 'ERROR', + message: 'failed', + now: FIXED, + err, + }); + expect(line).toBe( + '2026-05-26T03:14:15.926Z [ERROR] [DAEMON] failed\n' + + ' Plain: no stack\n', + ); + }); +}); + +describe('initDaemonLogger opt-out', () => { + const originalEnv = process.env['QWEN_DAEMON_LOG_FILE']; + afterEach(() => { + if (originalEnv === undefined) delete process.env['QWEN_DAEMON_LOG_FILE']; + else process.env['QWEN_DAEMON_LOG_FILE'] = originalEnv; + }); + + for (const val of ['0', 'false', 'off', 'no', 'False', ' OFF ']) { + it(`returns no-op logger when QWEN_DAEMON_LOG_FILE=${JSON.stringify(val)}`, () => { + process.env['QWEN_DAEMON_LOG_FILE'] = val; + const stderr: string[] = []; + const logger = initDaemonLogger({ + boundWorkspace: '/tmp/ws', + baseDir: '/tmp/nonexistent-should-not-touch', + stderr: (s) => stderr.push(s), + }); + logger.info('hello'); + logger.warn('there'); + logger.error('boom'); + logger.raw('raw'); + expect(stderr).toEqual([]); // no-op = nothing + expect(logger.getLogPath()).toBe(''); + expect(logger.getDaemonId()).toBe(''); + }); + } +}); + +describe('initDaemonLogger file init', () => { + let tmp: string; + beforeEach(() => { + tmp = mkdtempSync(path.join(os.tmpdir(), 'daemon-log-')); + }); + afterEach(() => { + try { + rmSync(tmp, { recursive: true, force: true }); + } catch { + // cleanup best-effort + } + }); + + it('derives daemon-id "serve--" and creates log file', () => { + const logger = initDaemonLogger({ + boundWorkspace: '/workspace/foo', + pid: 1234, + baseDir: tmp, + }); + expect(logger.getDaemonId()).toMatch(/^serve-1234-[0-9a-f]{8}$/); + expect(logger.getLogPath()).toBe( + path.join(tmp, 'daemon', `${logger.getDaemonId()}.log`), + ); + expect(existsSync(logger.getLogPath())).toBe(true); + expect(readFileSync(logger.getLogPath(), 'utf8')).toMatch( + /\[INFO\] \[DAEMON\] daemon started pid=1234 workspace=\/workspace\/foo/, + ); + }); + + it('falls back to no-op when mkdir fails', () => { + const stderr: string[] = []; + // Create a file where the directory should be -> mkdir EEXIST/ENOTDIR + const blockingFile = path.join(tmp, 'daemon'); + writeFileSync(blockingFile, 'blocker'); + + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + stderr: (s) => stderr.push(s), + }); + expect(logger.getLogPath()).toBe(''); + expect(stderr.join('\n')).toMatch(/daemon log disabled/); + expect(() => logger.info('after')).not.toThrow(); + }); +}); + +describe('initDaemonLogger raw', () => { + let tmp: string; + beforeEach(() => { + tmp = mkdtempSync(path.join(os.tmpdir(), 'daemon-log-')); + }); + afterEach(() => { + try { + rmSync(tmp, { recursive: true, force: true }); + } catch { + // cleanup best-effort + } + }); + + it('appends prefixed line, no stderr tee', async () => { + const stderr: string[] = []; + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + stderr: (s) => stderr.push(s), + }); + const stderrBefore = stderr.length; + logger.raw('[serve pid=123 cwd=/x] child crashed', 'warn'); + logger.raw('[serve pid=123 cwd=/x] another'); + await logger.flush(); + const content = readFileSync(logger.getLogPath(), 'utf8'); + expect(content).toContain( + '[WARN] [DAEMON] [serve pid=123 cwd=/x] child crashed\n', + ); + expect(content).toContain( + '[INFO] [DAEMON] [serve pid=123 cwd=/x] another\n', + ); + // No new stderr lines from raw() + expect(stderr.length).toBe(stderrBefore); + }); +}); + +describe('initDaemonLogger info/warn/error', () => { + let tmp: string; + beforeEach(() => { + tmp = mkdtempSync(path.join(os.tmpdir(), 'daemon-log-')); + }); + afterEach(() => { + try { + rmSync(tmp, { recursive: true, force: true }); + } catch { + // cleanup best-effort + } + }); + + it('info appends to file and tees to stderr', async () => { + const stderr: string[] = []; + const fixed = new Date('2026-05-26T03:14:15.926Z'); + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + stderr: (s) => stderr.push(s), + now: () => fixed, + }); + logger.info('hello', { route: 'GET /' }); + await logger.flush(); + const content = readFileSync(logger.getLogPath(), 'utf8'); + expect(content).toContain('[INFO] [DAEMON] route=GET / hello\n'); + // Stderr saw the same line (after boot banner, which isn't teed here). + const teedLines = stderr.filter((s) => s.includes('[INFO] [DAEMON]')); + expect(teedLines).toHaveLength(1); + }); + + it('error appends err.stack as continuation', async () => { + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + }); + const err = new Error('boom'); + logger.error('route failed', err, { route: 'POST /x' }); + await logger.flush(); + const content = readFileSync(logger.getLogPath(), 'utf8'); + expect(content).toMatch( + /\[ERROR\] \[DAEMON\] route=POST \/x route failed\n {2}Error: boom/, + ); + }); + + it('flush awaits all pending appends', async () => { + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + }); + for (let i = 0; i < 50; i++) logger.info(`msg-${i}`); + await logger.flush(); + const lines = readFileSync(logger.getLogPath(), 'utf8').split('\n'); + const msgLines = lines.filter((l) => /msg-\d+$/.test(l)); + expect(msgLines).toHaveLength(50); + for (let i = 0; i < 50; i++) { + expect(msgLines[i]).toContain(`msg-${i}`); + } + }); + + it('warns once on append failure and keeps trying', async () => { + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + stderr: () => {}, + }); + // Sabotage by removing the parent directory so subsequent appendFile fails with ENOENT. + rmSync(path.dirname(logger.getLogPath()), { recursive: true, force: true }); + logger.info('after-rm-1'); + logger.info('after-rm-2'); + await logger.flush(); + // No throw — degraded path swallows. + }); +}); + +describe('initDaemonLogger latest symlink', () => { + let tmp: string; + beforeEach(() => { + tmp = mkdtempSync(path.join(os.tmpdir(), 'daemon-log-')); + }); + afterEach(() => { + try { + rmSync(tmp, { recursive: true, force: true }); + } catch { + // cleanup best-effort + } + }); + + it('creates daemon/latest pointing to the current log', async () => { + const logger = initDaemonLogger({ + boundWorkspace: '/w', + pid: 42, + baseDir: tmp, + }); + // Allow the async symlink to settle. + await new Promise((r) => setTimeout(r, 50)); + const linkPath = path.join(tmp, 'daemon', 'latest'); + expect(lstatSync(linkPath).isSymbolicLink()).toBe(true); + expect(realpathSync(linkPath)).toBe(realpathSync(logger.getLogPath())); + }); + + it('updates latest on subsequent init in same dir', async () => { + const a = initDaemonLogger({ boundWorkspace: '/w', pid: 1, baseDir: tmp }); + await new Promise((r) => setTimeout(r, 50)); + const b = initDaemonLogger({ boundWorkspace: '/w', pid: 2, baseDir: tmp }); + await new Promise((r) => setTimeout(r, 50)); + expect(realpathSync(path.join(tmp, 'daemon', 'latest'))).toBe( + realpathSync(b.getLogPath()), + ); + expect(realpathSync(a.getLogPath())).not.toBe(realpathSync(b.getLogPath())); + }); +}); diff --git a/packages/cli/src/serve/daemonLogger.ts b/packages/cli/src/serve/daemonLogger.ts new file mode 100644 index 00000000000..274386e1e5f --- /dev/null +++ b/packages/cli/src/serve/daemonLogger.ts @@ -0,0 +1,211 @@ +/** + * @license + * Copyright 2025 Qwen Team + * SPDX-License-Identifier: Apache-2.0 + */ + +import * as nodeFs from 'node:fs'; +import * as nodePath from 'node:path'; +import * as crypto from 'node:crypto'; +import { writeStderrLine } from '../utils/stdioHelpers.js'; +import { Storage, updateSymlink } from '@qwen-code/qwen-code-core'; + +export type DaemonLogLevel = 'INFO' | 'WARN' | 'ERROR'; + +export interface DaemonLogContext { + route?: string; + sessionId?: string; + clientId?: string; + childPid?: number; + channelId?: string; + [key: string]: unknown; +} + +const FIXED_CTX_ORDER = [ + 'route', + 'sessionId', + 'clientId', + 'childPid', + 'channelId', +] as const; + +const FIXED_CTX_SET: ReadonlySet = new Set(FIXED_CTX_ORDER); + +function renderCtxValue(value: unknown): string { + const s = String(value); + return /[\s=]/.test(s) ? JSON.stringify(s) : s; +} + +function renderCtx(ctx: DaemonLogContext | undefined): string { + if (!ctx) return ''; + const parts: string[] = []; + for (const key of FIXED_CTX_ORDER) { + const v = ctx[key]; + if (v !== undefined && v !== null) { + parts.push(`${key}=${String(v)}`); + } + } + const extraKeys = Object.keys(ctx) + .filter( + (k) => !FIXED_CTX_SET.has(k) && ctx[k] !== undefined && ctx[k] !== null, + ) + .sort(); + for (const key of extraKeys) { + parts.push(`${key}=${renderCtxValue(ctx[key])}`); + } + return parts.length > 0 ? parts.join(' ') + ' ' : ''; +} + +function renderErr(err: Error | undefined): string { + if (!err) return ''; + const body = err.stack ?? `${err.name ?? 'Error'}: ${err.message}`; + return ( + body + .split('\n') + .map((l) => ` ${l}`) + .join('\n') + '\n' + ); +} + +export interface BuildDaemonLogLineArgs { + level: DaemonLogLevel; + message: string; + now: Date; + ctx?: DaemonLogContext; + err?: Error; +} + +export function buildDaemonLogLine(args: BuildDaemonLogLineArgs): string { + const ts = args.now.toISOString(); + const ctxStr = renderCtx(args.ctx); + return `${ts} [${args.level}] [DAEMON] ${ctxStr}${args.message}\n${renderErr(args.err)}`; +} + +export interface DaemonLogger { + info(message: string, ctx?: DaemonLogContext): void; + warn(message: string, ctx?: DaemonLogContext): void; + error(message: string, err?: Error | null, ctx?: DaemonLogContext): void; + raw(line: string, level?: 'info' | 'warn' | 'error'): void; + getLogPath(): string; + getDaemonId(): string; + flush(): Promise; +} + +export interface InitDaemonLoggerOptions { + boundWorkspace: string; + pid?: number; + now?: () => Date; + stderr?: (line: string) => void; + baseDir?: string; +} + +const NOOP_LOGGER: DaemonLogger = { + info: () => {}, + warn: () => {}, + error: () => {}, + raw: () => {}, + getLogPath: () => '', + getDaemonId: () => '', + flush: () => Promise.resolve(), +}; + +function isOptedOut(): boolean { + const raw = process.env['QWEN_DAEMON_LOG_FILE']; + if (!raw) return false; + return ['0', 'false', 'off', 'no'].includes(raw.trim().toLowerCase()); +} + +function computeDaemonId(pid: number, boundWorkspace: string): string { + const hash = crypto + .createHash('sha256') + .update(boundWorkspace) + .digest('hex') + .slice(0, 8); + return `serve-${pid}-${hash}`; +} + +export function initDaemonLogger(opts: InitDaemonLoggerOptions): DaemonLogger { + if (isOptedOut()) return NOOP_LOGGER; + + const pid = opts.pid ?? process.pid; + const now = opts.now ?? (() => new Date()); + const stderr = opts.stderr ?? writeStderrLine; + const baseDir = opts.baseDir ?? Storage.getGlobalDebugDir(); + + const daemonId = computeDaemonId(pid, opts.boundWorkspace); + const daemonDir = nodePath.join(baseDir, 'daemon'); + const logPath = nodePath.join(daemonDir, `${daemonId}.log`); + + try { + nodeFs.mkdirSync(daemonDir, { recursive: true }); + const firstLine = buildDaemonLogLine({ + level: 'INFO', + message: `daemon started pid=${pid} workspace=${opts.boundWorkspace}`, + now: now(), + }); + nodeFs.appendFileSync(logPath, firstLine); + } catch (err) { + stderr( + `qwen serve: daemon log disabled — init failed: ${ + err instanceof Error ? err.message : String(err) + }`, + ); + return NOOP_LOGGER; + } + + try { + const aliasPath = nodePath.join(daemonDir, 'latest'); + void updateSymlink(aliasPath, logPath, { fallbackCopy: false }).catch( + () => { + // Best-effort. Symlink failure must not degrade primary writes. + }, + ); + } catch { + // Defensive: any sync throw is ignored. + } + + let pending: Promise = Promise.resolve(); + let degraded = false; + + const enqueueAppend = (line: string): void => { + pending = pending.then(() => + nodeFs.promises.appendFile(logPath, line).catch((err) => { + if (!degraded) { + degraded = true; + stderr( + `qwen serve: daemon log write failed — entering degraded mode: ${ + err instanceof Error ? err.message : String(err) + }`, + ); + } + }), + ); + }; + + const teeLine = ( + level: DaemonLogLevel, + message: string, + ctx?: DaemonLogContext, + err?: Error, + ): void => { + const line = buildDaemonLogLine({ level, message, now: now(), ctx, err }); + // stderr first (synchronous, preserves human-visible order), then file. + stderr(line.trimEnd()); + enqueueAppend(line); + }; + + return { + info: (message, ctx) => teeLine('INFO', message, ctx), + warn: (message, ctx) => teeLine('WARN', message, ctx), + error: (message, err, ctx) => + teeLine('ERROR', message, ctx, err ?? undefined), + raw: (line: string, level: 'info' | 'warn' | 'error' = 'info') => { + const upper = level.toUpperCase() as DaemonLogLevel; + const formatted = `${now().toISOString()} [${upper}] [DAEMON] ${line}\n`; + enqueueAppend(formatted); + }, + getLogPath: () => logPath, + getDaemonId: () => daemonId, + flush: () => pending, + }; +} diff --git a/packages/cli/src/serve/runQwenServe.test.ts b/packages/cli/src/serve/runQwenServe.test.ts index 7cdaa4dd1d4..aa4f1925bb3 100644 --- a/packages/cli/src/serve/runQwenServe.test.ts +++ b/packages/cli/src/serve/runQwenServe.test.ts @@ -4,12 +4,17 @@ * SPDX-License-Identifier: Apache-2.0 */ -import { describe, it, expect, vi } from 'vitest'; +import * as os from 'node:os'; +import * as path from 'node:path'; +import * as fs from 'node:fs'; +import { describe, it, expect, vi, afterEach } from 'vitest'; import { extractContextFilename, InvalidPolicyConfigError, + runQwenServe, validatePolicyConfig, } from './runQwenServe.js'; +import type { HttpAcpBridge } from './httpAcpBridge.js'; /** * #4297 fold-in 7 (deepseek S1, addresses #3262690842). Lock the @@ -173,3 +178,87 @@ describe('validatePolicyConfig (#4335 boot validation)', () => { ); }); }); + +/** + * Integration test: verify daemon logger is initialized and written to + * during `runQwenServe` boot + shutdown. Uses a fake bridge to avoid + * spawning real `qwen --acp` child processes. + */ +describe('runQwenServe daemon logger wiring', () => { + let tmpDir: string; + + afterEach(() => { + if (tmpDir) { + fs.rmSync(tmpDir, { recursive: true, force: true }); + } + }); + + it('creates a daemon log file at boot and flushes on shutdown', async () => { + tmpDir = fs.realpathSync(fs.mkdtempSync(path.join(os.tmpdir(), 'qws-dl-'))); + const workspace = tmpDir; + const debugDir = path.join(tmpDir, 'debug'); + + // Minimal fake bridge satisfying the shape runQwenServe expects. + const fakeBridge: HttpAcpBridge = { + spawnOrAttach: vi.fn(), + shutdown: vi.fn().mockResolvedValue(undefined), + killAllSync: vi.fn(), + getSession: vi.fn(), + getAllSessions: vi.fn().mockReturnValue([]), + publishWorkspaceEvent: vi.fn(), + getEventRing: vi.fn().mockReturnValue({ getAll: () => [] }), + resume: vi.fn(), + } as unknown as HttpAcpBridge; + + // Point daemon logger at our temp debug dir + const origEnv = process.env['QWEN_RUNTIME_DIR']; + process.env['QWEN_RUNTIME_DIR'] = tmpDir; + + try { + const handle = await runQwenServe( + { + port: 0, + hostname: '127.0.0.1', + mode: 'http-bridge', + workspace, + maxSessions: 1, + }, + { bridge: fakeBridge }, + ); + + // Daemon log directory should exist + const daemonDir = path.join(debugDir, 'daemon'); + expect(fs.existsSync(daemonDir)).toBe(true); + + // Find the log file (pattern: serve--.log) + const logFiles = fs + .readdirSync(daemonDir) + .filter((f) => f.endsWith('.log')); + expect(logFiles.length).toBeGreaterThanOrEqual(1); + + const logContent = fs.readFileSync( + path.join(daemonDir, logFiles[0]!), + 'utf8', + ); + // Should contain the "daemon started" boot line + expect(logContent).toContain('daemon started'); + expect(logContent).toContain(`pid=${process.pid}`); + expect(logContent).toContain(`workspace=${workspace}`); + + // Close the handle (graceful shutdown) + await handle.close(); + + // The log should still be readable after shutdown + const finalContent = fs.readFileSync( + path.join(daemonDir, logFiles[0]!), + 'utf8', + ); + expect(finalContent).toContain('daemon started'); + } finally { + delete process.env['QWEN_RUNTIME_DIR']; + if (origEnv !== undefined) { + process.env['QWEN_RUNTIME_DIR'] = origEnv; + } + } + }); +}); diff --git a/packages/cli/src/serve/runQwenServe.ts b/packages/cli/src/serve/runQwenServe.ts index bc64a3c393c..cc4f5dd911b 100644 --- a/packages/cli/src/serve/runQwenServe.ts +++ b/packages/cli/src/serve/runQwenServe.ts @@ -25,6 +25,8 @@ import { PermissionAuditRing, } from './permissionAudit.js'; import { createServeApp, resolveBridgeFsFactory } from './server.js'; +import { initDaemonLogger, type DaemonLogger } from './daemonLogger.js'; +import { createSpawnChannelFactory } from '@qwen-code/acp-bridge/spawnChannel'; import { SERVE_CAPABILITY_REGISTRY } from './capabilities.js'; import type { ServeOptions } from './types.js'; import type { WorkspaceFileSystemFactory } from './fs/index.js'; @@ -518,6 +520,14 @@ export async function runQwenServe( // server.ts's raw `opts.workspace` and clients see one path on // `/capabilities` but another on `POST /session` responses. const boundWorkspace = canonicalizeWorkspace(rawWorkspace); + + // Init daemon logger early so all subsequent lifecycle events + // (bridge spawn diagnostics, shutdown errors) are captured to file. + const daemonLog: DaemonLogger = initDaemonLogger({ boundWorkspace }); + writeStderrLine( + `qwen serve: daemon log → ${daemonLog.getLogPath() || '(disabled)'}`, + ); + // Issue #4175 PR 14. The MCP client guardrails enforce in the ACP // child process (where `McpClientManager` lives), not the daemon. // Forward the budget config via env vars so the child's @@ -681,6 +691,14 @@ export async function runQwenServe( ...(deps.fsAuditEmit ? { emit: deps.fsAuditEmit } : {}), }); + // Create a spawn channel factory that tees child-stderr diagnostics + // into the daemon log file (file-only, no duplicate stderr write). + const diagnosticSink = (line: string, level?: 'info' | 'warn' | 'error') => + daemonLog.raw(line, level); + const channelFactory = createSpawnChannelFactory({ + onDiagnosticLine: diagnosticSink, + }); + const bridge = deps.bridge ?? createHttpAcpBridge({ @@ -690,6 +708,8 @@ export async function runQwenServe( : {}), boundWorkspace, childEnvOverrides, + channelFactory, + onDiagnosticLine: diagnosticSink, // F3 Commit 5 — wire the validated policy/quorum from // settings into the bridge. Bridge factory does its own // defensive `Number.isInteger` recheck on the quorum so a @@ -787,6 +807,7 @@ export async function runQwenServe( bridge, boundWorkspace, fsFactory, + daemonLog, }); // Issue #4175 PR 21 — `createServeApp` parks the device-flow registry // on `app.locals` when it constructs (or accepts) one. Pull it back @@ -936,25 +957,27 @@ export async function runQwenServe( // vanishes but its child processes keep running with // dangling stdin/stdout pipes — visible as orphan // `qwen` processes in the operator's `ps` output. - writeStderrLine( - `qwen serve: received ${signal} during drain — forcing exit`, - ); + daemonLog.warn(`received ${signal} during drain — forcing exit`); try { bridge.killAllSync(); } catch (err) { - writeStderrLine( - `qwen serve: force-kill error: ${err instanceof Error ? err.message : String(err)}`, + daemonLog.error( + 'force-kill error', + err instanceof Error ? err : null, ); } + await daemonLog.flush().catch(() => {}); process.exit(1); return; } - writeStderrLine(`qwen serve: received ${signal}, draining...`); + daemonLog.warn(`received ${signal}, draining`); try { await handle.close(); + await daemonLog.flush(); process.exit(0); } catch (err) { - writeStderrLine(`qwen serve: shutdown error: ${String(err)}`); + daemonLog.error('shutdown error', err instanceof Error ? err : null); + await daemonLog.flush().catch(() => {}); process.exit(1); } }; @@ -1028,8 +1051,8 @@ export async function runQwenServe( try { deviceFlowRegistry.dispose(); } catch (err) { - writeStderrLine( - `qwen serve: device-flow registry dispose error: ${ + daemonLog.warn( + `device-flow registry dispose error: ${ err instanceof Error ? err.message : String(err) }`, ); @@ -1038,8 +1061,9 @@ export async function runQwenServe( bridge .shutdown() .catch((err) => { - writeStderrLine( - `qwen serve: bridge shutdown error: ${String(err)}`, + daemonLog.error( + 'bridge shutdown error', + err instanceof Error ? err : null, ); bridgeShutdownError = err instanceof Error ? err : new Error(String(err)); @@ -1063,8 +1087,8 @@ export async function runQwenServe( const SECONDARY_DEADLINE_MS = 2_000; let secondaryTimer: NodeJS.Timeout | undefined; const forceTimer = setTimeout(() => { - writeStderrLine( - `qwen serve: ${SHUTDOWN_FORCE_CLOSE_MS}ms listener-drain timeout reached; force-closing remaining connections`, + daemonLog.warn( + `${SHUTDOWN_FORCE_CLOSE_MS}ms listener-drain timeout reached; force-closing remaining connections`, ); server.closeAllConnections(); // After force-close, server.close's callback @@ -1074,8 +1098,8 @@ export async function runQwenServe( // logged so the operator knows the contract was // bent. secondaryTimer = setTimeout(() => { - writeStderrLine( - `qwen serve: server.close did not fire ${SECONDARY_DEADLINE_MS}ms after force-close; resolving anyway`, + daemonLog.warn( + `server.close did not fire ${SECONDARY_DEADLINE_MS}ms after force-close; resolving anyway`, ); finish(); }, SECONDARY_DEADLINE_MS); @@ -1104,9 +1128,7 @@ export async function runQwenServe( // persistent listener that logs to stderr instead. server.removeAllListeners('error'); server.on('error', (err) => { - writeStderrLine( - `qwen serve: server error: ${err instanceof Error ? err.message : String(err)}`, - ); + daemonLog.error('server error', err instanceof Error ? err : null); }); resolve(handle); }); diff --git a/packages/cli/src/serve/server.test.ts b/packages/cli/src/serve/server.test.ts index 28d44e4a7cf..4b0d011c2a5 100644 --- a/packages/cli/src/serve/server.test.ts +++ b/packages/cli/src/serve/server.test.ts @@ -7527,3 +7527,58 @@ describe('T2.9 serve-side errorKind taxonomy (issue #4514)', () => { expect(SERVE_ERROR_KINDS).toContain('writer_idle_timeout'); }); }); + +describe('sendBridgeError daemonLog routing', () => { + it('routes 5xx errors through daemonLog when provided', async () => { + const tmp = await fsp.mkdtemp(path.join(os.tmpdir(), 'daemon-log-')); + const stderrLines: string[] = []; + const { initDaemonLogger } = await import('./daemonLogger.js'); + const daemonLog = initDaemonLogger({ + boundWorkspace: '/w', + pid: 1, + baseDir: tmp, + stderr: (line: string) => stderrLines.push(line), + }); + const bridge = fakeBridge({ + spawnImpl: async () => { + throw new Error('daemon-log-test-boom'); + }, + }); + const app = createServeApp(baseOpts, undefined, { bridge, daemonLog }); + const res = await request(app) + .post('/session') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .send({ cwd: '/work/a' }); + expect(res.status).toBe(500); + expect(res.body.error).toBe('daemon-log-test-boom'); + await daemonLog.flush(); + // Verify the daemon log file contains the structured error + const logPath = daemonLog.getLogPath(); + const logContent = await fsp.readFile(logPath, 'utf8'); + expect(logContent).toContain('[ERROR]'); + expect(logContent).toContain('[DAEMON]'); + expect(logContent).toContain('daemon-log-test-boom'); + expect(logContent).toContain('route=POST /session'); + // Verify stderr also received the line (tee behavior) + expect(stderrLines.some((l) => l.includes('daemon-log-test-boom'))).toBe( + true, + ); + await fsp.rm(tmp, { recursive: true, force: true }); + }); + + it('falls back to writeStderrLine when daemonLog is not provided', async () => { + const bridge = fakeBridge({ + spawnImpl: async () => { + throw new Error('legacy-stderr-test-boom'); + }, + }); + // No daemonLog in deps → legacy path + const app = createServeApp(baseOpts, undefined, { bridge }); + const res = await request(app) + .post('/session') + .set('Host', `127.0.0.1:${baseOpts.port}`) + .send({ cwd: '/work/a' }); + expect(res.status).toBe(500); + expect(res.body.error).toBe('legacy-stderr-test-boom'); + }); +}); diff --git a/packages/cli/src/serve/server.ts b/packages/cli/src/serve/server.ts index 402bab00fd7..99f3cbeb4a9 100644 --- a/packages/cli/src/serve/server.ts +++ b/packages/cli/src/serve/server.ts @@ -14,6 +14,7 @@ import { TrustGateError, } from '@qwen-code/qwen-code-core'; import { writeStderrLine } from '../utils/stdioHelpers.js'; +import type { DaemonLogger } from './daemonLogger.js'; import { allowOriginCors, bearerAuth, @@ -260,6 +261,13 @@ export interface ServeAppDeps { * Qwen provider. Used by tests that stub the OAuth flow. */ deviceFlowProviders?: DeviceFlowProvider[]; + /** + * Optional daemon logger. When provided, `sendBridgeError` routes + * each 5xx error through `daemonLog.error(...)` (which tees to stderr + + * the daemon log file). When omitted, falls back to existing + * stderr-only behavior. + */ + daemonLog?: DaemonLogger; } /** @@ -631,6 +639,25 @@ export function createServeApp( // detaching `runQwenServe`'s shutdown dispose call. setDeviceFlowRegistry(app, deviceFlowRegistry); + // Daemon logger — when injected via `deps.daemonLog`, 5xx errors logged + // by `sendBridgeError` route through the structured daemon log (which + // already tees to stderr). When absent (tests, direct embeds), the + // legacy `writeStderrLine` path is preserved. + const { daemonLog } = deps; + + // Curry `daemonLog` into the module-level error helpers so route + // handlers don't repeat the parameter at every call site. + const sendBridgeError = ( + res: import('express').Response, + err: unknown, + ctx?: { route?: string; sessionId?: string }, + ) => sendBridgeErrorImpl(res, err, ctx, daemonLog); + const sendPermissionVoteError = ( + res: import('express').Response, + err: unknown, + ctx: { route: string; sessionId?: string }, + ) => sendPermissionVoteErrorImpl(res, err, ctx, daemonLog); + // Order matters: rejection guards (CORS / Host allowlist / bearer auth) // run BEFORE the JSON body parser. Otherwise an unauthenticated POST // gets a full 10MB `JSON.parse` before the 401 fires — a trivially @@ -3044,10 +3071,11 @@ function parseLastEventId(raw: unknown): number | undefined { return n; } -function sendPermissionVoteError( +function sendPermissionVoteErrorImpl( res: import('express').Response, err: unknown, ctx: { route: string; sessionId?: string }, + daemonLog?: DaemonLogger, ): void { // BkwQI: voter's `optionId` wasn't in the option set the agent // originally offered (e.g. forging `ProceedAlways*` when the @@ -3101,7 +3129,7 @@ function sendPermissionVoteError( }); return; } - sendBridgeError(res, err, ctx); + sendBridgeErrorImpl(res, err, ctx, daemonLog); } function formatSseFrame(event: BridgeEvent | OmitId): string { @@ -3170,10 +3198,11 @@ type OmitId = Omit; * /session/:id/prompt', sessionId })`. Optional so test/dev call * sites that don't care about the log can omit it. */ -function sendBridgeError( +function sendBridgeErrorImpl( res: import('express').Response, err: unknown, ctx?: { route?: string; sessionId?: string }, + daemonLog?: DaemonLogger, ): void { if (err instanceof WorkspaceInitConflictError) { // #4175 Wave 4 PR 17. The target file already exists with non- @@ -3380,18 +3409,29 @@ function sendBridgeError( // 5xx is the kind of error operators need to see in their daemon log // — bridge ENOMEM, agent stack trace, unexpected throw, etc. Without // logging here every 500 disappears once the caller consumes the - // response body. This is a stop-gap until structured access/error - // logging lands (tracked under §10 follow-ups). Use the stdio helper - // (not `console.error`) to keep the no-console lint rule happy and - // route through the same writer the rest of the daemon uses. - const ctxParts = [ - ctx?.route, - ctx?.sessionId ? `session=${ctx.sessionId}` : undefined, - ].filter(Boolean); - const ctxStr = ctxParts.length > 0 ? ` (${ctxParts.join(' ')})` : ''; - writeStderrLine( - `qwen serve: bridge error${ctxStr}: ${err instanceof Error ? (err.stack ?? err.message) : String(err)}`, - ); + // response body. When `daemonLog` is provided, route through the + // structured daemon logger (which tees to stderr + log file). When + // absent (tests, direct embeds), fall back to the legacy stderr-only + // `writeStderrLine` path. + if (daemonLog) { + daemonLog.error( + err instanceof Error ? err.message : String(err), + err instanceof Error ? err : undefined, + { + ...(ctx?.route ? { route: ctx.route } : {}), + ...(ctx?.sessionId ? { sessionId: ctx.sessionId } : {}), + }, + ); + } else { + const ctxParts = [ + ctx?.route, + ctx?.sessionId ? `session=${ctx.sessionId}` : undefined, + ].filter(Boolean); + const ctxStr = ctxParts.length > 0 ? ` (${ctxParts.join(' ')})` : ''; + writeStderrLine( + `qwen serve: bridge error${ctxStr}: ${err instanceof Error ? (err.stack ?? err.message) : String(err)}`, + ); + } res.status(500).json(errorPayload(err)); }