From e039f21a5304b140e59e1eaffd20efaa50a65c67 Mon Sep 17 00:00:00 2001 From: rfhold Date: Wed, 29 Jul 2026 15:40:39 -0400 Subject: [PATCH] feat: structured logging for provider diagnostics + Cursor SDK rules/skills logs Converts every console.warn/console.error in the provider (agent-backend, agent-events, language-model) to route through opencode's client.app.log() API instead, with a console.* fallback when no client bridge is published. Also captures @cursor/sdk's own internal rules/skills load-completion diagnostics (e.g. "LocalCursorRulesService load completed meta={durationMs, ruleCount}"), which the SDK writes straight to console.log with no public logger hook, and re-emits them as structured opencode logs instead of raw terminal noise: - In-process transport: a narrowly-scoped console.log interceptor matches only the three known Cursor rules/skills messages; everything else passes through unchanged (src/provider/cursor-log-intercept.ts). - Sidecar transport: the child process installs the same interception and forwards matches over the existing JSONL protocol as a new "log" event (src/sidecar/agent-host.mjs), which SidecarClient forwards via a new onLog option. New src/provider/log-bridge.ts mirrors the existing subagent-bridge.ts globalThis pattern to give the provider layer access to the plugin's opencode client without a circular import. --- CHANGELOG.md | 17 +++++ src/plugin/index.ts | 7 +- src/provider/agent-backend.ts | 27 ++++--- src/provider/agent-events.ts | 25 ++++--- src/provider/cursor-log-intercept.ts | 92 ++++++++++++++++++++++++ src/provider/language-model.ts | 26 +++---- src/provider/log-bridge.ts | 81 +++++++++++++++++++++ src/provider/sidecar-client.ts | 20 ++++++ src/sidecar/agent-host.mjs | 43 +++++++++++ test/cursor-log-intercept.test.ts | 104 +++++++++++++++++++++++++++ test/fixtures/fake-cursor-sdk.mjs | 15 ++++ test/log-bridge.test.ts | 73 +++++++++++++++++++ test/sidecar.test.ts | 26 ++++++- 13 files changed, 524 insertions(+), 32 deletions(-) create mode 100644 src/provider/cursor-log-intercept.ts create mode 100644 src/provider/log-bridge.ts create mode 100644 test/cursor-log-intercept.test.ts create mode 100644 test/log-bridge.test.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index 373ecbb..f29682d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,23 @@ All notable changes to this project will be documented in this file. ## [Unreleased] +- **Structured logging via `client.app.log()` instead of raw `console.*`.** The + plugin's own diagnostics (transport fallback warnings, per-turn debug traces + gated on `OPENCODE_CURSOR_DEBUG=1`) now route through opencode's plugin + logging API (`service: "opencode-cursor"`) rather than `console.warn`/ + `console.error`. Falls back to `console.*` when no client is available + (e.g. running the provider standalone). +- **Cursor SDK's own "rules"/"skills" load diagnostics captured and forwarded.** + `@cursor/sdk`'s bundled local-exec runtime writes internal messages like + `LocalCursorRulesService load completed meta={durationMs, ruleCount}` and + `AgentSkillsCursorRulesService load completed meta={durationMs, ruleCount, + skillCount}` straight to `console.log`, with no public logger hook to + redirect it. These are now recognized (in-process transport via a narrowly + scoped `console.log` interceptor; sidecar transport via the child process's + own interceptor forwarding over the existing JSONL protocol) and re-emitted + as structured opencode logs instead of raw terminal noise. Every other + `console.log` call passes through unchanged. + ## [0.6.2] — 2026-07-28 Version-check UX cleanup from #79. diff --git a/src/plugin/index.ts b/src/plugin/index.ts index c40be2f..aeb9e39 100644 --- a/src/plugin/index.ts +++ b/src/plugin/index.ts @@ -15,6 +15,7 @@ import { import { buildCursorTools } from "./cursor-tools.js"; import { getLocalVersion, getLatestVersion, clearVersionCache, PLUGIN_CACHE_PATH } from "../version-check.js"; import { removeSystemRule } from "../provider/system-rule.js"; +import { clearLogBridge, setLogBridge } from "../provider/log-bridge.js"; import { clearSubagentBridge, setSubagentBridge, @@ -103,7 +104,10 @@ export const CursorPlugin: Plugin = async (input) => { // create a real child session for each Cursor subagent (making its `task` // card clickable / `ctrl+x`-navigable). Same-process handoff via a globalThis // registry; the provider degrades gracefully when it's absent. - if (client) setSubagentBridge({ client, directory }); + if (client) { + setSubagentBridge({ client, directory }); + setLogBridge({ client, directory }); + } // Canonical working directory for the generated system-prompt rule: the // provider writes `.cursor/rules/opencode.mdc` under this path and dispose // cleans it up from the same path. The config hook threads it into the @@ -390,6 +394,7 @@ export const CursorPlugin: Plugin = async (input) => { // so a user-owned opencode.mdc is never deleted. removeSystemRule(resolvedCwd); clearSubagentBridge(); + clearLogBridge(); }, }; }; diff --git a/src/provider/agent-backend.ts b/src/provider/agent-backend.ts index 89725cb..6e7e727 100644 --- a/src/provider/agent-backend.ts +++ b/src/provider/agent-backend.ts @@ -18,6 +18,8 @@ import { execSync } from "node:child_process"; import { existsSync } from "node:fs"; import { fileURLToPath } from "node:url"; import { loadCursorSdk } from "../cursor-runtime.js"; +import { installCursorLogInterceptor } from "./cursor-log-intercept.js"; +import { pluginLog } from "./log-bridge.js"; import { SidecarClient, type AgentLike } from "./sidecar-client.js"; export type { AgentLike, AgentRunLike, AgentSendOptions } from "./sidecar-client.js"; @@ -109,6 +111,11 @@ async function ensureHttp1Configured(): Promise { } function inProcessBackend(useHttp1: boolean): AgentBackend { + // The SDK runs in this process and writes its own diagnostics straight to + // the shared global `console` (see cursor-log-intercept.ts); install once + // so its rules/skills load-completion logs route through opencode logging + // instead of appearing as raw stdout noise. + installCursorLogInterceptor(); return { kind: "in-process", createAgent: async (options) => { @@ -143,7 +150,11 @@ export function resolveSidecarScript(): string | undefined { } function sidecarBackend(nodePath: string, scriptPath: string): AgentBackend { - const client = new SidecarClient({ scriptPath, nodePath }); + const client = new SidecarClient({ + scriptPath, + nodePath, + onLog: (level, message, meta) => pluginLog(level, message, meta), + }); return { kind: "sidecar", createAgent: (options) => client.createAgent(options), @@ -161,18 +172,18 @@ export function loadAgentBackend(): AgentBackend { const scriptPath = transport === "sidecar" ? resolveSidecarScript() : undefined; if (transport === "sidecar" && (!env.nodePath || !scriptPath)) { // Explicit sidecar request we can't satisfy: fall back loudly. - console.error( - "[opencode-cursor] Node sidecar requested but unavailable " + - `(node: ${env.nodePath ?? "not found"}, script: ${scriptPath ?? "not found"}); ` + - "falling back to in-process HTTP/1.1 transport.", + pluginLog( + "warn", + "Node sidecar requested but unavailable; falling back to in-process HTTP/1.1 transport.", + { node: env.nodePath ?? null, script: scriptPath ?? null }, ); cached = inProcessBackend(true); return cached; } if (transport === "http2-direct" && env.isBun) { - console.error( - "[opencode-cursor] http2-direct under Bun: Cursor streams may fail " + - "(Bun node:http2 incompatibility, oven-sh/bun#31499). " + + pluginLog( + "warn", + "http2-direct under Bun: Cursor streams may fail (Bun node:http2 incompatibility, oven-sh/bun#31499). " + "Set OPENCODE_CURSOR_TRANSPORT=http1 (recommended) or sidecar.", ); } diff --git a/src/provider/agent-events.ts b/src/provider/agent-events.ts index 0adf74e..6099124 100644 --- a/src/provider/agent-events.ts +++ b/src/provider/agent-events.ts @@ -1,6 +1,7 @@ import type { AgentModeOption, SDKUserMessage } from "@cursor/sdk"; import type { AgentLike, AgentRunLike, AgentSendOptions } from "./agent-backend.js"; import { classifyError } from "./error-classify.js"; +import { pluginLog } from "./log-bridge.js"; /** Token usage as reported by Cursor's `turn-ended` update. */ export interface CursorUsage { @@ -202,9 +203,11 @@ export async function* streamAgentTurn( if (options.abortSignal?.aborted) void Promise.resolve(run.cancel()).catch(() => {}); const result = await run.wait(); if (debug) { - console.error( - `[cursor:debug] updates=${JSON.stringify(counts)} status=${result.status} resultLen=${(result.result ?? "").length}`, - ); + pluginLog("debug", "turn finished", { + updates: counts, + status: result.status, + resultLen: (result.result ?? "").length, + }); } // Superseded by a watchdog force-resend: this run is abandoned. if (gen !== runGen || finished) return; @@ -221,7 +224,11 @@ export async function* streamAgentTurn( .catch((err) => { if (gen !== runGen) return; failure = err; - if (debug) console.error(`[cursor:debug] send failed: ${err instanceof Error ? err.message : String(err)}`); + if (debug) { + pluginLog("debug", "send failed", { + error: err instanceof Error ? err.message : String(err), + }); + } }) .finally(() => { // Only the live run finishes the stream; a superseded (cancelled-for- @@ -265,7 +272,7 @@ export async function* streamAgentTurn( return; } forced = true; - if (debug) console.error("[cursor:debug] stream stalled; cancelling and resending with local.force"); + if (debug) pluginLog("debug", "stream stalled; cancelling and resending with local.force"); try { await runHolder.run?.cancel(); } catch { @@ -324,7 +331,7 @@ export async function sendWithRecovery( } catch (err) { const classified = classifyError(err); if (classified.kind === "agent-busy") { - if (debug) console.error("[cursor:debug] agent busy; retrying send with local.force"); + if (debug) pluginLog("debug", "agent busy; retrying send with local.force"); return agent.send(message, { ...sendOptions, local: { force: true } }); } if ( @@ -332,9 +339,9 @@ export async function sendWithRecovery( attempt < RETRY_BACKOFF_MS.length ) { if (debug) - console.error( - `[cursor:debug] ${classified.kind}; retrying send in ${RETRY_BACKOFF_MS[attempt]}ms`, - ); + pluginLog("debug", `${classified.kind}; retrying send`, { + delayMs: RETRY_BACKOFF_MS[attempt], + }); await sleep(RETRY_BACKOFF_MS[attempt]!); continue; } diff --git a/src/provider/cursor-log-intercept.ts b/src/provider/cursor-log-intercept.ts new file mode 100644 index 0000000..9a7347e --- /dev/null +++ b/src/provider/cursor-log-intercept.ts @@ -0,0 +1,92 @@ +import { pluginLog } from "./log-bridge.js"; + +// eslint-disable-next-line no-control-regex +const ANSI_PATTERN = /\x1b\[[0-9;]*m/g; + +function stripAnsi(input: string): string { + return input.replace(ANSI_PATTERN, ""); +} + +/** + * `@cursor/sdk`'s bundled local-exec runtime formats its "rules"/"skills" + * loading diagnostics (context logger `local-exec:cursor-rules`) into one + * preformatted string and writes it straight to `console.log` — there is no + * public logger hook to redirect it instead. Observed shapes (colors + * stripped): + * + * 16:05:53.036 INFO LocalCursorRulesService load completed meta={durationMs: 89, ruleCount: 1} + * 16:05:53.036 INFO AgentSkillsCursorRulesService load completed meta={durationMs: 86, ruleCount: 18, skillCount: 18} + * 16:05:53.036 INFO CursorPluginsAgentSkillsService load completed meta={durationMs: 12, ruleCount: 2, skillCount: 0} + * + * The context path (`ctx=...`) is only present in some builds/configs. + */ +const RULE_LOAD_PATTERN = + /^\d{2}:\d{2}:\d{2}\.\d{3}\s+INFO\s+(LocalCursorRulesService|AgentSkillsCursorRulesService|CursorPluginsAgentSkillsService) load completed(?:\s+ctx=\S+)?\s+meta=\{([^}]*)\}\s*$/; + +/** Parses the `meta={key: value, ...}` tail into a plain numeric object. */ +export function parseCursorLogMeta(raw: string): Record { + const out: Record = {}; + for (const part of raw.split(",")) { + const [key, value] = part.split(":").map((s) => s.trim()); + if (!key || value === undefined) continue; + const num = Number(value); + if (Number.isFinite(num)) out[key] = num; + } + return out; +} + +export interface ParsedCursorRuleLog { + service: string; + meta: Record; +} + +/** Matches one line against the known Cursor rules/skills load-completion shape. */ +export function parseCursorRuleLoadLine(line: string): ParsedCursorRuleLog | undefined { + const match = RULE_LOAD_PATTERN.exec(stripAnsi(line)); + if (!match) return undefined; + const [, service, meta] = match; + if (!service) return undefined; + return { service, meta: parseCursorLogMeta(meta ?? "") }; +} + +let installed = false; +let original: typeof console.log | undefined; + +/** + * Installs a narrowly-scoped `console.log` interceptor that recognizes only + * the known Cursor rules/skills "load completed" messages (see + * {@link parseCursorRuleLoadLine}) and re-emits them as structured opencode + * logs via {@link pluginLog}. Every other `console.log` call — including + * anything else the SDK or the host process writes — passes through + * unchanged. + * + * Only relevant to the in-process transport, where the SDK runs inside this + * process and writes directly to the shared global `console`. The sidecar + * transport intercepts the same messages in the child process instead (see + * `src/sidecar/agent-host.mjs`) and forwards them over the JSONL protocol. + * + * Idempotent: safe to call on every agent creation. + */ +export function installCursorLogInterceptor(): void { + if (installed) return; + original = console.log.bind(console); + const passthrough = original; + console.log = (...args: unknown[]) => { + if (args.length === 1 && typeof args[0] === "string") { + const parsed = parseCursorRuleLoadLine(args[0]); + if (parsed) { + pluginLog("info", `${parsed.service} load completed`, parsed.meta); + return; + } + } + passthrough(...(args as Parameters)); + }; + installed = true; +} + +/** Test hook. */ +export function resetCursorLogInterceptor(): void { + if (original) console.log = original; + original = undefined; + installed = false; +} diff --git a/src/provider/language-model.ts b/src/provider/language-model.ts index f7ac250..9d31eae 100644 --- a/src/provider/language-model.ts +++ b/src/provider/language-model.ts @@ -23,6 +23,7 @@ import { } from "./message-map.js"; import { extractSystemText, resolveSystemDelivery } from "./system-rule.js"; import { classifyError } from "./error-classify.js"; +import { pluginLog } from "./log-bridge.js"; import { addUsage, sendAgentTurnSilently, @@ -126,7 +127,7 @@ export class CursorLanguageModel implements LanguageModelV3 { private warnOnce(message: string): void { if (this.warned.has(message)) return; this.warned.add(message); - console.warn(`[${this.provider}] ${message}`); + pluginLog("warn", message, { provider: this.provider }); } private requireApiKey(): string { @@ -159,9 +160,10 @@ export class CursorLanguageModel implements LanguageModelV3 { providerOptions, ); if (process.env["OPENCODE_CURSOR_DEBUG"] === "1") { - console.error( - `[cursor:debug] model=${this.modelId} selection=${JSON.stringify(modelSelection)}`, - ); + pluginLog("debug", "model call", { + model: this.modelId, + selection: modelSelection, + }); } const sessionID = typeof providerOptions?.["sessionID"] === "string" @@ -240,9 +242,7 @@ export class CursorLanguageModel implements LanguageModelV3 { : classification.kind === "continuation-multi" ? `resume-multi:${multiNewUserCount}` : `fresh:${classification.kind}`; - console.error( - `[cursor:debug] turn classification=${label} session=${sessionID}`, - ); + pluginLog("debug", "turn classification", { label, session: sessionID }); } } @@ -448,8 +448,9 @@ export class CursorLanguageModel implements LanguageModelV3 { !options.abortSignal?.aborted ) { if (process.env["OPENCODE_CURSOR_DEBUG"] === "1") { - console.error( - "[cursor:debug] resumed turn failed before emitting; retrying with a fresh agent", + pluginLog( + "debug", + "resumed turn failed before emitting; retrying with a fresh agent", ); } acquired.release(); @@ -468,10 +469,9 @@ export class CursorLanguageModel implements LanguageModelV3 { // Non-Error throw or pre-existing cause: the original resume // failure can't ride along as `cause`, so log it instead of // dropping it silently. - console.error( - "[cursor:debug] original resume failure (not attachable as cause):", - err, - ); + pluginLog("debug", "original resume failure (not attachable as cause)", { + error: err instanceof Error ? err.message : String(err), + }); } throw retryErr; } diff --git a/src/provider/log-bridge.ts b/src/provider/log-bridge.ts new file mode 100644 index 0000000..be517ba --- /dev/null +++ b/src/provider/log-bridge.ts @@ -0,0 +1,81 @@ +import type { OpencodeClient } from "@opencode-ai/sdk"; + +export type LogLevel = "debug" | "info" | "warn" | "error"; + +export interface LogBridge { + client: OpencodeClient; + /** Workspace directory forwarded on each log call. */ + directory?: string; +} + +const BRIDGE_KEY = Symbol.for("@stablekernel/opencode-cursor:log-bridge"); + +type BridgeHolder = { [BRIDGE_KEY]?: LogBridge }; + +/** Publish the opencode client + directory for the provider to log through. */ +export function setLogBridge(bridge: LogBridge): void { + (globalThis as BridgeHolder)[BRIDGE_KEY] = bridge; +} + +/** Drop the bridge (plugin dispose). */ +export function clearLogBridge(): void { + delete (globalThis as BridgeHolder)[BRIDGE_KEY]; +} + +/** Read the current bridge, or `undefined` when the plugin hasn't published one. */ +export function getLogBridge(): LogBridge | undefined { + return (globalThis as BridgeHolder)[BRIDGE_KEY]; +} + +const SERVICE = "opencode-cursor"; + +/** + * Structured log emission for the provider layer, which has no direct access + * to the opencode client. Routes through `client.app.log()` (see + * `plugins.mdx`) when the plugin has published a bridge via + * {@link setLogBridge}; otherwise falls back to `console.*` so the provider + * still surfaces diagnostics when used standalone (tests, scripts, or the + * provider package without the plugin). + * + * Best-effort: a failed `app.log` call (e.g. server unavailable) is swallowed + * rather than thrown, matching every other fire-and-forget client call in + * this plugin. + */ +export function pluginLog( + level: LogLevel, + message: string, + extra?: Record, +): void { + const bridge = getLogBridge(); + if (bridge) { + void bridge.client.app + .log({ + body: { + service: SERVICE, + level, + message, + ...(extra ? { extra } : {}), + }, + ...(bridge.directory ? { query: { directory: bridge.directory } } : {}), + }) + .catch(() => {}); + return; + } + const line = extra + ? `[${SERVICE}] ${message} ${JSON.stringify(extra)}` + : `[${SERVICE}] ${message}`; + switch (level) { + case "debug": + console.debug(line); + break; + case "info": + console.info(line); + break; + case "warn": + console.warn(line); + break; + case "error": + console.error(line); + break; + } +} diff --git a/src/provider/sidecar-client.ts b/src/provider/sidecar-client.ts index 2a4687a..7316721 100644 --- a/src/provider/sidecar-client.ts +++ b/src/provider/sidecar-client.ts @@ -39,6 +39,13 @@ export interface SidecarClientOptions { env?: Record; /** Mirror child stderr to this process (debug aid). */ debug?: boolean; + /** + * Structured log lines the child recognized on the SDK's stdout (currently + * Cursor's rules/skills load-completion diagnostics; see + * src/sidecar/agent-host.mjs) and forwarded over the protocol instead of + * discarding as non-JSON noise. + */ + onLog?: (level: "debug" | "info" | "warn" | "error", message: string, meta?: Record) => void; } interface Pending { @@ -149,6 +156,19 @@ export class SidecarClient { } catch { return; // ignore non-protocol noise on stdout } + if (msg["ev"] === "log") { + const level = msg["level"]; + const message = msg["message"]; + if (typeof level === "string" && typeof message === "string") { + this.options.onLog?.( + level as "debug" | "info" | "warn" | "error", + message, + msg["meta"] as Record | undefined, + ); + } + return; + } + const id = msg["id"]; if (typeof id !== "number") return; const pending = this.pending.get(id); diff --git a/src/sidecar/agent-host.mjs b/src/sidecar/agent-host.mjs index a2ddcb9..43edf8a 100644 --- a/src/sidecar/agent-host.mjs +++ b/src/sidecar/agent-host.mjs @@ -38,6 +38,49 @@ function write(payload) { process.stdout.write(`${JSON.stringify(payload)}\n`); } +// eslint-disable-next-line no-control-regex +const ANSI_PATTERN = /\x1b\[[0-9;]*m/g; + +// `@cursor/sdk`'s bundled local-exec runtime writes its rules/skills +// load-completion diagnostics straight to `console.log` (no public logger +// hook exists to redirect it — see src/provider/cursor-log-intercept.ts, +// which applies the identical pattern for the in-process transport). This +// process's own JSONL protocol never uses console.log (only +// process.stdout.write via write() above), so console.log here is entirely +// free for the SDK's use: recognized lines are forwarded to the parent as a +// structured "log" event instead of being written as raw, unparseable text. +const RULE_LOAD_PATTERN = + /^\d{2}:\d{2}:\d{2}\.\d{3}\s+INFO\s+(LocalCursorRulesService|AgentSkillsCursorRulesService|CursorPluginsAgentSkillsService) load completed(?:\s+ctx=\S+)?\s+meta=\{([^}]*)\}\s*$/; + +function parseLogMeta(raw) { + const out = {}; + for (const part of raw.split(",")) { + const [key, value] = part.split(":").map((s) => s.trim()); + if (!key || value === undefined) continue; + const num = Number(value); + if (Number.isFinite(num)) out[key] = num; + } + return out; +} + +const originalConsoleLog = console.log.bind(console); +console.log = (...args) => { + if (args.length === 1 && typeof args[0] === "string") { + const match = RULE_LOAD_PATTERN.exec(args[0].replace(ANSI_PATTERN, "")); + if (match) { + const [, service, meta] = match; + write({ + ev: "log", + level: "info", + message: `${service} load completed`, + meta: parseLogMeta(meta ?? ""), + }); + return; + } + } + originalConsoleLog(...args); +}; + let sdkPromise; function loadSdk() { // OPENCODE_CURSOR_SDK_PATH lets tests substitute a fake SDK module. diff --git a/test/cursor-log-intercept.test.ts b/test/cursor-log-intercept.test.ts new file mode 100644 index 0000000..96098fb --- /dev/null +++ b/test/cursor-log-intercept.test.ts @@ -0,0 +1,104 @@ +import { afterEach, describe, expect, it, vi } from "vitest"; +import { + installCursorLogInterceptor, + parseCursorRuleLoadLine, + resetCursorLogInterceptor, +} from "../src/provider/cursor-log-intercept.js"; +import { clearLogBridge, setLogBridge } from "../src/provider/log-bridge.js"; + +afterEach(() => { + resetCursorLogInterceptor(); + clearLogBridge(); +}); + +describe("parseCursorRuleLoadLine", () => { + it("parses LocalCursorRulesService with a two-field meta", () => { + const parsed = parseCursorRuleLoadLine( + "16:05:53.036 INFO LocalCursorRulesService load completed meta={durationMs: 89, ruleCount: 1}", + ); + expect(parsed).toEqual({ + service: "LocalCursorRulesService", + meta: { durationMs: 89, ruleCount: 1 }, + }); + }); + + it("parses AgentSkillsCursorRulesService with a three-field meta", () => { + const parsed = parseCursorRuleLoadLine( + "16:05:53.036 INFO AgentSkillsCursorRulesService load completed meta={durationMs: 86, ruleCount: 18, skillCount: 18}", + ); + expect(parsed).toEqual({ + service: "AgentSkillsCursorRulesService", + meta: { durationMs: 86, ruleCount: 18, skillCount: 18 }, + }); + }); + + it("parses CursorPluginsAgentSkillsService", () => { + const parsed = parseCursorRuleLoadLine( + "16:05:53.036 INFO CursorPluginsAgentSkillsService load completed meta={durationMs: 12, ruleCount: 2, skillCount: 0}", + ); + expect(parsed?.service).toBe("CursorPluginsAgentSkillsService"); + }); + + it("strips ANSI color codes before matching", () => { + const parsed = parseCursorRuleLoadLine( + "\x1b[2m16:05:53.036\x1b[0m \x1b[34mINFO \x1b[0m LocalCursorRulesService load completed \x1b[2mmeta=\x1b[0m{durationMs: 5, ruleCount: 0}", + ); + expect(parsed).toEqual({ + service: "LocalCursorRulesService", + meta: { durationMs: 5, ruleCount: 0 }, + }); + }); + + it("returns undefined for unrelated log lines", () => { + expect(parseCursorRuleLoadLine("some unrelated cursor sdk output")).toBeUndefined(); + expect(parseCursorRuleLoadLine("Plugins reload completed: 3 plugins loaded")).toBeUndefined(); + }); +}); + +describe("installCursorLogInterceptor", () => { + it("routes recognized lines through pluginLog and passes everything else to the original console.log", () => { + const log = vi.fn().mockResolvedValue(undefined); + setLogBridge({ client: { app: { log } } as never }); + + const passthrough = vi.spyOn(console, "log").mockImplementation(() => {}); + installCursorLogInterceptor(); + + console.log( + "16:05:53.036 INFO LocalCursorRulesService load completed meta={durationMs: 89, ruleCount: 1}", + ); + console.log("totally unrelated output", 42); + + expect(log).toHaveBeenCalledTimes(1); + expect(log).toHaveBeenCalledWith({ + body: { + service: "opencode-cursor", + level: "info", + message: "LocalCursorRulesService load completed", + extra: { durationMs: 89, ruleCount: 1 }, + }, + }); + + resetCursorLogInterceptor(); + // The spy is the pre-interceptor console.log; passthrough calls must + // reach it, but the recognized line must not. + expect(passthrough).toHaveBeenCalledTimes(1); + expect(passthrough).toHaveBeenCalledWith("totally unrelated output", 42); + passthrough.mockRestore(); + }); + + it("is idempotent across repeated installs", () => { + installCursorLogInterceptor(); + const first = console.log; + installCursorLogInterceptor(); + expect(console.log).toBe(first); + }); + + it("restores the original console.log on reset", () => { + const passthrough = vi.spyOn(console, "log").mockImplementation(() => {}); + installCursorLogInterceptor(); + resetCursorLogInterceptor(); + console.log("plain line after reset"); + expect(passthrough).toHaveBeenCalledWith("plain line after reset"); + passthrough.mockRestore(); + }); +}); diff --git a/test/fixtures/fake-cursor-sdk.mjs b/test/fixtures/fake-cursor-sdk.mjs index e5e9665..a20a18c 100644 --- a/test/fixtures/fake-cursor-sdk.mjs +++ b/test/fixtures/fake-cursor-sdk.mjs @@ -8,9 +8,24 @@ * "rich" -> send() rejects with an error carrying status/code/isRetryable/helpUrl * "hang" -> run.wait() never resolves (until cancel(), which resolves cancelled) * other -> emits one text-delta "echo:" update, wait() -> done: + * + * `options.emitRulesLog` -> Agent.create/resume writes the same rules/skills + * "load completed" lines the real @cursor/sdk writes to console.log (see + * src/sidecar/agent-host.mjs / src/provider/cursor-log-intercept.ts), plus + * one unrelated console.log line, to verify the sidecar's log interception + * forwards only the recognized lines and passes everything else through. */ function makeAgent(agentId, options) { + if (options?.emitRulesLog) { + console.log( + "16:05:53.036 INFO LocalCursorRulesService load completed meta={durationMs: 89, ruleCount: 1}", + ); + console.log( + "16:05:53.036 INFO AgentSkillsCursorRulesService load completed meta={durationMs: 86, ruleCount: 18, skillCount: 18}", + ); + console.log("some unrelated cursor sdk output"); + } return { agentId, model: options?.model, diff --git a/test/log-bridge.test.ts b/test/log-bridge.test.ts new file mode 100644 index 0000000..6a5098e --- /dev/null +++ b/test/log-bridge.test.ts @@ -0,0 +1,73 @@ +import { afterEach, describe, expect, it, vi } from "vitest"; +import { + clearLogBridge, + getLogBridge, + pluginLog, + setLogBridge, +} from "../src/provider/log-bridge.js"; + +afterEach(() => { + clearLogBridge(); +}); + +describe("log bridge", () => { + it("has no bridge until published", () => { + expect(getLogBridge()).toBeUndefined(); + }); + + it("stores and clears the published bridge", () => { + const client = { app: { log: vi.fn() } } as never; + setLogBridge({ client, directory: "/work" }); + expect(getLogBridge()).toMatchObject({ directory: "/work" }); + clearLogBridge(); + expect(getLogBridge()).toBeUndefined(); + }); +}); + +describe("pluginLog", () => { + it("routes through client.app.log with service/level/message/extra when a bridge is published", () => { + const log = vi.fn().mockResolvedValue(undefined); + setLogBridge({ client: { app: { log } } as never, directory: "/work" }); + + pluginLog("warn", "something degraded", { reason: "no sidecar" }); + + expect(log).toHaveBeenCalledWith({ + body: { + service: "opencode-cursor", + level: "warn", + message: "something degraded", + extra: { reason: "no sidecar" }, + }, + query: { directory: "/work" }, + }); + }); + + it("omits extra and query.directory when not provided", () => { + const log = vi.fn().mockResolvedValue(undefined); + setLogBridge({ client: { app: { log } } as never }); + + pluginLog("info", "no extras here"); + + expect(log).toHaveBeenCalledWith({ + body: { service: "opencode-cursor", level: "info", message: "no extras here" }, + }); + }); + + it("swallows a rejected app.log call instead of throwing", async () => { + const log = vi.fn().mockRejectedValue(new Error("network down")); + setLogBridge({ client: { app: { log } } as never }); + + expect(() => pluginLog("error", "boom")).not.toThrow(); + // Let the fire-and-forget promise settle before the test ends. + await Promise.resolve(); + }); + + it("falls back to console.* when no bridge is published", () => { + const spy = vi.spyOn(console, "warn").mockImplementation(() => {}); + pluginLog("warn", "standalone warning", { foo: "bar" }); + expect(spy).toHaveBeenCalledWith( + expect.stringContaining("[opencode-cursor] standalone warning"), + ); + spy.mockRestore(); + }); +}); diff --git a/test/sidecar.test.ts b/test/sidecar.test.ts index eebeb6e..a238778 100644 --- a/test/sidecar.test.ts +++ b/test/sidecar.test.ts @@ -7,10 +7,13 @@ const FAKE_SDK = fileURLToPath(new URL("./fixtures/fake-cursor-sdk.mjs", import. const clients: SidecarClient[] = []; -function makeClient(): SidecarClient { +function makeClient( + onLog?: (level: "debug" | "info" | "warn" | "error", message: string, meta?: Record) => void, +): SidecarClient { const client = new SidecarClient({ scriptPath: SCRIPT, env: { OPENCODE_CURSOR_SDK_PATH: FAKE_SDK }, + ...(onLog ? { onLog } : {}), }); clients.push(client); return client; @@ -103,6 +106,27 @@ describe("SidecarClient", () => { await expect(run.wait()).resolves.toMatchObject({ status: "cancelled" }); }); + it("forwards recognized Cursor rules/skills log lines via onLog, and drops everything else", async () => { + const logs: Array<{ level: string; message: string; meta?: Record }> = []; + const client = makeClient((level, message, meta) => { + logs.push({ level, message, meta }); + }); + await client.createAgent({ ...CREATE_OPTIONS, emitRulesLog: true }); + + expect(logs).toEqual([ + { + level: "info", + message: "LocalCursorRulesService load completed", + meta: { durationMs: 89, ruleCount: 1 }, + }, + { + level: "info", + message: "AgentSkillsCursorRulesService load completed", + meta: { durationMs: 86, ruleCount: 18, skillCount: 18 }, + }, + ]); + }); + it("rejects in-flight requests when the client is disposed", async () => { const client = makeClient(); const agent = await client.createAgent(CREATE_OPTIONS);