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..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"; @@ -456,6 +457,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 +497,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 +585,43 @@ pub fn run_sample_scenario(sample: &Sample) { "cleared state left files behind: {state:?}" ); } + +/// 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 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}: {records:#?}" + ); + assert_eq!(matches[0]["level"], *level); + 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..841e47c --- /dev/null +++ b/sdk/rust/plugin-sdk/src/diagnostics.rs @@ -0,0 +1,170 @@ +//! 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 { + request_id + .as_u64() + .filter(|id| *id <= MAX_INTEGER)? + .to_string() + }; + 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(); +}