From deb90ee9f06bcfdf3281ac9dfbc0f11fe95fbeb5 Mon Sep 17 00:00:00 2001 From: Yao Jingxi <23722032@bjtu.edu.cn> Date: Wed, 4 Nov 2026 10:32:06 +0800 Subject: [PATCH 1/3] =?UTF-8?q?feat(sdk):=20=E4=B8=89=E7=A7=8D=20SDK=20?= =?UTF-8?q?=E6=8E=A5=E5=85=A5=20litheLogging=201=20=E7=BB=93=E6=9E=84?= =?UTF-8?q?=E5=8C=96=E8=AF=8A=E6=96=AD?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Node、Java、Rust SDK 在 initialize 中强制协商 litheLogging 1，删除自由文本 log API，改为通过 lithe/log 上报受控事实（finished/failed/degraded/recovered） - 操作终态自动上报并保留真实 op；成功可按注册或当前调用抑制，失败始终保留； 初始化完成前最多缓存八条，响应后发送；正常终态先于 RPC 响应 - 快捷键导入请求 lithe/keymap/import 也自动上报终态，事实中的 operation 用 Core 注册的线协议方法名，而不是按 provider 区分的调用 id；三种 SDK 的 operation 白名单同步加入该方法 - Rust SDK 在捕获范围内屏蔽 panic payload，范围外保留原 panic hook - 新增 guides/plugin-logging.md，更新三种 SDK README、示例与端到端场景 --- README.md | 4 +- guides/plugin-logging.md | 79 ++++++ scripts/sdk-e2e.mjs | 4 +- sdk/e2e/plugin_sdk/backend.rs | 2 + sdk/e2e/plugin_sdk/mod.rs | 18 ++ sdk/e2e/plugin_sdk/vcs.rs | 9 +- sdk/java/README.md | 22 +- .../org/example/samplebuild/SampleBuild.java | 5 +- .../github/litheidea/plugin/sdk/Backend.java | 99 +++++--- .../litheidea/plugin/sdk/CallContext.java | 10 +- .../litheidea/plugin/sdk/Cancellation.java | 9 +- .../litheidea/plugin/sdk/Diagnostics.java | 72 ++++++ .../litheidea/plugin/sdk/HostChannel.java | 4 +- .../litheidea/plugin/sdk/PluginError.java | 2 +- .../litheidea/plugin/sdk/Processes.java | 14 +- .../litheidea/plugin/sdk/BackendTest.java | 86 ++++++- .../litheidea/plugin/sdk/KeymapTest.java | 11 + .../github/litheidea/plugin/sdk/TestHost.java | 2 + sdk/node/README.md | 27 +- .../examples/sample-build/backend/main.mjs | 3 +- sdk/node/src/backend.mjs | 88 +++++-- sdk/node/src/diagnostics.mjs | 34 +++ sdk/node/src/errors.mjs | 4 +- sdk/node/src/host.mjs | 4 +- sdk/node/src/index.d.ts | 15 +- sdk/node/test/backend.test.mjs | 18 +- sdk/node/test/build.test.mjs | 2 +- sdk/node/test/diagnostics.test.mjs | 85 +++++++ sdk/node/test/harness.mjs | 2 +- sdk/node/test/keymap.test.mjs | 3 + sdk/node/test/vcs.test.mjs | 2 +- sdk/rust/README.md | 24 +- sdk/rust/examples/sample-backend/src/main.rs | 21 +- sdk/rust/plugin-sdk/src/backend.rs | 239 ++++++++++++------ sdk/rust/plugin-sdk/src/diagnostics.rs | 169 +++++++++++++ sdk/rust/plugin-sdk/src/error.rs | 4 +- sdk/rust/plugin-sdk/src/host.rs | 4 +- sdk/rust/plugin-sdk/src/lib.rs | 6 +- sdk/rust/plugin-sdk/src/panic_boundary.rs | 29 +++ sdk/rust/plugin-sdk/src/stdio.rs | 5 +- sdk/rust/plugin-sdk/tests/common/mod.rs | 3 +- sdk/rust/plugin-sdk/tests/keymap.rs | 25 +- sdk/rust/plugin-sdk/tests/session.rs | 160 +++++++++++- 43 files changed, 1208 insertions(+), 220 deletions(-) create mode 100644 guides/plugin-logging.md create mode 100644 sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Diagnostics.java create mode 100644 sdk/node/src/diagnostics.mjs create mode 100644 sdk/node/test/diagnostics.test.mjs create mode 100644 sdk/rust/plugin-sdk/src/diagnostics.rs create mode 100644 sdk/rust/plugin-sdk/src/panic_boundary.rs diff --git a/README.md b/README.md index 9aedd21..8f94ada 100644 --- a/README.md +++ b/README.md @@ -14,6 +14,7 @@ | 跟着教程完整做一遍 | [教程](#教程) | | 写 `plugin.json` 时有提示和校验 | [在编辑器里校验](#在编辑器里校验-pluginjson) | | 需要自己的后端进程 | [插件后端 SDK](#插件后端-sdk可选) | +| 接入宿主日志、排查插件故障 | [插件接入统一日志](guides/plugin-logging.md) | | 参考现成插件 | [示例插件](#示例插件) | | 查字段的准确含义 | [插件契约](#插件契约) | @@ -34,7 +35,7 @@ Lithe 读取并校验 `plugin.json`，然后自己启动其中声明的外部进 - `id` 用你自己的反向域名，例如 `io.github.<你的用户名>.zig-support`。`dev.lithe` 和 `dev.lithe.*` 是官方保留命名空间。 - `vendor.signatureRequirement` 写 `"none"`。社区插件不带 Lithe 签名，用户安装前会看到完整的程序、权限和来源，并确认。 - 包内路径只用 `/`，不能有 `..`、绝对路径或符号链接。 -- 插件包安装后是只读的。缓存、状态和日志写到 Lithe 通过启动模板传给你的目录（`${stateDir}`、`${workspaceStateDir}`），不要写进插件包。 +- 插件包安装后是只读的。缓存和状态使用 Lithe 通过启动模板传入的 `${stateDir}`、`${workspaceStateDir}`；诊断日志使用 SDK 与宿主统一入口。确需原生文件日志时，先确认目标宿主支持 `${logDir}`，详见[插件接入统一日志](guides/plugin-logging.md)。 ## 五步做出第一个插件 @@ -128,6 +129,7 @@ SDK 的源码都在本仓库的 `sdk/` 下，发布在[本仓库的 Releases](ht | 教程 | 内容 | | --- | --- | | [LSP 插件完整生命周期](guides/lsp-plugin-lifecycle.md) | 从 Lua 模板开始：清单、服务器打包、激活、状态目录、停止、升级与卸载 | +| [插件接入统一日志](guides/plugin-logging.md) | 三 SDK 的安全失败边界、受管诊断通道、macOS v2 / Windows v1 状态，以及 `${logDir}` 的本地会话生命周期 | | [原生构建工作流（开发中）](guides/native-build-workflows.md) | Node/Java SDK 的构建执行、精确测试、运行准备，以及未提交源码的真实 Core 验证 | | [构建、运行与测试接入](guides/build-tool-integration.md) | 可用的执行提供者示例、工程后端边界，以及开发中的 API 3 状态 | | [编写调试适配器插件](guides/debug-adapter-plugin.md) | API 4：从最小清单到启动方式、先编译再调试的 `executable`、调试控制台补全，以及预发布与转正 | diff --git a/guides/plugin-logging.md b/guides/plugin-logging.md new file mode 100644 index 0000000..d5b6053 --- /dev/null +++ b/guides/plugin-logging.md @@ -0,0 +1,79 @@ +# 插件接入统一日志 + +新版本插件使用 `litheLogging` 1 与 `lithe/log` 发送受限的操作事实，由宿主的共享事件目录、脱敏、队列和文件写入器落盘。三个 SDK 不再提供自由文本 `log` 接口，也没有 stderr 回退。插件无需实现 v2 文件格式、文件轮转、脱敏器或后台写入线程。 + +宿主必须在 initialize 中提供 `capabilities.experimental.litheLogging.versions: [1]`，SDK 回复 `capabilities.experimental.litheLogging.version: 1`。缺少协议时，新 SDK 拒绝初始化；不自动退回旧日志。初始化尚未协商时的失败只通过原有 RPC 错误与宿主进程生命周期记录，不能提前发送未协商的日志通知。 + +本文描述源码中的新 API。插件本轮将源码与真实哈希一起固定在可复现的构建输入中；正式发布 SDK 后也可以改为锁定真实 release tag 与 SHA-256。不要引用不存在的发布版本或开发机的绝对 path 依赖。 + +## 每种事实与级别 + +| `kind` | v2 目录事件 | 级别与用途 | +| --- | --- | --- | +| `operationFinished` | `plugins.operation.finished` | INFO，关键用户操作的真实成功终态 | +| `operationFailed` | `plugins.operation.failed` | ERROR，影响请求结果的失败；SDK 在拥有结果的边界发送一次 | +| `degraded` | `plugins.operation.fallback_selected` | WARN，已处理并选择回退的失败 | +| `recovered` | `plugins.operation.recovery_finished` | WARN，曾失败后的真实恢复 | + +`operationFinished` 和 `operationFailed` 必须有单调时钟计算的 `durationMs`。失败、降级、恢复使用受控的 `code`；成功没有 `code`。可选 `count` 与 `durationMs` 都是 0…9007199254740991 的整数。API 不接受原始 message、stack、request、URL、SQL、命令输出或字段字典。 + +`operation` 只接受本 SDK 已注册的函数 ID 或封闭协议操作，超过 64 字节的已注册函数 ID 统一为 `function-call`。公开的协议操作包括 initialize/shutdown/notification/function-call/result-encoding、SDK 已知的 `lithe/build/*` 与 `lithe/vcs/*` 方法，以及快捷键导入请求 `lithe/keymap/import`（三种 SDK 自动上报其终态）；任意用户文本即使字符合法也不接受。`code` 是最长 64 字节的 ASCII 类别标识，不是错误正文。 + +通道由宿主从已校验的安装插件 ID 得到 `plugins//host`，插件不能更改通道或拼接路径。上下文诊断优先携带宿主原始 `operationID`，缺少合法值时沿用当前请求原始 JSON-RPC ID（安全字符串或整数的十进制字符串），wire 名为 `operationId`，只保留最长 128 字节的受控 ASCII 标识；无真实身份时省略。通知没有请求 ID，不生成回退身份。后台共享任务可以使用 backend/handle 的无 op 诊断，不能伪造一个操作 ID。 + +## 三个 SDK 的用法 + +```js +backend.function('project.refresh', async (params, context) => { + // 只在决定继续执行的真实降级分支调用，不把异常正文传进日志。 + context.diagnostics.degraded('project.refresh', 'cache_unavailable', 1); + return refreshWithoutCache(params); +}); +// 高频读取或轮询不产生 INFO 成功噪声，失败仍自动记录。 +backend.function('project.inspect', (params) => inspectProject(params)); +backend.suppressSuccessDiagnostics('project.inspect'); +backend.diagnostics.recovered('project.refresh', 'cache_restored'); +``` + +```java +context.diagnostics().degraded("lithe/build/model", "snapshot_unavailable", 1L); +backend.diagnostics().recovered("lithe/build/model", "snapshot_restored"); +backend.suppressSuccessDiagnostics("lithe/build/dependencies"); +``` + +```rust +context.diagnostics().degraded("query.run", "rows_truncated", Some(1))?; +handle.diagnostics().recovered("query.run", "connection_restored", None)?; +backend.suppress_success_diagnostics("query.inspect")?; +``` + +`degraded`、`recovered` 的 operation 必须已注册，静态示例需要放到实际的注册完成之后。Rust 的返回错误只表达调用参数非法；协议写入复用现有 writer，诊断传输失败不会把已经成功的用户操作改成失败。没有额外 writer 或后台队列。 + +混合用户操作和高频读取的单个入口可以在当前调用上使用 `context.suppressSuccessDiagnostics()`（Rust 为 `context.suppress_success_diagnostics()`）；该决定只影响本次成功事实，不影响其他调用与失败。 + +SDK 在函数与受管 build/VCS 请求的结果边界自动发送一次终态，通知在 RPC 响应之前发送，宿主才能关联仍活动的请求。不要在处理函数里先发送失败再返回或抛出同一次失败。取消不产生失败事件，正常缺失的收尾对象不应产生 WARN。高频只读、预览、统计与轮询通过 `suppressSuccessDiagnostics` / `suppress_success_diagnostics` 关闭成功事实；失败与真正降级仍保留。 + +Rust SDK 用一次安装的 panic hook 包装器，仅在线程处于 SDK 拥有的 catch 边界时屏蔽原始 payload 输出，随后发送固定 `panic` 类别。其他线程和边界外的 panic 继续执行原 hook。不要把用户内容放进 panic，插件也不要在 SDK 启动后替换该 hook 来恢复正文输出。 + +## 上游诊断与文件位置 + +上游语言服务器的 stderr、`window/logMessage` 继续由宿主接收；它们不是插件自己的结构化日志入口。插件不得把源码、协议载荷、SQL、HTTP body 或构建输出复制进上游诊断，以为脱敏与截断能使其安全。控制台输出走已有 Build、Run、Test、VCS 或插件界面结果。 + +macOS 的日志窗口与导出读取 v2。Windows 的持久化仍是 v1，新的 Core 接收与目录事件不等于 Windows 文件窗口已经迁移；只有在对应目标平台执行工作流后才能声明该平台已验证。 + +只有上游工具确实只能写文件时，才使用 `${logDir}`。宿主显式提供当前会话的 `plugins//files/`，通过可写存储适配器创建，不能从插件安装路径或 app bundle 推导： + +- 日志目录只属于当前会话，不保存数据库、索引、下载或工作区状态，不跨工作树共享。 +- 缓存和状态继续使用 `${stateDir}`、`${workspaceStateDir}`。 +- 日志存储不可用时，宿主不提供该变量。远程进程不能使用本机日志目录；引用 `${logDir}` 却没有绝对 `logDirectory` 的启动计划会失败。 +- 不需要原生文件的插件不要增加这个启动依赖。先核对目标宿主和平台确实支持，再修改启动模板。 +- 原生文件不自动变成 v2 时间线事件，不能再把整个文件打印进 stderr。 +- app bundle、插件包、Windows 安装目录运行时只读；日志与锁文件不得改变签名或 Sparkle 增量更新基线。 + +## 最小验证 + +1. 用已有有界协议测试确认 logging v1 协商、四类事实、级别、原始操作关联、成功抑制、取消和非法参数拒绝。 +2. 触发真实失败，确认原有用户错误码与提示保持不变，诊断只有固定类别，不含请求正文、原始异常或堆栈。 +3. 使用真实 Core 查询 `diagnostics.drainCoreEvents`，核对目录事件与 `op`；不要把 v1 poll 中的旧 detail 当作新结构化记录。 +4. 在目标宿主中安装并执行对应工作流，核对日志窗口。SDK 组件通过不能替代产品验收。 +5. 原生日志位置有变化时比较工作流前后安装目录清单或哈希，确认发行资源不变；结束后清理本轮进程。 diff --git a/scripts/sdk-e2e.mjs b/scripts/sdk-e2e.mjs index 80fd836..3e7edc4 100644 --- a/scripts/sdk-e2e.mjs +++ b/scripts/sdk-e2e.mjs @@ -124,8 +124,10 @@ async function copyScenario(destination) { async function javaSample() { if (process.env.LITHE_PLUGIN_SDK_JAVA_SAMPLE) return resolve(process.env.LITHE_PLUGIN_SDK_JAVA_SAMPLE); + // Shade can otherwise reuse a sample JAR containing a previous SDK after only + // the reactor dependency changed. E2E must execute the current SDK sources. await run(await which('mvn'), ['-B', '-ntp', '-q', '-f', join(repository, 'sdk/java/pom.xml'), - '-DskipTests', 'package']); + '-DskipTests', 'clean', 'package']); const jar = join(repository, 'sdk/java/examples/sample-build/target/sample-build.jar'); await access(jar); return jar; diff --git a/sdk/e2e/plugin_sdk/backend.rs b/sdk/e2e/plugin_sdk/backend.rs index 250d537..90ca375 100644 --- a/sdk/e2e/plugin_sdk/backend.rs +++ b/sdk/e2e/plugin_sdk/backend.rs @@ -117,6 +117,8 @@ pub fn run_backend_scenario(package: &Path) { "a machine path reached the host: {failed}" ); + super::assert_log_facts(&plugin_id, &[("save", "plugins.operation.finished", "INFO"), ("fail", "plugins.operation.failed", "ERROR")]); + // Credentials travel as host requests and never touch the state directory. let mut store = BTreeMap::new(); let remembered = serve_host( diff --git a/sdk/e2e/plugin_sdk/mod.rs b/sdk/e2e/plugin_sdk/mod.rs index 8d534a5..d3f9fa4 100644 --- a/sdk/e2e/plugin_sdk/mod.rs +++ b/sdk/e2e/plugin_sdk/mod.rs @@ -456,6 +456,7 @@ pub fn run_sample_scenario(sample: &Sample) { dependencies["dependencies"]["dependencies"][0]["name"], "left-pad", "{dependencies}" ); + assert_log_facts(&plugin_id, &[("model", "plugins.operation.finished", "INFO"), ("dependencies", "plugins.operation.finished", "INFO")]); // A multi-step function: prepare, run the tool, record a snapshot. let built = session.call( @@ -495,6 +496,8 @@ pub fn run_sample_scenario(sample: &Sample) { ); assert_eq!(failed["error"]["pluginErrorCode"], "sample.buildFailed"); + assert_log_facts(&plugin_id, &[("build-app", "plugins.operation.finished", "INFO"), ("build-broken", "plugins.operation.failed", "ERROR")]); + // Cancelling a running build ends the tool the backend started. session.invoke( "build-slow", @@ -581,3 +584,18 @@ pub fn run_sample_scenario(sample: &Sample) { "cleared state left files behind: {state:?}" ); } + +/// Typed SDK notifications reach the Core-owned queue, with host operation correlation. +fn assert_log_facts(plugin: &str, expected: &[(&str, &str, &str)]) { + let drained = core("diagnostics.drainCoreEvents", json!({})); + let records = drained["events"].as_array().expect("bounded catalog facts"); + for (operation, event, level) in expected { + let matches: Vec<_> = records.iter().filter(|fact| fact["event"] == *event && fact["op"] == *operation).collect(); + assert_eq!(matches.len(), 1, "one terminal {event} for {operation}: {drained}"); + assert_eq!(matches[0]["level"], *level); + assert_eq!(matches[0]["channel"], format!("plugins/{plugin}/host")); + assert!(matches[0]["fields"]["duration_ms"].as_u64().is_some()); + assert!(!matches[0].to_string().contains("built app")); + assert!(!matches[0].to_string().contains("s3cr3t")); + } +} diff --git a/sdk/e2e/plugin_sdk/vcs.rs b/sdk/e2e/plugin_sdk/vcs.rs index 6f5cd74..513e382 100644 --- a/sdk/e2e/plugin_sdk/vcs.rs +++ b/sdk/e2e/plugin_sdk/vcs.rs @@ -53,7 +53,14 @@ impl Provider<'_> { "arguments": arguments, }), ); - self.session.completion(&operation_id) + let completed = self.session.completion(&operation_id); + let (event, level) = if completed.get("error").is_some() { + ("plugins.operation.failed", "ERROR") + } else { + ("plugins.operation.finished", "INFO") + }; + super::assert_log_facts(&self.session.plugin_id, &[(&operation_id, event, level)]); + completed } /// Sends one operation and returns the reply as `vcs.decodeReply` normalizes it. diff --git a/sdk/java/README.md b/sdk/java/README.md index bd281dd..b5c827b 100644 --- a/sdk/java/README.md +++ b/sdk/java/README.md @@ -84,6 +84,18 @@ SHA-256. The SDK is not published to a Maven repository. Use it like this: A plugin package is installed read-only and must run offline, so the backend JAR it starts must hold everything it loads. +## Logging + +The new SDK requires `experimental.litheLogging` version 1 at initialization. +See [plugin logging](../../guides/plugin-logging.md) for the typed diagnostics +API, host-owned catalog, exact levels, operation correlation and `${logDir}`. +Use `diagnostics.degraded/recovered` (Rust: `diagnostics().degraded/recovered`) +for handled fallback or recovery facts. Function and build/VCS terminal facts +are automatic; do not log a failure before returning it to the SDK. Suppress +successful high-frequency reads with `suppressSuccessDiagnostics(operation)` +(Rust: `suppress_success_diagnostics`). The old free-text `log` API is removed; +there is no stderr fallback or plugin-owned file writer. + ## API | API | Purpose | @@ -104,7 +116,7 @@ JAR it starts must hold everything it loads. | `onInitialize(hook)`, `onShutdown(hook)` | Lifecycle hooks. `onInitialize` receives the `initialize` params and what was negotiated. | | `onRequest(method, handler)`, `onNotification(method, handler)` | Ordinary LSP methods. Lifecycle and `lithe/*` methods are reserved. | | `sendRequest`, `sendNotification` | Ordinary LSP messages to the host. `lithe/*` methods are reserved. | -| `log(message[, error])` | Writes to stderr, which the host keeps in its log. | +| `diagnostics().degraded(operation, code[, count])`, `.recovered(...)` | Typed handled fallback/recovery; no payload text. | | `listen()` | Serves stdio until `exit` or the end of input, then exits the JVM with the protocol's exit code. `listen(in, out, err)` serves other streams and returns the code instead. | | `PluginError(code, message)` | A failure meant for your own UI. | | `Processes.run(command[, options])` | Runs a process without a shell. Its stdin is closed. `Options` set the directory, environment, output limits, a cancellation, and output callbacks. | @@ -117,7 +129,7 @@ Handlers run on their own threads. Every handler receives a `CallContext`: | `cancellation()`, `isCancelled()` | Cancelled when any of these happens: Lithe cancels the call, its deadline passes, the function is withdrawn, the session ends, or the handler finishes. Finishing the handler stops the work it left running. | | `throwIfCancelled()` | Throws `CancelledException` once the call is cancelled. | | `run(command[, options])` | `Processes.run` bound to the call: cancelling or ending the call stops the process. | -| `log(message)` | Same as `Backend.log`. | +| `diagnostics()` | Typed diagnostics correlated with this call. | | `functionId()` | Functions only. | | `host()` | [Host services](#host-services) bound to the call: ending the call cancels the requests it left unanswered. | | `workspaceContext()` | Protocol 3 functions: the `{ contextID, generation }` of the window that invoked the call, or null. | @@ -136,8 +148,8 @@ build operations follow their domain contract: - A returned value becomes `result.value`. - `PluginError` becomes `plugin.function.failed` with your message and `pluginErrorCode`. -- Any other exception is reported with a generic message, and its stack trace - goes to stderr. +- Any other exception is reported with a generic message; automatic diagnostics + keep a fixed failure category without its message, cause or stack. - `CancelledException` ends the call as cancelled. - A result larger than 1 MiB of JSON fails like an unexpected error. @@ -233,6 +245,8 @@ In Java: passes through launch templates (`${stateDir}`, `${workspaceStateDir}`). `StateStore.open` refuses a directory inside the plugin package. It finds the package by walking up from the SDK's own JAR to `plugin.json`. + Diagnostics use the SDK and host; native log files require an explicitly + supplied `${logDir}` on a compatible local host. 5. **Work ends with its call.** Start processes with `context.run`, and check `isCancelled()` in long loops. On cancellation the SDK first asks the process to stop, then stops it forcibly after a grace period. diff --git a/sdk/java/examples/sample-build/src/main/java/org/example/samplebuild/SampleBuild.java b/sdk/java/examples/sample-build/src/main/java/org/example/samplebuild/SampleBuild.java index cc89284..f29e44d 100644 --- a/sdk/java/examples/sample-build/src/main/java/org/example/samplebuild/SampleBuild.java +++ b/sdk/java/examples/sample-build/src/main/java/org/example/samplebuild/SampleBuild.java @@ -126,8 +126,7 @@ private Object build(Map params, CallContext context) throws IOE command.add((String) part); } Processes.Result result = context.run(command, new Processes.Options() - .directory(inside(workspaceRoot, (String) project.get("path"))) - .onStdout(text -> context.log("[" + name + "] " + text.trim()))); + .directory(inside(workspaceRoot, (String) project.get("path")))); results.add(object("name", name, "exitCode", result.exitCode())); if (result.exitCode() != 0) { record(results, "failed"); @@ -167,7 +166,7 @@ private void offerClear() { return null; }).whenComplete((ignored, error) -> { if (error != null) { - backend.log("snapshot.clear stays unavailable: " + error.getMessage()); + backend.diagnostics().degraded("initialize", "registration_failed"); } }); } diff --git a/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Backend.java b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Backend.java index 9058e61..15bee55 100644 --- a/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Backend.java +++ b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Backend.java @@ -200,6 +200,10 @@ private enum Phase { IDLE, LISTENING, INITIALIZING, READY, SHUTTING_DOWN, EXITED BUILD_FORMATS = Collections.unmodifiableMap(formats); } + private volatile boolean logging; + private boolean loggingReady; + private final List> earlyDiagnostics = new ArrayList<>(); + private final java.util.Set quietSuccess = new java.util.HashSet<>(); private final String name; private final String version; private final Map capabilities; @@ -238,9 +242,10 @@ private Backend(String name, String version, Map capabilities) { if (experimental instanceof Map && (((Map) experimental).containsKey("litheBuild") || ((Map) experimental).containsKey("litheFunctions") - || ((Map) experimental).containsKey("litheKeymapImport"))) { + || ((Map) experimental).containsKey("litheKeymapImport") + || ((Map) experimental).containsKey("litheLogging"))) { throw new PluginSdkError("sdk.capabilities.reserved", - "litheBuild, litheFunctions and litheKeymapImport are negotiated by the SDK; declare handlers instead."); + "litheBuild, litheFunctions, litheKeymapImport and litheLogging are negotiated by the SDK; declare handlers instead."); } this.name = name == null ? "lithe-plugin-backend" : name; this.version = version; @@ -482,6 +487,7 @@ public CompletableFuture registerFunction(String id, Handler handler) { if (error != null) { synchronized (lock) { functions.remove(id); + quietSuccess.remove(id); } throw new CompletionException(unwrap(error)); } @@ -497,6 +503,7 @@ public CompletableFuture unregisterFunction(String id) { if (functions.remove(id) == null) { return failed(unknownFunction(id)); } + quietSuccess.remove(id); return CompletableFuture.completedFuture(null); } } @@ -513,6 +520,7 @@ public CompletableFuture unregisterFunction(String id) { List running = new ArrayList<>(); synchronized (lock) { functions.remove(id); + quietSuccess.remove(id); for (Call call : incoming.values()) { if (id.equals(call.functionId)) { running.add(call); @@ -543,18 +551,26 @@ public void sendNotification(String method, Object params) { write(message); } - /** Writes a diagnostic line to stderr, which the host keeps in its log. */ - public void log(String message) { - errorOutput.println("[" + name + "] " + message); + public Diagnostics diagnostics() { return new Diagnostics(this, null); } + + public Backend suppressSuccessDiagnostics(String operation) { + if (!loggingOperation(operation)) throw new PluginSdkError("sdk.logging.invalidOperation", "Suppress a registered operation."); + synchronized (lock) { quietSuccess.add(operation); } + return this; + } + + boolean loggingOperation(String operation) { + synchronized (lock) { return Diagnostics.OPERATIONS.contains(operation) || functions.containsKey(operation); } } - /** Writes a diagnostic line and the failure's stack trace to stderr. */ - public void log(String message, Throwable error) { - PrintStream stream = errorOutput; - synchronized (stream) { - stream.println("[" + name + "] " + message + " " + error); - error.printStackTrace(stream); + void logFact(Map params) { + synchronized (lock) { + if (!logging) return; + if (!loggingReady) { if (earlyDiagnostics.size() < 8) earlyDiagnostics.add(params); return; } } + Map notification = message(null, "lithe/log"); + notification.put("params", params); + write(notification); } /** @@ -597,7 +613,7 @@ public int listen(InputStream input, OutputStream output, PrintStream errorOutpu try { messages = decoder.push(chunk, 0, count); } catch (Framing.FramingException error) { - log("Ending the session: " + error.getMessage()); + diagnostics().terminal("notification", new IllegalStateException(), System.nanoTime()); finish(1); break; } @@ -743,7 +759,7 @@ private void hostNotification(String method, Object raw) { handler = commandId instanceof String ? commandHandlers.get(commandId) : null; } if (handler == null) { - log("No handler for command " + commandId + "."); + diagnostics().degraded("notification", "command_unhandled"); return; } Map context = workspaceContext(params.get("context")); @@ -769,7 +785,7 @@ private void notifyHandler(String method, Notified handler) { try { handler.run(); } catch (Throwable error) { - log("Notification " + method + " failed:", error); + diagnostics().terminal("notification", error, System.nanoTime()); } }); } @@ -785,6 +801,14 @@ private void initialize(Object id, Map params) { phase = Phase.INITIALIZING; initializeParams = params; Map offered = experimental(params.get("capabilities")); + loggingReady = false; + earlyDiagnostics.clear(); + logging = offers(offered.get("litheLogging"), 1); + if (!logging) { + phase = Phase.LISTENING; + respond(id, null, error(Protocol.INVALID_REQUEST, "The backend requires litheLogging version 1.")); + return; + } int buildVersion = 0; if (!buildHandlers.isEmpty()) { for (int version = Protocol.BUILD_VERSION; version > 0; version--) { @@ -811,7 +835,6 @@ private void initialize(Object id, Map params) { hook.run(params, agreed); } } catch (Throwable failure) { - log("initialize failed:", failure); synchronized (lock) { if (phase == Phase.INITIALIZING) { phase = Phase.LISTENING; @@ -828,10 +851,10 @@ private void initialize(Object id, Map params) { return; } if (!agreed.functions() && !functions.isEmpty()) { - log("The host did not offer a litheFunctions version from 1 to " + Protocol.FUNCTIONS_VERSION - + "; functions stay unavailable."); + diagnostics().degraded("initialize", "functions_unavailable"); } Map experimental = new LinkedHashMap<>(experimental(capabilities)); + experimental.put("litheLogging", singleton("version", 1)); Map offeredCapabilities = experimental(params.get("capabilities")); Object keymap = offeredCapabilities.get("litheKeymapImport"); if (offers(keymap, 1) && keymap instanceof Map) { @@ -870,6 +893,10 @@ private void initialize(Object id, Map params) { result.put("serverInfo", serverInfo); phase = Phase.READY; respond(id, result, null); + loggingReady = true; + List> early = new ArrayList<>(earlyDiagnostics); + earlyDiagnostics.clear(); + for (Map fact : early) logFact(fact); } }); } @@ -890,7 +917,7 @@ private void shutdown(Object id) { try { hook.run(); } catch (Throwable error) { - log("A shutdown hook failed:", error); + diagnostics().terminal("shutdown", error, System.nanoTime()); } } Processes.killAll(); @@ -910,8 +937,8 @@ private void invokeKeymap(Object id, Object raw) { respond(id, null, error(Protocol.INVALID_PARAMS, "Invalid shortcut import request.")); return; } - run(id, null, null, context -> handler.handle(new KeymapSnapshot((String) provider, (String) snapshot, context.host()), context), - Backend::functionResult, null); + run(id, null, null, null, context -> handler.handle(new KeymapSnapshot((String) provider, (String) snapshot, context.host()), context), + Backend::functionResult, null, null, "lithe/keymap/import"); } private static boolean validKeymapProvider(String id) { @@ -974,7 +1001,7 @@ private void invokeBuild(Object id, String method, Map arguments return; } if (!Protocol.buildProgress(method)) { - run(id, null, null, context -> handler.handle(arguments, context), result -> buildResult(method, result), null); + run(id, null, null, null, context -> handler.handle(arguments, context), result -> buildResult(method, result), null, null, method); return; } Object wireId = arguments.get("operationID"); @@ -1001,7 +1028,7 @@ public void report(String text, Double percentage, String output) { } }; run(id, null, (String) wireId, null, context -> handler.handle(arguments, context), - result -> buildResult(method, result), () -> reporting.set(false), progress); + result -> buildResult(method, result), () -> reporting.set(false), progress, method); } private interface Invocation { @@ -1019,12 +1046,19 @@ private void run(Object id, String functionId, String operationId, Invocation in /** Runs one handler with its own cancellation and answers exactly once. */ private void run(Object id, String functionId, String operationId, Map workspaceContext, Invocation invoke, Shape shape, Runnable onSettled, CallContext.ProgressSink progress) { - Cancellation cancellation = new Cancellation(); + run(id, functionId, operationId, workspaceContext, invoke, shape, onSettled, progress, functionId == null ? "function-call" : functionId); + } + + private void run(Object id, String functionId, String operationId, Map workspaceContext, + Invocation invoke, Shape shape, Runnable onSettled, CallContext.ProgressSink progress, String diagnosticOperation) { + long started = System.nanoTime(); + String diagnosticOperationId = Diagnostics.requestOperationId(operationId, id); + Cancellation cancellation = new Cancellation(() -> diagnostics().degraded("notification", "cancellation_listener_failed")); String key = requestKey(id); synchronized (lock) { incoming.put(key, new Call(cancellation, functionId)); } - CallContext context = new CallContext(cancellation, this, functionId, operationId, progress, + CallContext context = new CallContext(cancellation, this, functionId, diagnosticOperationId, progress, new Host(channel, Collections.singletonList(cancellation)), workspaceContext); executor.execute(() -> { Object result = null; @@ -1035,10 +1069,15 @@ private void run(Object id, String functionId, String operationId, Map error) { writeEncoded(Framing.encode(message)); } catch (Json.JsonException failure) { // A result JSON cannot encode must not end the session. - log("The result could not be encoded:", failure); + diagnostics().terminal("result-encoding", failure, System.nanoTime()); Map fallback = message(id, null); fallback.put("error", toResponseError(failure, null)); write(fallback); @@ -1246,7 +1285,7 @@ private void writeEncoded(byte[] frame) { stream.flush(); } catch (IOException error) { // The host closed the pipe; the input side ends the session. - log("Writing to the host failed: " + error.getMessage()); + // The closed protocol pipe leaves the host owning the terminal process fact. } } } @@ -1267,7 +1306,7 @@ static Map toResponseError(Throwable failure, Cancellation cance return response; } // Unexpected exceptions often embed absolute paths or internals; the - // caller logs the details to stderr instead. + // caller logs only a fixed failure category to stderr. return error(Protocol.INTERNAL_ERROR, "The plugin backend failed unexpectedly."); } @@ -1462,12 +1501,12 @@ public void notify(String method, Object params) { @Override public void log(String message) { - Backend.this.log(message); + Backend.this.diagnostics().degraded("notification", "subscription_queue_full"); } @Override public void log(String message, Throwable error) { - Backend.this.log(message, error); + Backend.this.diagnostics().terminal("notification", error, System.nanoTime()); } @Override diff --git a/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/CallContext.java b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/CallContext.java index 715dcf2..ceffda4 100644 --- a/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/CallContext.java +++ b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/CallContext.java @@ -16,6 +16,7 @@ interface ProgressSink { default void report(String message, Double percentage, String output) { report(message, percentage); } } + private final java.util.concurrent.atomic.AtomicBoolean quietSuccess = new java.util.concurrent.atomic.AtomicBoolean(); private final Cancellation cancellation; private final Backend backend; private final String functionId; @@ -58,6 +59,7 @@ public void throwIfCancelled() { */ public Processes.Result run(List command, Processes.Options options) throws IOException { Processes.Options settings = options == null ? new Processes.Options() : options.copy(); + settings.listenerFailure(() -> diagnostics().degraded("notification", "output_listener_failed")); Cancellation own = settings.cancellation(); settings.cancellation(own == null ? cancellation : cancellation.combinedWith(own)); return Processes.run(command, settings); @@ -68,10 +70,10 @@ public Processes.Result run(List command) throws IOException { return run(command, null); } - /** Writes a diagnostic line to stderr, which the host keeps in its log. */ - public void log(String message) { - backend.log(message); - } + public void suppressSuccessDiagnostics() { quietSuccess.set(true); } + boolean quietSuccess() { return quietSuccess.get(); } + + public Diagnostics diagnostics() { return new Diagnostics(backend, operationId); } /** * Reports progress of a function or bounded build call. Function messages diff --git a/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Cancellation.java b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Cancellation.java index 49b00ce..d80cd7d 100644 --- a/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Cancellation.java +++ b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Cancellation.java @@ -15,6 +15,9 @@ public final class Cancellation { private final Object lock = new Object(); private final List listeners = new ArrayList<>(); private String reason; + private final Runnable listenerFailure; + public Cancellation() { this(() -> {}); } + Cancellation(Runnable listenerFailure) { this.listenerFailure = listenerFailure; } /** Cancels with {@code reason}; later calls have no effect. */ public void cancel(String reason) { @@ -73,7 +76,7 @@ public Registration onCancel(Runnable listener) { * a plugin may also stop for its own reasons. */ public Cancellation combinedWith(Cancellation other) { - Cancellation combined = new Cancellation(); + Cancellation combined = new Cancellation(listenerFailure); Registration first = onCancel(() -> combined.cancel(reasonOrDefault())); Registration second = other.onCancel(() -> combined.cancel(other.reasonOrDefault())); combined.onCancel(() -> { @@ -83,11 +86,11 @@ public Cancellation combinedWith(Cancellation other) { return combined; } - private static void runIsolated(Runnable listener) { + private void runIsolated(Runnable listener) { try { listener.run(); } catch (RuntimeException error) { - System.err.println("A cancellation listener failed: " + error); + listenerFailure.run(); } } diff --git a/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Diagnostics.java b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Diagnostics.java new file mode 100644 index 0000000..c4d9bd4 --- /dev/null +++ b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Diagnostics.java @@ -0,0 +1,72 @@ +package io.github.litheidea.plugin.sdk; + +import java.util.Arrays; +import java.util.HashSet; +import java.util.LinkedHashMap; +import java.util.Map; +import java.util.Set; + +/** Typed facts for the host's litheLogging 1 catalog; never accepts message or payload text. */ +public final class Diagnostics { + static final long MAX_INTEGER = 9007199254740991L; + static final Set OPERATIONS = new HashSet<>(Arrays.asList( + "initialize", "shutdown", "notification", "function-call", "result-encoding", + "lithe/build/model", "lithe/build/dependencies", "lithe/build/execute", "lithe/build/test", + "lithe/build/discoverTests", "lithe/build/prepareRun", "lithe/build/prepareDebug", + "lithe/vcs/status", "lithe/vcs/baseContent", "lithe/vcs/history", "lithe/vcs/fileHistory", + "lithe/vcs/annotate", "lithe/vcs/checkin", "lithe/vcs/rollback", "lithe/vcs/update", + "lithe/vcs/fileOperation", "lithe/vcs/resolve", "lithe/vcs/cleanup", + "lithe/keymap/import")); + private final Backend backend; + private final String operationId; + + Diagnostics(Backend backend, String operationId) { + this.backend = backend; + this.operationId = operationId; + } + + public void degraded(String operation, String code, Long count) { record("degraded", operation, code, count, null); } + public void recovered(String operation, String code, Long count) { record("recovered", operation, code, count, null); } + public void degraded(String operation, String code) { degraded(operation, code, null); } + public void recovered(String operation, String code) { recovered(operation, code, null); } + + static boolean token(String value, int maximum) { + return value != null && value.length() > 0 && value.length() <= maximum && value.matches("[A-Za-z0-9._:/\\-$]+"); + } + + static String requestOperationId(String operationId, Object requestId) { + if (token(operationId, 128)) return operationId; + String fallback = requestId instanceof String ? (String) requestId : null; + if (requestId instanceof Number) { + double number = ((Number) requestId).doubleValue(); + if (Double.isFinite(number) && Math.abs(number) <= MAX_INTEGER && number == Math.rint(number)) { + fallback = Long.toString(((Number) requestId).longValue()); + } + } + return token(fallback, 128) ? fallback : null; + } + + void terminal(String operation, Throwable failure, long started) { + String code = null; + if (failure != null) { + Throwable error = Backend.unwrap(failure); + code = error instanceof PluginError ? ((PluginError) error).code() : "internal_error"; + } + record(failure == null ? "operationFinished" : "operationFailed", operation, code, null, + Math.min(MAX_INTEGER, Math.max(0, (System.nanoTime() - started) / 1000000))); + } + + private void record(String kind, String operation, String code, Long count, Long duration) { + if (!backend.loggingOperation(operation)) throw new PluginSdkError("sdk.logging.invalidOperation", "Diagnostics need a registered operation."); + if (code != null && !token(code, 64)) throw new PluginSdkError("sdk.logging.invalidCode", "Diagnostics need a controlled code."); + if (count != null && (count < 0 || count > MAX_INTEGER)) throw new PluginSdkError("sdk.logging.invalidCount", "Diagnostics need a nonnegative safe count."); + Map params = new LinkedHashMap<>(); + params.put("kind", kind); + params.put("operation", operation.length() <= 64 ? operation : "function-call"); + if (code != null) params.put("code", code); + if (count != null) params.put("count", count); + if (duration != null) params.put("durationMs", duration); + if (token(operationId, 128)) params.put("operationId", operationId); + backend.logFact(params); + } +} diff --git a/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/HostChannel.java b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/HostChannel.java index e334eab..274fbd4 100644 --- a/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/HostChannel.java +++ b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/HostChannel.java @@ -258,7 +258,7 @@ void deliver(Map params) { if (early.size() < MAX_EARLY_EVENTS) { early.add(new Early((String) id, sequence, params.get("event"))); } else { - transport.log("Dropped an early event of subscription " + id + "."); + transport.log("Dropped an early subscription event: queue_full"); } } // Otherwise the subscription was disposed; nothing follows a disposal. @@ -477,7 +477,7 @@ private void run(Route route) { route.listener.onEvent(event); } } catch (Throwable error) { - transport.log("Subscription " + route.id + " failed to handle an event:", error); + transport.log("A subscription listener failed:", error); } } } diff --git a/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/PluginError.java b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/PluginError.java index aa7b972..c7e83b3 100644 --- a/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/PluginError.java +++ b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/PluginError.java @@ -22,7 +22,7 @@ public PluginError(String code, String message) { this(code, message, null); } - /** As {@link #PluginError(String, String)}; {@code cause} is kept for logs only. */ + /** As {@link #PluginError(String, String)}; {@code cause} stays in memory, outside automatic diagnostics. */ public PluginError(String code, String message, Throwable cause) { super(message, cause); if (!Protocol.isPluginErrorCode(code)) { diff --git a/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Processes.java b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Processes.java index 76c36ca..6764cca 100644 --- a/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Processes.java +++ b/sdk/java/plugin-sdk/src/main/java/io/github/litheidea/plugin/sdk/Processes.java @@ -79,6 +79,7 @@ public static final class Options { private long killGraceMillis = 2000; private Consumer onStdout; private Consumer onStderr; + private Runnable listenerFailure = () -> {}; /** Working directory; defaults to the backend's. */ public Options directory(Path value) { @@ -122,6 +123,8 @@ public Options onStderr(Consumer value) { return this; } + Options listenerFailure(Runnable value) { listenerFailure = value; return this; } + Cancellation cancellation() { return cancellation; } @@ -135,6 +138,7 @@ Options copy() { copy.killGraceMillis = killGraceMillis; copy.onStdout = onStdout; copy.onStderr = onStderr; + copy.listenerFailure = listenerFailure; return copy; } } @@ -213,8 +217,8 @@ public static Result run(List command, Options options) throws IOExcepti process.getOutputStream().close(); Running entry = new Running(process, grouped ? GROUPS.leader(process) : 0); RUNNING.add(entry); - Capture stdout = new Capture(process.getInputStream(), settings.maxOutputBytes, settings.onStdout, "stdout"); - Capture stderr = new Capture(process.getErrorStream(), settings.maxOutputBytes, settings.onStderr, "stderr"); + Capture stdout = new Capture(process.getInputStream(), settings.maxOutputBytes, settings.onStdout, "stdout", settings.listenerFailure); + Capture stderr = new Capture(process.getErrorStream(), settings.maxOutputBytes, settings.onStderr, "stderr", settings.listenerFailure); Cancellation.Registration registration = cancellation == null ? () -> {} : cancellation.onCancel(() -> entry.stop(settings.killGraceMillis)); @@ -377,13 +381,15 @@ private static final class Capture { private final InputStream input; private final int limit; private final Consumer listener; + private final Runnable listenerFailure; private final CharsetDecoder decoder = StandardCharsets.UTF_8.newDecoder() .onMalformedInput(CodingErrorAction.REPLACE) .onUnmappableCharacter(CodingErrorAction.REPLACE); private final Thread thread; private volatile boolean truncated; - Capture(InputStream input, int limit, Consumer listener, String name) { + Capture(InputStream input, int limit, Consumer listener, String name, Runnable listenerFailure) { + this.listenerFailure = listenerFailure; this.input = input; this.limit = limit; this.listener = listener; @@ -433,7 +439,7 @@ private void deliver(ByteBuffer bytes, boolean end) { try { listener.accept(characters.toString()); } catch (RuntimeException error) { - System.err.println("An output listener failed: " + error); + listenerFailure.run(); } } } diff --git a/sdk/java/plugin-sdk/src/test/java/io/github/litheidea/plugin/sdk/BackendTest.java b/sdk/java/plugin-sdk/src/test/java/io/github/litheidea/plugin/sdk/BackendTest.java index fc20fef..df05e50 100644 --- a/sdk/java/plugin-sdk/src/test/java/io/github/litheidea/plugin/sdk/BackendTest.java +++ b/sdk/java/plugin-sdk/src/test/java/io/github/litheidea/plugin/sdk/BackendTest.java @@ -56,7 +56,7 @@ void initializeAnswersTheOfferedProtocolsWithSortedFunctions() { TestHost host = new TestHost(backend); Map result = object(host.initialize().get("result")); assertEquals( - map("litheBuild", map("version", 1L), + map("litheLogging", map("version", 1L), "litheBuild", map("version", 1L), "litheFunctions", map("version", 1L, "functions", Arrays.asList(map("id", "install.prepare"), map("id", "snapshot.refresh")))), object(result.get("capabilities")).get("experimental")); @@ -69,7 +69,7 @@ void initializeAnswersTheOfferedProtocolsWithSortedFunctions() { @Test void aHostThatOffersNothingGetsNoLitheCapabilities() { TestHost quiet = new TestHost(functionBackend()); - assertEquals(map(), object(object(quiet.initialize(map()).get("result")).get("capabilities")).get("experimental")); + assertEquals(map("litheLogging", map("version", 1L)), object(object(quiet.initialize(map()).get("result")).get("capabilities")).get("experimental")); quiet.close(); // No build handler: litheBuild is never claimed. Only an unknown version: no functions. @@ -77,7 +77,7 @@ void aHostThatOffersNothingGetsNoLitheCapabilities() { Map answer = object(other.initialize(map( "litheBuild", map("versions", Arrays.asList(1L)), "litheFunctions", map("versions", Arrays.asList(99L)))).get("result")); - assertEquals(map(), object(answer.get("capabilities")).get("experimental")); + assertEquals(map("litheLogging", map("version", 1L)), object(answer.get("capabilities")).get("experimental")); other.close(); } @@ -219,10 +219,88 @@ void aPluginErrorCarriesItsCodeAndOtherFailuresHideTheirDetails() { assertEquals(-32603L, crash.get("code")); assertFalse(((String) crash.get("message")).contains("/Users/")); assertFalse(crash.containsKey("data")); + assertEquals("", host.errors()); + List> facts = new ArrayList<>(); + for (Map message : host.messages()) { + if ("lithe/log".equals(message.get("method"))) facts.add(object(message.get("params"))); + } + assertEquals(2, facts.size()); + assertEquals("operationFailed", facts.get(0).get("kind")); + assertEquals("maven.snapshotLocked", facts.get(0).get("code")); + assertEquals("internal_error", facts.get(1).get("code")); + assertEquals("b", facts.get(1).get("operationId")); assertThrows(IllegalArgumentException.class, () -> new PluginError("bad code!", "x")); host.close(); } + @Test + void typedDiagnosticsCorrelateAndSuppressOnlySuccess() { + Backend backend = Backend.create(null, null).function("work.inspect", (params, context) -> { + context.diagnostics().degraded("work.inspect", "cache_unavailable", 2L); + context.diagnostics().recovered("work.inspect", "cache_restored"); + if (Boolean.TRUE.equals(params.get("fail"))) throw new PluginError("work.failed", "private explanation"); + return null; + }).suppressSuccessDiagnostics("work.inspect"); + TestHost host = new TestHost(backend); + try { + host.initialize(); + host.request("lithe/function/invoke", invoke("work.inspect", "host-success", map("fail", false))); + host.request("lithe/function/invoke", invoke("work.inspect", "host-failure", map("fail", true))); + List> facts = new ArrayList<>(); + for (Map message : host.messages()) { + if ("lithe/log".equals(message.get("method"))) facts.add(object(message.get("params"))); + } + assertEquals(5, facts.size()); + assertEquals("operationFailed", facts.get(4).get("kind")); + assertEquals("host-failure", facts.get(4).get("operationId")); + assertEquals("work.failed", facts.get(4).get("code")); + assertFalse(facts.toString().contains("private explanation")); + assertEquals("", host.errors()); + assertThrows(PluginSdkError.class, () -> backend.diagnostics().degraded("unknown", "failure")); + assertThrows(PluginSdkError.class, () -> backend.diagnostics().degraded("work.inspect", "raw message")); + } finally { host.close(); } + } + + @Test + void modelDiagnosticsReuseOriginalRpcIdWhenOperationIsAbsent() { + Backend backend = Backend.create(null, null).onModel((params, context) -> { + context.diagnostics().degraded("lithe/build/model", "snapshot_unavailable"); + return map("projects", Collections.emptyList()); + }); + TestHost host = new TestHost(backend); + try { + host.initialize(); + host.request("lithe/build/model", map("root", "."), 42L); + List operations = new ArrayList<>(); + for (Map message : host.messages()) { + if ("lithe/log".equals(message.get("method"))) operations.add(object(message.get("params")).get("operationId")); + } + assertEquals(Arrays.asList("42", "42"), operations); + } finally { host.close(); } + } + + @Test + void initializeDiagnosticsWaitForCapabilityAnswerAndStayBounded() { + Backend backend = Backend.create(null, null); + backend.onInitialize((params, negotiated) -> { + for (long count = 0; count < 10; count++) { + backend.diagnostics().degraded("initialize", "snapshot_unavailable", count); + } + }); + TestHost host = new TestHost(backend); + try { + host.initialize(); + host.request("lithe/function/invoke", invoke("missing", "barrier", null)); + List> messages = host.messages(); + assertNotNull(messages.get(0).get("result"), "capability answer precedes diagnostics"); + List counts = new ArrayList<>(); + for (Map message : messages) { + if ("lithe/log".equals(message.get("method"))) counts.add(object(message.get("params")).get("count")); + } + assertEquals(Arrays.asList(0L, 1L, 2L, 3L, 4L, 5L, 6L, 7L), counts); + } finally { host.close(); } + } + @Test void aFailingCancellationListenerNeitherSkipsTheOthersNorTheReply() { CountDownLatch laterListenerRan = new CountDownLatch(1); @@ -476,7 +554,7 @@ void aShutdownDuringASlowInitializeHookKeepsTheSessionClosed() { }); TestHost host = new TestHost(backend); CompletableFuture> initialize = host.requestAsync("initialize", - map("capabilities", map()), 3001L); + map("capabilities", map("experimental", map("litheLogging", map("versions", Arrays.asList(1))))), 3001L); Fixtures.await(hookStarted, "the initialize hook"); assertNull(host.request("shutdown", null).get("error")); release.countDown(); diff --git a/sdk/java/plugin-sdk/src/test/java/io/github/litheidea/plugin/sdk/KeymapTest.java b/sdk/java/plugin-sdk/src/test/java/io/github/litheidea/plugin/sdk/KeymapTest.java index 4a25697..575c74d 100644 --- a/sdk/java/plugin-sdk/src/test/java/io/github/litheidea/plugin/sdk/KeymapTest.java +++ b/sdk/java/plugin-sdk/src/test/java/io/github/litheidea/plugin/sdk/KeymapTest.java @@ -4,8 +4,10 @@ import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertNotNull; +import java.util.ArrayList; import java.util.Arrays; import java.util.Collections; +import java.util.List; import java.util.Map; import java.nio.charset.StandardCharsets; import java.util.concurrent.CompletableFuture; @@ -37,6 +39,15 @@ void negotiatesOnlyOfferedProvidersAndRejectsUnscopedRequests() { object(capabilities.get("experimental")).get("litheKeymapImport")); assertEquals(map("bindings", Collections.emptyList()), host.request("lithe/keymap/import", map("providerID", "first", "snapshotID", "snapshot-1")).get("result")); + // The terminal fact precedes the response and names the wire method Core accepts. + List> facts = new ArrayList<>(); + for (Map message : host.messages()) { + if ("lithe/log".equals(message.get("method"))) { + Map fact = object(message.get("params")); + facts.add(Arrays.asList(fact.get("kind"), fact.get("operation"))); + } + } + assertEquals(Collections.singletonList(Arrays.asList("operationFinished", "lithe/keymap/import")), facts); assertNotNull(host.request("lithe/keymap/import", map("providerID", "not-offered", "snapshotID", "snapshot-1")).get("error")); assertNotNull(host.request("lithe/keymap/import", map("providerID", "first", "snapshotID", "../private")).get("error")); } finally { host.close(); } diff --git a/sdk/java/plugin-sdk/src/test/java/io/github/litheidea/plugin/sdk/TestHost.java b/sdk/java/plugin-sdk/src/test/java/io/github/litheidea/plugin/sdk/TestHost.java index 8fc2c5c..33a5830 100644 --- a/sdk/java/plugin-sdk/src/test/java/io/github/litheidea/plugin/sdk/TestHost.java +++ b/sdk/java/plugin-sdk/src/test/java/io/github/litheidea/plugin/sdk/TestHost.java @@ -100,6 +100,8 @@ Map initialize() { } Map initialize(Map experimental) { + experimental = new LinkedHashMap<>(experimental); + experimental.put("litheLogging", Fixtures.map("versions", Arrays.asList(1))); Map response = request("initialize", Fixtures.map( "processId", null, "rootUri", "file:///workspace", diff --git a/sdk/node/README.md b/sdk/node/README.md index 292491b..aad62f9 100644 --- a/sdk/node/README.md +++ b/sdk/node/README.md @@ -130,6 +130,18 @@ A plugin package is installed read-only, has no `node_modules` install step, and must run offline, so everything the backend imports has to be inside the package. The SDK has no dependencies. +## Logging + +The new SDK requires `experimental.litheLogging` version 1 at initialization. +See [plugin logging](../../guides/plugin-logging.md) for the typed diagnostics +API, host-owned catalog, exact levels, operation correlation and `${logDir}`. +Use `diagnostics.degraded/recovered` (Rust: `diagnostics().degraded/recovered`) +for handled fallback or recovery facts. Function and build/VCS terminal facts +are automatic; do not log a failure before returning it to the SDK. Suppress +successful high-frequency reads with `suppressSuccessDiagnostics(operation)` +(Rust: `suppress_success_diagnostics`). The old free-text `log` API is removed; +there is no stderr fallback or plugin-owned file writer. + ## API | API | Purpose | @@ -151,7 +163,7 @@ package. The SDK has no dependencies. | `backend.onInitialize(hook)`, `backend.onShutdown(hook)` | Lifecycle hooks. `onInitialize` receives the `initialize` params and what was negotiated. | | `backend.onRequest(method, handler)`, `backend.onNotification(method, handler)` | Ordinary LSP methods, such as `textDocument/hover` for a language server. Lifecycle and `lithe/*` methods are reserved. | | `backend.sendRequest`, `backend.sendNotification` | Ordinary LSP messages to the host; `lithe/*` methods are reserved. | -| `backend.log(...)` | Writes a line to stderr, which the host keeps in its log. | +| `backend.diagnostics.degraded(operation, code, count?)`, `.recovered(...)` | Typed handled fallback/recovery; no payload text. | | `backend.listen()` | Serves stdio until `exit` or the end of input. | | `PluginError(code, message)` | A failure meant for your own UI, or with a `VCS_ERRORS` code, for the host's. | | `HostError` | The host refused or failed a host request: `code` (`error.data.code`), `rpcCode`, and protocol 3 `details`. `HOST_ERRORS` maps each code to its number. | @@ -165,7 +177,7 @@ Every handler receives a context: | `signal` | Aborted when Lithe cancels the call, its deadline passes, the function is withdrawn, or the session ends; also once the handler has settled, so work it left running stops. | | `throwIfCancelled()` | Throws the cancellation if `signal` is aborted. | | `run(command, args, options)` | `runProcess` bound to the call: cancelling or ending the call ends the whole process tree. In VCS handlers it also reports the finished command unless `options.report` is `false`. | -| `log(...)` | Same as `backend.log`. | +| `diagnostics` | Typed diagnostics correlated with this call. | | `host` | `backend.host` bound to the call: host requests it left unanswered are cancelled when the call ends. | | `functionID` | Functions only. | | `workspaceContext` | Functions only, protocol 3: `{ contextID, generation }` of the page's window, or `null`. | @@ -264,12 +276,12 @@ their domain result/error contract; see the native workflow guide above. | --- | --- | | Returns a value (including `null`) | `result.value` | | Throws `PluginError(code, message)` | `plugin.function.failed` with your `message` and `pluginErrorCode`. The code is for your plugin's own UI; Lithe never branches on it. | -| Throws anything else | `plugin.function.failed` with a generic message, so paths and stack traces never reach the UI. The real error goes to stderr. | +| Throws anything else | `plugin.function.failed` with a generic message, so paths and stack traces never reach the UI. Automatic diagnostics record only a fixed failure category. | | Ends because of `signal` | `requestCancelled` (or Lithe's timeout/revocation outcome) | A result must serialize to at most 1 MiB of JSON. A value JSON cannot encode (a `BigInt`, a cycle) or a larger one fails like any other unexpected error and -is logged to stderr; the session keeps running. A function ID is dot-separated +emits one typed failure fact; the session keeps running. A function ID is dot-separated lowerCamelCase segments (`snapshot.refresh`), at most 128 bytes, and a session holds at most 256 functions. A `PluginError` code matches `[A-Za-z][A-Za-z0-9._-]*`, at most 64 bytes. @@ -294,11 +306,12 @@ lifecycle unified. The SDK enforces the ones it can. 3. **stdout belongs to the protocol.** When serving stdio, the SDK moves `console.log`, `console.info`, and `console.debug` to stderr. Never write to `process.stdout` yourself. -4. **The package is read-only.** Keep caches, snapshots, and logs under the +4. **The package is read-only.** Keep caches and snapshots under the directories Lithe passes through launch templates (`${stateDir}`, `${workspaceStateDir}`). `openStateStore` refuses any directory inside the - plugin package. Writing to the package breaks code signing and update - deltas. + plugin package. Diagnostics use the SDK and host; native log files require + an explicitly supplied `${logDir}` on a compatible local host. Writing to + the package breaks code signing and update deltas. 5. **Work ends with its call.** Start processes with `context.run`, and check `signal` in long loops. On cancellation the SDK stops the process tree politely, then forcibly. When the handler returns or throws, tools of that diff --git a/sdk/node/examples/sample-build/backend/main.mjs b/sdk/node/examples/sample-build/backend/main.mjs index 79ca6b0..fa813ed 100644 --- a/sdk/node/examples/sample-build/backend/main.mjs +++ b/sdk/node/examples/sample-build/backend/main.mjs @@ -75,7 +75,6 @@ backend.function('workspace.build', async ({ projects: selected }, context) => { const [tool, ...args] = project.build; const { exitCode } = await context.run(tool === 'node' ? process.execPath : tool, args, { cwd: inside(workspaceRoot, project.path), - onStdout: (text) => context.log(`[${project.name}] ${text.trimEnd()}`), }); results.push({ name: project.name, exitCode }); if (exitCode !== 0) { @@ -110,7 +109,7 @@ function offerClear() { store.delete('snapshot'); return null; }) - .catch((error) => backend.log('snapshot.clear stays unavailable:', error.message)); + .catch(() => backend.diagnostics.degraded('initialize', 'registration_failed')); } /** Every project, or exactly the named ones; an unknown name is an error, not an empty build. */ diff --git a/sdk/node/src/backend.mjs b/sdk/node/src/backend.mjs index 184577a..950cd36 100644 --- a/sdk/node/src/backend.mjs +++ b/sdk/node/src/backend.mjs @@ -9,8 +9,10 @@ // shared/contracts/vcs-provider-v1.md. import { format } from 'node:util'; +import { performance } from 'node:perf_hooks'; +import { diagnostics, KNOWN_OPERATIONS, requestOperationId } from './diagnostics.mjs'; import { encodeFrame, FrameDecoder, FramingError, MALFORMED } from './framing.mjs'; -import { HostError, PluginSdkError, toResponseError } from './errors.mjs'; +import { HostError, PluginError, PluginSdkError, toResponseError } from './errors.mjs'; import { createHost, HostChannel } from './host.mjs'; import { killAllProcesses, runProcess } from './process.mjs'; import { @@ -60,6 +62,10 @@ export function createBackend(options = {}) { } class Backend { + #logging = false; + #loggingReady = false; + #earlyDiagnostics = []; + #quietSuccess = new Set(); #name; #version; #capabilities; @@ -106,10 +112,10 @@ class Backend { constructor({ name = 'lithe-plugin-backend', version, capabilities = {} } = {}) { const experimental = capabilities.experimental ?? {}; - if ('litheBuild' in experimental || 'litheFunctions' in experimental || 'litheVcs' in experimental || 'litheKeymapImport' in experimental) { + if ('litheLogging' in experimental || 'litheBuild' in experimental || 'litheFunctions' in experimental || 'litheVcs' in experimental || 'litheKeymapImport' in experimental) { throw new PluginSdkError( 'sdk.capabilities.reserved', - 'litheBuild, litheFunctions, litheVcs, and litheKeymapImport are negotiated by the SDK; declare handlers instead.', + 'litheLogging, litheBuild, litheFunctions, litheVcs, and litheKeymapImport are negotiated by the SDK; declare handlers instead.', ); } this.#name = String(name); @@ -133,7 +139,7 @@ class Backend { ready: () => this.#phase === 'ready', send: (method, params) => this.#send(method, params), notify: (method, params) => this.#write({ jsonrpc: '2.0', method, params }), - log: (...parts) => this.log(...parts), + log: () => this.#diagnostics().degraded('notification', 'event_handler_failed'), }); this.host = createHost(this.#channel); } @@ -319,6 +325,7 @@ class Backend { await this.#request(METHODS.functionRegister, { functions: [{ id }] }); } catch (error) { this.#functions.delete(id); + this.#quietSuccess.delete(id); throw error; } }); @@ -331,6 +338,7 @@ class Backend { if (!this.#functions.delete(id)) { throw new PluginSdkError('sdk.function.unknown', `Function ${id} is not registered.`); } + this.#quietSuccess.delete(id); }); } return this.#queueRegistration(async () => { @@ -340,6 +348,7 @@ class Backend { } await this.#request(METHODS.functionUnregister, { ids: [id] }); this.#functions.delete(id); + this.#quietSuccess.delete(id); for (const call of this.#incoming.values()) { if (call.functionID === id) call.controller.abort(); } @@ -358,9 +367,20 @@ class Backend { this.#write({ jsonrpc: '2.0', method, ...(params === undefined ? {} : { params }) }); } - /** Writes a diagnostic line to stderr, which the host keeps in its log. */ - log(...parts) { - this.#errorOutput.write(`[${this.#name}] ${format(...parts)}\n`); + get diagnostics() { return this.#diagnostics(); } + + suppressSuccessDiagnostics(operation) { + if (!KNOWN_OPERATIONS.has(operation) && !this.#functions.has(operation)) throw new PluginSdkError('sdk.logging.invalidOperation', 'Suppress a registered operation.'); + this.#quietSuccess.add(operation); + return this; + } + + #diagnostics(operationId) { + return diagnostics((params) => { + if (!this.#logging) return; + if (!this.#loggingReady) { if (this.#earlyDiagnostics.length < 8) this.#earlyDiagnostics.push(params); return; } + this.#write({ jsonrpc: '2.0', method: 'lithe/log', params }); + }, (id) => this.#functions.has(id), operationId); } /** @@ -406,7 +426,7 @@ class Backend { messages = decoder.push(chunk); } catch (error) { if (!(error instanceof FramingError)) throw error; - this.log('Ending the session:', error.message); + this.#diagnostics().terminal('notification', {code:'framing_error'}, 0); this.#finish(1); return; } @@ -472,7 +492,7 @@ class Backend { } const vcs = this.#negotiated.vcs ? this.#vcs.methods.get(method) : undefined; if (vcs) { - this.#run(id, null, (context) => vcs(params ?? {}, this.#vcsContext(context)), (result) => vcsResult(method, result)); + this.#run(id, null, (context) => vcs(params ?? {}, this.#vcsContext(context)), (result) => vcsResult(method, result), undefined, method, params?.operationID); return; } const handler = this.#requestHandlers.get(method); @@ -501,7 +521,7 @@ class Backend { if (!handler) return; Promise.resolve() .then(() => handler(params)) - .catch((error) => this.log(`Notification ${method} failed:`, error)); + .catch((error) => this.#diagnostics().terminal('notification', { code: failureKind(error) }, 0)); } /** @@ -520,7 +540,7 @@ class Backend { handler = this.#commandHandlers.get(params.commandID); event = { commandID: params.commandID, workspaceContext: isContextReference(params.context) ? params.context : null }; if (!handler) { - this.log(`No handler for command ${params.commandID}.`); + this.#diagnostics().degraded('notification', 'command_unhandled'); return; } } else if (method === HOST_NOTIFICATIONS.didChangeContexts) { @@ -531,7 +551,7 @@ class Backend { if (!handler) return; Promise.resolve() .then(() => handler(event)) - .catch((error) => this.log(`Notification ${method} failed:`, error)); + .catch((error) => this.#diagnostics().terminal('notification', { code: failureKind(error) }, 0)); } async #initialize(id, params) { @@ -542,6 +562,14 @@ class Backend { this.#phase = 'initializing'; this.#initializeParams = params; const offered = params.capabilities?.experimental ?? {}; + this.#loggingReady = false; + this.#earlyDiagnostics = []; + this.#logging = offered.litheLogging?.versions?.includes(1) === true; + if (!this.#logging) { + this.#phase = 'listening'; + this.#respond(id, undefined, { code: ERROR_CODES.invalidRequest, message: 'The backend requires litheLogging version 1.' }); + return; + } const offers = (entry, version) => Array.isArray(entry?.versions) && entry.versions.includes(version); const highest = (entry, latest) => Array.from({ length: latest }, (_, index) => latest - index) .find((version) => offers(entry, version)) ?? null; @@ -557,7 +585,6 @@ class Backend { await hook({ params, negotiated: this.#negotiated }); } } catch (error) { - this.log('initialize failed:', error); if (this.#phase === 'initializing') this.#phase = 'listening'; this.#respond(id, undefined, toResponseError(error)); return; @@ -569,9 +596,9 @@ class Backend { return; } if (!this.#negotiated.functions && this.#functions.size > 0) { - this.log(`The host did not offer a litheFunctions version from 1 to ${FUNCTIONS_VERSION}; functions stay unavailable.`); + this.#diagnostics().degraded('initialize', 'functions_unavailable'); } - const experimental = { ...(this.#capabilities.experimental ?? {}) }; + const experimental = { ...(this.#capabilities.experimental ?? {}), litheLogging: { version: 1 } }; if (offers(offered.litheKeymapImport, 1) && Array.isArray(offered.litheKeymapImport?.providers) && offered.litheKeymapImport.providers.length <= 8) { this.#selectedKeymapProviders = new Set(offered.litheKeymapImport.providers.filter((id) => this.#keymapProviders.has(id))); @@ -583,7 +610,7 @@ class Backend { if (this.#negotiated.vcs) { experimental.litheVcs = { version: VCS_VERSION, vcs: this.#vcs.id, capabilities: this.#vcs.capabilities }; } else if (this.#vcs) { - this.log('The host did not offer litheVcs version 1; the VCS provider stays unavailable.'); + this.#diagnostics().degraded('initialize', 'vcs_unavailable'); } if (this.#negotiated.functions) { experimental.litheFunctions = { @@ -596,6 +623,8 @@ class Backend { capabilities: { ...this.#capabilities, experimental }, serverInfo: { name: this.#name, ...(this.#version ? { version: this.#version } : {}) }, }); + this.#loggingReady = true; + for (const params of this.#earlyDiagnostics.splice(0)) this.#write({ jsonrpc: '2.0', method: 'lithe/log', params }); } async #shutdown(id) { @@ -609,7 +638,7 @@ class Backend { try { await hook(); } catch (error) { - this.log('A shutdown hook failed:', error); + this.#diagnostics().terminal('shutdown', { code: failureKind(error) }, 0); } } killAllProcesses(); @@ -640,7 +669,7 @@ class Backend { if (Number.isFinite(percentage)) report.percentage = Math.min(100, Math.max(0, Math.round(percentage))); this.#write({ jsonrpc: '2.0', method: METHODS.buildProgress, params: report }); }, - } : context), (result) => buildResult(method, result), () => { reporting = false; }); + } : context), (result) => buildResult(method, result), () => { reporting = false; }, method, operationID); } #invokeKeymap(id, params) { @@ -650,7 +679,7 @@ class Backend { return; } const handler = this.#keymapProviders.get(params.providerID); - this.#run(id, null, (context) => handler(keymapSnapshot(params, context.host), context), functionResult); + this.#run(id, null, (context) => handler(keymapSnapshot(params, context.host), context), functionResult, undefined, 'lithe/keymap/import'); } #invokeFunction(id, { functionID, operationID, params, context: workspaceContext }) { @@ -682,17 +711,24 @@ class Backend { () => { reporting = false; }, + functionID, + operationID, ); } /** Runs one handler with its own cancellation and answers exactly once. */ - #run(id, functionID, invoke, shape, onSettled) { + #run(id, functionID, invoke, shape, onSettled, operation = functionID ?? 'function-call', operationId) { + const started = performance.now(); + const diagnostic = this.#diagnostics(requestOperationId(operationId, id)); + let quietSuccess = false; const controller = new AbortController(); const key = requestKey(id); this.#incoming.set(key, { controller, functionID }); const { signal } = controller; const context = { signal, + diagnostics: diagnostic, + suppressSuccessDiagnostics: () => { quietSuccess = true; }, throwIfCancelled: () => signal.throwIfAborted(), run: (command, args, options = {}) => { const running = runProcess(command, args, { @@ -704,7 +740,6 @@ class Backend { running.catch(() => {}); return running; }, - log: (...parts) => this.log(...parts), host: createHost(this.#channel, signal), }; Promise.resolve() @@ -715,16 +750,15 @@ class Backend { return { result: shape(value) }; }, (error) => { - if (!signal.aborted) this.log(`${functionID ? `Function ${functionID}` : 'A request'} failed:`, error); return { error: toResponseError(error, signal) }; }, ) .catch((error) => { // Shaping the result failed, for example a build result in another format. - if (!signal.aborted) this.log('The result could not be sent:', error); return { error: toResponseError(error, signal) }; }) .then(({ result, error }) => { + if (!signal.aborted && (error || (!quietSuccess && !this.#quietSuccess.has(operation)))) diagnostic.terminal(operation, error ? { code: error.data?.code ?? 'internal_error' } : null, performance.now() - started); onSettled?.(); this.#incoming.delete(key); // Work belongs to its call: tools still running when the handler @@ -871,7 +905,7 @@ class Backend { } catch (failure) { // A result JSON cannot encode, such as a BigInt or a cycle, must not // become an unhandled rejection that ends the whole session. - this.log('The result could not be encoded:', failure); + this.#diagnostics().terminal('result-encoding', { code: 'result_encoding_failed' }, 0); this.#write({ jsonrpc: '2.0', id, error: toResponseError(failure) }); } } @@ -882,6 +916,12 @@ class Backend { } } +// Errors can include request bodies, credentials and paths. Only the category +// crosses the diagnostic boundary; the response keeps its existing error contract. +function failureKind(error) { + return error instanceof PluginError ? 'plugin_error' : 'internal_error'; +} + /** Runs `change` now and reports its outcome as a promise. */ function settle(change) { try { diff --git a/sdk/node/src/diagnostics.mjs b/sdk/node/src/diagnostics.mjs new file mode 100644 index 0000000..8fcdc99 --- /dev/null +++ b/sdk/node/src/diagnostics.mjs @@ -0,0 +1,34 @@ +// Typed plugin diagnostics use the host's catalog and writer. No payload text crosses this API. +import { PluginSdkError } from './errors.mjs'; + +export const KNOWN_OPERATIONS = new Set([ + 'initialize', 'shutdown', 'notification', 'function-call', 'result-encoding', + ...['model', 'dependencies', 'execute', 'test', 'discoverTests', 'prepareRun', 'prepareDebug'].map((name) => `lithe/build/${name}`), + ...['status', 'baseContent', 'history', 'fileHistory', 'annotate', 'checkin', 'rollback', 'update', 'fileOperation', 'resolve', 'cleanup'].map((name) => `lithe/vcs/${name}`), + 'lithe/keymap/import', +]); +const token = (value, maximum) => typeof value === 'string' && value.length > 0 && value.length <= maximum && /^[A-Za-z0-9._:/\-$]+$/.test(value); +export function requestOperationId(operationId, requestId) { + if (token(operationId, 128)) return operationId; + const fallback = typeof requestId === 'string' ? requestId : Number.isSafeInteger(requestId) ? String(requestId) : undefined; + return token(fallback, 128) ? fallback : undefined; +} +export function diagnostics(send, registered, operationId) { + const record = (kind, operation, code, count, durationMs) => { + if (!KNOWN_OPERATIONS.has(operation) && !registered(operation)) throw new PluginSdkError('sdk.logging.invalidOperation', 'Diagnostics need a registered operation.'); + if (code !== undefined && !token(code, 64)) throw new PluginSdkError('sdk.logging.invalidCode', 'Diagnostics need a controlled code.'); + if (count !== undefined && (!Number.isSafeInteger(count) || count < 0)) throw new PluginSdkError('sdk.logging.invalidCount', 'Diagnostics need a nonnegative safe count.'); + const params = { kind, operation: operation.length <= 64 ? operation : 'function-call' }; + if (code !== undefined) params.code = code; + if (count !== undefined) params.count = count; + if (durationMs !== undefined) params.durationMs = Math.min(Number.MAX_SAFE_INTEGER, Math.max(0, Math.floor(durationMs))); + if (token(operationId, 128)) params.operationId = operationId; + send(params); + }; + return Object.freeze({ + degraded: (operation, code, count) => record('degraded', operation, code, count), + recovered: (operation, code, count) => record('recovered', operation, code, count), + terminal: (operation, error, durationMs = 0) => record(error ? 'operationFailed' : 'operationFinished', operation, + error ? (token(error.code, 64) ? error.code : 'internal_error') : undefined, undefined, durationMs), + }); +} diff --git a/sdk/node/src/errors.mjs b/sdk/node/src/errors.mjs index 7a24af7..048cae0 100644 --- a/sdk/node/src/errors.mjs +++ b/sdk/node/src/errors.mjs @@ -9,7 +9,7 @@ export class PluginError extends Error { /** * @param {string} code Identifier of at most 64 bytes, such as `maven.snapshotLocked`. * @param {string} message User-facing text; Core keeps the first 1024 bytes. - * @param {object} [options] `{ cause }`, kept for logs only. + * @param {object} [options] `{ cause }`, retained in memory and omitted from automatic diagnostics. */ constructor(code, message, options) { super(message, options); @@ -96,6 +96,6 @@ export function toResponseError(error, signal) { }; } // Unexpected exceptions often embed absolute paths (ENOENT) or internals; - // the caller logs the details to stderr instead. + // the caller logs only a fixed failure category to stderr. return { code: ERROR_CODES.internalError, message: 'The plugin backend failed unexpectedly.' }; } diff --git a/sdk/node/src/host.mjs b/sdk/node/src/host.mjs index 1aafa4c..87640c9 100644 --- a/sdk/node/src/host.mjs +++ b/sdk/node/src/host.mjs @@ -181,7 +181,7 @@ export class HostChannel { if (this.#early.length < MAX_EARLY_EVENTS) { this.#early.push({ subscriptionID, sequence, event }); } else { - this.#transport.log(`Dropped an early event of subscription ${subscriptionID}.`); + this.#transport.log('Dropped an early subscription event: queue_full'); } } // Otherwise the subscription was disposed; nothing follows a disposal. @@ -233,7 +233,7 @@ export class HostChannel { subscription.lastSequence = sequence; Promise.resolve() .then(() => subscription.onEvent(event, { subscriptionID, sequence, gap })) - .catch((error) => this.#transport.log(`Subscription ${subscriptionID} failed to handle an event:`, error)); + .catch(() => this.#transport.log('A subscription listener failed: internal_error')); } #drain() { diff --git a/sdk/node/src/index.d.ts b/sdk/node/src/index.d.ts index d3d2af4..fe7585b 100644 --- a/sdk/node/src/index.d.ts +++ b/sdk/node/src/index.d.ts @@ -27,6 +27,12 @@ export interface ProcessResult { truncated: boolean; } +/** Typed facts for the host-owned litheLogging 1 event catalog. */ +export interface Diagnostics { + degraded(operation: string, code: string, count?: number): void; + recovered(operation: string, code: string, count?: number): void; +} + /** Shared by every handler. */ export interface RequestContext { /** Aborted when the host cancels the call, the call times out, the session ends, or the call has settled. */ @@ -34,8 +40,10 @@ export interface RequestContext { throwIfCancelled(): void; /** `runProcess` bound to this call: its tree ends when the call is cancelled or settles. */ run(command: string, args?: string[], options?: RunProcessOptions): Promise; - /** Writes a line to stderr, which the host keeps in its log. */ - log(...parts: unknown[]): void; + /** Fixed facts, correlated with the host operation; never accepts payload text. */ + readonly diagnostics: Diagnostics; + /** Omits only this call's successful fact; failures remain visible. */ + suppressSuccessDiagnostics(): void; /** `backend.host` bound to this call: its unanswered host requests are cancelled when the call ends. */ host: Host; } @@ -529,7 +537,8 @@ export interface Backend { onShutdown(hook: () => unknown): Backend; sendRequest(method: string, params?: unknown): Promise; sendNotification(method: string, params?: unknown): void; - log(...parts: unknown[]): void; + readonly diagnostics: Diagnostics; + suppressSuccessDiagnostics(operation: string): this; listen(options?: ListenOptions): Promise; } diff --git a/sdk/node/test/backend.test.mjs b/sdk/node/test/backend.test.mjs index 2bb9bb8..2d3dda8 100644 --- a/sdk/node/test/backend.test.mjs +++ b/sdk/node/test/backend.test.mjs @@ -20,6 +20,7 @@ test('initialize answers the protocols the host offered, with sorted functions', const host = new TestHost(backend); const { result } = await host.initialize(); assert.deepEqual(result.capabilities.experimental, { + litheLogging: { version: 1 }, litheBuild: { version: 1 }, litheFunctions: { version: 1, functions: [{ id: 'install.prepare' }, { id: 'snapshot.refresh' }] }, }); @@ -30,12 +31,12 @@ test('initialize answers the protocols the host offered, with sorted functions', test('a host that offers nothing gets no Lithe capabilities, and a backend without build handlers never claims litheBuild', async () => { const quiet = new TestHost(functionBackend()); - assert.deepEqual((await quiet.initialize({})).result.capabilities.experimental, {}); + assert.deepEqual((await quiet.initialize({})).result.capabilities.experimental, { litheLogging: { version: 1 } }); await quiet.close(); const other = new TestHost(functionBackend()); const answer = (await other.initialize({ litheBuild: { versions: [1] }, litheFunctions: { versions: [99] } })).result; - assert.deepEqual(answer.capabilities.experimental, {}); + assert.deepEqual(answer.capabilities.experimental, { litheLogging: { version: 1 } }); await other.close(); }); @@ -128,7 +129,7 @@ test('progress echoes the operation ID, is bounded, and stops once the call ende assert.ok(!host.messages.some((message) => message.params?.message === 'too late')); }); -test('a PluginError carries its code; other failures hide their details', async () => { +test('a PluginError carries its code; automatic diagnostics omit failure contents', async (t) => { const backend = createBackend() .function('locked', () => { throw new PluginError('maven.snapshotLocked', 'Snapshot is locked.'); @@ -137,6 +138,9 @@ test('a PluginError carries its code; other failures hide their details', async throw new Error('ENOENT: no such file, open /Users/someone/secret'); }); const host = new TestHost(backend); + t.after(() => host.close()); + const diagnostics = []; + host.errorOutput.on('data', (chunk) => diagnostics.push(chunk.toString())); await host.initialize(); const locked = await host.request('lithe/function/invoke', { functionID: 'locked', operationID: 'a' }); assert.deepEqual(locked.error, { code: -32000, message: 'Snapshot is locked.', data: { code: 'maven.snapshotLocked' } }); @@ -144,6 +148,14 @@ test('a PluginError carries its code; other failures hide their details', async assert.equal(crash.error.code, -32603); assert.ok(!crash.error.message.includes('/Users/')); assert.equal(crash.error.data, undefined); + assert.equal(diagnostics.join(''), ''); + const records = host.messages.filter((message) => message.method === 'lithe/log').map(({ params }) => params); + assert.equal(records.length, 2); + assert.deepEqual(records.map(({ kind, operation, code, operationId }) => ({ kind, operation, code, operationId })), [ + { kind: 'operationFailed', operation: 'locked', code: 'maven.snapshotLocked', operationId: 'a' }, + { kind: 'operationFailed', operation: 'crash', code: 'internal_error', operationId: 'b' }, + ]); + assert.ok(records.every(({ durationMs }) => Number.isSafeInteger(durationMs) && durationMs >= 0)); assert.throws(() => new PluginError('bad code!', 'x'), TypeError); await host.close(); }); diff --git a/sdk/node/test/build.test.mjs b/sdk/node/test/build.test.mjs index 080eea2..dc1ea42 100644 --- a/sdk/node/test/build.test.mjs +++ b/sdk/node/test/build.test.mjs @@ -47,7 +47,7 @@ test('build negotiation chooses the highest common integer version', { timeout: const response = await host.initialize({ litheBuild: { versions } }); assert.equal(backend.buildVersion, versions[0] === 1 ? 4 : null); assert.deepEqual(response.result.capabilities.experimental, - versions[0] === 1 ? { litheBuild: { version: 4 } } : {}); + versions[0] === 1 ? { litheLogging: { version: 1 }, litheBuild: { version: 4 } } : { litheLogging: { version: 1 } }); await host.close(); } }); diff --git a/sdk/node/test/diagnostics.test.mjs b/sdk/node/test/diagnostics.test.mjs new file mode 100644 index 0000000..7b44662 --- /dev/null +++ b/sdk/node/test/diagnostics.test.mjs @@ -0,0 +1,85 @@ +import assert from 'node:assert/strict'; +import { test } from 'node:test'; +import { createBackend, PluginError } from '../src/index.mjs'; +import { TestHost } from './harness.mjs'; + +test('typed diagnostics validate facts, correlate the host operation, and suppress only successful polls', async (t) => { + const backend = createBackend().function('work.run', ({ fail }, context) => { + context.diagnostics.degraded('work.run', 'cache_unavailable', 2); + context.diagnostics.recovered('work.run', 'cache_restored'); + if (fail) throw new PluginError('work.failed', 'Private user-facing explanation.'); + return null; + }).suppressSuccessDiagnostics('work.run'); + const host = new TestHost(backend); + t.after(() => host.close()); + const stderr = []; + host.errorOutput.on('data', (chunk) => stderr.push(chunk.toString())); + await host.initialize(); + for (const [operationID, fail] of [['host-success', false], ['host-failure', true]]) { + await host.request('lithe/function/invoke', { functionID: 'work.run', operationID, params: { fail } }); + } + const records = host.messages.filter(({ method }) => method === 'lithe/log').map(({ params }) => params); + assert.deepEqual(records.map(({ kind }) => kind), ['degraded', 'recovered', 'degraded', 'recovered', 'operationFailed']); + assert.equal(records.at(-1).operationId, 'host-failure'); + assert.equal(records.at(-1).code, 'work.failed'); + assert.ok(Number.isSafeInteger(records.at(-1).durationMs)); + assert.equal(stderr.join(''), ''); + assert.ok(!JSON.stringify(records).includes('Private user-facing')); + for (const change of [ + () => backend.diagnostics.degraded('unknown.input', 'failure'), + () => backend.diagnostics.degraded('work.run', 'body with spaces'), + () => backend.diagnostics.degraded('work.run', 'failure', Number.MAX_SAFE_INTEGER + 1), + ]) assert.throws(change); +}); + +test('the new SDK requires logging v1 and never silently falls back to stderr', async (t) => { + const host = new TestHost(createBackend()); + t.after(() => host.close()); + const reply = await host.request('initialize', { capabilities: {} }); + assert.equal(reply.error.code, -32600); + assert.equal(host.messages.filter(({ method }) => method === 'lithe/log').length, 0); +}); + +test('per-call suppression keeps user actions and failures', async (t) => { + const backend = createBackend().function('database.call', ({ readOnly, fail }, context) => { + if (readOnly) context.suppressSuccessDiagnostics(); + if (fail) throw new Error('private failure'); + return null; + }); + const host = new TestHost(backend); + t.after(() => host.close()); + await host.initialize(); + for (const [id, params] of [['read', {readOnly:true}], ['query', {}], ['failure', {readOnly:true,fail:true}]]) { + await host.request('lithe/function/invoke', {functionID:'database.call',operationID:id,params}); + } + const facts = host.messages.filter(({method}) => method === 'lithe/log').map(({params}) => params); + assert.deepEqual(facts.map(({kind,operationId}) => [kind,operationId]), [['operationFinished','query'],['operationFailed','failure']]); +}); + +test('initialize diagnostics wait for the capability answer and keep only eight facts', async (t) => { + const backend = createBackend(); + backend.onInitialize(() => { + for (let count = 0; count < 10; count++) backend.diagnostics.degraded('initialize', 'snapshot_unavailable', count); + }); + const host = new TestHost(backend); + t.after(() => host.close()); + await host.initialize(); + assert.equal(host.messages[0].result.capabilities.experimental.litheLogging.version, 1); + const facts = host.messages.filter(({method}) => method === 'lithe/log'); + assert.deepEqual(facts.map(({params}) => params.count), [0, 1, 2, 3, 4, 5, 6, 7]); +}); + +test('domain diagnostics reuse the original RPC id when no wire operation is present', async (t) => { + const backend = createBackend(); + backend.build.model((_params, context) => { + context.diagnostics.degraded('lithe/build/model', 'snapshot_unavailable'); + return { projects: [] }; + }); + const host = new TestHost(backend); + t.after(() => host.close()); + await host.initialize(); + await host.request('lithe/build/model', { root: '.' }, 42); + await host.request('lithe/build/model', { root: '.', operationID: 'wire-original' }, 'rpc-second'); + const facts = host.messages.filter(({method}) => method === 'lithe/log').map(({params}) => params); + assert.deepEqual(facts.map(({operationId}) => operationId), ['42', '42', 'wire-original', 'wire-original']); +}); diff --git a/sdk/node/test/harness.mjs b/sdk/node/test/harness.mjs index 4988ed5..34da7bc 100644 --- a/sdk/node/test/harness.mjs +++ b/sdk/node/test/harness.mjs @@ -58,7 +58,7 @@ export class TestHost { const response = await this.request('initialize', { processId: null, rootUri, - capabilities: { experimental }, + capabilities: { experimental: { litheLogging: { versions: [1] }, ...experimental } }, }); this.notify('initialized', {}); return response; diff --git a/sdk/node/test/keymap.test.mjs b/sdk/node/test/keymap.test.mjs index 50170ad..d52b8f2 100644 --- a/sdk/node/test/keymap.test.mjs +++ b/sdk/node/test/keymap.test.mjs @@ -26,6 +26,9 @@ test('shortcut providers negotiate separately and read scoped snapshot inputs', assert.equal(read.params.fileID, 'file-0'); host.send({ id: read.id, result: { data: 'ZGF0YQ==' } }); assert.deepEqual((await pending).result, { bindings: [{ commandID: 'find-next', keys: [{ key: 'f3', modifiers: [] }] }] }); + // The terminal fact precedes the response and names the wire method Core accepts. + const facts = host.messages.filter((message) => message.method === 'lithe/log').map(({ params }) => [params.kind, params.operation]); + assert.deepEqual(facts, [['operationFinished', 'lithe/keymap/import']]); assert.ok((await host.request('lithe/keymap/import', { providerID: 'not-offered', snapshotID: 'snapshot-1' })).error); assert.ok((await host.request('lithe/keymap/import', { providerID: 'first', snapshotID: '../private' })).error); } finally { await host.close(); } diff --git a/sdk/node/test/vcs.test.mjs b/sdk/node/test/vcs.test.mjs index 7ee7f2c..5b19389 100644 --- a/sdk/node/test/vcs.test.mjs +++ b/sdk/node/test/vcs.test.mjs @@ -81,7 +81,7 @@ test('a host that does not offer litheVcs gets no provider and no VCS answers', const backend = createBackend().vcs('svn', required()); const host = new TestHost(backend); const { result } = await host.initialize({ litheVcs: { versions: [2] } }); - assert.deepEqual(result.capabilities.experimental, {}); + assert.deepEqual(result.capabilities.experimental, { litheLogging: { version: 1 } }); assert.equal(backend.negotiated.vcs, false); const refused = await host.request('lithe/vcs/status', { root: ROOT, tool: null }); assert.equal(refused.error.code, ERROR_CODES.methodNotFound); diff --git a/sdk/rust/README.md b/sdk/rust/README.md index 7496a78..932e3ba 100644 --- a/sdk/rust/README.md +++ b/sdk/rust/README.md @@ -105,6 +105,18 @@ exact contents: Check the archive against the SHA-256 you pinned, unpack it into your repository, and use it as a `path` dependency. +## Logging + +The new SDK requires `experimental.litheLogging` version 1 at initialization. +See [plugin logging](../../guides/plugin-logging.md) for the typed diagnostics +API, host-owned catalog, exact levels, operation correlation and `${logDir}`. +Use `diagnostics.degraded/recovered` (Rust: `diagnostics().degraded/recovered`) +for handled fallback or recovery facts. Function and build/VCS terminal facts +are automatic; do not log a failure before returning it to the SDK. Suppress +successful high-frequency reads with `suppressSuccessDiagnostics(operation)` +(Rust: `suppress_success_diagnostics`). The old free-text `log` API is removed; +there is no stderr fallback or plugin-owned file writer. + ## API | API | Purpose | @@ -134,7 +146,7 @@ context offers: | `progress(message, percentage)` | The message is cut to 1024 bytes and the percentage to 100; reports after the call ended are dropped. | | `host()` | Host services bound to the call: a request still waiting for the host when the call is cancelled ends at once. `credentials()` is `host().credentials()`. | | `workspace_context()` | From protocol 3, the `WorkspaceContext` of the window whose page made the call; `None` under older protocols or when no window made it. | -| `backend()`, `function_id()`, `log(message)` | The handle, the function's ID, and a line on stderr. | +| `backend()`, `function_id()`, `diagnostics()` | The handle, the function's ID, and typed diagnostics correlated with this call. | ## Host services @@ -253,7 +265,7 @@ nothing is stored. | --- | --- | | `Ok(value)` (including `Value::Null`) | `result.value` | | `Err(PluginError)` | `plugin.function.failed` with your message and `pluginErrorCode`. The code is for your plugin's own UI; Lithe never branches on it. | -| Any other error, or a panic | `plugin.function.failed` with a generic message, so paths, secrets, and stack traces never reach the UI. The details go to stderr. A panic ends only its call. | +| Any other error, or a panic | `plugin.function.failed` with a generic message, so paths, secrets, and stack traces never reach the UI. Automatic SDK diagnostics record only a fixed failure category. A panic ends only its call; SDK catch boundaries suppress raw payload printing. | | `Err(Cancelled)`, or any outcome after cancellation | `requestCancelled` (or Lithe's timeout or revocation outcome) | `?` converts `PluginError`, `Cancelled`, `SdkError`, `std::io::Error`, and @@ -270,9 +282,11 @@ panics on any other code. protocol to a duplicate of the stdout descriptor and points stdout at stderr, so a stray `println!` in your code or a dependency lands in the host's log. Elsewhere, never print to stdout. -2. **The package is read-only.** Keep caches, databases, and logs under - `${stateDir}`, which Lithe also passes as the root and working directory. - Writing to the package breaks code signing and update deltas. +2. **The package is read-only.** Keep caches and databases under `${stateDir}`, + which Lithe also passes as the root and working directory. Diagnostics use + the SDK and host; native log files require an explicitly supplied `${logDir}` + on a compatible local host. Writing to the package breaks code signing and + update deltas. 3. **Secrets go to the credentials service.** Never write a password or token to `${stateDir}`, to a log line, or to a `PluginError` message. 4. **Work ends with its call.** Check the cancellation in long loops, use diff --git a/sdk/rust/examples/sample-backend/src/main.rs b/sdk/rust/examples/sample-backend/src/main.rs index 6512dee..804d40d 100644 --- a/sdk/rust/examples/sample-backend/src/main.rs +++ b/sdk/rust/examples/sample-backend/src/main.rs @@ -215,9 +215,7 @@ fn main() { // A backend that keeps state per workspace would refresh it here. let handle = backend.handle(); backend.on_contexts_changed(move |_| { - let listed = handle.host().workspace().list_contexts()?; - let open = listed["contexts"].as_array().map_or(0, Vec::len); - handle.log(format_args!("{open} workspace(s) open")); + let _contexts = handle.host().workspace().list_contexts()?; Ok(()) }); @@ -247,10 +245,14 @@ fn offer_clear(backend: &BackendHandle, state: &Arc) { return; } let notes = Arc::clone(state); - if let Err(error) = - backend.register_function("note.clear", move |_, context| clear(¬es, context)) + if backend + .register_function("note.clear", move |_, context| clear(¬es, context)) + .is_err() { - backend.log(format_args!("note.clear stays unavailable: {error}")); + backend + .diagnostics() + .degraded("initialize", "registration_failed", None) + .expect("fixed diagnostic"); } } @@ -304,8 +306,11 @@ fn next_change(context: &Context) -> Result { } }; // A subscription outlives the call until it is disposed. - if let Err(error) = watch.dispose() { - context.log(format_args!("could not dispose the watch: {error}")); + if watch.dispose().is_err() { + context + .diagnostics() + .degraded("files.nextChange", "subscription_dispose_failed", None) + .expect("fixed diagnostic"); } outcome } diff --git a/sdk/rust/plugin-sdk/src/backend.rs b/sdk/rust/plugin-sdk/src/backend.rs index 57aad09..1bcb4c2 100644 --- a/sdk/rust/plugin-sdk/src/backend.rs +++ b/sdk/rust/plugin-sdk/src/backend.rs @@ -7,12 +7,14 @@ //! Contract: `contract/v1/README.md` ("Plugin backend", "Plugin functions", //! and "Host services"). +use crate::diagnostics::{Diagnostics, OPERATIONS}; use crate::error::{ cancelled_response, internal_response, response_error, sdk_codes, Cancelled, FunctionError, SdkError, }; use crate::framing::{read_frame, write_frame, Frame}; use crate::host::{Channel, Credentials, Host, Outcome, Outgoing, WorkspaceContext}; +use crate::panic_boundary::catch as catch_unwind; use crate::protocol::{ bounded_text, error_codes, is_command_id, is_function_id, methods, CONTEXT_VERSION, FUNCTIONS_VERSIONS, MAX_FUNCTIONS, MAX_MESSAGE_BYTES, MAX_RESULT_BYTES, @@ -21,14 +23,13 @@ use base64::{engine::general_purpose::STANDARD as BASE64, Engine as _}; use serde_json::{json, Map, Value}; use std::any::Any; use std::collections::{BTreeMap, BTreeSet, HashMap}; -use std::fmt::Display; use std::io::{self, BufReader, Read, Write}; -use std::panic::{catch_unwind, AssertUnwindSafe}; +use std::panic::AssertUnwindSafe; use std::path::PathBuf; use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; use std::sync::{Arc, Condvar, Mutex, MutexGuard, PoisonError}; use std::thread; -use std::time::Duration; +use std::time::{Duration, Instant}; type Handler = Arc Result + Send + Sync>; type InitializeHook = Box Result<(), FunctionError> + Send>; @@ -38,6 +39,9 @@ type CommandHandler = type NotificationHandler = Arc Result<(), FunctionError> + Send + Sync>; type Answer = Result; +/// Host request for one selected shortcut source; also the operation its diagnostic facts name. +const KEYMAP_IMPORT_METHOD: &str = "lithe/keymap/import"; + /// `Idle` → `Listening` → `Initializing` → `Ready` → `ShuttingDown` → `Exited`. #[derive(Clone, Copy, Debug, PartialEq, Eq)] pub(crate) enum Phase { @@ -51,9 +55,13 @@ pub(crate) enum Phase { pub(crate) struct State { pub(crate) phase: Phase, - functions: BTreeMap, + pub(crate) functions: BTreeMap, keymap_providers: BTreeMap, selected_keymap_providers: BTreeSet, + pub(crate) logging: bool, + pub(crate) logging_ready: bool, + pub(crate) early_diagnostics: Vec, + quiet_success: std::collections::HashSet, /// The negotiated plugin-function protocol version. functions_version: Option, /// Host requests being handled, by JSON-RPC ID. @@ -138,6 +146,10 @@ impl Backend { functions: BTreeMap::new(), keymap_providers: BTreeMap::new(), selected_keymap_providers: BTreeSet::new(), + logging: false, + logging_ready: false, + early_diagnostics: Vec::new(), + quiet_success: std::collections::HashSet::new(), functions_version: None, incoming: HashMap::new(), outgoing: HashMap::new(), @@ -158,6 +170,20 @@ impl Backend { } } + /// Omits successful terminal diagnostics for a registered high-frequency operation. + pub fn suppress_success_diagnostics(&mut self, operation: &str) -> Result<&mut Self, SdkError> { + let mut state = lock(&self.shared.state); + if !OPERATIONS.contains(&operation) && !state.functions.contains_key(operation) { + return Err(SdkError::new( + "sdk.logging.invalidOperation", + "Suppress a registered operation.", + )); + } + state.quiet_success.insert(operation.to_string()); + drop(state); + Ok(self) + } + /// Reported as `serverInfo.version`. pub fn version(mut self, version: impl Into) -> Self { self.version = Some(version.into()); @@ -343,8 +369,12 @@ impl Backend { let code = i32::from(self.shared.phase() != Phase::ShuttingDown); return self.shared.finish(code); } - Err(error) => { - self.shared.log(format_args!("Ending the session: {error}")); + Err(_) => { + self.handle().diagnostics().terminal( + "notification", + Some(&FunctionError::internal("framing_error")), + Instant::now(), + ); return self.shared.finish(1); } Ok(Some(Frame::Malformed)) => self.shared.respond( @@ -400,7 +430,7 @@ impl Backend { Phase::Ready if method == methods::FUNCTION_INVOKE => { Shared::invoke(&self.shared, id, ¶ms) } - Phase::Ready if method == "lithe/keymap/import" => { + Phase::Ready if method == KEYMAP_IMPORT_METHOD => { Shared::invoke_keymap(&self.shared, id, ¶ms) } Phase::Ready => self.shared.respond( @@ -462,9 +492,7 @@ impl Backend { methods::COMMAND_DID_RUN => { let command_id = params["commandID"].as_str().unwrap_or_default(); let Some(handler) = self.commands.get(command_id).cloned() else { - return self - .shared - .log(format_args!("No handler for command {command_id}.")); + return self.shared.failed("notification", "command_unhandled"); }; let command_id = command_id.to_string(); let context = WorkspaceContext::from_reference(¶ms["context"]); @@ -503,6 +531,23 @@ impl Backend { let keymap_offer = params .pointer("/capabilities/experimental/litheKeymapImport") .cloned(); + let logging = params + .pointer("/capabilities/experimental/litheLogging/versions") + .and_then(Value::as_array) + .is_some_and(|versions| versions.iter().any(|v| v.as_u64() == Some(1))); + lock(&self.shared.state).logging = logging; + lock(&self.shared.state).logging_ready = false; + lock(&self.shared.state).early_diagnostics.clear(); + if !logging { + lock(&self.shared.state).phase = Phase::Listening; + return self.shared.respond( + &id, + Err(rpc_error( + error_codes::INVALID_REQUEST, + "The backend requires litheLogging version 1.", + )), + ); + } let offered = params .pointer("/capabilities/experimental/litheFunctions/versions") .and_then(Value::as_array); @@ -520,15 +565,8 @@ impl Backend { let outcome = catch_unwind(AssertUnwindSafe(|| hook(&mut initialize))); let error = match outcome { Ok(Ok(())) => continue, - Ok(Err(error)) => { - self.shared.log(format_args!("initialize failed: {error}")); - response_error(&error) - } - Err(panic) => { - self.shared - .log(format_args!("initialize failed: {}", panic_message(&panic))); - internal_response() - } + Ok(Err(error)) => response_error(&error), + Err(_) => internal_response(), }; lock(&self.shared.state).phase = Phase::Listening; return self.shared.respond(&id, Err(error)); @@ -540,6 +578,7 @@ impl Backend { state.functions.extend(initialize.added); state.functions_version = functions_version; let mut experimental = Map::new(); + experimental.insert("litheLogging".into(), json!({ "version": 1 })); if let Some(offer) = keymap_offer { let version = offer .get("versions") @@ -578,9 +617,7 @@ impl Backend { json!({ "version": version, "functions": functions }), ); } - None if !state.functions.is_empty() => self.shared.log( - "The host did not offer a litheFunctions version from 1 to 3; functions stay unavailable.", - ), + None if !state.functions.is_empty() => {} None => {} } let mut server_info = json!({ "name": self.shared.name }); @@ -592,6 +629,13 @@ impl Backend { &id, Ok(json!({ "capabilities": { "experimental": experimental }, "serverInfo": server_info })), ); + state.logging_ready = true; + let early = std::mem::take(&mut state.early_diagnostics); + drop(state); + for params in early { + self.shared + .write(&json!({"jsonrpc":"2.0", "method":"lithe/log", "params":params})); + } } fn shutdown(&mut self, id: Value) { @@ -615,11 +659,8 @@ impl Backend { }; running.iter().for_each(Cancellation::cancel); for hook in &mut self.shutdown_hooks { - if let Err(panic) = catch_unwind(AssertUnwindSafe(&mut *hook)) { - self.shared.log(format_args!( - "A shutdown hook failed: {}", - panic_message(&panic) - )); + if catch_unwind(AssertUnwindSafe(&mut *hook)).is_err() { + self.shared.failed("shutdown", "panic"); } } self.shared.respond(&id, Ok(Value::Null)); @@ -660,8 +701,12 @@ impl Shared { lock(&self.state).functions_version } - pub(crate) fn log(&self, message: impl Display) { - let _ = writeln!(io::stderr(), "[{}] {message}", self.name); + pub(crate) fn failed(&self, operation: &str, code: &str) { + self.write( + &json!({ "jsonrpc": "2.0", "method": "lithe/log", "params": { + "kind": "operationFailed", "operation": operation, "code": code, "durationMs": 0 + }}), + ); } fn finish(&self, code: i32) -> i32 { @@ -689,16 +734,12 @@ impl Shared { .name(format!("lithe-notification-{method}")) .spawn(move || match catch_unwind(AssertUnwindSafe(handler)) { Ok(Ok(())) => {} - Ok(Err(error)) => shared.log(format_args!("Notification {method} failed: {error}")), - Err(panic) => shared.log(format_args!( - "Notification {method} panicked: {}", - panic_message(&panic) - )), + Ok(Err(FunctionError::Cancelled)) => {} + Ok(Err(error)) => shared.failed("notification", failure_kind(&error)), + Err(_) => shared.failed("notification", "panic"), }); - if let Err(error) = spawned { - self.log(format_args!( - "A notification handler could not start: {error}" - )); + if spawned.is_err() { + self.failed("notification", "worker_start_failed"); } } @@ -707,11 +748,11 @@ impl Shared { let Some(writer) = output.as_mut() else { return; }; - if let Err(error) = write_frame(writer.as_mut(), message) { + if write_frame(writer.as_mut(), message).is_err() { // Every later write would fail the same way. *output = None; drop(output); - self.log(format_args!("The host stream failed: {error}")); + // The protocol pipe is gone; the host owns the process terminal fact. } } @@ -731,7 +772,7 @@ impl Shared { .get("snapshotID") .and_then(Value::as_str) .unwrap_or_default(); - if !params.as_object().is_some_and(|object| object.len() == 2) + if params.as_object().is_none_or(|object| object.len() != 2) || !valid_keymap_provider_id(provider) || !valid_snapshot_id(snapshot) { @@ -781,10 +822,13 @@ impl Shared { .name("lithe-keymap-import".into()) .spawn(move || { let ended = Cancellation::new(); + let diagnostic_operation_id = + crate::diagnostics::request_operation_id(&Value::Null, &thread_id); let context = Context { shared: Arc::clone(&worker), function_id: call_id, operation_id: Value::Null, + diagnostic_operation_id, host: Host::new( Arc::clone(&worker), vec![cancellation.clone(), ended.clone()], @@ -792,16 +836,20 @@ impl Shared { cancellation, workspace_context: None, reporting: AtomicBool::new(false), + quiet_success: AtomicBool::new(false), }; + let started = Instant::now(); let outcome = catch_unwind(AssertUnwindSafe(|| handler(call_params, &context))); ended.cancel(); - let answer = worker.function_answer(&context, outcome); + // Facts name the wire method Core registered, not the per-provider call id. + let answer = + worker.function_answer(&context, KEYMAP_IMPORT_METHOD, outcome, started); lock(&worker.state).incoming.remove(&thread_key); worker.respond(&thread_id, answer); }); - if let Err(error) = spawned { + if spawned.is_err() { lock(&shared.state).incoming.remove(&key); - shared.log(format_args!("The import could not start: {error}")); + shared.failed(KEYMAP_IMPORT_METHOD, "worker_start_failed"); shared.respond(&id, Err(internal_response())); } } @@ -855,10 +903,13 @@ impl Shared { .spawn(move || { // Ends host requests the call left behind, on clones of its host. let ended = Cancellation::new(); + let diagnostic_operation_id = + crate::diagnostics::request_operation_id(&operation_id, &thread_id); let context = Context { shared: Arc::clone(&worker), function_id, operation_id, + diagnostic_operation_id, host: Host::new( Arc::clone(&worker), vec![cancellation.clone(), ended.clone()], @@ -866,61 +917,71 @@ impl Shared { cancellation, workspace_context, reporting: AtomicBool::new(true), + quiet_success: AtomicBool::new(false), }; + let started = Instant::now(); let outcome = catch_unwind(AssertUnwindSafe(|| handler(call_params, &context))); context.reporting.store(false, Ordering::SeqCst); ended.cancel(); - let answer = worker.function_answer(&context, outcome); + let answer = + worker.function_answer(&context, &context.function_id, outcome, started); lock(&worker.state).incoming.remove(&thread_key); worker.respond(&thread_id, answer); }); - if let Err(error) = spawned { + if spawned.is_err() { lock(&shared.state).incoming.remove(&key); - shared.log(format_args!("The call could not start: {error}")); + shared.failed("function-call", "worker_start_failed"); shared.respond(&id, Err(internal_response())); } } /// The answer to one call. A cancelled call answers as cancelled whatever /// the handler returned, and only failures the host never sees in full - /// are logged with their details. + /// are logged with a fixed category, without their private contents. fn function_answer( &self, context: &Context, + function: &str, outcome: Result, Box>, + started: Instant, ) -> Answer { let cancelled = context.cancellation.is_cancelled(); - let function = &context.function_id; match outcome { _ if cancelled => Err(cancelled_response()), Ok(Ok(value)) => { let size = serde_json::to_vec(&value).map_or(usize::MAX, |bytes| bytes.len()); if size > MAX_RESULT_BYTES { - self.log(format_args!( - "Function {function} returned {size} bytes; results are limited to {MAX_RESULT_BYTES}." - )); + context.diagnostics().terminal( + function, + Some(&FunctionError::internal("result_limit")), + started, + ); Err(internal_response()) } else { + let quiet = context.quiet_success.load(Ordering::SeqCst) + || lock(&self.state).quiet_success.contains(function); + if !quiet { + context.diagnostics().terminal(function, None, started); + } Ok(value) } } Ok(Err(error)) => { - match &error { - FunctionError::Plugin(error) => { - self.log(format_args!("Function {function} failed: {error}")) - } - FunctionError::Internal(details) => self.log(format_args!( - "Function {function} failed unexpectedly: {details}" - )), - FunctionError::Cancelled => {} + if !matches!(error, FunctionError::Cancelled) { + context + .diagnostics() + .terminal(function, Some(&error), started); } Err(response_error(&error)) } - Err(panic) => { - self.log(format_args!( - "Function {function} panicked: {}", - panic_message(&panic) - )); + Err(_) => { + let _ = context.diagnostics().record( + "operationFailed", + function, + Some("panic"), + None, + Some(started.elapsed().as_millis().min(9_007_199_254_740_991) as u64), + ); Err(internal_response()) } } @@ -954,12 +1015,14 @@ fn check_new_function(id: &str, functions: &BTreeMap) -> Result Ok(()) } -fn panic_message(panic: &Box) -> String { - panic - .downcast_ref::<&str>() - .map(|message| message.to_string()) - .or_else(|| panic.downcast_ref::().cloned()) - .unwrap_or_else(|| "a panic without a message".into()) +// Failure values can contain user data. Never format their messages or panic payloads +// into diagnostics; preserve the existing response contract separately. +fn failure_kind(error: &FunctionError) -> &'static str { + match error { + FunctionError::Plugin(_) => "plugin_error", + FunctionError::Internal(_) => "internal_error", + FunctionError::Cancelled => "cancelled", + } } /// What a hook sees of `initialize`, before the backend answers it. @@ -1048,13 +1111,28 @@ pub struct Context { shared: Arc, function_id: String, operation_id: Value, + diagnostic_operation_id: Option, cancellation: Cancellation, host: Host, workspace_context: Option, reporting: AtomicBool, + quiet_success: AtomicBool, } impl Context { + /// Omits only this call's successful terminal fact; failures remain visible. + pub fn suppress_success_diagnostics(&self) { + self.quiet_success.store(true, Ordering::SeqCst); + } + + /// Structured diagnostics correlated with the host's original operation ID. + pub fn diagnostics(&self) -> Diagnostics { + Diagnostics { + shared: Arc::clone(&self.shared), + operation_id: self.diagnostic_operation_id.clone(), + } + } + pub fn function_id(&self) -> &str { &self.function_id } @@ -1115,11 +1193,6 @@ impl Context { shared: Arc::clone(&self.shared), } } - - /// Writes a diagnostic line to stderr, which the host keeps in its log. - pub fn log(&self, message: impl Display) { - self.shared.log(message); - } } /// A single host-authorized source snapshot for a shortcut import. @@ -1251,6 +1324,14 @@ pub struct BackendHandle { } impl BackendHandle { + /// Structured facts outside a call; no operation ID is fabricated. + pub fn diagnostics(&self) -> Diagnostics { + Diagnostics { + shared: Arc::clone(&self.shared), + operation_id: None, + } + } + /// The negotiated plugin-function protocol version; `None` before /// `initialize` or when the host offered none this SDK speaks. pub fn functions_version(&self) -> Option { @@ -1307,6 +1388,7 @@ impl BackendHandle { let running: Vec<_> = { let mut state = lock(&self.shared.state); state.functions.remove(id); + state.quiet_success.remove(id); state .incoming .values() @@ -1328,11 +1410,6 @@ impl BackendHandle { pub fn credentials(&self) -> Credentials { self.host().credentials() } - - /// Writes a diagnostic line to stderr, which the host keeps in its log. - pub fn log(&self, message: impl Display) { - self.shared.log(message); - } } /// The cancellation of one call, or of work a plugin may stop for its own diff --git a/sdk/rust/plugin-sdk/src/diagnostics.rs b/sdk/rust/plugin-sdk/src/diagnostics.rs new file mode 100644 index 0000000..0116030 --- /dev/null +++ b/sdk/rust/plugin-sdk/src/diagnostics.rs @@ -0,0 +1,169 @@ +//! Typed plugin facts transported to the host's litheLogging 1 catalog. +use crate::backend::{lock, Shared}; +use crate::{FunctionError, SdkError}; +use serde_json::json; +use std::sync::Arc; +use std::time::Instant; + +pub(crate) const MAX_INTEGER: u64 = 9_007_199_254_740_991; +pub(crate) const OPERATIONS: &[&str] = &[ + "initialize", + "shutdown", + "notification", + "function-call", + "result-encoding", + "lithe/build/model", + "lithe/build/dependencies", + "lithe/build/execute", + "lithe/build/test", + "lithe/build/discoverTests", + "lithe/build/prepareRun", + "lithe/build/prepareDebug", + "lithe/vcs/status", + "lithe/vcs/baseContent", + "lithe/vcs/history", + "lithe/vcs/fileHistory", + "lithe/vcs/annotate", + "lithe/vcs/checkin", + "lithe/vcs/rollback", + "lithe/vcs/update", + "lithe/vcs/fileOperation", + "lithe/vcs/resolve", + "lithe/vcs/cleanup", + "lithe/keymap/import", +]; +fn token(value: &str, maximum: usize) -> bool { + !value.is_empty() + && value.len() <= maximum + && value + .bytes() + .all(|c| c.is_ascii_alphanumeric() || b"._:/-$".contains(&c)) +} + +pub(crate) fn request_operation_id( + operation_id: &serde_json::Value, + request_id: &serde_json::Value, +) -> Option { + if let Some(id) = operation_id.as_str().filter(|id| token(id, 128)) { + return Some(id.to_string()); + } + let fallback = if let Some(id) = request_id.as_str() { + id.to_string() + } else if let Some(id) = request_id + .as_i64() + .filter(|id| id.unsigned_abs() <= MAX_INTEGER) + { + id.to_string() + } else if let Some(id) = request_id.as_u64().filter(|id| *id <= MAX_INTEGER) { + id.to_string() + } else { + return None; + }; + token(&fallback, 128).then_some(fallback) +} +/// A lightweight handle using the existing protocol writer, without a queue or file I/O. +#[derive(Clone)] +pub struct Diagnostics { + pub(crate) shared: Arc, + pub(crate) operation_id: Option, +} +impl Diagnostics { + /// Records a handled degradation; code is a controlled category, never an error message. + pub fn degraded( + &self, + operation: &str, + code: &str, + count: Option, + ) -> Result<(), SdkError> { + self.record("degraded", operation, Some(code), count, None) + } + /// Records a real recovery, with the same controlled operation and category. + pub fn recovered( + &self, + operation: &str, + code: &str, + count: Option, + ) -> Result<(), SdkError> { + self.record("recovered", operation, Some(code), count, None) + } + pub(crate) fn terminal( + &self, + operation: &str, + error: Option<&FunctionError>, + started: Instant, + ) { + let code = error.map(|error| match error { + FunctionError::Plugin(error) => error.code(), + FunctionError::Cancelled => "cancelled", + FunctionError::Internal(_) => "internal_error", + }); + let _ = self.record( + if error.is_some() { + "operationFailed" + } else { + "operationFinished" + }, + operation, + code, + None, + Some(started.elapsed().as_millis().min(u128::from(MAX_INTEGER)) as u64), + ); + } + pub(crate) fn record( + &self, + kind: &str, + operation: &str, + code: Option<&str>, + count: Option, + duration: Option, + ) -> Result<(), SdkError> { + let state = lock(&self.shared.state); + if !OPERATIONS.contains(&operation) && !state.functions.contains_key(operation) { + return Err(SdkError::new( + "sdk.logging.invalidOperation", + "Diagnostics need a registered operation.", + )); + } + let enabled = state.logging; + drop(state); + if code.is_some_and(|code| !token(code, 64)) { + return Err(SdkError::new( + "sdk.logging.invalidCode", + "Diagnostics need a controlled code.", + )); + } + if count.is_some_and(|count| count > MAX_INTEGER) { + return Err(SdkError::new( + "sdk.logging.invalidCount", + "Diagnostics need a safe count.", + )); + } + if !enabled { + return Ok(()); + } + let mut params = json!({ "kind": kind, "operation": if operation.len() <= 64 {operation} else {"function-call"} }); + if let Some(code) = code { + params["code"] = json!(code); + } + if let Some(count) = count { + params["count"] = json!(count); + } + if let Some(duration) = duration { + params["durationMs"] = json!(duration); + } + if let Some(id) = self.operation_id.as_deref().filter(|id| token(id, 128)) { + params["operationId"] = json!(id); + } + let mut state = lock(&self.shared.state); + if !state.logging_ready { + if state.early_diagnostics.len() < 8 { + state.early_diagnostics.push(params); + } + return Ok(()); + } + drop(state); + self.shared + .write(&json!({ "jsonrpc": "2.0", "method": "lithe/log", "params": params })); + Ok(()) + } +} diff --git a/sdk/rust/plugin-sdk/src/error.rs b/sdk/rust/plugin-sdk/src/error.rs index c6b0571..207440f 100644 --- a/sdk/rust/plugin-sdk/src/error.rs +++ b/sdk/rust/plugin-sdk/src/error.rs @@ -182,12 +182,12 @@ impl std::error::Error for SdkError {} /// How a function handler fails. `?` converts every error type a handler /// typically meets: a [`PluginError`] keeps its code, [`Cancelled`] (and a /// host request cut short by cancellation) answers as cancelled, and anything -/// else becomes a generic internal error whose details only reach stderr. +/// else becomes a generic internal error; automatic diagnostics omit its contents. #[derive(Debug)] pub enum FunctionError { Plugin(PluginError), Cancelled, - /// Logged to stderr; the host sees only that the backend failed. + /// Retained in memory; automatic diagnostics record only the internal-error category. Internal(String), } diff --git a/sdk/rust/plugin-sdk/src/host.rs b/sdk/rust/plugin-sdk/src/host.rs index 03143d9..6a95364 100644 --- a/sdk/rust/plugin-sdk/src/host.rs +++ b/sdk/rust/plugin-sdk/src/host.rs @@ -289,9 +289,7 @@ impl Shared { .push_back((subscription_id.to_string(), sequence, event)); } else { drop(state); - self.log(format_args!( - "Dropped an early event of subscription {subscription_id}." - )); + self.failed("notification", "subscription_queue_full"); } } // Otherwise the subscription was disposed; nothing follows a disposal. diff --git a/sdk/rust/plugin-sdk/src/lib.rs b/sdk/rust/plugin-sdk/src/lib.rs index 69615e1..5680ead 100644 --- a/sdk/rust/plugin-sdk/src/lib.rs +++ b/sdk/rust/plugin-sdk/src/lib.rs @@ -19,14 +19,17 @@ //! own, so handlers may block. A handler returns `Ok(value)` with a JSON //! result, a [`PluginError`] the plugin's UI can tell apart by its code, or //! any other error, which reaches the host only as a generic failure while -//! its details go to stderr. A panic ends only its call. +//! automatic diagnostics omit its contents. A panic ends only its call; +//! SDK catch boundaries suppress raw panic payload printing. //! //! See [`Backend`] for a minimal backend. mod backend; +mod diagnostics; mod error; mod framing; mod host; +mod panic_boundary; mod protocol; mod stdio; @@ -34,6 +37,7 @@ pub use backend::{ Backend, BackendHandle, Cancellation, Context, Initialize, KeymapImportRequest, KeymapSourceFile, }; +pub use diagnostics::Diagnostics; pub use error::{sdk_codes, Cancelled, FunctionError, PluginError, SdkError, HOST_ERROR_CODES}; pub use host::{ Browser, Credentials, Documents, Editor, Event, Host, Preview, Subscription, Subscriptions, diff --git a/sdk/rust/plugin-sdk/src/panic_boundary.rs b/sdk/rust/plugin-sdk/src/panic_boundary.rs new file mode 100644 index 0000000..c788cea --- /dev/null +++ b/sdk/rust/plugin-sdk/src/panic_boundary.rs @@ -0,0 +1,29 @@ +//! Suppresses payload printing only for panics owned by an SDK catch boundary. +use std::any::Any; +use std::cell::Cell; +use std::panic::{self, UnwindSafe}; +use std::sync::Once; + +thread_local! { static CAUGHT: Cell = const { Cell::new(false) }; } +static INSTALL: Once = Once::new(); + +pub(crate) fn catch( + operation: impl FnOnce() -> T + UnwindSafe, +) -> Result> { + INSTALL.call_once(|| { + let previous = panic::take_hook(); + panic::set_hook(Box::new(move |info| { + if !CAUGHT.with(Cell::get) { + previous(info); + } + })); + }); + struct Restore(bool); + impl Drop for Restore { + fn drop(&mut self) { + CAUGHT.with(|active| active.set(self.0)); + } + } + let _restore = Restore(CAUGHT.with(|active| active.replace(true))); + panic::catch_unwind(operation) +} diff --git a/sdk/rust/plugin-sdk/src/stdio.rs b/sdk/rust/plugin-sdk/src/stdio.rs index 21f95f3..cd7b591 100644 --- a/sdk/rust/plugin-sdk/src/stdio.rs +++ b/sdk/rust/plugin-sdk/src/stdio.rs @@ -21,10 +21,7 @@ pub(crate) fn protocol_output() -> Box { let protocol = dup(1); if protocol >= 0 { if dup2(2, 1) < 0 { - let _ = writeln!( - io::stderr(), - "Could not redirect stdout; printing to stdout corrupts the protocol." - ); + std::process::exit(1); } return Box::new(std::fs::File::from_raw_fd(protocol)); } diff --git a/sdk/rust/plugin-sdk/tests/common/mod.rs b/sdk/rust/plugin-sdk/tests/common/mod.rs index 0172e01..fd69dec 100644 --- a/sdk/rust/plugin-sdk/tests/common/mod.rs +++ b/sdk/rust/plugin-sdk/tests/common/mod.rs @@ -81,11 +81,12 @@ impl Host { } pub fn initialize(&mut self, versions: Value) -> Value { - let capabilities = if versions.is_null() { + let mut capabilities = if versions.is_null() { json!({}) } else { json!({ "experimental": { "litheFunctions": { "versions": versions } } }) }; + capabilities["experimental"]["litheLogging"] = json!({ "versions": [1] }); self.request( 0, "initialize", diff --git a/sdk/rust/plugin-sdk/tests/keymap.rs b/sdk/rust/plugin-sdk/tests/keymap.rs index b1e2bab..5b36d3f 100644 --- a/sdk/rust/plugin-sdk/tests/keymap.rs +++ b/sdk/rust/plugin-sdk/tests/keymap.rs @@ -27,6 +27,7 @@ fn negotiates_only_offered_providers_and_invokes_typed_domain_request() { 0, "initialize", json!({"capabilities": {"experimental": { + "litheLogging": {"versions": [1]}, "litheKeymapImport": {"versions": [1], "providers": ["first", "unknown"]} }}}), ); @@ -40,7 +41,16 @@ fn negotiates_only_offered_providers_and_invokes_typed_domain_request() { "lithe/keymap/import", json!({"providerID":"first", "snapshotID":"snapshot-1"}), ); - assert_eq!(host.answer(1).0["result"], json!({"bindings":[]})); + let (answer, before) = host.answer(1); + assert_eq!(answer["result"], json!({"bindings":[]})); + // The fact names the wire method Core accepts, never the provider-scoped call id. + let facts: Vec<_> = before + .iter() + .filter(|frame| frame["method"] == "lithe/log") + .collect(); + assert_eq!(facts.len(), 1); + assert_eq!(facts[0]["params"]["kind"], "operationFinished"); + assert_eq!(facts[0]["params"]["operation"], "lithe/keymap/import"); host.request( 2, "lithe/keymap/import", @@ -81,7 +91,7 @@ fn cancellation_reaches_a_running_provider() { }) .unwrap(); let mut host = Host::start(backend); - host.request(0, "initialize", json!({"capabilities":{"experimental":{"litheKeymapImport":{"versions":[1],"providers":["first"]}}}})); + host.request(0, "initialize", json!({"capabilities":{"experimental":{"litheLogging":{"versions":[1]},"litheKeymapImport":{"versions":[1],"providers":["first"]}}}})); host.answer(0); host.request( 1, @@ -111,9 +121,14 @@ fn provider_lists_and_reads_selected_files_through_scoped_host() { }) .unwrap(); let mut host = Host::start(backend); - host.request(0, "initialize", json!({"capabilities":{"experimental":{ - "litheFunctions":{"versions":[3]}, "litheKeymapImport":{"versions":[1],"providers":["first"]} - }}})); + host.request( + 0, + "initialize", + json!({"capabilities":{"experimental":{ + "litheLogging":{"versions":[1]}, "litheFunctions":{"versions":[3]}, + "litheKeymapImport":{"versions":[1],"providers":["first"]} + }}}), + ); host.answer(0); host.request( 1, diff --git a/sdk/rust/plugin-sdk/tests/session.rs b/sdk/rust/plugin-sdk/tests/session.rs index 80e7fb6..7250a9f 100644 --- a/sdk/rust/plugin-sdk/tests/session.rs +++ b/sdk/rust/plugin-sdk/tests/session.rs @@ -28,6 +28,7 @@ fn negotiates_the_newest_offered_version_and_lists_the_functions() { result, json!({ "capabilities": { "experimental": { + "litheLogging": {"version": 1}, "litheFunctions": { "version": version, "functions": [{ "id": "echo.value" }] } } }, "serverInfo": { "name": "test-backend", "version": "1.2.3" } @@ -44,7 +45,7 @@ fn a_host_without_plugin_functions_gets_no_functions() { let mut host = Host::start(echo_backend()); assert_eq!( host.initialize(Value::Null)["capabilities"], - json!({ "experimental": {} }) + json!({ "experimental": {"litheLogging": {"version": 1}} }) ); host.invoke(1, "echo.value", json!({})); assert_eq!(host.answer(1).0["error"]["code"], -32602); @@ -114,12 +115,15 @@ fn maps_results_failures_and_panics() { let (answer, before) = host.answer(1); assert_eq!(answer["result"], json!({ "done": true })); assert_eq!( - before, - [json!({ + before[0], + json!({ "jsonrpc": "2.0", "method": "lithe/function/progress", "params": { "operationID": "op-1", "message": "Halfway", "percentage": 100 } - })] + }) ); + assert_eq!(before[1]["method"], "lithe/log"); + assert_eq!(before[1]["params"]["kind"], "operationFinished"); + assert_eq!(before[1]["params"]["operationId"], "op-1"); host.invoke(2, "work.run", json!({ "mode": "plugin" })); assert_eq!( @@ -256,7 +260,10 @@ fn credentials_need_protocol_two() { host.initialize(json!([1])); host.invoke(1, "secret.roundTrip", json!({ "key": "db:main" })); let (answer, before) = host.answer(1); - assert!(before.is_empty(), "{before:?}"); + assert!( + before.iter().all(|frame| frame["method"] == "lithe/log"), + "{before:?}" + ); assert_eq!(answer["error"]["message"], "plugin.host.unavailable"); host.close(); } @@ -390,7 +397,148 @@ fn initialize_hooks_see_the_root_and_add_functions() { let mut refusing = Backend::new("test-backend"); refusing.on_initialize(|_| Err(PluginError::new("test.notReady", "Not ready.").into())); let mut host = Host::start(refusing); - host.request(0, "initialize", json!({ "capabilities": {} })); + host.request( + 0, + "initialize", + json!({ "capabilities": {"experimental": {"litheLogging": {"versions": [1]}}} }), + ); assert_eq!(host.answer(0).0["error"]["data"]["code"], "test.notReady"); host.close(); } + +#[test] +fn typed_diagnostics_preserve_operation_and_suppress_only_success() { + let mut backend = Backend::new("test-backend"); + backend + .function("work.inspect", |params, context| { + context + .diagnostics() + .degraded("work.inspect", "cache_unavailable", Some(2))?; + context + .diagnostics() + .recovered("work.inspect", "cache_restored", None)?; + if params["fail"] == true { + return Err(PluginError::new("work.failed", "private explanation").into()); + } + Ok(Value::Null) + }) + .unwrap(); + backend + .suppress_success_diagnostics("work.inspect") + .unwrap(); + let mut host = Host::start(backend); + host.initialize(json!([3])); + host.invoke(1, "work.inspect", json!({"fail": false})); + let (_, success) = host.answer(1); + assert_eq!(success.len(), 2); + assert_eq!(success[0]["params"]["operationId"], "op-1"); + assert_eq!(success[0]["params"]["kind"], "degraded"); + assert_eq!(success[1]["params"]["kind"], "recovered"); + host.invoke(2, "work.inspect", json!({"fail": true})); + let (_, failure) = host.answer(2); + assert_eq!(failure.len(), 3); + assert_eq!(failure[2]["params"]["kind"], "operationFailed"); + assert_eq!(failure[2]["params"]["code"], "work.failed"); + assert!(failure[2]["params"]["durationMs"].as_u64().is_some()); + assert!(!failure[2].to_string().contains("private explanation")); + host.close(); +} + +#[test] +fn per_call_suppression_keeps_user_success_and_failures() { + let mut backend = Backend::new("test-backend"); + backend + .function("database.call", |params, context| { + if params["readOnly"] == true { + context.suppress_success_diagnostics(); + } + if params["fail"] == true { + return Err(FunctionError::internal("private failure")); + } + Ok(Value::Null) + }) + .unwrap(); + let mut host = Host::start(backend); + host.initialize(json!([3])); + host.invoke(1, "database.call", json!({"readOnly": true})); + assert!(host.answer(1).1.is_empty()); + host.invoke(2, "database.call", json!({})); + assert_eq!(host.answer(2).1[0]["params"]["kind"], "operationFinished"); + host.invoke(3, "database.call", json!({"readOnly": true,"fail": true})); + assert_eq!(host.answer(3).1[0]["params"]["kind"], "operationFailed"); + host.close(); +} + +#[test] +fn initialize_diagnostics_wait_for_capability_answer_and_stay_bounded() { + let mut backend = Backend::new("test-backend"); + let diagnostics = backend.handle().diagnostics(); + backend.on_initialize(move |_| { + for count in 0..10 { + diagnostics.degraded("initialize", "snapshot_unavailable", Some(count))?; + } + Ok(()) + }); + let mut host = Host::start(backend); + host.request( + 0, + "initialize", + json!({"capabilities":{"experimental":{"litheLogging":{"versions":[1]}}}}), + ); + let answer = host.next(); + assert_eq!( + answer["id"], 0, + "no diagnostic before capability answer: {answer}" + ); + assert_eq!( + answer["result"]["capabilities"]["experimental"]["litheLogging"]["version"], + 1 + ); + for count in 0..8 { + let fact = host.next(); + assert_eq!(fact["method"], "lithe/log"); + assert_eq!(fact["params"]["count"], count); + } + host.request(1, "shutdown", Value::Null); + assert_eq!( + host.next()["id"], + 1, + "initialization buffer is bounded to eight facts" + ); + host.close(); +} + +#[test] +fn diagnostics_use_original_rpc_id_when_operation_id_is_absent() { + let mut backend = Backend::new("test-backend"); + backend + .function("work.inspect", |_, context| { + context + .diagnostics() + .degraded("work.inspect", "cache_unavailable", None)?; + Ok(Value::Null) + }) + .unwrap(); + let mut host = Host::start(backend); + host.initialize(json!([3])); + host.request( + 42, + "lithe/function/invoke", + json!({"functionID":"work.inspect"}), + ); + let (_, facts) = host.answer(42); + assert_eq!(facts.len(), 2); + assert!(facts + .iter() + .all(|fact| fact["params"]["operationId"] == "42")); + host.request( + "rpc-second", + "lithe/function/invoke", + json!({"functionID":"work.inspect", "operationID":"wire-original"}), + ); + let (_, facts) = host.answer("rpc-second"); + assert!(facts + .iter() + .all(|fact| fact["params"]["operationId"] == "wire-original")); + host.close(); +} From e73f3dd477be68ecb679e51d94eeb8de05f32a36 Mon Sep 17 00:00:00 2001 From: Yao Jingxi <23722032@bjtu.edu.cn> Date: Wed, 4 Nov 2026 12:31:07 +0800 Subject: [PATCH 2/3] fix(sdk-rust): satisfy clippy question_mark on request id fallback --- sdk/rust/plugin-sdk/src/diagnostics.rs | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/sdk/rust/plugin-sdk/src/diagnostics.rs b/sdk/rust/plugin-sdk/src/diagnostics.rs index 0116030..841e47c 100644 --- a/sdk/rust/plugin-sdk/src/diagnostics.rs +++ b/sdk/rust/plugin-sdk/src/diagnostics.rs @@ -54,10 +54,11 @@ pub(crate) fn request_operation_id( .filter(|id| id.unsigned_abs() <= MAX_INTEGER) { id.to_string() - } else if let Some(id) = request_id.as_u64().filter(|id| *id <= MAX_INTEGER) { - id.to_string() } else { - return None; + request_id + .as_u64() + .filter(|id| *id <= MAX_INTEGER)? + .to_string() }; token(&fallback, 128).then_some(fallback) } From 708a034fa3ea070d6c6cea2e8fb3a491de2434ad Mon Sep 17 00:00:00 2001 From: Yao Jingxi <23722032@bjtu.edu.cn> Date: Wed, 4 Nov 2026 12:38:31 +0800 Subject: [PATCH 3/3] test(e2e): claim plugin facts from a shared drain under parallel tests Core's catalog queue is process-global and the tests of one binary run in parallel, so one test's drain could take another plugin's terminal facts (CI saw the Node build scenario consume the VCS checkin fact). Every drain now happens under one lock into a shared buffer, and each test takes only the facts on its own plugin's channel. --- sdk/e2e/plugin_sdk/mod.rs | 36 +++++++++++++++++++++++++++++++----- 1 file changed, 31 insertions(+), 5 deletions(-) diff --git a/sdk/e2e/plugin_sdk/mod.rs b/sdk/e2e/plugin_sdk/mod.rs index d3f9fa4..4126fc0 100644 --- a/sdk/e2e/plugin_sdk/mod.rs +++ b/sdk/e2e/plugin_sdk/mod.rs @@ -29,6 +29,7 @@ use std::collections::BTreeMap; use std::fs; use std::path::{Path, PathBuf}; use std::process::Command; +use std::sync::{Mutex, PoisonError}; use std::time::{Duration, Instant}; const BUILD_SYSTEM: &str = "sample"; @@ -585,15 +586,40 @@ pub fn run_sample_scenario(sample: &Sample) { ); } +/// Facts drained from Core's process-global catalog queue but not yet claimed. +/// +/// Tests in one binary run in parallel and share that queue, so a drain can +/// return facts recorded for another test's plugin. Every drain happens under +/// this lock and lands here; each test then takes only its own plugin's facts. +static DRAINED_FACTS: Mutex> = Mutex::new(Vec::new()); + +/// Drains Core's queue and returns every unclaimed fact on the plugin's channel. +fn take_plugin_facts(plugin: &str) -> Vec { + let channel = format!("plugins/{plugin}/host"); + let mut facts = DRAINED_FACTS.lock().unwrap_or_else(PoisonError::into_inner); + let drained = core("diagnostics.drainCoreEvents", json!({})); + facts.extend(drained["events"].as_array().cloned().unwrap_or_default()); + let (mine, others): (Vec, Vec) = facts + .drain(..) + .partition(|fact| fact["channel"] == channel.as_str()); + *facts = others; + mine +} + /// Typed SDK notifications reach the Core-owned queue, with host operation correlation. fn assert_log_facts(plugin: &str, expected: &[(&str, &str, &str)]) { - let drained = core("diagnostics.drainCoreEvents", json!({})); - let records = drained["events"].as_array().expect("bounded catalog facts"); + let records = take_plugin_facts(plugin); for (operation, event, level) in expected { - let matches: Vec<_> = records.iter().filter(|fact| fact["event"] == *event && fact["op"] == *operation).collect(); - assert_eq!(matches.len(), 1, "one terminal {event} for {operation}: {drained}"); + let matches: Vec<_> = records + .iter() + .filter(|fact| fact["event"] == *event && fact["op"] == *operation) + .collect(); + assert_eq!( + matches.len(), + 1, + "one terminal {event} for {operation}: {records:#?}" + ); assert_eq!(matches[0]["level"], *level); - assert_eq!(matches[0]["channel"], format!("plugins/{plugin}/host")); assert!(matches[0]["fields"]["duration_ms"].as_u64().is_some()); assert!(!matches[0].to_string().contains("built app")); assert!(!matches[0].to_string().contains("s3cr3t"));