Skip to content

Commit 2299bbf

Browse files
authored
feat: structured logging for provider diagnostics + Cursor SDK rules/skills logs (#85)
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.
1 parent 5c65825 commit 2299bbf

13 files changed

Lines changed: 524 additions & 32 deletions

‎CHANGELOG.md‎

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,23 @@ All notable changes to this project will be documented in this file.
44

55
## [Unreleased]
66

7+
- **Structured logging via `client.app.log()` instead of raw `console.*`.** The
8+
plugin's own diagnostics (transport fallback warnings, per-turn debug traces
9+
gated on `OPENCODE_CURSOR_DEBUG=1`) now route through opencode's plugin
10+
logging API (`service: "opencode-cursor"`) rather than `console.warn`/
11+
`console.error`. Falls back to `console.*` when no client is available
12+
(e.g. running the provider standalone).
13+
- **Cursor SDK's own "rules"/"skills" load diagnostics captured and forwarded.**
14+
`@cursor/sdk`'s bundled local-exec runtime writes internal messages like
15+
`LocalCursorRulesService load completed meta={durationMs, ruleCount}` and
16+
`AgentSkillsCursorRulesService load completed meta={durationMs, ruleCount,
17+
skillCount}` straight to `console.log`, with no public logger hook to
18+
redirect it. These are now recognized (in-process transport via a narrowly
19+
scoped `console.log` interceptor; sidecar transport via the child process's
20+
own interceptor forwarding over the existing JSONL protocol) and re-emitted
21+
as structured opencode logs instead of raw terminal noise. Every other
22+
`console.log` call passes through unchanged.
23+
724
## [0.6.2] — 2026-07-28
825

926
Version-check UX cleanup from #79.

‎src/plugin/index.ts‎

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@ import {
1515
import { buildCursorTools } from "./cursor-tools.js";
1616
import { getLocalVersion, getLatestVersion, clearVersionCache, PLUGIN_CACHE_PATH } from "../version-check.js";
1717
import { removeSystemRule } from "../provider/system-rule.js";
18+
import { clearLogBridge, setLogBridge } from "../provider/log-bridge.js";
1819
import {
1920
clearSubagentBridge,
2021
setSubagentBridge,
@@ -103,7 +104,10 @@ export const CursorPlugin: Plugin = async (input) => {
103104
// create a real child session for each Cursor subagent (making its `task`
104105
// card clickable / `ctrl+x`-navigable). Same-process handoff via a globalThis
105106
// registry; the provider degrades gracefully when it's absent.
106-
if (client) setSubagentBridge({ client, directory });
107+
if (client) {
108+
setSubagentBridge({ client, directory });
109+
setLogBridge({ client, directory });
110+
}
107111
// Canonical working directory for the generated system-prompt rule: the
108112
// provider writes `.cursor/rules/opencode.mdc` under this path and dispose
109113
// cleans it up from the same path. The config hook threads it into the
@@ -390,6 +394,7 @@ export const CursorPlugin: Plugin = async (input) => {
390394
// so a user-owned opencode.mdc is never deleted.
391395
removeSystemRule(resolvedCwd);
392396
clearSubagentBridge();
397+
clearLogBridge();
393398
},
394399
};
395400
};

‎src/provider/agent-backend.ts‎

Lines changed: 19 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,8 @@ import { execSync } from "node:child_process";
1818
import { existsSync } from "node:fs";
1919
import { fileURLToPath } from "node:url";
2020
import { loadCursorSdk } from "../cursor-runtime.js";
21+
import { installCursorLogInterceptor } from "./cursor-log-intercept.js";
22+
import { pluginLog } from "./log-bridge.js";
2123
import { SidecarClient, type AgentLike } from "./sidecar-client.js";
2224

2325
export type { AgentLike, AgentRunLike, AgentSendOptions } from "./sidecar-client.js";
@@ -109,6 +111,11 @@ async function ensureHttp1Configured(): Promise<void> {
109111
}
110112

111113
function inProcessBackend(useHttp1: boolean): AgentBackend {
114+
// The SDK runs in this process and writes its own diagnostics straight to
115+
// the shared global `console` (see cursor-log-intercept.ts); install once
116+
// so its rules/skills load-completion logs route through opencode logging
117+
// instead of appearing as raw stdout noise.
118+
installCursorLogInterceptor();
112119
return {
113120
kind: "in-process",
114121
createAgent: async (options) => {
@@ -143,7 +150,11 @@ export function resolveSidecarScript(): string | undefined {
143150
}
144151

145152
function sidecarBackend(nodePath: string, scriptPath: string): AgentBackend {
146-
const client = new SidecarClient({ scriptPath, nodePath });
153+
const client = new SidecarClient({
154+
scriptPath,
155+
nodePath,
156+
onLog: (level, message, meta) => pluginLog(level, message, meta),
157+
});
147158
return {
148159
kind: "sidecar",
149160
createAgent: (options) => client.createAgent(options),
@@ -161,18 +172,18 @@ export function loadAgentBackend(): AgentBackend {
161172
const scriptPath = transport === "sidecar" ? resolveSidecarScript() : undefined;
162173
if (transport === "sidecar" && (!env.nodePath || !scriptPath)) {
163174
// Explicit sidecar request we can't satisfy: fall back loudly.
164-
console.error(
165-
"[opencode-cursor] Node sidecar requested but unavailable " +
166-
`(node: ${env.nodePath ?? "not found"}, script: ${scriptPath ?? "not found"}); ` +
167-
"falling back to in-process HTTP/1.1 transport.",
175+
pluginLog(
176+
"warn",
177+
"Node sidecar requested but unavailable; falling back to in-process HTTP/1.1 transport.",
178+
{ node: env.nodePath ?? null, script: scriptPath ?? null },
168179
);
169180
cached = inProcessBackend(true);
170181
return cached;
171182
}
172183
if (transport === "http2-direct" && env.isBun) {
173-
console.error(
174-
"[opencode-cursor] http2-direct under Bun: Cursor streams may fail " +
175-
"(Bun node:http2 incompatibility, oven-sh/bun#31499). " +
184+
pluginLog(
185+
"warn",
186+
"http2-direct under Bun: Cursor streams may fail (Bun node:http2 incompatibility, oven-sh/bun#31499). " +
176187
"Set OPENCODE_CURSOR_TRANSPORT=http1 (recommended) or sidecar.",
177188
);
178189
}

‎src/provider/agent-events.ts‎

Lines changed: 16 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
import type { AgentModeOption, SDKUserMessage } from "@cursor/sdk";
22
import type { AgentLike, AgentRunLike, AgentSendOptions } from "./agent-backend.js";
33
import { classifyError } from "./error-classify.js";
4+
import { pluginLog } from "./log-bridge.js";
45

56
/** Token usage as reported by Cursor's `turn-ended` update. */
67
export interface CursorUsage {
@@ -202,9 +203,11 @@ export async function* streamAgentTurn(
202203
if (options.abortSignal?.aborted) void Promise.resolve(run.cancel()).catch(() => {});
203204
const result = await run.wait();
204205
if (debug) {
205-
console.error(
206-
`[cursor:debug] updates=${JSON.stringify(counts)} status=${result.status} resultLen=${(result.result ?? "").length}`,
207-
);
206+
pluginLog("debug", "turn finished", {
207+
updates: counts,
208+
status: result.status,
209+
resultLen: (result.result ?? "").length,
210+
});
208211
}
209212
// Superseded by a watchdog force-resend: this run is abandoned.
210213
if (gen !== runGen || finished) return;
@@ -221,7 +224,11 @@ export async function* streamAgentTurn(
221224
.catch((err) => {
222225
if (gen !== runGen) return;
223226
failure = err;
224-
if (debug) console.error(`[cursor:debug] send failed: ${err instanceof Error ? err.message : String(err)}`);
227+
if (debug) {
228+
pluginLog("debug", "send failed", {
229+
error: err instanceof Error ? err.message : String(err),
230+
});
231+
}
225232
})
226233
.finally(() => {
227234
// Only the live run finishes the stream; a superseded (cancelled-for-
@@ -265,7 +272,7 @@ export async function* streamAgentTurn(
265272
return;
266273
}
267274
forced = true;
268-
if (debug) console.error("[cursor:debug] stream stalled; cancelling and resending with local.force");
275+
if (debug) pluginLog("debug", "stream stalled; cancelling and resending with local.force");
269276
try {
270277
await runHolder.run?.cancel();
271278
} catch {
@@ -324,17 +331,17 @@ export async function sendWithRecovery(
324331
} catch (err) {
325332
const classified = classifyError(err);
326333
if (classified.kind === "agent-busy") {
327-
if (debug) console.error("[cursor:debug] agent busy; retrying send with local.force");
334+
if (debug) pluginLog("debug", "agent busy; retrying send with local.force");
328335
return agent.send(message, { ...sendOptions, local: { force: true } });
329336
}
330337
if (
331338
(classified.kind === "rate-limit" || classified.kind === "network") &&
332339
attempt < RETRY_BACKOFF_MS.length
333340
) {
334341
if (debug)
335-
console.error(
336-
`[cursor:debug] ${classified.kind}; retrying send in ${RETRY_BACKOFF_MS[attempt]}ms`,
337-
);
342+
pluginLog("debug", `${classified.kind}; retrying send`, {
343+
delayMs: RETRY_BACKOFF_MS[attempt],
344+
});
338345
await sleep(RETRY_BACKOFF_MS[attempt]!);
339346
continue;
340347
}
Lines changed: 92 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,92 @@
1+
import { pluginLog } from "./log-bridge.js";
2+
3+
// eslint-disable-next-line no-control-regex
4+
const ANSI_PATTERN = /\x1b\[[0-9;]*m/g;
5+
6+
function stripAnsi(input: string): string {
7+
return input.replace(ANSI_PATTERN, "");
8+
}
9+
10+
/**
11+
* `@cursor/sdk`'s bundled local-exec runtime formats its "rules"/"skills"
12+
* loading diagnostics (context logger `local-exec:cursor-rules`) into one
13+
* preformatted string and writes it straight to `console.log` — there is no
14+
* public logger hook to redirect it instead. Observed shapes (colors
15+
* stripped):
16+
*
17+
* 16:05:53.036 INFO LocalCursorRulesService load completed meta={durationMs: 89, ruleCount: 1}
18+
* 16:05:53.036 INFO AgentSkillsCursorRulesService load completed meta={durationMs: 86, ruleCount: 18, skillCount: 18}
19+
* 16:05:53.036 INFO CursorPluginsAgentSkillsService load completed meta={durationMs: 12, ruleCount: 2, skillCount: 0}
20+
*
21+
* The context path (`ctx=...`) is only present in some builds/configs.
22+
*/
23+
const RULE_LOAD_PATTERN =
24+
/^\d{2}:\d{2}:\d{2}\.\d{3}\s+INFO\s+(LocalCursorRulesService|AgentSkillsCursorRulesService|CursorPluginsAgentSkillsService) load completed(?:\s+ctx=\S+)?\s+meta=\{([^}]*)\}\s*$/;
25+
26+
/** Parses the `meta={key: value, ...}` tail into a plain numeric object. */
27+
export function parseCursorLogMeta(raw: string): Record<string, number> {
28+
const out: Record<string, number> = {};
29+
for (const part of raw.split(",")) {
30+
const [key, value] = part.split(":").map((s) => s.trim());
31+
if (!key || value === undefined) continue;
32+
const num = Number(value);
33+
if (Number.isFinite(num)) out[key] = num;
34+
}
35+
return out;
36+
}
37+
38+
export interface ParsedCursorRuleLog {
39+
service: string;
40+
meta: Record<string, number>;
41+
}
42+
43+
/** Matches one line against the known Cursor rules/skills load-completion shape. */
44+
export function parseCursorRuleLoadLine(line: string): ParsedCursorRuleLog | undefined {
45+
const match = RULE_LOAD_PATTERN.exec(stripAnsi(line));
46+
if (!match) return undefined;
47+
const [, service, meta] = match;
48+
if (!service) return undefined;
49+
return { service, meta: parseCursorLogMeta(meta ?? "") };
50+
}
51+
52+
let installed = false;
53+
let original: typeof console.log | undefined;
54+
55+
/**
56+
* Installs a narrowly-scoped `console.log` interceptor that recognizes only
57+
* the known Cursor rules/skills "load completed" messages (see
58+
* {@link parseCursorRuleLoadLine}) and re-emits them as structured opencode
59+
* logs via {@link pluginLog}. Every other `console.log` call — including
60+
* anything else the SDK or the host process writes — passes through
61+
* unchanged.
62+
*
63+
* Only relevant to the in-process transport, where the SDK runs inside this
64+
* process and writes directly to the shared global `console`. The sidecar
65+
* transport intercepts the same messages in the child process instead (see
66+
* `src/sidecar/agent-host.mjs`) and forwards them over the JSONL protocol.
67+
*
68+
* Idempotent: safe to call on every agent creation.
69+
*/
70+
export function installCursorLogInterceptor(): void {
71+
if (installed) return;
72+
original = console.log.bind(console);
73+
const passthrough = original;
74+
console.log = (...args: unknown[]) => {
75+
if (args.length === 1 && typeof args[0] === "string") {
76+
const parsed = parseCursorRuleLoadLine(args[0]);
77+
if (parsed) {
78+
pluginLog("info", `${parsed.service} load completed`, parsed.meta);
79+
return;
80+
}
81+
}
82+
passthrough(...(args as Parameters<typeof console.log>));
83+
};
84+
installed = true;
85+
}
86+
87+
/** Test hook. */
88+
export function resetCursorLogInterceptor(): void {
89+
if (original) console.log = original;
90+
original = undefined;
91+
installed = false;
92+
}

‎src/provider/language-model.ts‎

Lines changed: 13 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@ import {
2323
} from "./message-map.js";
2424
import { extractSystemText, resolveSystemDelivery } from "./system-rule.js";
2525
import { classifyError } from "./error-classify.js";
26+
import { pluginLog } from "./log-bridge.js";
2627
import {
2728
addUsage,
2829
sendAgentTurnSilently,
@@ -126,7 +127,7 @@ export class CursorLanguageModel implements LanguageModelV3 {
126127
private warnOnce(message: string): void {
127128
if (this.warned.has(message)) return;
128129
this.warned.add(message);
129-
console.warn(`[${this.provider}] ${message}`);
130+
pluginLog("warn", message, { provider: this.provider });
130131
}
131132

132133
private requireApiKey(): string {
@@ -159,9 +160,10 @@ export class CursorLanguageModel implements LanguageModelV3 {
159160
providerOptions,
160161
);
161162
if (process.env["OPENCODE_CURSOR_DEBUG"] === "1") {
162-
console.error(
163-
`[cursor:debug] model=${this.modelId} selection=${JSON.stringify(modelSelection)}`,
164-
);
163+
pluginLog("debug", "model call", {
164+
model: this.modelId,
165+
selection: modelSelection,
166+
});
165167
}
166168
const sessionID =
167169
typeof providerOptions?.["sessionID"] === "string"
@@ -240,9 +242,7 @@ export class CursorLanguageModel implements LanguageModelV3 {
240242
: classification.kind === "continuation-multi"
241243
? `resume-multi:${multiNewUserCount}`
242244
: `fresh:${classification.kind}`;
243-
console.error(
244-
`[cursor:debug] turn classification=${label} session=${sessionID}`,
245-
);
245+
pluginLog("debug", "turn classification", { label, session: sessionID });
246246
}
247247
}
248248

@@ -448,8 +448,9 @@ export class CursorLanguageModel implements LanguageModelV3 {
448448
!options.abortSignal?.aborted
449449
) {
450450
if (process.env["OPENCODE_CURSOR_DEBUG"] === "1") {
451-
console.error(
452-
"[cursor:debug] resumed turn failed before emitting; retrying with a fresh agent",
451+
pluginLog(
452+
"debug",
453+
"resumed turn failed before emitting; retrying with a fresh agent",
453454
);
454455
}
455456
acquired.release();
@@ -468,10 +469,9 @@ export class CursorLanguageModel implements LanguageModelV3 {
468469
// Non-Error throw or pre-existing cause: the original resume
469470
// failure can't ride along as `cause`, so log it instead of
470471
// dropping it silently.
471-
console.error(
472-
"[cursor:debug] original resume failure (not attachable as cause):",
473-
err,
474-
);
472+
pluginLog("debug", "original resume failure (not attachable as cause)", {
473+
error: err instanceof Error ? err.message : String(err),
474+
});
475475
}
476476
throw retryErr;
477477
}

0 commit comments

Comments
 (0)