From d77ff3c7137be31be1a62d123c0a0b4442c8ce6e Mon Sep 17 00:00:00 2001 From: IanYet Date: Sat, 24 Oct 2026 21:12:10 +0800 Subject: [PATCH] fix: release bounded MCP collection improvements without Doctor --- claude/.claude-plugin/plugin.json | 4 +- .../chatcut-plugin-basics-claude/SKILL.md | 2 + .../references/connection-diagnostics.md | 35 +++ .../scripts/mcp-doctor.mjs | 207 ++++++++++++++++-- .../scripts/mcp-evidence.mjs | 20 ++ codex/.codex-plugin/plugin.json | 2 +- codex/.mcp.json | 2 +- codex/skills/chatcut-plugin-basics/SKILL.md | 2 + .../references/connection-diagnostics.md | 35 +++ .../scripts/mcp-doctor.mjs | 207 ++++++++++++++++-- .../scripts/mcp-evidence.mjs | 20 ++ docs/mcp-doctor.md | 12 + tests/collection-quality.test.mjs | 109 +++++++++ tests/fixtures/owned-codex-mcp-tool-error.log | 1 + tests/mcp-doctor.test.mjs | 14 +- tests/native-failure-index.test.mjs | 146 ++++++++++++ tests/real-native-log.test.mjs | 56 +++++ tests/windows-db-fallback.test.mjs | 86 ++++++++ 18 files changed, 909 insertions(+), 51 deletions(-) create mode 100644 tests/collection-quality.test.mjs create mode 100644 tests/fixtures/owned-codex-mcp-tool-error.log create mode 100644 tests/native-failure-index.test.mjs create mode 100644 tests/real-native-log.test.mjs create mode 100644 tests/windows-db-fallback.test.mjs diff --git a/claude/.claude-plugin/plugin.json b/claude/.claude-plugin/plugin.json index 395d78e..5a33e65 100644 --- a/claude/.claude-plugin/plugin.json +++ b/claude/.claude-plugin/plugin.json @@ -1,7 +1,7 @@ { "name": "chatcut", "displayName": "ChatCut", - "version": "1.10.23", + "version": "1.10.25", "description": "ChatCut plugin for editable video editing and creation workflows from Claude Code.", "author": { "name": "ChatCut", @@ -37,7 +37,7 @@ "headers": { "x-chatcut-mcp-client": "claude_code", "x-chatcut-mcp-surface": "embedded-preview", - "x-chatcut-plugin-version": "1.10.23" + "x-chatcut-plugin-version": "1.10.25" } } }, diff --git a/claude/skills/chatcut-plugin-basics-claude/SKILL.md b/claude/skills/chatcut-plugin-basics-claude/SKILL.md index 89fa6ff..a8b6563 100644 --- a/claude/skills/chatcut-plugin-basics-claude/SKILL.md +++ b/claude/skills/chatcut-plugin-basics-claude/SKILL.md @@ -32,6 +32,8 @@ Also use connection diagnostics when previously available tools disappear or the For a failed hosted ChatCut tool request after connection, immediately preserve the original tool error and any available failure time, conversation ID and local call ID in the dedicated failure record described there. The Agent gathers these facts; do not ask the user to manually reconstruct them. Startup-status notices and later successful checks do not establish what happened to that tool request. +Save the visible error before reading runtime databases, including unfamiliar error messages and cause. A failed Windows database read does not invalidate that error or prevent local collection with `--offline`. Keep independent bounded App evidence separate and check `evidenceSummary.hostLogCoverage` for retained and missing sources. Do not require prior stderr setup, database export or permission changes. A startup error hidden from the Agent still needs an accessible source. + 1. **Server not registered:** Offer to register the Hosted MCP server directly at user scope. Do not install, reinstall, repair, or enable a plugin to obtain the server: ```sh diff --git a/claude/skills/chatcut-plugin-basics-claude/references/connection-diagnostics.md b/claude/skills/chatcut-plugin-basics-claude/references/connection-diagnostics.md index c133f82..fe82f27 100644 --- a/claude/skills/chatcut-plugin-basics-claude/references/connection-diagnostics.md +++ b/claude/skills/chatcut-plugin-basics-claude/references/connection-diagnostics.md @@ -106,6 +106,15 @@ Only include ChatCut tool names; keep tool arguments and results out. ### Preserve the failed call before independent checks +Database reads are supplementary. Save the currently visible error first, then +continue local collection with `--offline` even when SQLite is unavailable. +This option sends no probes or upload, including when `--upload` is also given. +`evidenceSummary.hostLogCoverage` distinguishes the retained original error, +database failures and remaining sources. Existing App logs remain independent. +An already visible tool error needs no prior stderr setup; an unexposed startup +error still needs an accessible source. Never copy a live database, parse its +WAL separately, ignore locks or widen permissions to make collection pass. + When the host exposes the original failed tool result or runtime event, the Agent copies only its error and available identifiers into a new dedicated `.mcp-failure.json`. Do this before retries, reconnects or later probes. @@ -147,6 +156,24 @@ Do not start another authenticated session to manufacture replacement evidence. If only the original error text is accessible, use the text-file fallback below. Do not call a report with only startup-status notices a captured tool failure. +Save actual error fields rather than reconstructing a raw tool-result envelope. +The collector records a valid Codex `CODEX_THREAD_ID` in `collectionContext` as +the current collecting thread. It does not fill the original failure's thread +automatically. When the failure just happened in this same chat, that known +thread may be supplied in its failure record with the source explained. Never +use the diagnostic command's `CODEX_TOOL_CALL_ID` as the failed MCP call's ID. + +With a known original/session thread, `hostLogs.nativeFailedCalls` selects at +most ten failed hosted ChatCut MCP items in the bounded window from the native +`thread_history_1.sqlite` index. Only IDs, lifecycle times and error fields are +projected; whole history items, conversations, arguments and successful results +are not collected. An error above 128 KiB is explicitly omitted; the complete +local report is never trimmed to fit the 256 KiB upload limit. `nativeItemId` +is a native MCP item identity, distinct from Responses call IDs, RPC IDs and +server request IDs. `startedAtMs`/`completedAtMs` are lifecycle times, not the +original `occurredAt`. Matches remain unconfirmed; compare known thread, tool +and exact error without promoting nearby times to proof of association. + 1. Obtain the existing server's registered URL through the host. Preserve its environment. The helper accepts ChatCut production/beta/dev endpoints and loopback development servers; it reports unsupported endpoints rather than @@ -184,10 +211,18 @@ Codex SQLite locations follow `CODEX_SQLITE_HOME` when present. If the current host already supplies its actual `sqlite_home` or `log_dir`, pass that directory with `--codex-sqlite-home` or `--codex-log-dir`; do not read whole config files to find it. These options select existing log locations and do not enable logging. +If the caller already retained a dedicated native stderr stream, pass its +existing `.codex-stderr.log` with `--codex-stderr-file`. The helper reads only +its bounded ChatCut log tail, marks emission time as `loggedAt`, and does not +fill original failure time or association. This source is optional; it does +not capture a stream or recover discarded stderr. On Windows, SQLite error 14 can coexist with readable WAL files in a read-only sandbox. The report preserves the original error and bounded file-access facts; it does not prove a specific security product caused the restriction. Never copy the whole log database, ignore its WAL with immutable mode, or relax permissions. +Both SQLite readers preserve the failing operation and error, then continue +other sources; a close failure does not replace the primary error. Missing +native IDs and lifecycle times remain missing when the database is unreadable. On Windows, the helper also reads the existing Codex App startup-status notices under `%LOCALAPPDATA%/Codex/Logs/YYYY/MM/DD`. This is independent of TUI logging. It selects only `AppServerConnection` startup notices for the hosted ChatCut diff --git a/claude/skills/chatcut-plugin-basics-claude/scripts/mcp-doctor.mjs b/claude/skills/chatcut-plugin-basics-claude/scripts/mcp-doctor.mjs index 513ba4a..bf76c45 100644 --- a/claude/skills/chatcut-plugin-basics-claude/scripts/mcp-doctor.mjs +++ b/claude/skills/chatcut-plugin-basics-claude/scripts/mcp-doctor.mjs @@ -24,8 +24,33 @@ function redactFieldValue(_match, prefix, value) { return prefix + (quote ? quote + "[REDACTED]" + quote : "[REDACTED]"); } -export function redact(text) { - return String(text) +export function redact(text, jsonDepth = 0) { + let value = String(text); + // A host may quote/stringify an entire JSON response inside its error. Decode + // only JSON string tokens containing this credential label, redact their full + // value, then restore the quoting. A partial escaped-field regex can leak the + // suffix after an escaped quote/backslash. Input collection is size bounded. + if (jsonDepth < 16) value = value.replace(/"(?:\\.|[^"\\\r\n])*"/g, (token) => { + try { + const decoded = JSON.parse(token); + if (/mcp[-_]session[-_]id/i.test(decoded)) { + const sanitized = redact(decoded, jsonDepth + 1); + if (sanitized !== decoded) return JSON.stringify(sanitized); + } + } catch { /* Non-JSON diagnostic text is retained for the normal rules. */ } + return token; + }); + return value + .replace(/\b(Mcp-Session-Id[ \t]*:[ \t]*)\S+/gi, "$1[REDACTED]") + .replace( + /(["']mcp[-_]session[-_]id["']\s*[:=]\s*)("(?:\\.|[^"\\\r\n])*"|'(?:\\.|[^'\\\r\n])*')/gi, + redactFieldValue, + ) + .replace( + /\b((?:mcp[-_]session[-_]id)\s*[:=]\s*)("(?:\\.|[^"\\\r\n])*"|'(?:\\.|[^'\\\r\n])*'|[^\s"'<>]+)/gi, + redactFieldValue, + ) + .replace(/((?:\\*["'])mcp[-_]session[-_]id(?:\\*["'])\s*[:=]\s*(?:\\*["']))[^"'\\\r\n]*/gi, "$1[REDACTED]") .replace( /\bBearer\s+(?!(?:token|required)\b|<|(?:realm|scope|error(?:_description|_uri)?|resource_metadata)\s*=)[A-Za-z0-9._~+/=-]+/gi, "Bearer [REDACTED]", @@ -55,7 +80,7 @@ export function redact(text) { function clean(value) { return JSON.parse( JSON.stringify(value, (key, item) => - /^(?:access_?token|refresh_?token|id_?token|client_?secret|session_?token|api[_-]?key|authorization|token|cookie|set-cookie)$/i.test( + /^(?:mcp[-_]session[-_]id|access_?token|refresh_?token|id_?token|client_?secret|session_?token|api[_-]?key|authorization|token|cookie|set-cookie)$/i.test( key, ) ? "[REDACTED]" @@ -253,7 +278,7 @@ export async function probeEntry(endpoint, diagnosticId, fetchImpl = fetch) { params: { protocolVersion: "2025-11-25", capabilities: {}, - clientInfo: { name: "chatcut-mcp-doctor", version: "1.2.3" }, + clientInfo: { name: "chatcut-mcp-doctor", version: "1.2.4" }, }, }), }); @@ -390,8 +415,11 @@ function runtimeContext(body) { return { ...(conversationId && { conversationId }), ...(callId && { callId }) }; } -function hostedTextRecord(line) { +function hostedTextRecord(line, nativeLevel) { if (/^\s/.test(line)) return false; + // Inspect explicit echo prefixes before stripping trace context: a payload + // itself can contain "}:" and must not become a diagnostic via lastIndex. + if (/(?:^|\}:\s*)(?:tool (?:call|result)\s*:|(?:function_call(?:_output)?|tool_call(?:_output)?)\s*:?\s*[{[])/i.test(line)) return false; let body = line.replace( /^\d{4}-\d{2}-\d{2}T\S+\s+(?:(?:\[(?:TRACE|DEBUG|INFO|WARN|ERROR)\]|TRACE|DEBUG|INFO|WARN|ERROR)\s+)?/i, "", @@ -399,7 +427,7 @@ function hostedTextRecord(line) { const module = body.match(/^([A-Za-z_]\w*(?:::\w+)+):\s*/); if (module) { if ( - !/^(?:codex_(?:mcp|rmcp_client|plugins|core(?:::|_)plugins)(?:::|$)|rmcp::)/.test(module[1]) + !/^(?:codex_(?:mcp|rmcp_client|plugins|core(?:::|_)plugins)(?:::|$)|rmcp::|codex_core::mcp_tool_call$)/.test(module[1]) ) return false; body = body.slice(module[0].length); @@ -417,9 +445,23 @@ function hostedTextRecord(line) { const server = context.match(/\bserver_name=["']?([\w:.-]+)/)?.[1] ?? scope?.[1] ?? scope?.[2] ?? scope?.[3]; if (server && !["chatcut", "plugin:chatcut:chatcut"].includes(server)) return false; - if (!CHATCUT_MESSAGE.test(body)) return false; - if (/\bmethod=["']?tools\/call(?:["'\s}]|$)/.test(context)) return false; - const message = scope ? body.slice(scope[0].length) : body; + const header = line.match(/^\d{4}-\d{2}-\d{2}T\S+\s+(?:\[(WARN|ERROR)\]|(WARN|ERROR))\s+/i); + const level = String(nativeLevel ?? header?.[1] ?? header?.[2]).toUpperCase(); + const nativeToolError = module?.[1] === "codex_core::mcp_tool_call" && + ["ERROR", "WARN"].includes(level) && + /^MCP tool call error:\s*["']?tool call error: tool call failed for `(?:chatcut|plugin:chatcut:chatcut)\/[A-Za-z0-9_.:-]+`/.test(body); + if (module?.[1] === "codex_core::mcp_tool_call" && !nativeToolError) return false; + if (!CHATCUT_MESSAGE.test(body) && !nativeToolError) return false; + if (/\bmethod=["']?tools\/call(?:["'\s}]|$)/.test(context)) { + // A trusted native ERROR/WARN can describe a failed tools/call without + // echoing its content. SQLite supplies its separate native level column. + if (!module || !["ERROR", "WARN"].includes(level)) return false; + // Inspect the unstripped body: a payload can itself contain "}:". + const contentCheck = body.replace(/\\+(?=["'])/g, ""); + if (/["'](?:params|arguments)["']\s*:\s*[{[]|["'](?:prompt|transcript)["']\s*:\s*["'{[]|["']result["']\s*:\s*\{[\s\S]*?["']content["']\s*:\s*\[|["']role["']\s*:\s*["'](?:user|assistant|system|developer)["']|["']type["']\s*:\s*["'](?:function_call(?:_output)?|tool_call(?:_output)?|tool_result|user(?:_message)?|assistant(?:_message)?)["']/i.test(contentCheck)) return false; + if (/(?:^|\}:\s*)(?:prompt|transcript)\s*:/i.test(body)) return false; + } + const message = scope ? body.slice(scope[0].length) : logMessage(body); // Runtime error contents can name tools; only explicit echo records are excluded. if (TEXT_ECHO.test(message)) return false; if ( @@ -507,7 +549,11 @@ async function textLog(path, source, gaps, window, select = hostedTextRecord) { !TEXT_ECHO.test(lines[i + 1].trimStart()) ) block.push(lines[++i]); + if (block.length > 1 && !select(block.join("\n"))) continue; const occurredAt = logTime(block[0]); + const context = runtimeContext(block[0]); + if (window.conversationId && context.conversationId && context.conversationId !== window.conversationId) + continue; if ( occurredAt && (Date.parse(occurredAt) < window.since * 1000 || @@ -520,7 +566,7 @@ async function textLog(path, source, gaps, window, select = hostedTextRecord) { occurredAt, timeStatus: occurredAt ? "within_requested_window" : "unknown; not_confirmed_within_window", message: redact(block.join("\n")), - ...runtimeContext(block[0]), + ...context, originalAttemptMatch: "unconfirmed", }); } @@ -679,11 +725,80 @@ async function inspectSqliteAccess(path) { }; } +async function nativeFailedMcpItems(sqliteRoot, conversationId, window, gaps) { + const source = "codex_native_failed_mcp_items"; + if (!conversationId) { + gaps.push({ source, reason: "known_conversation_id_unavailable; no_history_query" }); + return []; + } + let db; + const databasePath = join(sqliteRoot, "thread_history_1.sqlite"); + let operation = "locate_database"; + try { + await stat(databasePath); + operation = "load_sqlite_module"; + const { DatabaseSync } = await import("node:sqlite"); + operation = "open_database"; + db = new DatabaseSync(databasePath, { readOnly: true, timeout: 1000 }); + operation = "set_query_only"; + db.exec("PRAGMA query_only=ON"); + operation = "inspect_schema"; + const columns = db.prepare("PRAGMA table_info(thread_items)").all().map(column => column.name); + if (!["thread_id", "turn_id", "item_id", "item_type", "item_json", "started_at_ms", "completed_at_ms"].every(name => columns.includes(name))) { + gaps.push({ source, reason: "unsupported_schema; no_conversation_rows_read" }); + return []; + } + // Only scalar/error projections leave SQLite; never select whole item_json, + // chat roles, arguments, successful results or rollout contents. + const field = name => `json_extract(CASE WHEN json_valid(item_json) THEN item_json ELSE '{}' END,'$.${name}')`; + const error = field("error"); + operation = "prepare_failed_items_query"; + const query = db.prepare(`SELECT thread_id,turn_id,item_id,started_at_ms,completed_at_ms, + ${field("server")} AS server,${field("tool")} AS operation, + CASE WHEN length(CAST(${error} AS BLOB))<=${READ_LIMIT} THEN ${error} END AS error_json, + length(CAST(${error} AS BLOB)) AS error_bytes + FROM thread_items WHERE thread_id=? AND item_type='mcpToolCall' + AND ((started_at_ms>=? AND started_at_ms<=?) OR (completed_at_ms>=? AND completed_at_ms<=?)) + AND ${field("type")}='mcpToolCall' AND ${field("server")} IN ('chatcut','plugin:chatcut:chatcut') + AND ${field("status")}='failed' ORDER BY completed_at_ms DESC,item_id LIMIT 11`); + operation = "select_failed_mcp_items"; + const rows = query.all(conversationId, window.since * 1000, window.until * 1000, window.since * 1000, window.until * 1000); + if (rows.length > 10) gaps.push({ source, reason: "native_failure_record_limit", limit: 10 }); + if (!rows.length) gaps.push({ source, reason: "no_failed_mcp_items_in_bounded_window" }); + return rows.slice(0, 10).map(row => { + if (row.error_bytes > READ_LIMIT) gaps.push({ source, reason: "native_error_size_limit", nativeItemId: row.item_id, limitBytes: READ_LIMIT }); + let error = null; + if (row.error_json) { + try { error = JSON.parse(row.error_json); } + catch { error = { message: String(row.error_json) }; } + } + return { + source, sourceFile: "thread_history_1.sqlite", conversationId: row.thread_id, turnId: row.turn_id, + nativeItemId: row.item_id, idKind: "codex_native_mcp_item_id; not_responses_call_id_rpc_id_or_server_request_id", + serverName: row.server, operation: row.operation, status: "failed", + startedAtMs: row.started_at_ms, completedAtMs: row.completed_at_ms, + timeSource: "native_thread_items_lifecycle_columns; not_original_occurredAt_or_log_time", + error, ...(row.error_bytes > READ_LIMIT && { errorCaptureLimited: true }), originalAttemptMatch: "unconfirmed", + }; + }); + } catch (error) { + gaps.push({ source, reason: "unavailable", operation, error: errorDetails(error), + ...(platform() === "win32" && error?.errcode === 14 + ? { accessEvidence: await inspectSqliteAccess(databasePath) } : {}), + }); + return []; + } finally { + try { db?.close(); } + catch (error) { gaps.push({ source, reason: "close_failed", operation: "close_database", error: errorDetails(error) }); } + } +} + export async function collectHostLogs(host, options = {}) { const userHome = options.home ?? homedir(); const gaps = []; const entries = []; let appLog; + let nativeFailedCalls; const now = options.now ?? Date.now(); const center = options.occurredAt ? Date.parse(options.occurredAt) : now; const since = Math.floor((center - (options.occurredAt ? 15 : 30) * 60_000) / 1000); @@ -694,20 +809,29 @@ export async function collectHostLogs(host, options = {}) { const logRoot = options.codexLogDir ?? join(root, "log"); const databasePath = join(sqliteRoot, "logs_2.sqlite"); let db; + let operation = "locate_database"; try { await stat(databasePath); + operation = "load_sqlite_module"; const { DatabaseSync } = await import("node:sqlite"); + operation = "open_database"; db = new DatabaseSync(databasePath, { readOnly: true, timeout: 1000 }); + operation = "set_query_only"; db.exec("PRAGMA query_only=ON"); + operation = "inspect_schema"; const hasThreadId = db .prepare("PRAGMA table_info(logs)") .all() .some((column) => column.name === "thread_id"); - const rows = db - .prepare( - `SELECT id,ts,level,target,feedback_log_body${hasThreadId ? ",thread_id" : ""} FROM logs WHERE ts>=? AND ts<=? AND (target LIKE 'codex_mcp%' OR target LIKE 'rmcp%' OR target LIKE 'codex_plugins%' OR target LIKE 'codex_core::plugins%') AND feedback_log_body LIKE '%chatcut%' ORDER BY ts DESC LIMIT 200`, - ) - .all(since, until); + const threadFilter = hasThreadId && options.conversationId + ? " AND (thread_id IS NULL OR thread_id='' OR thread_id=?)" : ""; + operation = "prepare_runtime_logs_query"; + const query = db.prepare( + `SELECT id,ts,level,target,feedback_log_body${hasThreadId ? ",thread_id" : ""} FROM logs WHERE ts>=? AND ts<=?${threadFilter} AND (target LIKE 'codex_mcp%' OR target LIKE 'codex_rmcp_client%' OR target LIKE 'rmcp%' OR target LIKE 'codex_plugins%' OR target LIKE 'codex_core::plugins%' OR target='codex_core::mcp_tool_call') AND feedback_log_body LIKE '%chatcut%' ORDER BY ts DESC LIMIT 200`, + ); + operation = "select_runtime_logs"; + const rows = query.all(since, until, ...(threadFilter ? [options.conversationId] : [])); + operation = "filter_runtime_logs"; for (const row of rows) { const message = logMessage(row.feedback_log_body ?? ""); const original = row.feedback_log_body ?? ""; @@ -719,7 +843,8 @@ export async function collectHostLogs(host, options = {}) { context.conversationId !== options.conversationId ) continue; - if (!CHATCUT_MESSAGE.test(original) || /server_name="?chatcut_desktop/.test(original)) + if (!hostedTextRecord(`${row.target}: ${original}`, row.level) || + !hostedTextRecord(`MCP server "chatcut" ${message}`)) continue; if ( !["ERROR", "WARN"].includes(row.level) && @@ -744,6 +869,7 @@ export async function collectHostLogs(host, options = {}) { gaps.push({ source: "codex_runtime_sqlite", reason: "unavailable", + operation, error: errorDetails(error), locationSource: options.codexSqliteHome ? "explicit_host_location" @@ -755,18 +881,35 @@ export async function collectHostLogs(host, options = {}) { : {}), }); } finally { - db?.close(); + try { db?.close(); } + catch (error) { gaps.push({ source: "codex_runtime_sqlite", reason: "close_failed", operation: "close_database", error: errorDetails(error) }); } } + nativeFailedCalls = await nativeFailedMcpItems(sqliteRoot, options.conversationId, { since, until }, gaps); try { entries.push( ...(await textLog(join(logRoot, "codex-tui.log"), "codex_tui_log", gaps, { since, until, + conversationId: options.conversationId, })), ); } catch (error) { gaps.push({ source: "codex_tui_log", reason: "unavailable", error: errorDetails(error) }); } + if (options.codexStderrFile) { + try { + if (!basename(options.codexStderrFile).endsWith(".codex-stderr.log")) + throw new Error("Use an existing dedicated .codex-stderr.log native capture, never config/auth/session files"); + const captured = await textLog(options.codexStderrFile, "codex_stderr_log", gaps, { + since, until, conversationId: options.conversationId, + }); + entries.push(...captured.map(({ occurredAt, ...entry }) => ({ + ...entry, loggedAt: occurredAt, timestampKind: "native_log_time_not_original_failure_time", + }))); + } catch (error) { + gaps.push({ source: "codex_stderr_log", reason: "unavailable", error: errorDetails(error) }); + } + } const appData = options.localAppData ?? process.env.LOCALAPPDATA; const sandboxAppData = !options.localAppData && @@ -830,12 +973,13 @@ export async function collectHostLogs(host, options = {}) { gaps.push({ source: "claude_debug_log", reason: "unavailable", error: errorDetails(error) }); } } - if (!entries.length) + if (!entries.length && !nativeFailedCalls?.length) gaps.push({ source: "host_logs", reason: "no_matching_records_in_bounded_window" }); return clean({ entries, gaps, ...(appLog ? { appLog } : {}), + ...(nativeFailedCalls ? { nativeFailedCalls } : {}), window: { since: new Date(since * 1000).toISOString(), until: new Date(until * 1000).toISOString(), @@ -899,16 +1043,24 @@ export async function runDoctor(options, dependencies = {}) { throw new Error("--occurred-at must be an ISO timestamp with timezone; omit it when unknown"); } const fetchImpl = dependencies.fetchImpl ?? fetch; + const threadEnv = options.host === "codex" ? process.env.CODEX_THREAD_ID : undefined; + const collectionConversationId = /^[a-f0-9]{8}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{12}$/i.test(threadEnv ?? "") + ? threadEnv : null; const diagnosticId = randomUUID(); const report = { schemaVersion: 2, - collectorVersion: "1.2.3", + collectorVersion: "1.2.4", diagnosticId, collectedAt: new Date().toISOString(), scope: "cloud", host: options.host, hostVersion: options.hostVersion ?? null, hostVersionSource: options.hostVersion ? "agent_supplied" : "unavailable", + collectionContext: { + conversationId: collectionConversationId, + source: collectionConversationId ? "CODEX_THREAD_ID" : "unavailable", + association: "current_collection_thread; original_failed_attempt_unconfirmed", + }, environment: { platform: platform(), architecture: arch(), @@ -1063,10 +1215,11 @@ export async function runDoctor(options, dependencies = {}) { codexAppLogDir: options.codexAppLogDir, codexAppLogFiles: options.codexAppLogFiles, codexAppLogOffset: options.codexAppLogOffset, + codexStderrFile: options.codexStderrFile, conversationId: report.originalFailure.conversationId ?? report.hostSnapshot?.session?.conversationId ?? - process.env.CODEX_THREAD_ID, + collectionConversationId, }); } catch (error) { report.hostLogs = { @@ -1078,11 +1231,13 @@ export async function runDoctor(options, dependencies = {}) { disabledBySnapshot || report.hostSnapshot?.configuration?.enabled === false || report.hostSnapshot?.session?.connectionStatus === "disabled"; - if (disabled || !endpoint) { + if (options.offline || disabled || !endpoint) { report.gaps.push({ source: "probes", reason: disabled ? "host_reports_intentionally_disabled; no_requests_sent" + : options.offline + ? "offline_requested; no_requests_sent" : "registered_endpoint_unavailable; no_requests_sent", }); } else { @@ -1189,6 +1344,8 @@ export async function runDoctor(options, dependencies = {}) { report.upload = { status: disabled ? "skipped_intentionally_disabled" + : options.offline + ? "skipped_offline" : !endpoint ? "skipped_endpoint_unavailable" : options.upload @@ -1200,7 +1357,7 @@ export async function runDoctor(options, dependencies = {}) { const save = async (flag) => writeFile(path, JSON.stringify(clean(report), null, 2) + "\n", { flag, mode: 0o600 }); await save("wx"); - if (options.upload && !disabled && endpoint) { + if (options.upload && !options.offline && !disabled && endpoint) { try { const events = fragmentEvents(report); const response = await fetchImpl(new URL("/telemetry/events", endpoint.origin).href, { @@ -1240,11 +1397,13 @@ if (process.argv[1] && resolve(process.argv[1]) === fileURLToPath(import.meta.ur "occurred-at": { type: "string" }, "codex-sqlite-home": { type: "string" }, "codex-log-dir": { type: "string" }, + "codex-stderr-file": { type: "string" }, "codex-app-log-dir": { type: "string" }, "codex-app-log-file": { type: "string", multiple: true }, "codex-app-log-offset": { type: "string" }, output: { type: "string" }, upload: { type: "boolean", default: false }, + offline: { type: "boolean", default: false }, "wire-evidence": { type: "boolean", default: true }, "create-snapshot": { type: "string" }, "validate-snapshot": { type: "string" }, @@ -1284,7 +1443,7 @@ if (process.argv[1] && resolve(process.argv[1]) === fileURLToPath(import.meta.ur console.log(JSON.stringify({ snapshotValid: true, networkRequests: 0 })); } else if (values.help) { console.log( - "node mcp-doctor.mjs --create-snapshot | --validate-snapshot | --host codex|claude --server-url [--host-snapshot ] [--host-version ] [--failure-record | --original-error ] [--occurred-at ] [--codex-sqlite-home ] [--codex-log-dir ] [--codex-app-log-dir ] [--codex-app-log-file ] [--wire-evidence] [--output ] [--upload]", + "node mcp-doctor.mjs --create-snapshot | --validate-snapshot | --host codex|claude --server-url [--host-snapshot ] [--host-version ] [--failure-record | --original-error ] [--occurred-at ] [--codex-sqlite-home ] [--codex-log-dir ] [--codex-stderr-file ] [--codex-app-log-dir ] [--codex-app-log-file ] [--wire-evidence] [--output ] [--offline] [--upload]", ); } else { const { path, report } = await runDoctor({ @@ -1297,6 +1456,7 @@ if (process.argv[1] && resolve(process.argv[1]) === fileURLToPath(import.meta.ur occurredAt: values["occurred-at"], codexSqliteHome: values["codex-sqlite-home"], codexLogDir: values["codex-log-dir"], + codexStderrFile: values["codex-stderr-file"], codexAppLogDir: values["codex-app-log-dir"], codexAppLogFiles: values["codex-app-log-file"], codexAppLogOffset: @@ -1305,6 +1465,7 @@ if (process.argv[1] && resolve(process.argv[1]) === fileURLToPath(import.meta.ur : Number(values["codex-app-log-offset"]), output: values.output, upload: values.upload, + offline: values.offline, wireEvidence: values["wire-evidence"], }); console.log( diff --git a/claude/skills/chatcut-plugin-basics-claude/scripts/mcp-evidence.mjs b/claude/skills/chatcut-plugin-basics-claude/scripts/mcp-evidence.mjs index da0ed7c..b0ab995 100644 --- a/claude/skills/chatcut-plugin-basics-claude/scripts/mcp-evidence.mjs +++ b/claude/skills/chatcut-plugin-basics-claude/scripts/mcp-evidence.mjs @@ -240,10 +240,23 @@ export function evidenceSummary(report) { ...(entry.conversationId && { conversationId: entry.conversationId }), ...(entry.callId && { callId: entry.callId }), })); + const databaseReadFailures = (report.hostLogs.gaps ?? []).filter(gap => + ["codex_runtime_sqlite", "codex_native_failed_mcp_items"].includes(gap.source) && + ["unavailable", "close_failed"].includes(gap.reason)).map(gap => ({ + source: gap.source, operation: gap.operation ?? null, + code: gap.error?.code ?? null, errcode: gap.error?.errcode ?? null, + })); return { stages, otherObservations: unknown, logHints, + collectionContext: report.collectionContext ?? null, + nativeFailedCalls: (report.hostLogs.nativeFailedCalls ?? []).map((item, index) => ({ + evidence: `hostLogs.nativeFailedCalls[${index}]`, source: item.source, + nativeItemId: item.nativeItemId, idKind: item.idKind, conversationId: item.conversationId, + operation: item.operation, startedAtMs: item.startedAtMs, completedAtMs: item.completedAtMs, + originalAttemptMatch: "unconfirmed", + })), originalRequestCorrelation: { status: originalRequests.length ? "agent_reported_same_attempt" : "unconfirmed", observations: originalRequests, @@ -260,6 +273,13 @@ export function evidenceSummary(report) { } : null, hostLogCoverage: { + originalErrorRetained: report.originalFailure.status === "recorded", + originalErrorRetainedWithoutDatabase: report.originalFailure.status === "recorded" && databaseReadFailures.length > 0, + databaseReadFailures, + runtimeCollectionFailed: (report.hostLogs.gaps ?? []).some(gap => gap.source === "host_logs" && gap.reason === "collector_failed"), + nativeFailedMcpItems: report.hostLogs.nativeFailedCalls?.length ?? 0, + retainedStderrRecords: report.hostLogs.entries.filter(entry => entry.source === "codex_stderr_log").length, + priorStderrCaptureRequired: false, records: report.hostLogs.entries.length, appStartupRecords: appNotices.length, failedAppStartupRecords: failedAppNotices.length, diff --git a/codex/.codex-plugin/plugin.json b/codex/.codex-plugin/plugin.json index 5d170b4..bb9eda4 100644 --- a/codex/.codex-plugin/plugin.json +++ b/codex/.codex-plugin/plugin.json @@ -1,6 +1,6 @@ { "name": "chatcut", - "version": "1.10.21", + "version": "1.10.23", "description": "ChatCut Codex plugin for editable video editing and creation workflows from Codex.", "author": { "name": "ChatCut", diff --git a/codex/.mcp.json b/codex/.mcp.json index c02fca1..1c15b6e 100644 --- a/codex/.mcp.json +++ b/codex/.mcp.json @@ -3,7 +3,7 @@ "chatcut": { "http_headers": { "x-chatcut-mcp-surface": "codex", - "x-chatcut-plugin-version": "1.10.21" + "x-chatcut-plugin-version": "1.10.23" }, "oauth_resource": "https://api.chatcut.io/api/external-mcp/mcp", "url": "https://api.chatcut.io/api/external-mcp/mcp" diff --git a/codex/skills/chatcut-plugin-basics/SKILL.md b/codex/skills/chatcut-plugin-basics/SKILL.md index e6ec7b3..5937684 100644 --- a/codex/skills/chatcut-plugin-basics/SKILL.md +++ b/codex/skills/chatcut-plugin-basics/SKILL.md @@ -32,6 +32,8 @@ Also use connection diagnostics when previously available tools disappear or the For a failed hosted ChatCut tool request after connection, immediately preserve the original tool error and any available failure time, conversation ID and local call ID in the dedicated failure record described there. The Agent gathers these facts; do not ask the user to manually reconstruct them. Startup-status notices and later successful checks do not establish what happened to that tool request. +Save the visible error before reading runtime databases, including unfamiliar error messages and cause. A failed Windows database read does not invalidate that error or prevent local collection with `--offline`. Keep independent bounded App evidence separate and check `evidenceSummary.hostLogCoverage` for retained and missing sources. Do not require prior stderr setup, database export or permission changes. A startup error hidden from the Agent still needs an accessible source. + 1. **Server not registered:** Offer to register the Hosted MCP server directly. Do not install, reinstall, repair, or enable a plugin to obtain the server: ```sh diff --git a/codex/skills/chatcut-plugin-basics/references/connection-diagnostics.md b/codex/skills/chatcut-plugin-basics/references/connection-diagnostics.md index c133f82..fe82f27 100644 --- a/codex/skills/chatcut-plugin-basics/references/connection-diagnostics.md +++ b/codex/skills/chatcut-plugin-basics/references/connection-diagnostics.md @@ -106,6 +106,15 @@ Only include ChatCut tool names; keep tool arguments and results out. ### Preserve the failed call before independent checks +Database reads are supplementary. Save the currently visible error first, then +continue local collection with `--offline` even when SQLite is unavailable. +This option sends no probes or upload, including when `--upload` is also given. +`evidenceSummary.hostLogCoverage` distinguishes the retained original error, +database failures and remaining sources. Existing App logs remain independent. +An already visible tool error needs no prior stderr setup; an unexposed startup +error still needs an accessible source. Never copy a live database, parse its +WAL separately, ignore locks or widen permissions to make collection pass. + When the host exposes the original failed tool result or runtime event, the Agent copies only its error and available identifiers into a new dedicated `.mcp-failure.json`. Do this before retries, reconnects or later probes. @@ -147,6 +156,24 @@ Do not start another authenticated session to manufacture replacement evidence. If only the original error text is accessible, use the text-file fallback below. Do not call a report with only startup-status notices a captured tool failure. +Save actual error fields rather than reconstructing a raw tool-result envelope. +The collector records a valid Codex `CODEX_THREAD_ID` in `collectionContext` as +the current collecting thread. It does not fill the original failure's thread +automatically. When the failure just happened in this same chat, that known +thread may be supplied in its failure record with the source explained. Never +use the diagnostic command's `CODEX_TOOL_CALL_ID` as the failed MCP call's ID. + +With a known original/session thread, `hostLogs.nativeFailedCalls` selects at +most ten failed hosted ChatCut MCP items in the bounded window from the native +`thread_history_1.sqlite` index. Only IDs, lifecycle times and error fields are +projected; whole history items, conversations, arguments and successful results +are not collected. An error above 128 KiB is explicitly omitted; the complete +local report is never trimmed to fit the 256 KiB upload limit. `nativeItemId` +is a native MCP item identity, distinct from Responses call IDs, RPC IDs and +server request IDs. `startedAtMs`/`completedAtMs` are lifecycle times, not the +original `occurredAt`. Matches remain unconfirmed; compare known thread, tool +and exact error without promoting nearby times to proof of association. + 1. Obtain the existing server's registered URL through the host. Preserve its environment. The helper accepts ChatCut production/beta/dev endpoints and loopback development servers; it reports unsupported endpoints rather than @@ -184,10 +211,18 @@ Codex SQLite locations follow `CODEX_SQLITE_HOME` when present. If the current host already supplies its actual `sqlite_home` or `log_dir`, pass that directory with `--codex-sqlite-home` or `--codex-log-dir`; do not read whole config files to find it. These options select existing log locations and do not enable logging. +If the caller already retained a dedicated native stderr stream, pass its +existing `.codex-stderr.log` with `--codex-stderr-file`. The helper reads only +its bounded ChatCut log tail, marks emission time as `loggedAt`, and does not +fill original failure time or association. This source is optional; it does +not capture a stream or recover discarded stderr. On Windows, SQLite error 14 can coexist with readable WAL files in a read-only sandbox. The report preserves the original error and bounded file-access facts; it does not prove a specific security product caused the restriction. Never copy the whole log database, ignore its WAL with immutable mode, or relax permissions. +Both SQLite readers preserve the failing operation and error, then continue +other sources; a close failure does not replace the primary error. Missing +native IDs and lifecycle times remain missing when the database is unreadable. On Windows, the helper also reads the existing Codex App startup-status notices under `%LOCALAPPDATA%/Codex/Logs/YYYY/MM/DD`. This is independent of TUI logging. It selects only `AppServerConnection` startup notices for the hosted ChatCut diff --git a/codex/skills/chatcut-plugin-basics/scripts/mcp-doctor.mjs b/codex/skills/chatcut-plugin-basics/scripts/mcp-doctor.mjs index 513ba4a..bf76c45 100644 --- a/codex/skills/chatcut-plugin-basics/scripts/mcp-doctor.mjs +++ b/codex/skills/chatcut-plugin-basics/scripts/mcp-doctor.mjs @@ -24,8 +24,33 @@ function redactFieldValue(_match, prefix, value) { return prefix + (quote ? quote + "[REDACTED]" + quote : "[REDACTED]"); } -export function redact(text) { - return String(text) +export function redact(text, jsonDepth = 0) { + let value = String(text); + // A host may quote/stringify an entire JSON response inside its error. Decode + // only JSON string tokens containing this credential label, redact their full + // value, then restore the quoting. A partial escaped-field regex can leak the + // suffix after an escaped quote/backslash. Input collection is size bounded. + if (jsonDepth < 16) value = value.replace(/"(?:\\.|[^"\\\r\n])*"/g, (token) => { + try { + const decoded = JSON.parse(token); + if (/mcp[-_]session[-_]id/i.test(decoded)) { + const sanitized = redact(decoded, jsonDepth + 1); + if (sanitized !== decoded) return JSON.stringify(sanitized); + } + } catch { /* Non-JSON diagnostic text is retained for the normal rules. */ } + return token; + }); + return value + .replace(/\b(Mcp-Session-Id[ \t]*:[ \t]*)\S+/gi, "$1[REDACTED]") + .replace( + /(["']mcp[-_]session[-_]id["']\s*[:=]\s*)("(?:\\.|[^"\\\r\n])*"|'(?:\\.|[^'\\\r\n])*')/gi, + redactFieldValue, + ) + .replace( + /\b((?:mcp[-_]session[-_]id)\s*[:=]\s*)("(?:\\.|[^"\\\r\n])*"|'(?:\\.|[^'\\\r\n])*'|[^\s"'<>]+)/gi, + redactFieldValue, + ) + .replace(/((?:\\*["'])mcp[-_]session[-_]id(?:\\*["'])\s*[:=]\s*(?:\\*["']))[^"'\\\r\n]*/gi, "$1[REDACTED]") .replace( /\bBearer\s+(?!(?:token|required)\b|<|(?:realm|scope|error(?:_description|_uri)?|resource_metadata)\s*=)[A-Za-z0-9._~+/=-]+/gi, "Bearer [REDACTED]", @@ -55,7 +80,7 @@ export function redact(text) { function clean(value) { return JSON.parse( JSON.stringify(value, (key, item) => - /^(?:access_?token|refresh_?token|id_?token|client_?secret|session_?token|api[_-]?key|authorization|token|cookie|set-cookie)$/i.test( + /^(?:mcp[-_]session[-_]id|access_?token|refresh_?token|id_?token|client_?secret|session_?token|api[_-]?key|authorization|token|cookie|set-cookie)$/i.test( key, ) ? "[REDACTED]" @@ -253,7 +278,7 @@ export async function probeEntry(endpoint, diagnosticId, fetchImpl = fetch) { params: { protocolVersion: "2025-11-25", capabilities: {}, - clientInfo: { name: "chatcut-mcp-doctor", version: "1.2.3" }, + clientInfo: { name: "chatcut-mcp-doctor", version: "1.2.4" }, }, }), }); @@ -390,8 +415,11 @@ function runtimeContext(body) { return { ...(conversationId && { conversationId }), ...(callId && { callId }) }; } -function hostedTextRecord(line) { +function hostedTextRecord(line, nativeLevel) { if (/^\s/.test(line)) return false; + // Inspect explicit echo prefixes before stripping trace context: a payload + // itself can contain "}:" and must not become a diagnostic via lastIndex. + if (/(?:^|\}:\s*)(?:tool (?:call|result)\s*:|(?:function_call(?:_output)?|tool_call(?:_output)?)\s*:?\s*[{[])/i.test(line)) return false; let body = line.replace( /^\d{4}-\d{2}-\d{2}T\S+\s+(?:(?:\[(?:TRACE|DEBUG|INFO|WARN|ERROR)\]|TRACE|DEBUG|INFO|WARN|ERROR)\s+)?/i, "", @@ -399,7 +427,7 @@ function hostedTextRecord(line) { const module = body.match(/^([A-Za-z_]\w*(?:::\w+)+):\s*/); if (module) { if ( - !/^(?:codex_(?:mcp|rmcp_client|plugins|core(?:::|_)plugins)(?:::|$)|rmcp::)/.test(module[1]) + !/^(?:codex_(?:mcp|rmcp_client|plugins|core(?:::|_)plugins)(?:::|$)|rmcp::|codex_core::mcp_tool_call$)/.test(module[1]) ) return false; body = body.slice(module[0].length); @@ -417,9 +445,23 @@ function hostedTextRecord(line) { const server = context.match(/\bserver_name=["']?([\w:.-]+)/)?.[1] ?? scope?.[1] ?? scope?.[2] ?? scope?.[3]; if (server && !["chatcut", "plugin:chatcut:chatcut"].includes(server)) return false; - if (!CHATCUT_MESSAGE.test(body)) return false; - if (/\bmethod=["']?tools\/call(?:["'\s}]|$)/.test(context)) return false; - const message = scope ? body.slice(scope[0].length) : body; + const header = line.match(/^\d{4}-\d{2}-\d{2}T\S+\s+(?:\[(WARN|ERROR)\]|(WARN|ERROR))\s+/i); + const level = String(nativeLevel ?? header?.[1] ?? header?.[2]).toUpperCase(); + const nativeToolError = module?.[1] === "codex_core::mcp_tool_call" && + ["ERROR", "WARN"].includes(level) && + /^MCP tool call error:\s*["']?tool call error: tool call failed for `(?:chatcut|plugin:chatcut:chatcut)\/[A-Za-z0-9_.:-]+`/.test(body); + if (module?.[1] === "codex_core::mcp_tool_call" && !nativeToolError) return false; + if (!CHATCUT_MESSAGE.test(body) && !nativeToolError) return false; + if (/\bmethod=["']?tools\/call(?:["'\s}]|$)/.test(context)) { + // A trusted native ERROR/WARN can describe a failed tools/call without + // echoing its content. SQLite supplies its separate native level column. + if (!module || !["ERROR", "WARN"].includes(level)) return false; + // Inspect the unstripped body: a payload can itself contain "}:". + const contentCheck = body.replace(/\\+(?=["'])/g, ""); + if (/["'](?:params|arguments)["']\s*:\s*[{[]|["'](?:prompt|transcript)["']\s*:\s*["'{[]|["']result["']\s*:\s*\{[\s\S]*?["']content["']\s*:\s*\[|["']role["']\s*:\s*["'](?:user|assistant|system|developer)["']|["']type["']\s*:\s*["'](?:function_call(?:_output)?|tool_call(?:_output)?|tool_result|user(?:_message)?|assistant(?:_message)?)["']/i.test(contentCheck)) return false; + if (/(?:^|\}:\s*)(?:prompt|transcript)\s*:/i.test(body)) return false; + } + const message = scope ? body.slice(scope[0].length) : logMessage(body); // Runtime error contents can name tools; only explicit echo records are excluded. if (TEXT_ECHO.test(message)) return false; if ( @@ -507,7 +549,11 @@ async function textLog(path, source, gaps, window, select = hostedTextRecord) { !TEXT_ECHO.test(lines[i + 1].trimStart()) ) block.push(lines[++i]); + if (block.length > 1 && !select(block.join("\n"))) continue; const occurredAt = logTime(block[0]); + const context = runtimeContext(block[0]); + if (window.conversationId && context.conversationId && context.conversationId !== window.conversationId) + continue; if ( occurredAt && (Date.parse(occurredAt) < window.since * 1000 || @@ -520,7 +566,7 @@ async function textLog(path, source, gaps, window, select = hostedTextRecord) { occurredAt, timeStatus: occurredAt ? "within_requested_window" : "unknown; not_confirmed_within_window", message: redact(block.join("\n")), - ...runtimeContext(block[0]), + ...context, originalAttemptMatch: "unconfirmed", }); } @@ -679,11 +725,80 @@ async function inspectSqliteAccess(path) { }; } +async function nativeFailedMcpItems(sqliteRoot, conversationId, window, gaps) { + const source = "codex_native_failed_mcp_items"; + if (!conversationId) { + gaps.push({ source, reason: "known_conversation_id_unavailable; no_history_query" }); + return []; + } + let db; + const databasePath = join(sqliteRoot, "thread_history_1.sqlite"); + let operation = "locate_database"; + try { + await stat(databasePath); + operation = "load_sqlite_module"; + const { DatabaseSync } = await import("node:sqlite"); + operation = "open_database"; + db = new DatabaseSync(databasePath, { readOnly: true, timeout: 1000 }); + operation = "set_query_only"; + db.exec("PRAGMA query_only=ON"); + operation = "inspect_schema"; + const columns = db.prepare("PRAGMA table_info(thread_items)").all().map(column => column.name); + if (!["thread_id", "turn_id", "item_id", "item_type", "item_json", "started_at_ms", "completed_at_ms"].every(name => columns.includes(name))) { + gaps.push({ source, reason: "unsupported_schema; no_conversation_rows_read" }); + return []; + } + // Only scalar/error projections leave SQLite; never select whole item_json, + // chat roles, arguments, successful results or rollout contents. + const field = name => `json_extract(CASE WHEN json_valid(item_json) THEN item_json ELSE '{}' END,'$.${name}')`; + const error = field("error"); + operation = "prepare_failed_items_query"; + const query = db.prepare(`SELECT thread_id,turn_id,item_id,started_at_ms,completed_at_ms, + ${field("server")} AS server,${field("tool")} AS operation, + CASE WHEN length(CAST(${error} AS BLOB))<=${READ_LIMIT} THEN ${error} END AS error_json, + length(CAST(${error} AS BLOB)) AS error_bytes + FROM thread_items WHERE thread_id=? AND item_type='mcpToolCall' + AND ((started_at_ms>=? AND started_at_ms<=?) OR (completed_at_ms>=? AND completed_at_ms<=?)) + AND ${field("type")}='mcpToolCall' AND ${field("server")} IN ('chatcut','plugin:chatcut:chatcut') + AND ${field("status")}='failed' ORDER BY completed_at_ms DESC,item_id LIMIT 11`); + operation = "select_failed_mcp_items"; + const rows = query.all(conversationId, window.since * 1000, window.until * 1000, window.since * 1000, window.until * 1000); + if (rows.length > 10) gaps.push({ source, reason: "native_failure_record_limit", limit: 10 }); + if (!rows.length) gaps.push({ source, reason: "no_failed_mcp_items_in_bounded_window" }); + return rows.slice(0, 10).map(row => { + if (row.error_bytes > READ_LIMIT) gaps.push({ source, reason: "native_error_size_limit", nativeItemId: row.item_id, limitBytes: READ_LIMIT }); + let error = null; + if (row.error_json) { + try { error = JSON.parse(row.error_json); } + catch { error = { message: String(row.error_json) }; } + } + return { + source, sourceFile: "thread_history_1.sqlite", conversationId: row.thread_id, turnId: row.turn_id, + nativeItemId: row.item_id, idKind: "codex_native_mcp_item_id; not_responses_call_id_rpc_id_or_server_request_id", + serverName: row.server, operation: row.operation, status: "failed", + startedAtMs: row.started_at_ms, completedAtMs: row.completed_at_ms, + timeSource: "native_thread_items_lifecycle_columns; not_original_occurredAt_or_log_time", + error, ...(row.error_bytes > READ_LIMIT && { errorCaptureLimited: true }), originalAttemptMatch: "unconfirmed", + }; + }); + } catch (error) { + gaps.push({ source, reason: "unavailable", operation, error: errorDetails(error), + ...(platform() === "win32" && error?.errcode === 14 + ? { accessEvidence: await inspectSqliteAccess(databasePath) } : {}), + }); + return []; + } finally { + try { db?.close(); } + catch (error) { gaps.push({ source, reason: "close_failed", operation: "close_database", error: errorDetails(error) }); } + } +} + export async function collectHostLogs(host, options = {}) { const userHome = options.home ?? homedir(); const gaps = []; const entries = []; let appLog; + let nativeFailedCalls; const now = options.now ?? Date.now(); const center = options.occurredAt ? Date.parse(options.occurredAt) : now; const since = Math.floor((center - (options.occurredAt ? 15 : 30) * 60_000) / 1000); @@ -694,20 +809,29 @@ export async function collectHostLogs(host, options = {}) { const logRoot = options.codexLogDir ?? join(root, "log"); const databasePath = join(sqliteRoot, "logs_2.sqlite"); let db; + let operation = "locate_database"; try { await stat(databasePath); + operation = "load_sqlite_module"; const { DatabaseSync } = await import("node:sqlite"); + operation = "open_database"; db = new DatabaseSync(databasePath, { readOnly: true, timeout: 1000 }); + operation = "set_query_only"; db.exec("PRAGMA query_only=ON"); + operation = "inspect_schema"; const hasThreadId = db .prepare("PRAGMA table_info(logs)") .all() .some((column) => column.name === "thread_id"); - const rows = db - .prepare( - `SELECT id,ts,level,target,feedback_log_body${hasThreadId ? ",thread_id" : ""} FROM logs WHERE ts>=? AND ts<=? AND (target LIKE 'codex_mcp%' OR target LIKE 'rmcp%' OR target LIKE 'codex_plugins%' OR target LIKE 'codex_core::plugins%') AND feedback_log_body LIKE '%chatcut%' ORDER BY ts DESC LIMIT 200`, - ) - .all(since, until); + const threadFilter = hasThreadId && options.conversationId + ? " AND (thread_id IS NULL OR thread_id='' OR thread_id=?)" : ""; + operation = "prepare_runtime_logs_query"; + const query = db.prepare( + `SELECT id,ts,level,target,feedback_log_body${hasThreadId ? ",thread_id" : ""} FROM logs WHERE ts>=? AND ts<=?${threadFilter} AND (target LIKE 'codex_mcp%' OR target LIKE 'codex_rmcp_client%' OR target LIKE 'rmcp%' OR target LIKE 'codex_plugins%' OR target LIKE 'codex_core::plugins%' OR target='codex_core::mcp_tool_call') AND feedback_log_body LIKE '%chatcut%' ORDER BY ts DESC LIMIT 200`, + ); + operation = "select_runtime_logs"; + const rows = query.all(since, until, ...(threadFilter ? [options.conversationId] : [])); + operation = "filter_runtime_logs"; for (const row of rows) { const message = logMessage(row.feedback_log_body ?? ""); const original = row.feedback_log_body ?? ""; @@ -719,7 +843,8 @@ export async function collectHostLogs(host, options = {}) { context.conversationId !== options.conversationId ) continue; - if (!CHATCUT_MESSAGE.test(original) || /server_name="?chatcut_desktop/.test(original)) + if (!hostedTextRecord(`${row.target}: ${original}`, row.level) || + !hostedTextRecord(`MCP server "chatcut" ${message}`)) continue; if ( !["ERROR", "WARN"].includes(row.level) && @@ -744,6 +869,7 @@ export async function collectHostLogs(host, options = {}) { gaps.push({ source: "codex_runtime_sqlite", reason: "unavailable", + operation, error: errorDetails(error), locationSource: options.codexSqliteHome ? "explicit_host_location" @@ -755,18 +881,35 @@ export async function collectHostLogs(host, options = {}) { : {}), }); } finally { - db?.close(); + try { db?.close(); } + catch (error) { gaps.push({ source: "codex_runtime_sqlite", reason: "close_failed", operation: "close_database", error: errorDetails(error) }); } } + nativeFailedCalls = await nativeFailedMcpItems(sqliteRoot, options.conversationId, { since, until }, gaps); try { entries.push( ...(await textLog(join(logRoot, "codex-tui.log"), "codex_tui_log", gaps, { since, until, + conversationId: options.conversationId, })), ); } catch (error) { gaps.push({ source: "codex_tui_log", reason: "unavailable", error: errorDetails(error) }); } + if (options.codexStderrFile) { + try { + if (!basename(options.codexStderrFile).endsWith(".codex-stderr.log")) + throw new Error("Use an existing dedicated .codex-stderr.log native capture, never config/auth/session files"); + const captured = await textLog(options.codexStderrFile, "codex_stderr_log", gaps, { + since, until, conversationId: options.conversationId, + }); + entries.push(...captured.map(({ occurredAt, ...entry }) => ({ + ...entry, loggedAt: occurredAt, timestampKind: "native_log_time_not_original_failure_time", + }))); + } catch (error) { + gaps.push({ source: "codex_stderr_log", reason: "unavailable", error: errorDetails(error) }); + } + } const appData = options.localAppData ?? process.env.LOCALAPPDATA; const sandboxAppData = !options.localAppData && @@ -830,12 +973,13 @@ export async function collectHostLogs(host, options = {}) { gaps.push({ source: "claude_debug_log", reason: "unavailable", error: errorDetails(error) }); } } - if (!entries.length) + if (!entries.length && !nativeFailedCalls?.length) gaps.push({ source: "host_logs", reason: "no_matching_records_in_bounded_window" }); return clean({ entries, gaps, ...(appLog ? { appLog } : {}), + ...(nativeFailedCalls ? { nativeFailedCalls } : {}), window: { since: new Date(since * 1000).toISOString(), until: new Date(until * 1000).toISOString(), @@ -899,16 +1043,24 @@ export async function runDoctor(options, dependencies = {}) { throw new Error("--occurred-at must be an ISO timestamp with timezone; omit it when unknown"); } const fetchImpl = dependencies.fetchImpl ?? fetch; + const threadEnv = options.host === "codex" ? process.env.CODEX_THREAD_ID : undefined; + const collectionConversationId = /^[a-f0-9]{8}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{12}$/i.test(threadEnv ?? "") + ? threadEnv : null; const diagnosticId = randomUUID(); const report = { schemaVersion: 2, - collectorVersion: "1.2.3", + collectorVersion: "1.2.4", diagnosticId, collectedAt: new Date().toISOString(), scope: "cloud", host: options.host, hostVersion: options.hostVersion ?? null, hostVersionSource: options.hostVersion ? "agent_supplied" : "unavailable", + collectionContext: { + conversationId: collectionConversationId, + source: collectionConversationId ? "CODEX_THREAD_ID" : "unavailable", + association: "current_collection_thread; original_failed_attempt_unconfirmed", + }, environment: { platform: platform(), architecture: arch(), @@ -1063,10 +1215,11 @@ export async function runDoctor(options, dependencies = {}) { codexAppLogDir: options.codexAppLogDir, codexAppLogFiles: options.codexAppLogFiles, codexAppLogOffset: options.codexAppLogOffset, + codexStderrFile: options.codexStderrFile, conversationId: report.originalFailure.conversationId ?? report.hostSnapshot?.session?.conversationId ?? - process.env.CODEX_THREAD_ID, + collectionConversationId, }); } catch (error) { report.hostLogs = { @@ -1078,11 +1231,13 @@ export async function runDoctor(options, dependencies = {}) { disabledBySnapshot || report.hostSnapshot?.configuration?.enabled === false || report.hostSnapshot?.session?.connectionStatus === "disabled"; - if (disabled || !endpoint) { + if (options.offline || disabled || !endpoint) { report.gaps.push({ source: "probes", reason: disabled ? "host_reports_intentionally_disabled; no_requests_sent" + : options.offline + ? "offline_requested; no_requests_sent" : "registered_endpoint_unavailable; no_requests_sent", }); } else { @@ -1189,6 +1344,8 @@ export async function runDoctor(options, dependencies = {}) { report.upload = { status: disabled ? "skipped_intentionally_disabled" + : options.offline + ? "skipped_offline" : !endpoint ? "skipped_endpoint_unavailable" : options.upload @@ -1200,7 +1357,7 @@ export async function runDoctor(options, dependencies = {}) { const save = async (flag) => writeFile(path, JSON.stringify(clean(report), null, 2) + "\n", { flag, mode: 0o600 }); await save("wx"); - if (options.upload && !disabled && endpoint) { + if (options.upload && !options.offline && !disabled && endpoint) { try { const events = fragmentEvents(report); const response = await fetchImpl(new URL("/telemetry/events", endpoint.origin).href, { @@ -1240,11 +1397,13 @@ if (process.argv[1] && resolve(process.argv[1]) === fileURLToPath(import.meta.ur "occurred-at": { type: "string" }, "codex-sqlite-home": { type: "string" }, "codex-log-dir": { type: "string" }, + "codex-stderr-file": { type: "string" }, "codex-app-log-dir": { type: "string" }, "codex-app-log-file": { type: "string", multiple: true }, "codex-app-log-offset": { type: "string" }, output: { type: "string" }, upload: { type: "boolean", default: false }, + offline: { type: "boolean", default: false }, "wire-evidence": { type: "boolean", default: true }, "create-snapshot": { type: "string" }, "validate-snapshot": { type: "string" }, @@ -1284,7 +1443,7 @@ if (process.argv[1] && resolve(process.argv[1]) === fileURLToPath(import.meta.ur console.log(JSON.stringify({ snapshotValid: true, networkRequests: 0 })); } else if (values.help) { console.log( - "node mcp-doctor.mjs --create-snapshot | --validate-snapshot | --host codex|claude --server-url [--host-snapshot ] [--host-version ] [--failure-record | --original-error ] [--occurred-at ] [--codex-sqlite-home ] [--codex-log-dir ] [--codex-app-log-dir ] [--codex-app-log-file ] [--wire-evidence] [--output ] [--upload]", + "node mcp-doctor.mjs --create-snapshot | --validate-snapshot | --host codex|claude --server-url [--host-snapshot ] [--host-version ] [--failure-record | --original-error ] [--occurred-at ] [--codex-sqlite-home ] [--codex-log-dir ] [--codex-stderr-file ] [--codex-app-log-dir ] [--codex-app-log-file ] [--wire-evidence] [--output ] [--offline] [--upload]", ); } else { const { path, report } = await runDoctor({ @@ -1297,6 +1456,7 @@ if (process.argv[1] && resolve(process.argv[1]) === fileURLToPath(import.meta.ur occurredAt: values["occurred-at"], codexSqliteHome: values["codex-sqlite-home"], codexLogDir: values["codex-log-dir"], + codexStderrFile: values["codex-stderr-file"], codexAppLogDir: values["codex-app-log-dir"], codexAppLogFiles: values["codex-app-log-file"], codexAppLogOffset: @@ -1305,6 +1465,7 @@ if (process.argv[1] && resolve(process.argv[1]) === fileURLToPath(import.meta.ur : Number(values["codex-app-log-offset"]), output: values.output, upload: values.upload, + offline: values.offline, wireEvidence: values["wire-evidence"], }); console.log( diff --git a/codex/skills/chatcut-plugin-basics/scripts/mcp-evidence.mjs b/codex/skills/chatcut-plugin-basics/scripts/mcp-evidence.mjs index da0ed7c..b0ab995 100644 --- a/codex/skills/chatcut-plugin-basics/scripts/mcp-evidence.mjs +++ b/codex/skills/chatcut-plugin-basics/scripts/mcp-evidence.mjs @@ -240,10 +240,23 @@ export function evidenceSummary(report) { ...(entry.conversationId && { conversationId: entry.conversationId }), ...(entry.callId && { callId: entry.callId }), })); + const databaseReadFailures = (report.hostLogs.gaps ?? []).filter(gap => + ["codex_runtime_sqlite", "codex_native_failed_mcp_items"].includes(gap.source) && + ["unavailable", "close_failed"].includes(gap.reason)).map(gap => ({ + source: gap.source, operation: gap.operation ?? null, + code: gap.error?.code ?? null, errcode: gap.error?.errcode ?? null, + })); return { stages, otherObservations: unknown, logHints, + collectionContext: report.collectionContext ?? null, + nativeFailedCalls: (report.hostLogs.nativeFailedCalls ?? []).map((item, index) => ({ + evidence: `hostLogs.nativeFailedCalls[${index}]`, source: item.source, + nativeItemId: item.nativeItemId, idKind: item.idKind, conversationId: item.conversationId, + operation: item.operation, startedAtMs: item.startedAtMs, completedAtMs: item.completedAtMs, + originalAttemptMatch: "unconfirmed", + })), originalRequestCorrelation: { status: originalRequests.length ? "agent_reported_same_attempt" : "unconfirmed", observations: originalRequests, @@ -260,6 +273,13 @@ export function evidenceSummary(report) { } : null, hostLogCoverage: { + originalErrorRetained: report.originalFailure.status === "recorded", + originalErrorRetainedWithoutDatabase: report.originalFailure.status === "recorded" && databaseReadFailures.length > 0, + databaseReadFailures, + runtimeCollectionFailed: (report.hostLogs.gaps ?? []).some(gap => gap.source === "host_logs" && gap.reason === "collector_failed"), + nativeFailedMcpItems: report.hostLogs.nativeFailedCalls?.length ?? 0, + retainedStderrRecords: report.hostLogs.entries.filter(entry => entry.source === "codex_stderr_log").length, + priorStderrCaptureRequired: false, records: report.hostLogs.entries.length, appStartupRecords: appNotices.length, failedAppStartupRecords: failedAppNotices.length, diff --git a/docs/mcp-doctor.md b/docs/mcp-doctor.md index 4d0c7e9..961a824 100644 --- a/docs/mcp-doctor.md +++ b/docs/mcp-doctor.md @@ -12,6 +12,18 @@ need a runtime with `node:sqlite`; missing support is an explicit evidence gap. ## Evidence and delivery contract +Collector 1.2.4 keeps the complete collector in the existing basics skills. +It adds bounded Codex failed-MCP index projections, current collecting-thread +context, explicit already-retained stderr, native tool-error formats and SQL +thread scoping before the row limit. Original, lifecycle and log times stay +separate; no native identity is promoted to a server request ID. SQLite errors +retain the failing operation while original errors and independent sources +continue. `evidenceSummary.hostLogCoverage` makes these gaps explicit, and +`--offline` suppresses all probes/uploads. Already visible errors need no +preconfigured stderr. Hidden startup errors with no accessible source remain +unavailable. MCP session credentials in error text are redacted. This change +adds no separate Doctor Skill, diagnosis/repair rules or publication workflow. + Collector 1.2.3 adds a dedicated `.mcp-failure.json` input for the original host tool/runtime error, its available failure time and local conversation/call IDs. The Skill preserves this evidence before retries; a missing failure timestamp diff --git a/tests/collection-quality.test.mjs b/tests/collection-quality.test.mjs new file mode 100644 index 0000000..81040bd --- /dev/null +++ b/tests/collection-quality.test.mjs @@ -0,0 +1,109 @@ +import assert from "node:assert/strict"; +import test from "node:test"; +import { mkdtemp, writeFile, rm } from "node:fs/promises"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { DatabaseSync } from "node:sqlite"; +import { collectHostLogs } from "../codex/skills/chatcut-plugin-basics/scripts/mcp-doctor.mjs"; + +// Owned native-format fixtures test actual collector I/O, not natural failures +// or a model's autonomous collection ability. +async function fixture(t) { + const dir = await mkdtemp(join(tmpdir(), "chatcut-collection-quality-")); + t.after(() => rm(dir, { recursive: true, force: true })); + return { dir, now: Date.now() }; +} +function database(dir) { + const db = new DatabaseSync(join(dir, "logs_2.sqlite")); + db.exec("CREATE TABLE logs(id INTEGER,ts INTEGER,level TEXT,target TEXT,feedback_log_body TEXT,thread_id TEXT)"); + return db; +} +const options = ({ dir, now }) => ({ codexHome: dir, codexSqliteHome: dir, codexLogDir: dir, codexAppLogDir: dir, now, conversationId: "current-thread" }); + +test("SQLite includes the already-supported codex_rmcp_client native module and excludes other services", async (t) => { + const f = await fixture(t), db = database(f.dir); + const add = db.prepare("INSERT INTO logs VALUES(?,?,?,?,?,?)"); + add.run(1, Math.floor(f.now / 1000), "ERROR", "codex_rmcp_client::rmcp_client", 'MCP server startup failed server_name="chatcut" error=E_NATIVE_RMCP', "current-thread"); + add.run(2, Math.floor(f.now / 1000), "ERROR", "codex_rmcp_client::rmcp_client", 'MCP server startup failed server_name="other" error=PRIVATE_OTHER_SERVICE', "current-thread"); + db.close(); + const logs = await collectHostLogs("codex", options(f)); + assert.ok(logs.entries.some(e => e.source === "codex_runtime_sqlite" && e.message.includes("E_NATIVE_RMCP"))); + assert.ok(!JSON.stringify(logs).includes("PRIVATE_OTHER_SERVICE")); +}); + +test("native ERROR/WARN tools/call diagnostics keep their local IDs and unknown cause without collecting echoes", async (t) => { + const f = await fixture(t), db = database(f.dir), lines = []; + const add = db.prepare("INSERT INTO logs VALUES(?,?,?,?,?,?)"); + let id = 0; + for (const level of ["ERROR", "WARN"]) { + const context = 'request{thread_id="current-thread" call_id="local-call" server_name="chatcut" method="tools/call"}: '; + const bodies = [ + 'Transport send error: E_UNFAMILIAR_CAUSE token=PRIVATE_TOKEN error={"type":"TlsError","code":"ECONNRESET","method":"tools/call","content":["native diagnostic detail"],"cause":{"message":"connection closed"}}', + 'tool call: {"params":{"arguments":{"prompt":"}: PRIVATE_ECHO"}}}', + 'tool result: {"result":{"content":[{"text":"}: PRIVATE_ECHO"}]}}', + '{"method":"tools/call","params":{"arguments":{"prompt":"}: PRIVATE_ECHO"}}}', + 'Received response: {"result":{"content":[{"text":"}: PRIVATE_ECHO"}]}}', + '{"type":"user_message","message":"}: PRIVATE_ECHO"}', + 'Transport failure details:\n {"result":{"content":[{"text":"}: PRIVATE_ECHO"}]}}', + 'Transport failure details: "{\\"type\\":\\"user_message\\",\\"message\\":\\"}: PRIVATE_ECHO\\"}"', + 'prompt: PRIVATE_ECHO', 'transcript: PRIVATE_ECHO', + ]; + for (const body of bodies) { + add.run(++id, Math.floor(f.now / 1000), level, "codex_mcp::rmcp_client", context + body, "current-thread"); + lines.push(`${new Date(f.now).toISOString()} ${level} codex_mcp::rmcp_client: ${context}${body}`); + } + } + // An INFO trace without an error diagnostic still cannot expose tool content. + lines.push(`${new Date(f.now).toISOString()} INFO rmcp::client: request{server_name=chatcut method="tools/call"}: PRIVATE_ECHO`); + db.close(); + await writeFile(join(f.dir, "codex-tui.log"), lines.join("\n")); + const logs = await collectHostLogs("codex", options(f)); + const errors = logs.entries.filter(e => e.message.includes("E_UNFAMILIAR_CAUSE")); + assert.equal(errors.length, 4, "Both native severities and both sources must survive"); + assert.ok(errors.every(e => e.message.includes('"type":"TlsError"') && e.message.includes('"cause":{"message":"connection closed"}'))); + assert.ok(errors.every(e => e.callId === "local-call" && e.conversationId === "current-thread" && e.originalAttemptMatch === "unconfirmed")); + assert.ok(errors.every(e => !e.requestId)); + assert.ok(!JSON.stringify(logs).includes("PRIVATE_ECHO")); + assert.ok(!JSON.stringify(logs).includes("PRIVATE_TOKEN")); +}); + +test("Codex TUI excludes explicit other conversations but retains unknown association", async (t) => { + const f = await fixture(t); + const prefix = `${new Date(f.now).toISOString()} ERROR codex_mcp::rmcp_client: `; + await writeFile(join(f.dir, "codex-tui.log"), [ + `${prefix}request{thread_id=other-thread call_id=foreign-call server_name=chatcut}: PRIVATE_FOREIGN_ERROR`, + `${prefix}request{thread_id=current-thread call_id=current-call server_name=chatcut}: E_CURRENT`, + `${prefix}MCP server "chatcut": E_THREAD_UNKNOWN`, + ].join("\n")); + const logs = await collectHostLogs("codex", options(f)); + assert.ok(!JSON.stringify(logs).includes("PRIVATE_FOREIGN_ERROR")); + assert.ok(!JSON.stringify(logs).includes("foreign-call")); + assert.ok(logs.entries.some(e => e.message.includes("E_CURRENT") && e.callId === "current-call")); + assert.ok(logs.entries.some(e => e.message.includes("E_THREAD_UNKNOWN") && !e.conversationId && e.originalAttemptMatch === "unconfirmed")); + const unscoped = await collectHostLogs("codex", { ...options(f), conversationId: undefined }); + assert.ok(unscoped.entries.some(e => e.conversationId === "other-thread" && e.originalAttemptMatch === "unconfirmed")); +}); + +test("SQLite scopes before LIMIT when thread_id exists and preserves unknown or legacy thread evidence", async (t) => { + for (const hasThread of [true, false]) { + const f = await fixture(t), db = new DatabaseSync(join(f.dir, "logs_2.sqlite")); + db.exec(`CREATE TABLE logs(id INTEGER,ts INTEGER,level TEXT,target TEXT,feedback_log_body TEXT${hasThread ? ",thread_id TEXT" : ""})`); + const insert = db.prepare(`INSERT INTO logs VALUES(?,?,?,?,?${hasThread ? ",?" : ""})`); + let id = 0; + const add = (age, thread, body) => insert.run(++id, Math.floor(f.now / 1000) - age, "ERROR", "codex_mcp::rmcp_client", body, ...(hasThread ? [thread] : [])); + add(500, "current-thread", 'request{server_name=chatcut thread_id=current-thread call_id=current-call}: E_CURRENT_BEFORE_LIMIT'); + add(499, null, 'MCP server "chatcut": E_NULL_THREAD'); + add(498, "", 'MCP server "chatcut": E_EMPTY_THREAD'); + // Legacy schemas still use explicit trace IDs after the bounded query. + // Only schemas with a native column can scope before LIMIT. + const foreignCount = hasThread ? 200 : 1; + for (let i = 0; i < foreignCount; i++) + add(200 - i, "other-thread", 'request{server_name=chatcut thread_id=other-thread}: PRIVATE_FOREIGN'); + db.close(); + const logs = await collectHostLogs("codex", options(f)); + assert.ok(logs.entries.some(e => e.message.includes("E_CURRENT_BEFORE_LIMIT"))); + assert.ok(!JSON.stringify(logs).includes("PRIVATE_FOREIGN")); + for (const marker of ["E_NULL_THREAD", "E_EMPTY_THREAD"]) + assert.ok(logs.entries.some(e => e.message.includes(marker) && !e.conversationId && e.originalAttemptMatch === "unconfirmed")); + } +}); diff --git a/tests/fixtures/owned-codex-mcp-tool-error.log b/tests/fixtures/owned-codex-mcp-tool-error.log new file mode 100644 index 0000000..faca88e --- /dev/null +++ b/tests/fixtures/owned-codex-mcp-tool-error.log @@ -0,0 +1 @@ +2026-10-24T09:37:03.806685Z WARN codex_core::mcp_tool_call: MCP tool call error: "tool call error: tool call failed for `chatcut/list_projects`\n\nCaused by:\n Mcp error: -32041: Owned read-only project lookup failed: E_NATIVE_READ_ONLY_724({\"cause\":{\"code\":\"E_OWNED_SOURCE\",\"message\":\"Controlled original cause; no operation was written\"}})" diff --git a/tests/mcp-doctor.test.mjs b/tests/mcp-doctor.test.mjs index fd251f7..7407e6d 100644 --- a/tests/mcp-doctor.test.mjs +++ b/tests/mcp-doctor.test.mjs @@ -722,7 +722,7 @@ test("App fallback remains bounded and does not promote host notices into the or codexLogDir: join(dir, "empty-tui"), output: join(dir, "report.json"), }); - assert.equal(report.collectorVersion, "1.2.3"); + assert.equal(report.collectorVersion, "1.2.4"); assert.equal( report.hostLogs.entries.filter((entry) => entry.source === "codex_app_log").length, 30, @@ -770,3 +770,15 @@ test("self-contained host packages ship identical helpers and diagnostic referen ); } }); + +test("MCP session credentials in native errors are redacted across punctuation and nested JSON strings", () => { + for (let code = 0x21; code <= 0x7e; code++) { + const opaque = `opaque${String.fromCharCode(code)}SECRET_SUFFIX`; + const document = JSON.stringify({ "Mcp-Session-Id": opaque, code: "E_KEEP" }); + for (const text of [`Mcp-Session-Id: ${opaque}\nError E_KEEP`, document, `Response: ${JSON.stringify(document)}`, `Response: ${JSON.stringify(JSON.stringify(document))}`]) { + assert.ok(!redact(text).includes("SECRET_SUFFIX")); + assert.ok(redact(text).includes("E_KEEP")); + } + } + assert.ok(redact("Mcp-Session-Id: private\ncallId=local-call").includes("callId=local-call")); +}); diff --git a/tests/native-failure-index.test.mjs b/tests/native-failure-index.test.mjs new file mode 100644 index 0000000..4558919 --- /dev/null +++ b/tests/native-failure-index.test.mjs @@ -0,0 +1,146 @@ +import assert from "node:assert/strict"; +import test from "node:test"; +import { mkdtemp, writeFile, readFile, rm } from "node:fs/promises"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { DatabaseSync } from "node:sqlite"; +import { collectHostLogs, runDoctor, fragmentEvents } from "../codex/skills/chatcut-plugin-basics/scripts/mcp-doctor.mjs"; + +async function fixture(t) { + const dir = await mkdtemp(join(tmpdir(), "chatcut-native-index-")); + t.after(() => rm(dir, { recursive: true, force: true })); + return dir; +} +const now = Date.parse("2026-10-24T10:30:00Z"); +const current = "00000000-0000-0000-0000-000000000123"; +const options = dir => ({ codexHome: dir, codexSqliteHome: dir, codexLogDir: dir, codexAppLogDir: dir, conversationId: current, now }); +function database(dir) { + const db = new DatabaseSync(join(dir, "thread_history_1.sqlite")); + db.exec("CREATE TABLE thread_items(thread_id TEXT,turn_id TEXT,item_id TEXT,item_type TEXT,created_at_ms INTEGER,started_at_ms INTEGER,completed_at_ms INTEGER,item_json TEXT)"); + return db; +} +const native = extra => ({ type: "mcpToolCall", server: "chatcut", tool: "list_projects", status: "failed", + error: { message: "Unfamiliar original error token=PRIVATE_TOKEN", code: -32041, cause: { message: "E_NATIVE_CAUSE" } }, + arguments: { prompt: "PRIVATE_ARGUMENTS" }, result: { content: [{ text: "PRIVATE_RESULT" }] }, ...extra }); + +test("native index projects only scoped failed MCP metadata and keeps lifecycle/ID kinds separate", async t => { + const dir = await fixture(t), db = database(dir), add = db.prepare("INSERT INTO thread_items VALUES(?,?,?,?,?,?,?,?)"); + const insert = (id, value, extra = {}) => add.run(extra.thread ?? current, "native-turn", id, extra.type ?? "mcpToolCall", now, + extra.started === undefined ? now - 1000 : extra.started, extra.completed === undefined ? now - 900 : extra.completed, typeof value === "string" ? value : JSON.stringify(value)); + insert("native-item", native()); + insert("foreign", native({ error: { message: "PRIVATE_FOREIGN" } }), { thread: "other-thread" }); + insert("success", native({ status: "completed", error: { message: "PRIVATE_SUCCESS" } })); + insert("other-server", native({ server: "other", error: { message: "PRIVATE_OTHER_SERVER" } })); + insert("desktop", native({ server: "chatcut_desktop", error: { message: "PRIVATE_DESKTOP" } })); + insert("user", { type: "userMessage", text: "PRIVATE_USER" }, { type: "userMessage" }); + insert("assistant", { type: "agentMessage", text: "PRIVATE_ASSISTANT" }, { type: "agentMessage" }); + insert("mismatched-type", native({ type: "agentMessage", error: { message: "PRIVATE_BAD_TYPE" } })); + insert("no-lifecycle", native({ error: { message: "PRIVATE_UNKNOWN_TIME" } }), { started: null, completed: null }); + insert("old", native({ error: { message: "PRIVATE_OLD" } }), { started: now - 7200000, completed: now - 7100000 }); + insert("malformed", "not JSON PRIVATE_BAD_JSON"); + db.close(); + const logs = await collectHostLogs("codex", options(dir)); + assert.equal(logs.nativeFailedCalls.length, 1); + const item = logs.nativeFailedCalls[0]; + assert.equal(item.nativeItemId, "native-item"); + assert.match(item.idKind, /codex_native_mcp_item_id/); + assert.equal(item.startedAtMs, now - 1000); + assert.equal(item.completedAtMs, now - 900); + assert.equal(item.occurredAt, undefined); + assert.equal(item.callId, undefined); + assert.equal(item.requestId, undefined); + assert.equal(item.originalAttemptMatch, "unconfirmed"); + assert.equal(item.error.cause.message, "E_NATIVE_CAUSE"); + assert.ok(!JSON.stringify(logs).includes("PRIVATE_")); + const unknown = await collectHostLogs("codex", { ...options(dir), conversationId: undefined }); + assert.equal(unknown.nativeFailedCalls.length, 0); + assert.ok(unknown.gaps.some(g => g.reason === "known_conversation_id_unavailable; no_history_query")); + const injected = await collectHostLogs("codex", { ...options(dir), conversationId: "' OR 1=1 --" }); + assert.equal(injected.nativeFailedCalls.length, 0); +}); + +test("record/error limits and unsupported schemas remain explicit without replacing the original error", async t => { + const dir = await fixture(t), db = database(dir), add = db.prepare("INSERT INTO thread_items VALUES(?,?,?,?,?,?,?,?)"); + for (let i = 0; i < 12; i++) add.run(current, "turn", `native-${i}`, "mcpToolCall", now, now - 1000, now - i, + JSON.stringify(native({ error: { message: i === 0 ? "X".repeat(140000) : i === 1 ? "X".repeat(20000) + "E_FULL_TAIL" : "E_NATIVE" } }))); + db.close(); + const logs = await collectHostLogs("codex", options(dir)); + assert.equal(logs.nativeFailedCalls.length, 10); + assert.ok(logs.gaps.some(g => g.reason === "native_failure_record_limit")); + assert.ok(logs.gaps.some(g => g.reason === "native_error_size_limit")); + assert.equal(logs.nativeFailedCalls.find(i => i.nativeItemId === "native-0").error, null); + assert.ok(logs.nativeFailedCalls.find(i => i.nativeItemId === "native-1").error.message.endsWith("E_FULL_TAIL")); + const unsupportedDir = await fixture(t), old = new DatabaseSync(join(unsupportedDir, "thread_history_1.sqlite")); + old.exec("CREATE TABLE thread_items(thread_id TEXT,item_json TEXT)"); old.close(); + const unsupported = await collectHostLogs("codex", options(unsupportedDir)); + assert.ok(unsupported.gaps.some(g => g.reason === "unsupported_schema; no_conversation_rows_read")); +}); + +test("native query errors retain their failing operation and local evidence is not trimmed to fit upload", async t => { + const dir = await fixture(t), db = new DatabaseSync(join(dir, "thread_history_1.sqlite")); + db.exec(`CREATE VIEW thread_items AS SELECT '${current}' AS thread_id,'turn' AS turn_id,'native' AS item_id, + 'mcpToolCall' AS item_type,${now - 1000} AS started_at_ms,${now - 900} AS completed_at_ms, + abs(-9223372036854775808) AS item_json`); + db.close(); + const runtime = new DatabaseSync(join(dir, "logs_2.sqlite")); + runtime.exec("CREATE TABLE logs(id INTEGER,ts INTEGER,level TEXT,target TEXT)"); + runtime.close(); + const broken = await collectHostLogs("codex", options(dir)); + assert.ok(broken.gaps.some(g => g.source === "codex_native_failed_mcp_items" && g.operation === "select_failed_mcp_items" && g.error?.message)); + assert.ok(broken.gaps.some(g => g.source === "codex_runtime_sqlite" && g.operation === "prepare_runtime_logs_query" && g.error?.message.includes("feedback_log_body"))); + const largeDir = await fixture(t), large = database(largeDir); + const insert = large.prepare("INSERT INTO thread_items VALUES(?,?,?,?,?,?,?,?)"); + for (let i = 0; i < 3; i++) insert.run(current, "turn", `native-${i}`, "mcpToolCall", now, now - 1000, now - i, + JSON.stringify(native({ error: { message: "X".repeat(100000) + "E_UNTRIMMED_TAIL" } }))); + large.close(); + const logs = await collectHostLogs("codex", options(largeDir)); + const { report, path } = await runDoctor({ host: "codex", serverUrl: "http://127.0.0.1:9/api/external-mcp/mcp", offline: true, output: join(largeDir, "large.json") }, { collectLogs: async () => logs }); + assert.ok(report.hostLogs.nativeFailedCalls.every(i => i.error.message.endsWith("E_UNTRIMMED_TAIL"))); + assert.ok((await readFile(path, "utf8")).length > 256 * 1024); + assert.throws(() => fragmentEvents(report), /upload budget; complete local report retained/); + assert.ok(report.hostLogs.nativeFailedCalls.every(i => i.error.message.endsWith("E_UNTRIMMED_TAIL"))); +}); + +test("current collection context and native item references never fill original fields", async t => { + const dir = await fixture(t), before = process.env.CODEX_THREAD_ID; + process.env.CODEX_THREAD_ID = current; + t.after(() => { if (before === undefined) delete process.env.CODEX_THREAD_ID; else process.env.CODEX_THREAD_ID = before; }); + const failure = join(dir, "original.mcp-failure.json"); + await writeFile(failure, JSON.stringify({ schemaVersion: 1, source: "host_tool_result", serverName: "chatcut", occurredAt: null, + operation: "list_projects", error: { message: "E_ORIGINAL" } })); + let query; + const { report, path } = await runDoctor({ host: "codex", failureRecord: failure, offline: true, output: join(dir, "out.json") }, { + collectLogs: async (_, value) => { query = value; return { entries: [], gaps: [], nativeFailedCalls: [{ source: "codex_native_failed_mcp_items", + nativeItemId: "PRIVATE_NATIVE_ID", idKind: "codex_native_mcp_item_id", conversationId: current, turnId: "PRIVATE_TURN_ID", + operation: "list_projects", startedAtMs: now - 1000, completedAtMs: now - 900, error: { message: "E_ORIGINAL" } }] }; }, + fetchImpl: () => assert.fail("Offline capture sends no request"), + }); + assert.equal(report.collectionContext.conversationId, current); + assert.equal(report.collectionContext.source, "CODEX_THREAD_ID"); + assert.equal(query.conversationId, current); + assert.equal(report.originalFailure.occurredAt, null); + assert.equal(report.originalFailure.conversationId, undefined); + assert.equal(report.originalFailure.callId, undefined); + assert.equal(report.evidenceSummary.originalLocalCall, null); + assert.equal(JSON.parse(await readFile(path, "utf8")).collectionContext.conversationId, current); + assert.equal(report.evidenceSummary.nativeFailedCalls[0].nativeItemId, "PRIVATE_NATIVE_ID"); + assert.equal(report.evidenceSummary.nativeFailedCalls[0].originalAttemptMatch, "unconfirmed"); +}); + +test("an explicit retained native stderr tail preserves log time and errors without importing echoes or original fields", async t => { + const dir = await fixture(t), path = join(dir, "owned.codex-stderr.log"); + const line = '2026-10-24T10:29:59.123456Z WARN codex_mcp::rmcp_client: MCP server startup failed server_name="chatcut" error=HTTP503 E_REAL_NATIVE token=PRIVATE_TOKEN'; + await writeFile(path, "unrelated log record\n".repeat(8000) + line + "\n" + + '2026-10-24T10:29:59Z ERROR codex_mcp::rmcp_client: request{server_name=chatcut}: tool result: {"content":[{"text":"PRIVATE_ECHO"}]}\n'); + const logs = await collectHostLogs("codex", { ...options(dir), codexStderrFile: path }); + const found = logs.entries.filter(e => e.source === "codex_stderr_log"); + assert.equal(found.length, 1); + assert.equal(found[0].loggedAt, "2026-10-24T10:29:59.123Z"); + assert.equal(found[0].occurredAt, undefined); + assert.equal(found[0].originalAttemptMatch, "unconfirmed"); + assert.ok(found[0].message.includes("E_REAL_NATIVE")); + assert.ok(!JSON.stringify(logs).includes("PRIVATE_")); + assert.ok(logs.gaps.some(g => g.source === "codex_stderr_log" && g.reason === "only_log_tail_read")); + const bad = await collectHostLogs("codex", { ...options(dir), codexStderrFile: join(dir, "auth.json") }); + assert.ok(bad.gaps.some(g => g.source === "codex_stderr_log" && g.reason === "unavailable")); +}); diff --git a/tests/real-native-log.test.mjs b/tests/real-native-log.test.mjs new file mode 100644 index 0000000..c2873d6 --- /dev/null +++ b/tests/real-native-log.test.mjs @@ -0,0 +1,56 @@ +import assert from "node:assert/strict"; +import test from "node:test"; +import { mkdtemp, readFile, writeFile, rm } from "node:fs/promises"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { DatabaseSync } from "node:sqlite"; +import { collectHostLogs } from "../codex/skills/chatcut-plugin-basics/scripts/mcp-doctor.mjs"; + +// Recorded native stderr from an owned real-model Codex CLI call against a +// local read-only MCP service. TUI/SQLite below are component replay containers, +// not claims that this event was persisted there by that native session. +const line = (await readFile(new URL("./fixtures/owned-codex-mcp-tool-error.log", import.meta.url), "utf8")).trimEnd(); +const now = Date.parse("2026-10-24T09:37:10Z"); +const occurredAt = "2026-10-24T09:37:03.806Z"; +async function fixture(t) { + const dir = await mkdtemp(join(tmpdir(), "chatcut-native-error-")); + t.after(() => rm(dir, { recursive: true, force: true })); + return dir; +} +const options = dir => ({ codexHome: dir, codexSqliteHome: dir, codexLogDir: dir, codexAppLogDir: dir, now }); + +test("the exact owned native MCP tool error survives text and SQLite component replay", async t => { + const dir = await fixture(t); + await writeFile(join(dir, "codex-tui.log"), line + "\n"); + const db = new DatabaseSync(join(dir, "logs_2.sqlite")); + db.exec("CREATE TABLE logs(id INTEGER,ts INTEGER,level TEXT,target TEXT,feedback_log_body TEXT)"); + const body = line.split("codex_core::mcp_tool_call: ")[1]; + db.prepare("INSERT INTO logs VALUES(?,?,?,?,?)").run(1, now / 1000 - 7, "WARN", "codex_core::mcp_tool_call", body); + db.close(); + const logs = await collectHostLogs("codex", options(dir)); + const text = logs.entries.find(e => e.source === "codex_tui_log"); + const sqlite = logs.entries.find(e => e.source === "codex_runtime_sqlite"); + assert.equal(text.message, line); + assert.equal(text.occurredAt, occurredAt); + assert.equal(sqlite.message, body); + for (const entry of [text, sqlite]) { + assert.ok(entry.message.includes("-32041") && entry.message.includes("E_OWNED_SOURCE")); + assert.equal(entry.callId, undefined); + assert.equal(entry.conversationId, undefined); + assert.equal(entry.requestId, undefined); + assert.equal(entry.originalAttemptMatch, "unconfirmed"); + } +}); + +test("exact native module support excludes other services, arbitrary core logs and content echoes", async t => { + const dir = await fixture(t); + await writeFile(join(dir, "codex-tui.log"), [ + line.replace("chatcut/list_projects", "chatcut_desktop/list_projects"), + line.replace("chatcut/list_projects", "other/list_projects"), + line.replace("codex_core::mcp_tool_call", "codex_core::unrelated"), + line.replace("WARN", "INFO"), + '2026-10-24T09:37:03Z WARN codex_core::mcp_tool_call: tool result server_name=chatcut {"content":[{"text":"PRIVATE_ECHO"}]}', + '2026-10-24T09:37:03Z WARN codex_core::mcp_tool_call: Unrelated message server_name=chatcut PRIVATE_ECHO', + ].join("\n")); + assert.equal((await collectHostLogs("codex", options(dir))).entries.length, 0); +}); diff --git a/tests/windows-db-fallback.test.mjs b/tests/windows-db-fallback.test.mjs new file mode 100644 index 0000000..664d5b9 --- /dev/null +++ b/tests/windows-db-fallback.test.mjs @@ -0,0 +1,86 @@ +import assert from "node:assert/strict"; +import test from "node:test"; +import { mkdtemp, writeFile, readFile, rm } from "node:fs/promises"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { execFile } from "node:child_process"; +import { promisify } from "node:util"; +import { fileURLToPath } from "node:url"; +import { runDoctor } from "../codex/skills/chatcut-plugin-basics/scripts/mcp-doctor.mjs"; + +const error = { message: "Unfamiliar provider error E_FALLBACK_NEW: transcript/tool_call are native error words", + code: "E_UNFAMILIAR_1024", cause: { type: "OpaqueNativeError", message: "Keep this original cause" } }; + +test("the bundled basics CLI saves an offline report even when upload is also requested", async t => { + const { dir, failure } = await fixture(t), output = join(dir, "cli.mcp-report.json"); + const helper = fileURLToPath(new URL("../codex/skills/chatcut-plugin-basics/scripts/mcp-doctor.mjs", import.meta.url)); + await promisify(execFile)(process.execPath, [helper, "--host", "claude", "--server-url", "http://127.0.0.1:1/api/external-mcp/mcp", "--failure-record", failure, "--output", output, "--offline", "--upload"]); + const report = JSON.parse(await readFile(output, "utf8")); + assert.equal(report.collectorVersion, "1.2.4"); + assert.deepEqual(report.originalFailure.error, error); + assert.equal(report.upload.status, "skipped_offline"); + assert.equal(report.entryProbe, undefined); + assert.equal(report.probes.length, 0); + assert.ok(report.gaps.some(g => g.reason === "offline_requested; no_requests_sent")); +}); +async function fixture(t) { + const dir = await mkdtemp(join(tmpdir(), "chatcut-db-fallback-")); + t.after(() => rm(dir, { recursive: true, force: true })); + const failure = join(dir, "original.mcp-failure.json"); + await writeFile(failure, JSON.stringify({ schemaVersion: 1, source: "host_tool_result", serverName: "chatcut", + occurredAt: null, operation: "list_projects", error })); + return { dir, failure }; +} +// Windows error14 is supplied as an owned unit fixture here. Real MXC access +// failure and native-source continuation are verified separately, not simulated +// by changing permissions, corrupting a user database or copying its WAL. +const dbGaps = ["codex_runtime_sqlite", "codex_native_failed_mcp_items"].map(source => ({ + source, reason: "unavailable", operation: "select_failed_mcp_items", + error: { code: "ERR_SQLITE_ERROR", errcode: 14, message: "unable to open database file" }, +})); + +test("database errors do not replace the visible original error or independent App evidence", async t => { + const { dir, failure } = await fixture(t); + const { report, path } = await runDoctor({ host: "codex", failureRecord: failure, offline: true, output: join(dir, "fallback.mcp-report.json") }, { + fetchImpl: () => assert.fail("No fallback network requests"), + collectLogs: async () => ({ entries: [{ source: "codex_app_log", occurredAt: "2026-10-24T10:00:00Z", + message: '2026-10-24T10:00:00Z warning [AppServerConnection] mcp_server_startup_status_updated error="PRIVATE_APP_ERROR" server=chatcut status=failed threadId=null', + originalAttemptMatch: "unconfirmed" }], gaps: dbGaps, nativeFailedCalls: [] }), + }); + assert.deepEqual(report.originalFailure.error, error); + assert.equal(report.originalFailure.occurredAt, null); + assert.equal(report.originalFailure.callId, undefined); + assert.equal(report.originalFailure.requestId, undefined); + const coverage = report.evidenceSummary.hostLogCoverage; + assert.equal(coverage.originalErrorRetainedWithoutDatabase, true); + assert.equal(coverage.databaseReadFailures.length, 2); + assert.ok(coverage.databaseReadFailures.every(g => g.errcode === 14)); + assert.equal(coverage.appStartupRecords, 1); + assert.equal(coverage.failedAppStartupRecords, 1); + assert.equal(coverage.priorStderrCaptureRequired, false); + assert.equal(coverage.retainedStderrRecords, 0); + assert.equal(report.upload.status, "skipped_offline"); + assert.deepEqual(JSON.parse(await readFile(path, "utf8")).originalFailure.error, error); +}); + +test("an unexpected runtime collector exception still produces the saved original error and explicit coverage", async t => { + const { dir, failure } = await fixture(t); + const { report, path } = await runDoctor({ host: "codex", failureRecord: failure, offline: true, output: join(dir, "collector-failed.mcp-report.json") }, { + collectLogs: async () => { throw Object.assign(Error("Unexpected runtime read failure"), { code: "ERR_SQLITE_ERROR", errcode: 14 }); }, + }); + assert.deepEqual(report.originalFailure.error, error); + assert.equal(report.evidenceSummary.hostLogCoverage.originalErrorRetained, true); + assert.equal(report.evidenceSummary.hostLogCoverage.runtimeCollectionFailed, true); + assert.equal(report.hostLogs.gaps[0].error.errcode, 14); + assert.ok((await readFile(path, "utf8")).includes("E_FALLBACK_NEW")); +}); + +test("database failure without an exposed original error is not called successful original capture", async t => { + const { dir } = await fixture(t); + const { report } = await runDoctor({ host: "codex", offline: true, output: join(dir, "unknown.mcp-report.json") }, { + collectLogs: async () => ({ entries: [], gaps: dbGaps, nativeFailedCalls: [] }), + }); + assert.equal(report.evidenceSummary.hostLogCoverage.originalErrorRetained, false); + assert.equal(report.evidenceSummary.hostLogCoverage.originalErrorRetainedWithoutDatabase, false); + assert.equal(report.originalFailure.occurredAt, null); +});