Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
1 change: 1 addition & 0 deletions README.zh-CN.md
Original file line number Diff line number Diff line change
Expand Up @@ -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]`。 |

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

README.zh-CN.md 中,_(未设置) 缺少了结尾的下划线 _,导致 Markdown 格式不一致。建议将其修改为 _(未设置)_ 以保持与第 62 行 _(自动发现)_ 一致的斜体格式。

Suggested change
| `ZCODE_ACP_DEBUG` | _(未设置)| 设为 `1` 可开启详细诊断日志(事件流、探测循环、状态更新)。默认安静——只输出警告类日志(后端管道错误、命令/权限失败、锁等待超时)。诊断桥接问题时开启;日志出现在 `Zed.log` 中,前缀为 `[zcode-acp]`|
| `ZCODE_ACP_DEBUG` | _(未设置)_ | 设为 `1` 可开启详细诊断日志(事件流、探测循环、状态更新)。默认安静——只输出警告类日志(后端管道错误、命令/权限失败、锁等待超时)。诊断桥接问题时开启;日志出现在 `Zed.log` 中,前缀为 `[zcode-acp]`|


## 开发

Expand Down
14 changes: 7 additions & 7 deletions src/backend/client.ts
Original file line number Diff line number Diff line change
Expand Up @@ -15,11 +15,11 @@
* workers) with `process.kill(-pid)` and leave no orphans.
*/

import { spawn, type ChildProcess } from "node:child_process";

Check warning on line 18 in src/backend/client.ts

View workflow job for this annotation

GitHub Actions / Build & Test (22.x)

Member 'ChildProcess' of the import declaration should be sorted alphabetically
import { createInterface } from "node:readline";
import process from "node:process";

import { log } from "../utils.js";
import { log, warn } from "../utils.js";

Check warning on line 22 in src/backend/client.ts

View workflow job for this annotation

GitHub Actions / Build & Test (22.x)

Expected 'multiple' syntax before 'single' syntax
import type {
ZcodeEvent,
ZcodeInbound,
Expand Down Expand Up @@ -71,7 +71,7 @@
// 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();
Expand Down Expand Up @@ -190,7 +190,7 @@
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({
Expand Down Expand Up @@ -221,7 +221,7 @@
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
Expand All @@ -234,7 +234,7 @@
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");
Expand All @@ -246,7 +246,7 @@
notify(method: string, params?: Record<string, unknown>): 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");
Expand All @@ -262,7 +262,7 @@
send(method: string, params?: Record<string, unknown>): 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++;
Expand Down
4 changes: 2 additions & 2 deletions src/config/runtime-model.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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);
Expand Down
16 changes: 11 additions & 5 deletions src/handlers/extensions.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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";

Expand Down Expand Up @@ -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`);
}
Expand All @@ -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)
Expand Down
20 changes: 11 additions & 9 deletions src/handlers/server-requests.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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";

Expand Down Expand Up @@ -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;
}
Expand Down Expand Up @@ -246,7 +246,7 @@ async function handleAskUserQuestion(
): Promise<ZcodeInteractionResponse> {
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 ?? "";
Expand All @@ -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;
Expand Down Expand Up @@ -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)`,
);
Comment on lines +337 to +339

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

To prevent potential runtime errors, it is safer to use optional chaining when accessing properties on requestedSchema. If requestedSchema or properties is undefined, calling Object.keys directly will throw a TypeError.

Suggested change
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",
Expand All @@ -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})`);
Expand Down Expand Up @@ -439,13 +441,13 @@ async function requestWithTimeout(
let cancelTimer: ReturnType<typeof setInterval> | undefined;
const timeout = new Promise<null>((resolve) => {
timer = setTimeout(() => {
log(` ⚠ ${label} timed out after ${timeoutMs}ms`);
warn(` ⚠ ${label} timed out after ${timeoutMs}ms`);
resolve(null);
}, timeoutMs);
});
const racers: Array<Promise<unknown>> = [
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,
Expand All @@ -458,7 +460,7 @@ async function requestWithTimeout(
new Promise<null>((resolve) => {
cancelTimer = setInterval(() => {
if (turn.cancelled) {
log(` ⚠ ${label} aborted (turn cancelled)`);
warn(` ⚠ ${label} aborted (turn cancelled)`);
resolve(null);
}
}, 100);
Expand Down
6 changes: 3 additions & 3 deletions src/handlers/session.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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)}`);
}
}

Expand Down
5 changes: 2 additions & 3 deletions src/handlers/slash.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand Down Expand Up @@ -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;
}
}
4 changes: 2 additions & 2 deletions src/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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<void> {
// stdout is the outbound channel to the client; stdin is inbound.
Expand Down Expand Up @@ -123,6 +123,6 @@ async function main(): Promise<void> {
}

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);
});
4 changes: 2 additions & 2 deletions src/translators/event-translator.ts
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,7 @@
* it when `scheduled` arrives without input.
*/

import { log } from "../utils.js";
import { log, warn } from "../utils.js";
import {
buildResultContent,
extractLocations,
Expand Down Expand Up @@ -74,7 +74,7 @@ export class EventTranslator {
this.turnError = (payload["error"] as Record<string, unknown>) ?? {};
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;
}
Expand Down
25 changes: 23 additions & 2 deletions src/utils.ts
Original file line number Diff line number Diff line change
Expand Up @@ -95,9 +95,30 @@ export const CONFIG_DISPATCH: Record<string, { method: string; paramKey: string
};

/**
* Log a message to stderr with a stable prefix. Never use console.log —
* stdout is reserved for the ACP JSON-RPC stream.
* Logging. Two levels, both write to stderr (stdout is reserved for the ACP
* JSON-RPC stream):
* - `warn(msg)`: always emitted — failures the user can perceive (fatal
* exit, broken backend pipe, command/permission failures, etc.).
* - `log(msg)`: verbose diagnostic detail — only emitted when
* `ZCODE_ACP_DEBUG=1` is set. Default (unset) keeps the log quiet so
* a stable bridge doesn't spam `Zed.log`.
*
* Never use `console.log` — it would corrupt the stdout protocol stream.
*/

/** True when the user opted into verbose diagnostics.
* Read at call time so tests can flip it without re-importing the module. */
function isDebug(): boolean {
return process.env.ZCODE_ACP_DEBUG === "1";
}

/** Verbose diagnostic log. Only emitted when `ZCODE_ACP_DEBUG=1`. */
export function log(msg: string): void {
if (!isDebug()) return;
process.stderr.write(`[zcode-acp] ${msg}\n`);
}

/** Warning — always emitted. For perceivable failures. */
export function warn(msg: string): void {
process.stderr.write(`[zcode-acp] ${msg}\n`);
}
50 changes: 50 additions & 0 deletions tests/utils.test.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,50 @@
/**
* Tests for the logging utilities: debug-gated verbose log and warn-always.
*
* Default behavior is QUIET: verbose `log()` is suppressed unless
* `ZCODE_ACP_DEBUG=1` is set; `warn()` always emits (perceivable failures).
*/

import { afterEach, beforeEach, describe, it, expect, vi } from "vitest";

import { log, warn } from "../src/utils.js";

describe("logging", () => {
const prevDebug = process.env.ZCODE_ACP_DEBUG;
let spy: ReturnType<typeof vi.spyOn>;

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();
});
});
Loading