diff --git a/README.md b/README.md index 691db9c..93cd14a 100644 --- a/README.md +++ b/README.md @@ -63,6 +63,7 @@ Restart Zed and pick **ZCode** from the agent dropdown. | `ZCODE_NODE` | _(discovered)_ | Explicit Node binary to run `ZCODE_BIN` with (must support `node:sqlite`) | | `ZCODE_MODEL` | _(from config)_ | Override the active model id | | `ZCODE_BASE_URL` | _(from config)_ | Override the provider base URL | +| `ZCODE_ACP_DEBUG` | _(unset)_ | Set to `1` to enable verbose diagnostic logs (event flow, probe loops, status updates). Default is quiet — only warnings (backend pipe errors, command/permission failures, lock timeouts) are emitted. Enable this when diagnosing bridge issues; the logs appear in `Zed.log` prefixed with `[zcode-acp]`. | ## Develop diff --git a/README.zh-CN.md b/README.zh-CN.md index 39378ff..e0563b2 100644 --- a/README.zh-CN.md +++ b/README.zh-CN.md @@ -62,6 +62,7 @@ ACP 客户端里配置启动它 —— 见下方的 **在 Zed 中配置** 或你 | `ZCODE_NODE` | _（自动发现）_ | 显式指定运行 `ZCODE_BIN` 的 Node 二进制（必须支持 `node:sqlite`）| | `ZCODE_MODEL` | _（来自 config）| 覆盖当前使用的模型 id | | `ZCODE_BASE_URL` | _（来自 config）| 覆盖 provider 的 base URL | +| `ZCODE_ACP_DEBUG` | _（未设置）| 设为 `1` 可开启详细诊断日志（事件流、探测循环、状态更新）。默认安静——只输出警告类日志（后端管道错误、命令/权限失败、锁等待超时）。诊断桥接问题时开启；日志出现在 `Zed.log` 中，前缀为 `[zcode-acp]`。 | ## 开发 diff --git a/src/backend/client.ts b/src/backend/client.ts index 34bb270..73c1621 100644 --- a/src/backend/client.ts +++ b/src/backend/client.ts @@ -19,7 +19,7 @@ import { spawn, type ChildProcess } from "node:child_process"; import { createInterface } from "node:readline"; import process from "node:process"; -import { log } from "../utils.js"; +import { log, warn } from "../utils.js"; import type { ZcodeEvent, ZcodeInbound, @@ -71,7 +71,7 @@ export class ZcodeBackend { // reader dead so the rest of the bridge stops talking to a gone backend. this.proc.stdin?.on("error", (err) => { this.readerDead = true; - log(`backend: stdin error: ${err.message}`); + warn(`backend: stdin error: ${err.message}`); }); this.startReader(); this.startWatchdog(); @@ -190,7 +190,7 @@ export class ZcodeBackend { private markReaderDead(reason: string): void { if (this.readerDead) return; this.readerDead = true; - log(`backend: reader exited (${reason})`); + warn(`backend: reader exited (${reason})`); for (const [, p] of this.pending) { clearTimeout(p.timer); p.resolve({ @@ -221,7 +221,7 @@ export class ZcodeBackend { sendReply(id: number, result: unknown): void { const stdin = this.proc.stdin; if (!stdin || stdin.destroyed) { - log("backend: sendReply dropped (stdin closed)"); + warn("backend: sendReply dropped (stdin closed)"); return; } // Write errors (EPIPE) are delivered via the stdin 'error' listener @@ -234,7 +234,7 @@ export class ZcodeBackend { sendError(id: number, code: number, message: string): void { const stdin = this.proc.stdin; if (!stdin || stdin.destroyed) { - log("backend: sendError dropped (stdin closed)"); + warn("backend: sendError dropped (stdin closed)"); return; } stdin.write(JSON.stringify({ id, error: { code, message } }) + "\n"); @@ -246,7 +246,7 @@ export class ZcodeBackend { notify(method: string, params?: Record): void { const stdin = this.proc.stdin; if (!stdin || stdin.destroyed) { - log("backend: notify dropped (stdin closed)"); + warn("backend: notify dropped (stdin closed)"); return; } stdin.write(JSON.stringify({ method, params }) + "\n"); @@ -262,7 +262,7 @@ export class ZcodeBackend { send(method: string, params?: Record): void { const stdin = this.proc.stdin; if (!stdin || stdin.destroyed) { - log("backend: send dropped (stdin closed)"); + warn("backend: send dropped (stdin closed)"); return; } const id = this.sendIdCounter++; diff --git a/src/config/runtime-model.ts b/src/config/runtime-model.ts index ae04b8c..6e5fa96 100644 --- a/src/config/runtime-model.ts +++ b/src/config/runtime-model.ts @@ -18,7 +18,7 @@ import { readFileSync } from "node:fs"; -import { ZCODE_CREDS_PATH, log } from "../utils.js"; +import { ZCODE_CREDS_PATH, log, warn } from "../utils.js"; import type { ZcodeAcpServer } from "../server.js"; interface ProviderConfig { @@ -118,7 +118,7 @@ export async function applyModelSwitch( 15000, ); if (resp.error) { - log(`runtime-model: switch failed: ${resp.error.message}`); + warn(`runtime-model: switch failed: ${resp.error.message}`); return false; } invalidateModelCache(server, zcodeSid); diff --git a/src/handlers/extensions.ts b/src/handlers/extensions.ts index 33c8888..af92ff6 100644 --- a/src/handlers/extensions.ts +++ b/src/handlers/extensions.ts @@ -17,7 +17,7 @@ import { emitInitialUsage } from "../config/model-cache.js"; import { applyModelSwitch } from "../config/runtime-model.js"; import { buildConfigOptions, buildModes } from "../config/options.js"; import { ProjectionDiffer } from "../translators/projection-differ.js"; -import { log } from "../utils.js"; +import { log, warn } from "../utils.js"; import type { ZcodeAcpServer } from "../server.js"; import { sendSessionUpdate } from "./io.js"; @@ -112,9 +112,11 @@ export async function goal(server: ZcodeAcpServer, params: ExtensionParams): Pro // timeout is in MILLISECONDS here (Date.now()-based), not seconds — Python's // timeout=60 becomes 60000. A bare 60 would expire on the first probe. const released = await waitForTurnIdle(server, zcodeSid, 60_000, "session/goal", false); - log( - `session/goal action=${action} → ok (${released ? "lock released" : "⚠ lock wait timeout"})`, - ); + if (released) { + log(`session/goal action=${action} → ok (lock released)`); + } else { + warn(`session/goal action=${action} → ⚠ lock wait timeout`); + } } else { log(`session/goal action=${action} → ok`); } @@ -139,7 +141,11 @@ export async function compact( // timeout=300 becomes 300000. A bare 300 expires on the first probe sleep, // making compact return "✓" while the internal turn lock is still held. const released = await waitForTurnIdle(server, zcodeSid, 300_000, "session/goal", true); - log(`session/compact → ok (${released ? "lock released" : "⚠ lock wait timeout"})`); + if (released) { + log("session/compact → ok (lock released)"); + } else { + warn("session/compact → ⚠ lock wait timeout (backend may still be compacting)"); + } if (released) { // Refresh usage so the UI reflects the reduced contextUsed post-compact. // Ensure a differ exists (compact may be the first action on a fresh session) diff --git a/src/handlers/server-requests.ts b/src/handlers/server-requests.ts index f85ad6b..0029db8 100644 --- a/src/handlers/server-requests.ts +++ b/src/handlers/server-requests.ts @@ -39,7 +39,7 @@ import { splitAskUserQuestions, zcodePermissionToAcp, } from "../interaction/adapter.js"; -import { log } from "../utils.js"; +import { log, warn } from "../utils.js"; import type { PendingTurn, ZcodeAcpServer } from "../server.js"; import { sendSessionUpdate } from "./io.js"; @@ -101,7 +101,7 @@ async function handleOne( const epm = isExitPlanMode(params); if (!perm && !(isUserInputRequestUnchecked(method) && (epm || ask))) { - log(` ⚠ unhandled server→client request: ${method} (id=${zcodeReqId})`); + warn(` ⚠ unhandled server→client request: ${method} (id=${zcodeReqId})`); sendZcodeError(backend, zcodeReqId, `bridge unsupported: ${method}`); return; } @@ -246,7 +246,7 @@ async function handleAskUserQuestion( ): Promise { const qs = splitAskUserQuestions(params); if (qs === null) { - log(" ⚠ AskUserQuestion: no valid questions, declining"); + warn(" ⚠ AskUserQuestion: no valid questions, declining"); return { action: "decline", reason: "no valid questions" }; } const toolCallId = params.toolCallId ?? ""; @@ -270,7 +270,7 @@ async function handleAskUserQuestion( const resp = await askOnce(server, cx, acpParams, idx + 1, qs.length, q.question, turn); const selected = parseAskUserResponse(resp); if (selected === null) { - log(` ⚠ AskUserQuestion [${idx + 1}] skip/cancel/timeout, declining`); + warn(` ⚠ AskUserQuestion [${idx + 1}] skip/cancel/timeout, declining`); return { action: "decline", reason: "skipped or cancelled" }; } answers[q.question] = selected; @@ -334,7 +334,9 @@ async function handleAskUserViaElicitation( _meta: { claudeCode: { toolName } }, }); const formParams = buildAskUserElicitationForm(params, acpSid, toolCallId || undefined); - log(` ⟳ AskUserQuestion forwarding elicitation/create (form, ${Object.keys(formParams.requestedSchema.properties).length} fields)`); + log( + ` ⟳ AskUserQuestion forwarding elicitation/create (form, ${Object.keys(formParams.requestedSchema.properties).length} fields)`, + ); const acpResp = await requestWithTimeout( cx, "elicitation/create", @@ -348,7 +350,7 @@ async function handleAskUserViaElicitation( } const answers = parseAskUserElicitationResponse(acpResp, params); if (answers === null) { - log(" ⚠ AskUserQuestion elicitation declined/cancelled"); + warn(" ⚠ AskUserQuestion elicitation declined/cancelled"); return { action: "decline", reason: "declined or cancelled" }; } log(` ✓ AskUserQuestion elicitation answered (${Object.keys(answers).length})`); @@ -439,13 +441,13 @@ async function requestWithTimeout( let cancelTimer: ReturnType | undefined; const timeout = new Promise((resolve) => { timer = setTimeout(() => { - log(` ⚠ ${label} timed out after ${timeoutMs}ms`); + warn(` ⚠ ${label} timed out after ${timeoutMs}ms`); resolve(null); }, timeoutMs); }); const racers: Array> = [ cx.request(method, params as never).catch((e: unknown) => { - log(` ⚠ ${label} failed: ${e instanceof Error ? e.message : String(e)}`); + warn(` ⚠ ${label} failed: ${e instanceof Error ? e.message : String(e)}`); return null; }), timeout, @@ -458,7 +460,7 @@ async function requestWithTimeout( new Promise((resolve) => { cancelTimer = setInterval(() => { if (turn.cancelled) { - log(` ⚠ ${label} aborted (turn cancelled)`); + warn(` ⚠ ${label} aborted (turn cancelled)`); resolve(null); } }, 100); diff --git a/src/handlers/session.ts b/src/handlers/session.ts index c6e45c3..5d1b4d8 100644 --- a/src/handlers/session.ts +++ b/src/handlers/session.ts @@ -31,7 +31,7 @@ import { ProjectionDiffer, } from "../translators/index.js"; import type { InternalEvent } from "../translators/index.js"; -import { log } from "../utils.js"; +import { log, warn } from "../utils.js"; import type { PendingTurn, ZcodeAcpServer } from "../server.js"; import { dispatchEvent } from "./dispatch.js"; import { sendSessionUpdate, sendTextChunk } from "./io.js"; @@ -512,7 +512,7 @@ async function preemptInFlightTurn( const t0 = Date.now(); while (server.pendingTurns.has(oldRequestId)) { if (Date.now() - t0 > PREEMPT_TIMEOUT_MS) { - log(` [preempt] timed out waiting for old turn ${oldRequestId} to exit`); + warn(` [preempt] timed out waiting for old turn ${oldRequestId} to exit`); return; // best-effort: continue anyway, session/send may fail } await sleep(200); @@ -834,7 +834,7 @@ async function emitModeIfChanged( }); log(`session/prompt: mode changed → ${modes.currentModeId}`); } catch (e) { - log(`emitModeIfChanged failed: ${e instanceof Error ? e.message : String(e)}`); + warn(`emitModeIfChanged failed: ${e instanceof Error ? e.message : String(e)}`); } } diff --git a/src/handlers/slash.ts b/src/handlers/slash.ts index fcca22f..5658ab2 100644 --- a/src/handlers/slash.ts +++ b/src/handlers/slash.ts @@ -16,8 +16,7 @@ import type * as acp from "@agentclientprotocol/sdk"; import { RequestError } from "@agentclientprotocol/sdk"; import { applyModelSwitch } from "../config/runtime-model.js"; import { emitConfigOptionUpdate } from "../config/options.js"; -import { CONFIG_DISPATCH } from "../utils.js"; -import { log } from "../utils.js"; +import { CONFIG_DISPATCH, warn } from "../utils.js"; import type { ZcodeAcpServer } from "../server.js"; import { sendTextChunk } from "./io.js"; import { compact, fork, rewind, steer } from "./extensions.js"; @@ -120,7 +119,7 @@ export async function handleSlashCommand( return null; } } catch (e) { - log(` /${cmd} failed: ${e instanceof Error ? e.message : String(e)}`); + warn(` /${cmd} failed: ${e instanceof Error ? e.message : String(e)}`); throw e; } } diff --git a/src/index.ts b/src/index.ts index dcf0769..80ceb05 100644 --- a/src/index.ts +++ b/src/index.ts @@ -38,7 +38,7 @@ import { } from "./handlers/extensions.js"; import { sendAvailableCommandsDeferred } from "./handlers/io.js"; import { ZcodeAcpServer } from "./server.js"; -import { AGENT_INFO, SLASH_COMMANDS, log } from "./utils.js"; +import { AGENT_INFO, SLASH_COMMANDS, log, warn } from "./utils.js"; async function main(): Promise { // stdout is the outbound channel to the client; stdin is inbound. @@ -123,6 +123,6 @@ async function main(): Promise { } main().catch((err) => { - log(`fatal: ${err instanceof Error ? (err.stack ?? err.message) : String(err)}`); + warn(`fatal: ${err instanceof Error ? (err.stack ?? err.message) : String(err)}`); process.exit(1); }); diff --git a/src/translators/event-translator.ts b/src/translators/event-translator.ts index 36da98b..eea2b8e 100644 --- a/src/translators/event-translator.ts +++ b/src/translators/event-translator.ts @@ -12,7 +12,7 @@ * it when `scheduled` arrives without input. */ -import { log } from "../utils.js"; +import { log, warn } from "../utils.js"; import { buildResultContent, extractLocations, @@ -74,7 +74,7 @@ export class EventTranslator { this.turnError = (payload["error"] as Record) ?? {}; this.turnResultType = (payload["resultType"] as string) ?? "error"; const err = this.turnError; - log(` [event] turn.failed (code=${err["code"] ?? err["type"] ?? "?"})`); + warn(` [event] turn.failed (code=${err["code"] ?? err["type"] ?? "?"})`); } return results; } diff --git a/src/utils.ts b/src/utils.ts index 8dcdef8..65af528 100644 --- a/src/utils.ts +++ b/src/utils.ts @@ -95,9 +95,30 @@ export const CONFIG_DISPATCH: Record { + const prevDebug = process.env.ZCODE_ACP_DEBUG; + let spy: ReturnType; + + beforeEach(() => { + spy = vi.spyOn(process.stderr, "write").mockImplementation(() => true); + }); + afterEach(() => { + spy.mockRestore(); + if (prevDebug === undefined) delete process.env.ZCODE_ACP_DEBUG; + else process.env.ZCODE_ACP_DEBUG = prevDebug; + }); + + it("log() is silenced by default (no ZCODE_ACP_DEBUG)", () => { + delete process.env.ZCODE_ACP_DEBUG; + log("should be silenced"); + expect(spy).not.toHaveBeenCalled(); + }); + + it("log() writes to stderr with the [zcode-acp] prefix when ZCODE_ACP_DEBUG=1", () => { + process.env.ZCODE_ACP_DEBUG = "1"; + log("hello"); + expect(spy).toHaveBeenCalledTimes(1); + expect(spy.mock.calls[0]?.[0]).toBe("[zcode-acp] hello\n"); + }); + + it("warn() always writes, even without ZCODE_ACP_DEBUG", () => { + delete process.env.ZCODE_ACP_DEBUG; + warn("visible warning"); + expect(spy).toHaveBeenCalledTimes(1); + expect(spy.mock.calls[0]?.[0]).toBe("[zcode-acp] visible warning\n"); + }); + + it("ZCODE_ACP_DEBUG=0 keeps log() silenced (only '1' enables verbose)", () => { + process.env.ZCODE_ACP_DEBUG = "0"; + log("still silenced"); + expect(spy).not.toHaveBeenCalled(); + }); +});