From ea7f3ee51a21c9bf30b7b12802d5627b3794c612 Mon Sep 17 00:00:00 2001 From: Yao Jingxi <23722032@bjtu.edu.cn> Date: Wed, 4 Nov 2026 14:16:12 +0800 Subject: [PATCH 1/3] =?UTF-8?q?feat(logging):=20=E5=A3=B0=E6=98=8E?= =?UTF-8?q?=E5=BC=8F=E6=8F=92=E4=BB=B6=E7=94=B1=E6=89=A7=E8=A1=8C=E6=96=B9?= =?UTF-8?q?=E4=BB=A3=E8=AE=B0=E6=8F=92=E4=BB=B6=E6=93=8D=E4=BD=9C=E4=BA=8B?= =?UTF-8?q?=E5=AE=9E?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 没有插件进程的语言服务器、调试适配器和构建命令来源，以前在 plugins//host 通道没有任何操作事实，和 SDK 插件不统一。 - Core 新增 diagnostics.recordPluginOperation 与贡献映射表 CONTRIBUTIONS： languageServer/start、debugAdapter/start（ProcessStart）与 lithe/build/model、lithe/build/dependencies（CommandRun），失败阶段统一映射到 host.* 码；非法输入统一 -32064。 - macOS 新增 PluginOperationReporter / PluginOperationAttempt：调试适配器启动、 构建模型与依赖命令由宿主记录；语言服务器启动前失败由宿主记录，之后通过 lsp.startServer.startupOperation 交给 Core 记录唯一结果。 - 取消、停止、过期结果与由插件后端提供的构建计划不记录；从不解析错误文本。 - 修复 RustCoreBridge.LogFailure 按 reason 解码 Core 日志域错误。 - 更新事件目录、fixture、Core API 与插件契约、Agent Note 和功能矩阵。 --- .../2026-11-03-structured-logging-channels.md | 35 +- .../Core/Rust/RustCoreBridge+Logging.swift | 13 +- .../Lithe/Core/Rust/RustCoreBridge.swift | 4 + .../RustLanguageServerRuntimeAdapter.swift | 3 + .../MacPluginDebugAdapterTransport.swift | 6 +- .../Platform/MacOS/MacServiceContainer.swift | 10 +- .../Debug/DebugAdapterContracts.swift | 8 + .../LanguageServerRuntimeContracts.swift | 3 + .../Language/LanguageToolingContracts.swift | 6 + .../CoreDebugAdapterProtocolSession.swift | 37 +- .../Services/BuildSystemService.swift | 46 +- .../Runtime/LanguageServerSession.swift | 17 +- .../LanguageToolingSessionManager.swift | 15 + .../Logging/PluginOperationReporter.swift | 172 ++++++ .../DebugModuleTests.swift | 169 ++++++ .../BuildSystemServiceTests.swift | 200 ++++++- .../MacBuildProviderSessionsTests.swift | 131 +++++ .../LitheTests/PluginDebugAdapterTests.swift | 35 ++ ...ginLanguageServerLaunchResolverTests.swift | 91 +++ .../Support/RecordedPluginOperations.swift | 28 + .../src/diagnostics/catalog_generated.rs | 14 +- rust/lithe-core/src/diagnostics/channel.rs | 17 + rust/lithe-core/src/diagnostics/mod.rs | 1 + .../src/diagnostics/plugin_operations.rs | 526 ++++++++++++++++++ rust/lithe-core/src/diagnostics/record.rs | 2 +- rust/lithe-core/src/lsp/interface/engine.rs | 104 ++++ .../src/lsp/interface/engine_logging.rs | 18 +- .../lsp/interface/engine_real_jdt_tests.rs | 1 + rust/lithe-core/src/protocol/command.rs | 3 + rust/lithe-core/src/runtime/dispatcher.rs | 6 + shared/contracts/plugins/v1/README.md | 26 + shared/contracts/rust-core-api.md | 58 ++ .../diagnostics/engine-logging-v2.json | 71 ++- shared/logging/events/plugins.json | 14 +- .../features/diagnostics-export.json | 6 +- 35 files changed, 1851 insertions(+), 45 deletions(-) create mode 100644 macos/Sources/LitheModuleAPI/Logging/PluginOperationReporter.swift create mode 100644 macos/Tests/LitheTests/Support/RecordedPluginOperations.swift create mode 100644 rust/lithe-core/src/diagnostics/plugin_operations.rs diff --git a/.agents/notes/implemented/architecture/2026-11-03-structured-logging-channels.md b/.agents/notes/implemented/architecture/2026-11-03-structured-logging-channels.md index ec3b195059..50b4bc4dee 100644 --- a/.agents/notes/implemented/architecture/2026-11-03-structured-logging-channels.md +++ b/.agents/notes/implemented/architecture/2026-11-03-structured-logging-channels.md @@ -4,7 +4,7 @@ ## 先说结论 -日志的每一种事实都先在共享事件目录里声明，再由生成的类型约束字段。Core 负责通道、单行格式、脱敏、查询和保留计划，平台只负责实际文件操作。macOS 全部写入 v2 会话文件，Windows 继续使用 v1。排查问题时，维护者能顺着同一个 op（操作关联身份）看到三层轨迹：用户按了什么，Core 执行了哪个请求，以及 Git 命令带着哪些已脱敏参数、怎样结束。 +日志的每一种事实都先在共享事件目录里声明，再由生成的类型约束字段。Core 负责通道、单行格式、脱敏、查询和保留计划，平台只负责实际文件操作。macOS 全部写入 v2 会话文件，Windows 继续使用 v1。排查问题时，维护者能顺着同一个 op（操作关联身份）看到三层轨迹：用户按了什么，Core 执行了哪个请求，以及 Git 命令带着哪些已脱敏参数、怎样结束。没有插件进程的声明式插件，由实际执行声明工作的宿主或 Core 按一张贡献映射表，代写与 SDK 插件相同的插件操作事实。 ## 问题 @@ -215,6 +215,34 @@ Core 的目录遍历和 scratch 清理使用 `app.search.directory_skipped`、`a 保留计划的默认值为 30 天、总量 100 MiB、性能 20 MiB、每插件每会话 files 20 MiB。性能预算可以删除非活动会话里的性能文件。插件超额时返回告警，只有启动清理允许删除非活动会话中最老的插件文件。这两项是完整会话删除之外的明确例外；告警去重由宿主负责。Core 接收平台采集的文件清单和显式时间，返回相对路径计划；平台执行删除并报告真实的 I/O 结果，不能把计划当成删除成功。 +### 声明式插件：由执行方代记同一组操作事实 + +声明式插件（只在 manifest 里声明语言服务器、调试适配器或构建命令，没有自己的后端进程）无法发送 `lithe/log`。 +如果不处理，Go、PHP、LLDB、Gradle 这类插件出错时，`plugins//host` 通道里什么都没有，日志窗口里它们和 +SDK 插件不统一。因此谁真正执行声明的工作，谁就替插件写那一条终态事实：事件仍是 +`plugins.operation.finished|failed`，通道仍是 `plugins//host`，和 SDK 插件写出的事实在同一处、同一格式。 + +所有贡献共用一个通用结构：Core 的 `DeclarativeOperation`（插件 ID、贡献、失败阶段、耗时、可选 op）， +Swift 侧对应 `PluginOperationAttempt`。差异只在 `plugin_operations.rs` 的 `CONTRIBUTIONS` 映射表里：每一行给出 +操作名和生命周期（`ProcessStart` 常驻进程启动，或 `CommandRun` 一次性命令）。生命周期持有“阶段 → `host.*` 码”的表， +同一个码在所有共享该生命周期的贡献中只有一个含义；某个生命周期到不了的阶段直接拒绝（-32064），不会被猜成别的码。 +以后新增声明式契约时，开发者加一行映射，并在实际执行它的地方开始和结束一次 attempt，不新增事件、通道或错误码。 +构建命令沿用 SDK 的请求名（`lithe/build/model` 等），所以同一工作不论由声明还是后端提供，日志里都叫同一个名字。 + +所有权按“谁执行，谁记录”划分： + +- 调试适配器启动和构建命令由 macOS 宿主执行，宿主在解析、启动、初始化、超时、退出和解码的真实边界推进阶段， + 通过 `diagnostics.recordPluginOperation` 写入。 +- 语言服务器由宿主解析启动方案、由 Core 拉起和握手。宿主只记录启动前的失败；进入启动后用 + `startupOperation:{operationId,elapsedMs}` 把 attempt 交给 Core。Core 在 spawn 失败、提前退出、握手失败、 + 初始化超时或初始化成功时记录唯一结果，耗时为宿主已用时间加 Core 计时。 +- 构建计划实际由插件后端提供时，宿主取消自己的 attempt，由 SDK 记录，避免同一次工作出现两条事实。 + +一次 attempt 只有第一次终态生效。取消、停止、被新请求取代的过期结果都不记录，因为它们不是插件故障； +错误码只来自阶段，从不解析本地化错误文本，也不带插件输出、路径或命令行。 +正确做法：`attempt.advance(to: .launch)` 放在真正调用 `start` 之前，失败时 `attempt.end(throwing:)`。 +不要这样做：在 catch 里按 `error.localizedDescription` 判断是哪一步失败，或在宿主里按插件名写分支。 + ## 考虑过的备选方案 - **JSON Lines**：通用解析方便，但每行都重复键名和身份信息，手工阅读噪声多。采用有严格语法和 fixture 的单行文本，代价是维护专门的编解码器。 @@ -233,6 +261,9 @@ Core 的目录遍历和 scratch 清理使用 `app.search.directory_skipped`、`a - **每条事实回调一次，或在回调里直接 drain**：突发事实会产生大量跨语言调用；在记录线程里 drain 会把磁盘 I/O 带到 Core 调用方的线程，还要重入 Core。回调只安排宿主已有的单次排空。 - **只在宿主侧过滤 DEBUG**：后台 DEBUG 会先占满 256 条的 Core 队列，之后的 WARN 和 ERROR 被丢弃，因此必须在入队前过滤。 - **Core 轨迹的失败直接记 ERROR**：Core 不知道宿主会不会重试或降级，ERROR 会把可恢复的失败误报成用户请求失败；同一次失败再由宿主记录还会产生两条终态。 +- **为声明式插件单独起一个监听服务进程**：它看不到宿主和 Core 内部的真实阶段边界，只能事后解析输出或状态，还多一个需要管理生命周期的进程。由执行方在边界处直接记录更准确，也不增加进程。 +- **每种贡献一个专用事件或一个封闭的大枚举**：新契约要改事件目录、生成类型和所有平台代码，码的含义也会在各贡献间漂移。改为通用结构加映射表。 +- **解析错误消息判断失败阶段**：消息是本地化文本，也可能带路径和插件输出，翻译或措辞一改分类就错。阶段由代码路径显式推进。 ## 后果 @@ -274,6 +305,7 @@ Core 的目录遍历和 scratch 清理使用 `app.search.directory_skipped`、`a - `cargo test --manifest-path rust/Cargo.toml -p lithe-core core_request_traces` - `cargo test --manifest-path rust/Cargo.toml -p lithe-core command_trace` - `cargo test --manifest-path rust/Cargo.toml -p lithe-core --test core_log_waker` +- `cargo test --manifest-path rust/Cargo.toml -p lithe-core plugin_operations` - `./scripts/rust-core/verify-rust-core-comments.sh` - `./scripts/architecture/verify-shared-contracts.sh` - `./scripts/windows/verify/verify-windows-boundaries.sh` @@ -289,6 +321,7 @@ fixture 覆盖往返、转义、非法输入、路径段、轮转与保留、共 - `rust/lithe-core/src/runtime/dispatcher.rs` - `rust/lithe-core/src/tests/core_request_traces.rs` - `rust/lithe-core/src/debug/engine.rs` +- `macos/Sources/LitheModuleAPI/Logging/PluginOperationReporter.swift` - `rust/lithe-agent-host/src/failure_log.rs` - `rust/lithe-git-host/src/failure_log.rs` - `rust/lithe-ide-host/src/failure_log.rs` diff --git a/macos/Sources/Lithe/Core/Rust/RustCoreBridge+Logging.swift b/macos/Sources/Lithe/Core/Rust/RustCoreBridge+Logging.swift index 8b17cd2951..e9113630d7 100644 --- a/macos/Sources/Lithe/Core/Rust/RustCoreBridge+Logging.swift +++ b/macos/Sources/Lithe/Core/Rust/RustCoreBridge+Logging.swift @@ -3,6 +3,17 @@ import LitheModuleAPI import LitheRustCore extension RustCoreBridge { + func recordPluginOperation(_ observation: PluginOperationObservation) { + do { + let response: LogDomainResult = try executeResult( + command: "diagnostics.recordPluginOperation", payload: observation).get() + _ = try response.get() + } catch { + coreLogSink?.emit(AppLoggingDiagnosticsFailed(error: error)) + } + } + private struct EmptyPluginOperationResult: Decodable {} + typealias LogScalar = CoreLogScalar struct LogInput: Encodable, Sendable { var ts: String @@ -28,7 +39,7 @@ extension RustCoreBridge { var previousEvent: LogInput? = nil var headers: [LogHeader] = [] } - struct LogFailure: Decodable, Error, Sendable { let code: Int; let message: String } + struct LogFailure: Decodable, Error, Sendable { let code: Int; let reason: String } struct LogEncoded: Decodable, Sendable { let line: String?; let channel: String?; let error: LogFailure? } struct LogBatchResult: Decodable { let results: [LogEncoded]; let headers: [LogEncoded]; let sessionPath: String? } struct LogDomainResult: Decodable { diff --git a/macos/Sources/Lithe/Core/Rust/RustCoreBridge.swift b/macos/Sources/Lithe/Core/Rust/RustCoreBridge.swift index c992577457..1f13dce037 100644 --- a/macos/Sources/Lithe/Core/Rust/RustCoreBridge.swift +++ b/macos/Sources/Lithe/Core/Rust/RustCoreBridge.swift @@ -14,6 +14,7 @@ struct RustCoreBridge: Sendable, IncrementalLanguageServerRuntimeCore { var logRole: LanguageServerLogRole = .languageServer var logSubject: String? = nil var logPluginID: String? = nil + var startupOperation: PluginOperationHandoff? = nil var coreLogSink: (any LogSink)? = nil var registerLogSession: (@Sendable (String, String) -> Void)? = nil var releaseLogSession: (@Sendable (String) -> Void)? = nil @@ -2016,6 +2017,8 @@ struct RustCoreBridge: Sendable, IncrementalLanguageServerRuntimeCore { let providerId: String /// The plugin that owns the process; nil for host-owned servers. let pluginId: String? + /// A declarative start attempt whose result Core records. + let startupOperation: PluginOperationHandoff? let executablePath: String let arguments: [String] let environment: [String: String] @@ -4007,6 +4010,7 @@ struct RustCoreBridge: Sendable, IncrementalLanguageServerRuntimeCore { role: logRole.rawValue, logSubject: logSubject, providerId: providerID, pluginId: pluginID ?? logPluginID, + startupOperation: startupOperation, executablePath: executableURL.standardizedFileURL.path, arguments: arguments, environment: environment, diff --git a/macos/Sources/Lithe/Core/Rust/RustLanguageServerRuntimeAdapter.swift b/macos/Sources/Lithe/Core/Rust/RustLanguageServerRuntimeAdapter.swift index 835c7c04de..767978b19f 100644 --- a/macos/Sources/Lithe/Core/Rust/RustLanguageServerRuntimeAdapter.swift +++ b/macos/Sources/Lithe/Core/Rust/RustLanguageServerRuntimeAdapter.swift @@ -3,6 +3,9 @@ import LitheCoreContracts import LitheModuleAPI extension RustCoreBridge: LanguageServerRuntimeCore { + func observingPluginStartup(_ handoff: PluginOperationHandoff) -> any LanguageServerRuntimeCore { + var runtime = self; runtime.startupOperation = handoff; return runtime + } func loggingRuntime(role: LanguageServerLogRole, logSubject: String?, pluginID: String?) -> any LanguageServerRuntimeCore { var runtime = self runtime.logRole = role; runtime.logSubject = logSubject; runtime.logPluginID = pluginID diff --git a/macos/Sources/Lithe/Platform/MacOS/Debug/MacPluginDebugAdapterTransport.swift b/macos/Sources/Lithe/Platform/MacOS/Debug/MacPluginDebugAdapterTransport.swift index 9f875c4387..4d5e68a079 100644 --- a/macos/Sources/Lithe/Platform/MacOS/Debug/MacPluginDebugAdapterTransport.swift +++ b/macos/Sources/Lithe/Platform/MacOS/Debug/MacPluginDebugAdapterTransport.swift @@ -8,7 +8,7 @@ import LitheModuleAPI /// starts, not when the provider is registered; a rejected plan surfaces as the /// start error. @MainActor -final class MacPluginDebugAdapterTransport: DebugAdapterDrainingTransport { +final class MacPluginDebugAdapterTransport: DebugAdapterDrainingTransport, DebugAdapterLaunchResolvingTransport { enum TransportError: LocalizedError, Equatable { case unsupportedExecutable(adapterID: String) case commandNotFound(adapterID: String, commands: [String]) @@ -38,6 +38,7 @@ final class MacPluginDebugAdapterTransport: DebugAdapterDrainingTransport { private let socketFactory: @MainActor (String, UInt16) -> any DebugAdapterSocketConnection private let logSink: (any LogSink)? private var transport: (any DebugAdapterTransport)? + var startupAttempt: PluginOperationAttempt? var onData: ((Data) -> Void)? var onErrorOutput: ((Data) -> Void)? @@ -87,6 +88,9 @@ final class MacPluginDebugAdapterTransport: DebugAdapterDrainingTransport { transport.onErrorOutput = { [weak self] in self?.onErrorOutput?($0) } transport.onTermination = { [weak self] in self?.onTermination?($0) } self.transport = transport + // The plan, the executable and the hosted command are known; what + // fails from here is starting the adapter. + startupAttempt?.advance(to: .launch) try transport.start(rootURL: rootURL) } diff --git a/macos/Sources/Lithe/Platform/MacOS/MacServiceContainer.swift b/macos/Sources/Lithe/Platform/MacOS/MacServiceContainer.swift index ed93df43c8..02f59be265 100644 --- a/macos/Sources/Lithe/Platform/MacOS/MacServiceContainer.swift +++ b/macos/Sources/Lithe/Platform/MacOS/MacServiceContainer.swift @@ -110,6 +110,9 @@ final class MacServiceContainer { gitPreferences: settings.gitExecutionPreferences, gitExecutionJournal: gitExecutionJournal, remoteWorkspaces: remoteWorkspaces) + // Declarative plugins have no process of their own to report their + // contributions; the host reports each attempt through Core. + let pluginOperations = PluginOperationReporter(record: { rustCore.recordPluginOperation($0) }) let mavenRepositoryURL = FileManager.default.homeDirectoryForCurrentUser .appendingPathComponent(".m2/repository", isDirectory: true) let gradleRepositoryURL = FileManager.default.homeDirectoryForCurrentUser @@ -590,6 +593,7 @@ final class MacServiceContainer { let sessions = LanguageToolingSessionManager( catalog: registry.catalog, logSink: logSink, + pluginOperations: pluginOperations, resolveLogSubject: { try rustCore.resolveEngineLogSubject(providerID: $0) }, runtimes: registry.toolingRuntimes, runtimeFactory: runtimeFactory, @@ -664,6 +668,7 @@ final class MacServiceContainer { let buildSystemPlugins = pluginStartup.registeredPlugins.filter { !$0.descriptor.buildSystems.isEmpty } let buildSystems = buildSystemPlugins.isEmpty ? nil : BuildSystemService( logSink: logSink, + pluginOperations: pluginOperations, planner: RustBuildSystemOperations(core: rustCore), tools: MacBuildToolResolver( runtime: runtimeService, @@ -850,7 +855,10 @@ final class MacServiceContainer { } ), core: rustCore, - deadlineScheduler: MacDebugOperationDeadlineScheduler() + deadlineScheduler: MacDebugOperationDeadlineScheduler(), + beginPluginStartup: { + pluginOperations.begin(pluginID: pluginID, operation: .debugAdapterStart, at: .resolve) + } ) // Remembered so withdrawing this plugin ends this session // and no other plugin's session for the same language. diff --git a/macos/Sources/LitheCoreContracts/Debug/DebugAdapterContracts.swift b/macos/Sources/LitheCoreContracts/Debug/DebugAdapterContracts.swift index 8cc4314cf1..b25a3ae973 100644 --- a/macos/Sources/LitheCoreContracts/Debug/DebugAdapterContracts.swift +++ b/macos/Sources/LitheCoreContracts/Debug/DebugAdapterContracts.swift @@ -20,6 +20,14 @@ public protocol DebugAdapterTransport: AnyObject { func stop() } +/// A transport that resolves a declared launch when it starts. It advances the +/// session's start attempt from `resolve` to `launch` once the launch is known, +/// so a start error is attributed to the stage that failed. +@MainActor +public protocol DebugAdapterLaunchResolvingTransport: DebugAdapterTransport { + var startupAttempt: PluginOperationAttempt? { get set } +} + /// Optional bounded best-effort flush for the final DAP disconnect frame. /// This ends the transport, never the external server; `stop` still aborts now. @MainActor diff --git a/macos/Sources/LitheCoreContracts/Language/LanguageServerRuntimeContracts.swift b/macos/Sources/LitheCoreContracts/Language/LanguageServerRuntimeContracts.swift index 0e330a7be1..ea487b223b 100644 --- a/macos/Sources/LitheCoreContracts/Language/LanguageServerRuntimeContracts.swift +++ b/macos/Sources/LitheCoreContracts/Language/LanguageServerRuntimeContracts.swift @@ -369,6 +369,8 @@ package struct JavaLanguageImportConfiguration: Equatable, Sendable { package enum LanguageServerLogRole: String, Sendable { case languageServer = "language_server", vcs, build, toolchain, backend } package protocol LanguageServerRuntimeCore: Sendable { + /// Core records the result of this declarative start attempt. + func observingPluginStartup(_ handoff: PluginOperationHandoff) -> any LanguageServerRuntimeCore func loggingRuntime(role: LanguageServerLogRole, logSubject: String?, pluginID: String?) -> any LanguageServerRuntimeCore func emitCoreLog(_ record: CoreLogRecord) @@ -646,6 +648,7 @@ package protocol LanguageServerRuntimeCore: Sendable { } package extension LanguageServerRuntimeCore { + func observingPluginStartup(_ handoff: PluginOperationHandoff) -> any LanguageServerRuntimeCore { self } func loggingRuntime(role: LanguageServerLogRole, logSubject: String?, pluginID: String?) -> any LanguageServerRuntimeCore { self } func emitCoreLog(_ record: CoreLogRecord) {} diff --git a/macos/Sources/LitheCoreContracts/Language/LanguageToolingContracts.swift b/macos/Sources/LitheCoreContracts/Language/LanguageToolingContracts.swift index 3789e69d8c..4018957b18 100644 --- a/macos/Sources/LitheCoreContracts/Language/LanguageToolingContracts.swift +++ b/macos/Sources/LitheCoreContracts/Language/LanguageToolingContracts.swift @@ -843,6 +843,10 @@ package enum WorkspaceConfigurationUpdateResult: Sendable { @MainActor package protocol LanguageServerSession: AnyObject { + /// The declarative start attempt this session continues: it fails the + /// attempt before launch or hands it to Core with the start request. + /// Sessions that never start a declarative process ignore it. + func observePluginStartup(_ attempt: PluginOperationAttempt) var onProjectPreparation: ((ProjectPreparationSnapshot) -> Void)? { get set } var onMavenProfileTask: ((String) -> Void)? { get set } var onMavenProfileProject: ((MavenProfileProjectResult) -> Void)? { get set } @@ -1004,6 +1008,8 @@ package protocol LanguageServerSession: AnyObject { } package extension LanguageServerSession { + func observePluginStartup(_ attempt: PluginOperationAttempt) {} + func stopAndWait() async -> Bool { stop() let deadline = ContinuousClock.now.advanced(by: .seconds(5)) diff --git a/macos/Sources/LitheDebugModule/Runtime/CoreDebugAdapterProtocolSession.swift b/macos/Sources/LitheDebugModule/Runtime/CoreDebugAdapterProtocolSession.swift index afc0886a07..8e2e29b0a1 100644 --- a/macos/Sources/LitheDebugModule/Runtime/CoreDebugAdapterProtocolSession.swift +++ b/macos/Sources/LitheDebugModule/Runtime/CoreDebugAdapterProtocolSession.swift @@ -45,9 +45,17 @@ public final class CoreDebugAdapterProtocolSession: DebugAdapterControllingSessi private var errorOutputDecoder = StreamingUTF8Decoder() private var ownsCoreSession = false private var isStopping = false + /// Begins a declarative adapter's start attempt; nil for host-owned adapters. + private let beginPluginStartup: (@MainActor () -> PluginOperationAttempt)? + /// Ends when the adapter leaves `initializing`, fails, or the session stops. + private var startupAttempt: PluginOperationAttempt? public private(set) var state: DebugAdapterState = .idle { - didSet { if oldValue != state { onStateChange?(state) } } + didSet { + guard oldValue != state else { return } + endStartupAttempt(in: state) + onStateChange?(state) + } } public var onStateChange: ((DebugAdapterState) -> Void)? public var onEvent: ((DebugAdapterEvent) -> Void)? @@ -70,8 +78,10 @@ public final class CoreDebugAdapterProtocolSession: DebugAdapterControllingSessi sessionID: String = UUID().uuidString, deadlineScheduler: any DebugOperationDeadlineScheduling, operationTimeoutMilliseconds: Int = 10_000, - initializationTimeoutMilliseconds: Int? = nil + initializationTimeoutMilliseconds: Int? = nil, + beginPluginStartup: (@MainActor () -> PluginOperationAttempt)? = nil ) { + self.beginPluginStartup = beginPluginStartup self.logSink = logSink self.adapterID = adapterID self.disabledCapabilities = disabledCapabilities @@ -96,17 +106,25 @@ public final class CoreDebugAdapterProtocolSession: DebugAdapterControllingSessi discardPendingRunInTerminalRequests() discardPendingStartDebuggingRequests() capabilities = .unknown + startupAttempt?.cancel() + startupAttempt = beginPluginStartup?() + let resolving = transport as? any DebugAdapterLaunchResolvingTransport + resolving?.startupAttempt = startupAttempt + defer { resolving?.startupAttempt = nil } do { try transport.start(rootURL: rootURL.standardizedFileURL) } catch { + startupAttempt?.end(throwing: error) logSink?.emit(DebugTransportFailed(stage: "process-start", operationID: sessionID)) throw error } + startupAttempt?.advance(to: .initialize) if let initializationTimeoutMilliseconds { let token = UUID() initializationToken = token initializationDeadline = deadlineScheduler.schedule(afterMilliseconds: initializationTimeoutMilliseconds) { [weak self] in guard let self, self.initializationToken == token, self.ownsCoreSession else { return } self.logSink?.emit(DebugTransportFailed(stage: "initialization-timeout", operationID: self.sessionID)) + self.startupAttempt?.advance(to: .timeout) self.onEvent?(.output(category: "stderr", output: DebugAdapterProtocolError.timedOut("initialize").localizedDescription + "\n")) guard self.initializationToken == token else { return } self.failSession() @@ -125,6 +143,7 @@ public final class CoreDebugAdapterProtocolSession: DebugAdapterControllingSessi ownsCoreSession = true try apply(update) } catch { + startupAttempt?.fail() cancelInitializationDeadline() transport.stop() releaseCoreSession() @@ -135,6 +154,7 @@ public final class CoreDebugAdapterProtocolSession: DebugAdapterControllingSessi public func stop() { guard state != .idle || transport.isRunning || ownsCoreSession else { return } + startupAttempt?.cancel() isStopping = true cancelInitializationDeadline() failPendingRunInTerminalRequests(DebugAdapterProtocolError.stopped) @@ -858,6 +878,7 @@ public final class CoreDebugAdapterProtocolSession: DebugAdapterControllingSessi private func transportTerminated(exitCode: Int) { guard !isStopping else { return } + startupAttempt?.advance(to: .exit) if exitCode != 0 && state != .failed { logSink?.emit(DebugTransportFailed(exitCode: Int64(exitCode), stage: "transport-exit", operationID: sessionID)) } @@ -882,6 +903,18 @@ public final class CoreDebugAdapterProtocolSession: DebugAdapterControllingSessi state = .failed } + /// Leaving `initializing` for a working state ends the start; a failure + /// ends it at the stage reached, and stopping already cancelled it. + private func endStartupAttempt(in state: DebugAdapterState) { + switch state { + case .ready, .launching, .running, .paused: startupAttempt?.succeed() + case .failed, .terminated: startupAttempt?.fail() + case .idle: startupAttempt?.cancel() + case .initializing: return + } + startupAttempt = nil + } + private func cancelInitializationDeadline() { initializationToken = nil initializationDeadline?.cancel() diff --git a/macos/Sources/LitheExecutionModule/Services/BuildSystemService.swift b/macos/Sources/LitheExecutionModule/Services/BuildSystemService.swift index 8dc7e06f03..eb56fe7dac 100644 --- a/macos/Sources/LitheExecutionModule/Services/BuildSystemService.swift +++ b/macos/Sources/LitheExecutionModule/Services/BuildSystemService.swift @@ -94,6 +94,7 @@ package struct BuildSystemEntry: Equatable, Identifiable, Sendable { @MainActor package final class BuildSystemService: ObservableObject { private let logSink: (any LogSink)? + private let pluginOperations: PluginOperationReporter package static let modelTimeout: Duration = .seconds(15 * 60) private static let visibleOutputLimit = 1_000_000 /// Rust Core refuses larger output. @@ -203,6 +204,7 @@ package final class BuildSystemService: ObservableObject { package init( logSink: (any LogSink)? = nil, + pluginOperations: PluginOperationReporter = .disabled, planner: any BuildSystemPlanning, tools: any BuildToolResolving, optionsStore: any BuildOptionsStoring, @@ -217,6 +219,7 @@ package final class BuildSystemService: ObservableObject { sources: @escaping @MainActor () -> [BuildSystemPluginSource] ) { self.logSink = logSink + self.pluginOperations = pluginOperations self.planner = planner self.tools = tools self.optionsStore = optionsStore @@ -681,10 +684,13 @@ package final class BuildSystemService: ObservableObject { reason: BuildLoadReason, owner: CommandOwner ) async -> Result { + let attempt = pluginOperations.begin(pluginID: entry.instance.pluginID, operation: .buildModel, at: .plan) do { return .success(try await withPlanContext(entry, workspaceURL: workspaceURL, allocatesOutputFile: true) { context, outputFile in let planner = planner - let plan = try await outputPlan(entry, workspaceURL: workspaceURL, reason: reason, owner: owner) { hints in + let plan = try await outputPlan( + entry, workspaceURL: workspaceURL, reason: reason, owner: owner, attempt: attempt + ) { hints in try planner.modelPlan(entry.target, context: context, outputFile: outputFile, providerHints: hints) } let title = L10n.string("Loading \(entry.instance.displayName) model") @@ -695,7 +701,8 @@ package final class BuildSystemService: ObservableObject { outputFile: outputFile, title: title, timeout: Self.modelTimeout, - owner: owner + owner: owner, + attempt: attempt ) let target = entry.target let root = entry.instance.root @@ -714,10 +721,13 @@ package final class BuildSystemService: ObservableObject { ) ) }.value + // A result made stale by changed inputs is superseded, not finished. guard modelInputsAreCurrent(context.modelInputs) else { throw CancellationError() } + attempt.succeed() return loaded }) } catch { + attempt.end(throwing: error) if !(error is CancellationError) { logSink?.emit(RunPreparationFailed(error: error)) } return .failure(error) } @@ -1184,11 +1194,16 @@ package final class BuildSystemService: ObservableObject { reason: BuildLoadReason, owner: CommandOwner ) async -> Result { + let attempt = pluginOperations.begin( + pluginID: entry.instance.pluginID, operation: .buildDependencies, at: .plan + ) do { return .success(try await withPlanContext(entry, workspaceURL: workspaceURL, allocatesOutputFile: true) { context, outputFile in let planner = planner let selection = project.map(BuildSelection.init(project:)) - let plan = try await outputPlan(entry, workspaceURL: workspaceURL, reason: reason, owner: owner) { hints in + let plan = try await outputPlan( + entry, workspaceURL: workspaceURL, reason: reason, owner: owner, attempt: attempt + ) { hints in try planner.dependencyPlan( entry.target, context: context, project: selection, outputFile: outputFile, providerHints: hints ) @@ -1201,7 +1216,8 @@ package final class BuildSystemService: ObservableObject { outputFile: outputFile, title: L10n.string("Loading dependencies of \(name)"), timeout: Self.modelTimeout, - owner: owner + owner: owner, + attempt: attempt ) let target = entry.target let root = entry.instance.root @@ -1210,10 +1226,13 @@ package final class BuildSystemService: ObservableObject { target, workspaceURL: workspaceURL, root: root, project: project?.path, output: output ) }.value + // A result made stale by changed inputs is superseded, not finished. guard modelInputsAreCurrent(context.modelInputs) else { throw CancellationError() } + attempt.succeed() return loaded }) } catch { + attempt.end(throwing: error) if !(error is CancellationError) { logSink?.emit(RunPreparationFailed(error: error)) } return .failure(error) } @@ -1708,15 +1727,20 @@ package final class BuildSystemService: ObservableObject { /// neither repeats the lookup nor answers a reload from a stale snapshot. /// The tool is only resolved once Core says the source is a provider; a /// command plan resolves it when it runs. + /// + /// The host reports `attempt` only while it does the work itself: a + /// provider plan hands the load to the plugin's process, which reports it. private func outputPlan( _ entry: BuildSystemEntry, workspaceURL: URL, reason: BuildLoadReason, owner: CommandOwner, + attempt: PluginOperationAttempt, plan: (BuildProviderHints) throws -> BuildOutputPlan ) async throws -> BuildOutputPlan { let planned = try plan(BuildProviderHints(reason: reason)) guard case .provider = planned else { return planned } + attempt.cancel() guard let executable = try await providerTool(entry, workspaceURL: workspaceURL, owner: owner) else { return planned } @@ -1764,13 +1788,14 @@ package final class BuildSystemService: ObservableObject { outputFile: URL?, title: String, timeout: Duration, - owner: CommandOwner + owner: CommandOwner, + attempt: PluginOperationAttempt ) async throws -> BuildCommandOutput { switch plan { case .process(let process): return try await runCapturedCommand( process, entry: entry, workspaceURL: workspaceURL, outputFile: outputFile, - title: title, timeout: timeout, owner: owner + title: title, timeout: timeout, owner: owner, attempt: attempt ) case .provider(let request): guard let providers else { throw BuildSystemServiceError(Self.providerUnsupportedMessage) } @@ -1792,9 +1817,11 @@ package final class BuildSystemService: ObservableObject { outputFile: URL?, title: String, timeout: Duration, - owner: CommandOwner + owner: CommandOwner, + attempt: PluginOperationAttempt ) async throws -> BuildCommandOutput { let capturesStandardOutput = plan.output != .outputFile + attempt.advance(to: .resolve) let request = try await commandRequest( plan, entry: entry, workspaceURL: workspaceURL, capturesStandardOutput: capturesStandardOutput, timeout: timeout @@ -1804,20 +1831,25 @@ package final class BuildSystemService: ObservableObject { appendOutput("\n▶ " + title + "\n" + Self.commandLine(request), in: directory) } let tail = OutputCollector(limit: 64 * 1024, keepsTail: true) + attempt.advance(to: .launch) let result = try await run(request, owner: owner) { [weak self] chunk in tail.append(chunk) self?.appendOutput(chunk, in: directory) } switch result.termination { case .timedOut: + attempt.advance(to: .timeout) throw BuildSystemServiceError(L10n.string("\(title) timed out.")) case .exited(let code) where code != 0: + attempt.advance(to: .exit) let detail = tail.text.trimmingCharacters(in: .whitespacesAndNewlines) let summary = L10n.string("The build tool exited with code \(Int(code)).") throw BuildSystemServiceError(detail.isEmpty ? summary : summary + "\n" + Self.lastLines(detail)) case .exited: break } + // The caller decodes the output under the same stage. + attempt.advance(to: .decode) if capturesStandardOutput { guard let text = result.standardOutput else { throw BuildSystemServiceError(L10n.string("The build tool output is too large or not UTF-8.")) diff --git a/macos/Sources/LitheLanguageIntelligenceModule/Runtime/LanguageServerSession.swift b/macos/Sources/LitheLanguageIntelligenceModule/Runtime/LanguageServerSession.swift index f54c6d83fe..a3b40ac438 100644 --- a/macos/Sources/LitheLanguageIntelligenceModule/Runtime/LanguageServerSession.swift +++ b/macos/Sources/LitheLanguageIntelligenceModule/Runtime/LanguageServerSession.swift @@ -39,6 +39,14 @@ package final class LanguageServerRuntimeSession: LanguageServerSession { private let prepareProcess: (@MainActor (URL) async throws -> PreparedLanguageServerProcess)? private var preparationTask: Task? private var startingPreparedProcess = false + /// Held until launch: a preparation failure ends it here, a launch hands it to Core. + private var startupAttempt: PluginOperationAttempt? + package func observePluginStartup(_ attempt: PluginOperationAttempt) { startupAttempt = attempt } + private func endStartupAttempt(throwing error: any Error) { + startupAttempt?.end(throwing: error) + startupAttempt = nil + } + private let launchResolver: (@MainActor (URL) throws -> ResolvedLanguageServerLaunch)? private let hostIntegrationLaunch: LanguageServerHostIntegrationLaunch? private let cacheDirectoryURL: URL? @@ -263,6 +271,7 @@ package final class LanguageServerRuntimeSession: LanguageServerSession { self.startingDocuments = [:] self.startingDocumentBytes = 0 self.startingFileChanges = [] + self.endStartupAttempt(throwing: error) let failure = LanguageServerSessionFailure(code: (error as? DeclarativePluginRejection)?.code ?? "plugin.launch.failed", stage: "processStart", message: error.localizedDescription) self.transition(to: .failed(failure)) @@ -282,6 +291,7 @@ package final class LanguageServerRuntimeSession: LanguageServerSession { initializationOptions = resolved.initializationOptions workspaceConfiguration = resolved.workspaceConfiguration } catch { + endStartupAttempt(throwing: error) let message = "Language server launch could not be prepared: \(error.localizedDescription)" let failure = LanguageServerSessionFailure( code: (error as? DeclarativePluginRejection)?.code ?? "plugin.launch.missing", @@ -300,7 +310,10 @@ package final class LanguageServerRuntimeSession: LanguageServerSession { ([executableURL.path] + arguments).joined(separator: " "), nil ) - let core = core + // Core now owns every terminal result, including a synchronous launch + // failure. Only this start carries the attempt; a later restart does not. + let core = startupAttempt?.handOff().map { self.core.observingPluginStartup($0) } ?? self.core + startupAttempt = nil let pluginID = pluginID let hostServices = hostServices let offeredToolchainProviders = offeredToolchainProviders @@ -1318,6 +1331,8 @@ package final class LanguageServerRuntimeSession: LanguageServerSession { } package func stop() { + startupAttempt?.cancel() + startupAttempt = nil beginStop(inBackground: false) } diff --git a/macos/Sources/LitheLanguageIntelligenceModule/Services/LanguageToolingSessionManager.swift b/macos/Sources/LitheLanguageIntelligenceModule/Services/LanguageToolingSessionManager.swift index 549b49c1ef..76e23916ff 100644 --- a/macos/Sources/LitheLanguageIntelligenceModule/Services/LanguageToolingSessionManager.swift +++ b/macos/Sources/LitheLanguageIntelligenceModule/Services/LanguageToolingSessionManager.swift @@ -96,9 +96,12 @@ package final class LanguageToolingSessionManager: ObservableObject, private var mavenContextProvider: (LanguageProviderDescriptor, URL) -> MavenLaunchContext? = { _, _ in nil } private var javaLanguageImportProvider: ((LanguageProviderDescriptor, URL) throws -> JavaLanguageImportConfiguration)? + private let pluginOperations: PluginOperationReporter + package init( catalog: LanguageProviderCatalog = .compatibilityFallback, logSink: (any LogSink)? = nil, + pluginOperations: PluginOperationReporter = .disabled, resolveLogSubject: @escaping (String) throws -> LogSegment? = { _ in nil }, runtimes: [any LanguageProviderRuntime] = [], runtimeFactory: (any LanguageProviderRuntimeFactory)? = nil, @@ -110,6 +113,7 @@ package final class LanguageToolingSessionManager: ObservableObject, workspaceStateResetter: ((LanguageProviderDescriptor, URL, String?) throws -> Void)? = nil, workspaceStateCleaner: ((LanguageProviderDescriptor, URL, String?) throws -> Int)? = nil ) { + self.pluginOperations = pluginOperations self.logSink = logSink self.resolveLogSubject = resolveLogSubject self.catalog = catalog @@ -1692,11 +1696,18 @@ package final class LanguageToolingSessionManager: ObservableObject, } languageServerStartupAttempts[descriptor.id] = (rootURL, attempts + 1) let operationID = requestedOperationID ?? UUID() + // Only a declarative launch has no plugin process to report its start. + let startupAttempt = (descriptor.languageServerLaunch?.launchSource?.pluginID).map { + pluginOperations.begin( + pluginID: $0, operation: .languageServerStart, at: .resolve, operationID: operationID.uuidString + ) + } languageServerOperationIDs[descriptor.id] = operationID recordSessionStage(.requested, providerID: descriptor.id, operationID: operationID.uuidString) recordSessionStage(.resolving, providerID: descriptor.id, operationID: operationID.uuidString) guard let created = runtime.makeLanguageServerSession(rootURL: rootURL) else { + startupAttempt?.fail() let message = runtime.unavailableToolingMessage ?? descriptor.displayName let state = LanguageServerSessionState.failed(LanguageServerSessionFailure( code: "tool_not_found", @@ -1716,6 +1727,7 @@ package final class LanguageToolingSessionManager: ObservableObject, rootURL ) } catch { + startupAttempt?.end(throwing: error) let state = LanguageServerSessionState.failed(LanguageServerSessionFailure( code: "workspace_fingerprint_failed", stage: "workspaceFingerprint", @@ -1744,6 +1756,7 @@ package final class LanguageToolingSessionManager: ObservableObject, } } + if let startupAttempt { created.observePluginStartup(startupAttempt) } let featureProvider = LanguageServerFeatureProvider( providerID: descriptor.id, session: created, @@ -1783,6 +1796,8 @@ package final class LanguageToolingSessionManager: ObservableObject, javaGradle: importConfiguration.javaGradle ) } catch { + // Before the session handed the attempt to Core; a no-op after. + startupAttempt?.end(throwing: error) if languageServerSessionIdentities[descriptor.id] == sessionIdentity { clearLanguageServerSession( providerID: descriptor.id, diff --git a/macos/Sources/LitheModuleAPI/Logging/PluginOperationReporter.swift b/macos/Sources/LitheModuleAPI/Logging/PluginOperationReporter.swift new file mode 100644 index 0000000000..f5ccf575c4 --- /dev/null +++ b/macos/Sources/LitheModuleAPI/Logging/PluginOperationReporter.swift @@ -0,0 +1,172 @@ +import Foundation + +// A declarative contribution has no plugin process to call `lithe/log`, so the +// host records its attempts on the plugin's behalf. Every contribution uses the +// same types: an attempt begins where the host starts the work, moves through +// stages, and ends exactly once. Core's contribution table maps the operation +// and the failure stage to the event, channel and `host.*` code; the host sends +// no message text and never maps codes itself. + +/// The point at which a declarative contribution attempt failed. +public enum PluginOperationStage: String, Encodable, Sendable, Equatable { + /// The declaration could not be turned into a command. + case plan + /// The declared executable or tool could not be found or prepared. + case resolve + /// The process could not be started. + case launch + /// The process started but its protocol handshake failed. + case initialize + /// The host's deadline elapsed. + case timeout + /// The process exited early, or exited with a failure status. + case exit + /// The command's output could not be read or decoded. + case decode +} + +/// A contribution in Core's contribution table, spelled as in the plugin +/// contract. Add a constant only together with the row in Core's table. +public struct PluginOperationKind: RawRepresentable, Hashable, Sendable { + public let rawValue: String + public init(rawValue: String) { self.rawValue = rawValue } + + public static let languageServerStart = Self(rawValue: "languageServer/start") + public static let debugAdapterStart = Self(rawValue: "debugAdapter/start") + public static let buildModel = Self(rawValue: "lithe/build/model") + public static let buildDependencies = Self(rawValue: "lithe/build/dependencies") +} + +/// The payload of `diagnostics.recordPluginOperation`. +public struct PluginOperationObservation: Encodable, Sendable, Equatable { + public let pluginId: String + public let operation: String + public let outcome: String + /// Present exactly when the attempt failed. + public let stage: PluginOperationStage? + public let durationMs: UInt64 + public let operationId: String + + public init( + pluginID: String, operation: PluginOperationKind, failure: PluginOperationStage?, + durationMs: UInt64, operationID: String + ) { + pluginId = pluginID + self.operation = operation.rawValue + outcome = failure == nil ? "finished" : "failed" + stage = failure + self.durationMs = durationMs + operationId = operationID + } +} + +/// An attempt passed to Core with the request that starts the process. Core +/// then records its result, adding its own time to `elapsedMs`. +public struct PluginOperationHandoff: Encodable, Sendable, Equatable { + public let operationId: String + public let elapsedMs: UInt64 +} + +/// Begins declarative contribution attempts and delivers their results. +/// `disabled` records nothing and hands nothing off. +public struct PluginOperationReporter: Sendable { + public typealias Record = @MainActor @Sendable (PluginOperationObservation) -> Void + public typealias Clock = @MainActor @Sendable () -> UInt64 + + fileprivate let record: Record? + fileprivate let clock: Clock + + public static let disabled = PluginOperationReporter(recording: nil, clock: { 0 }) + + /// `clock` returns monotonic milliseconds; durations never use wall-clock time. + public init(record: @escaping Record, clock: @escaping Clock = { PluginOperationReporter.uptimeMilliseconds() }) { + self.init(recording: record, clock: clock) + } + + private init(recording: Record?, clock: @escaping Clock) { + record = recording + self.clock = clock + } + + public static func uptimeMilliseconds() -> UInt64 { DispatchTime.now().uptimeNanoseconds / 1_000_000 } + + /// Starts timing one attempt. `stage` is where a failure is attributed until + /// the attempt advances. + @MainActor + public func begin( + pluginID: String, operation: PluginOperationKind, at stage: PluginOperationStage, + operationID: String = UUID().uuidString + ) -> PluginOperationAttempt { + PluginOperationAttempt( + reporter: self, pluginID: pluginID, operation: operation, stage: stage, operationID: operationID + ) + } +} + +/// One attempt of one declarative contribution. The first terminal call wins +/// and later ones do nothing, so each failure path may end the attempt without +/// knowing whether another path already did. Cancellation records nothing. +@MainActor +public final class PluginOperationAttempt { + public let pluginID: String + public let operation: PluginOperationKind + public let operationID: String + /// Where a failure without an explicit stage is attributed. + public private(set) var stage: PluginOperationStage + public private(set) var isEnded = false + private let reporter: PluginOperationReporter + private let started: UInt64 + + fileprivate init( + reporter: PluginOperationReporter, pluginID: String, operation: PluginOperationKind, + stage: PluginOperationStage, operationID: String + ) { + self.reporter = reporter + self.pluginID = pluginID + self.operation = operation + self.stage = stage + self.operationID = operationID + started = reporter.clock() + } + + public var elapsedMilliseconds: UInt64 { + let now = reporter.clock() + return now >= started ? now - started : 0 + } + + public func advance(to stage: PluginOperationStage) { + guard !isEnded else { return } + self.stage = stage + } + + public func succeed() { end(failure: nil) } + + /// Fails at `stage`, or at the current stage when it is nil. + public func fail(_ stage: PluginOperationStage? = nil) { end(failure: stage ?? self.stage) } + + /// Ends the attempt for a thrown error: cancellation records nothing, + /// any other error fails at the current stage. + public func end(throwing error: any Error) { + if error is CancellationError || Task.isCancelled { cancel() } else { fail() } + } + + public func cancel() { isEnded = true } + + /// Ends the attempt here and returns it for Core to finish; nil when it + /// already ended or nothing records it. + public func handOff() -> PluginOperationHandoff? { + guard !isEnded else { return nil } + isEnded = true + guard reporter.record != nil else { return nil } + return PluginOperationHandoff(operationId: operationID, elapsedMs: elapsedMilliseconds) + } + + private func end(failure: PluginOperationStage?) { + guard !isEnded else { return } + isEnded = true + reporter.record?(PluginOperationObservation( + pluginID: pluginID, operation: operation, failure: failure, + durationMs: elapsedMilliseconds, operationID: operationID + )) + } +} diff --git a/macos/Tests/LitheDebugModuleTests/DebugModuleTests.swift b/macos/Tests/LitheDebugModuleTests/DebugModuleTests.swift index b84a352c3b..d13135a56b 100644 --- a/macos/Tests/LitheDebugModuleTests/DebugModuleTests.swift +++ b/macos/Tests/LitheDebugModuleTests/DebugModuleTests.swift @@ -4966,6 +4966,127 @@ struct DebugModuleTests { return feature } + // MARK: Declarative adapter start + + @Test + func aDeclarativeAdapterThatBecomesReadyRecordsOneFinishedStart() throws { + let transport = RecordingTransport() + let core = RecordingDebugProtocolCore() + let operations = RecordedDebugStartOperations() + let session = declarativeAdapterSession(transport: transport, core: core, operations: operations) + + try session.start(rootURL: URL(fileURLWithPath: "/tmp/declarative-adapter")) + #expect(operations.observations.isEmpty) + core.enqueueReceive(state: "ready", events: [["sequence": 2, "type": "stateChanged", "state": "ready"]]) + transport.emitData(Data("initialize-response".utf8)) + #expect(session.state == .ready) + // An adapter that exits after its start finished does not end the start again. + transport.terminate(1) + + #expect(operations.observations == [RecordedDebugStartOperations.expected(failure: nil)]) + } + + @Test + func aDeclarativeAdapterWhoseExecutableIsUnavailableRecordsTheResolveStage() { + let transport = RecordingTransport() + transport.failsToStart = true + let operations = RecordedDebugStartOperations() + let session = declarativeAdapterSession( + transport: transport, core: RecordingDebugProtocolCore(), operations: operations + ) + + #expect(throws: RecordingTransport.StartFailure.self) { + try session.start(rootURL: URL(fileURLWithPath: "/tmp/declarative-adapter")) + } + + #expect(operations.observations == [RecordedDebugStartOperations.expected(failure: .resolve)]) + } + + @Test + func aDeclarativeAdapterThatFailsToLaunchRecordsTheStageItsTransportReached() { + let transport = LaunchFailingTransport() + let operations = RecordedDebugStartOperations() + let session = declarativeAdapterSession( + transport: transport, core: RecordingDebugProtocolCore(), operations: operations + ) + + #expect(throws: LaunchFailingTransport.LaunchFailure.self) { + try session.start(rootURL: URL(fileURLWithPath: "/tmp/declarative-adapter")) + } + + #expect(operations.observations == [RecordedDebugStartOperations.expected(failure: .launch)]) + #expect(transport.startupAttempt == nil, "The session lends the attempt only for the start call") + } + + @Test + func aDeclarativeAdapterThatNeverInitializesRecordsTheTimeout() throws { + let transport = RecordingTransport() + let deadlines = RecordingDebugDeadlineScheduler() + let operations = RecordedDebugStartOperations() + let session = declarativeAdapterSession( + transport: transport, core: RecordingDebugProtocolCore(), deadlines: deadlines, + operations: operations, initializationTimeoutMilliseconds: 1_000 + ) + + try session.start(rootURL: URL(fileURLWithPath: "/tmp/declarative-adapter")) + deadlines.fireLast() + + #expect(session.state == .failed) + #expect(operations.observations == [RecordedDebugStartOperations.expected(failure: .timeout)]) + } + + @Test(arguments: [0, 3]) + func aDeclarativeAdapterThatExitsBeforeItIsReadyRecordsTheExit(exitCode: Int) throws { + let transport = RecordingTransport() + let operations = RecordedDebugStartOperations() + let session = declarativeAdapterSession( + transport: transport, core: RecordingDebugProtocolCore(), operations: operations + ) + + try session.start(rootURL: URL(fileURLWithPath: "/tmp/declarative-adapter")) + transport.terminate(exitCode) + + #expect(operations.observations == [RecordedDebugStartOperations.expected(failure: .exit)]) + } + + @Test + func stoppingADeclarativeAdapterBeforeItIsReadyRecordsNothing() throws { + let transport = RecordingTransport() + let core = RecordingDebugProtocolCore() + let operations = RecordedDebugStartOperations() + let session = declarativeAdapterSession(transport: transport, core: core, operations: operations) + + try session.start(rootURL: URL(fileURLWithPath: "/tmp/declarative-adapter")) + session.stop() + transport.terminate(0) + #expect(session.state == .terminated) + #expect(operations.observations.isEmpty) + + // The next start is a new attempt of its own. + try session.start(rootURL: URL(fileURLWithPath: "/tmp/declarative-adapter")) + core.enqueueReceive(state: "ready", events: [["sequence": 2, "type": "stateChanged", "state": "ready"]]) + transport.emitData(Data("initialize-response".utf8)) + #expect(operations.observations == [RecordedDebugStartOperations.expected(failure: nil)]) + } + + private func declarativeAdapterSession( + transport: any DebugAdapterTransport, + core: RecordingDebugProtocolCore, + deadlines: RecordingDebugDeadlineScheduler = RecordingDebugDeadlineScheduler(), + operations: RecordedDebugStartOperations, + initializationTimeoutMilliseconds: Int? = nil + ) -> CoreDebugAdapterProtocolSession { + CoreDebugAdapterProtocolSession( + adapterID: "lldb-dap", + transport: transport, + core: core, + sessionID: "java-session", + deadlineScheduler: deadlines, + initializationTimeoutMilliseconds: initializationTimeoutMilliseconds, + beginPluginStartup: { operations.begin() } + ) + } + private func indexedVariables( _ range: Range, idPrefix: String = "item" @@ -4991,8 +5112,12 @@ private final class RecordingTransport: DebugAdapterTransport { var onTermination: ((Int) -> Void)? private(set) var sentData: [Data] = [] private(set) var stopCalls = 0 + struct StartFailure: Error {} + /// When set, `start` throws before anything runs, like an unresolved executable. + var failsToStart = false func start(rootURL: URL) throws { + if failsToStart { throw StartFailure() } isRunning = true } @@ -5743,6 +5868,50 @@ private struct RecordingRunInTerminalCompletion: Equatable { let errorDescription: String? } +/// Records the start attempts a session reports, on a clock that advances +/// `tick` milliseconds per reading, so every attempt lasts exactly one tick. +@MainActor +private final class RecordedDebugStartOperations { + static let pluginID = "io.example.debug" + static let operationID = "debug-start" + static let tick: UInt64 = 7 + private(set) var observations: [PluginOperationObservation] = [] + private var now: UInt64 = 0 + + func begin() -> PluginOperationAttempt { + PluginOperationReporter( + record: { [self] in observations.append($0) }, + clock: { [self] in now += Self.tick; return now } + ).begin(pluginID: Self.pluginID, operation: .debugAdapterStart, at: .resolve, operationID: Self.operationID) + } + + static func expected(failure: PluginOperationStage?) -> PluginOperationObservation { + PluginOperationObservation( + pluginID: pluginID, operation: .debugAdapterStart, failure: failure, + durationMs: tick, operationID: operationID + ) + } +} + +/// Resolves its launch like the plugin transport, then fails to start it. +@MainActor +private final class LaunchFailingTransport: DebugAdapterLaunchResolvingTransport { + struct LaunchFailure: Error {} + var startupAttempt: PluginOperationAttempt? + let isRunning = false + var onData: ((Data) -> Void)? + var onErrorOutput: ((Data) -> Void)? + var onTermination: ((Int) -> Void)? + + func start(rootURL _: URL) throws { + startupAttempt?.advance(to: .launch) + throw LaunchFailure() + } + + func send(_: Data) throws {} + func stop() {} +} + @MainActor private final class RecordingDebugDeadlineScheduler: DebugOperationDeadlineScheduling { private var deadlines: [RecordingDebugDeadline] = [] diff --git a/macos/Tests/LitheExecutionModuleTests/BuildSystemServiceTests.swift b/macos/Tests/LitheExecutionModuleTests/BuildSystemServiceTests.swift index fde84e278a..f8fed56ce2 100644 --- a/macos/Tests/LitheExecutionModuleTests/BuildSystemServiceTests.swift +++ b/macos/Tests/LitheExecutionModuleTests/BuildSystemServiceTests.swift @@ -3,6 +3,7 @@ import Foundation import LitheApplicationKernel @testable import LitheExecutionModule import LitheCoreContracts +import LitheModuleAPI import Testing @MainActor @@ -1933,6 +1934,143 @@ struct BuildSystemServiceTests { #expect(harness.service.testDiscovery(Self.instanceID) == nil) } + // MARK: Declarative plugin operations + + @Test + func declarativeModelCommandRecordsOneFinishedOperation() async throws { + let planner = FakeBuildPlanner() + planner.detection = BuildDetection(instances: [try Self.instance(modelSource: "command")]) + planner.modelOutput = .stdout + let runner = FakeBuildRunner() + runner.script = .init(chunks: [], result: BuildCommandResult(termination: .exited(0), standardOutput: "MODEL")) + let operations = RecordedPluginOperations() + let harness = Harness(planner: planner, runner: runner, pluginOperations: operations.reporter) + defer { harness.service.stop() } + harness.service.reset(workspaceURL: Self.workspace) + #expect(await harness.waitForEntries { $0.first?.modelState == .notLoaded }) + + harness.service.loadModel(Self.instanceID) + #expect(await harness.waitForEntries { $0.first?.modelState == .loaded }) + + let recorded = try #require(operations.observations.first) + #expect(operations.observations.count == 1) + #expect(recorded.pluginId == "dev.example") + #expect(recorded.operation == "lithe/build/model") + #expect(recorded.outcome == "finished") + #expect(recorded.stage == nil) + #expect(recorded.durationMs == RecordedPluginOperations.tick) + } + + /// Each host failure is attributed to the step that failed, never to the + /// message text the host shows. + @Test(arguments: DeclarativeCommandFailure.allCases) + func declarativeModelCommandFailureRecordsItsStage(_ failure: DeclarativeCommandFailure) async throws { + let planner = FakeBuildPlanner() + planner.detection = BuildDetection(instances: [try Self.instance(modelSource: "command")]) + planner.modelOutput = .stdout + let runner = FakeBuildRunner() + switch failure { + case .plan: + planner.modelPlanFailure = BuildSystemServiceError("Unsupported declaration.") + case .resolve: + break + case .launch: + runner.launchFailure = BuildSystemServiceError("The tool could not be started.") + case .timeout: + runner.script = .init(chunks: [], result: BuildCommandResult(termination: .timedOut)) + case .exit: + runner.script = .init(chunks: ["no such task\n"], result: BuildCommandResult(termination: .exited(2))) + case .decode: + runner.script = .init(chunks: [], result: BuildCommandResult(termination: .exited(0), standardOutput: nil)) + } + let operations = RecordedPluginOperations() + let harness = Harness(planner: planner, runner: runner, pluginOperations: operations.reporter) + if failure == .resolve { harness.tools.failure = BuildToolResolutionError("The tool is not installed.") } + defer { harness.service.stop() } + harness.service.reset(workspaceURL: Self.workspace) + #expect(await harness.waitForEntries { $0.first?.modelState == .notLoaded }) + + harness.service.loadModel(Self.instanceID) + #expect(await harness.waitForEntries { + if case .failed = $0.first?.modelState { return true } + return false + }) + + let recorded = try #require(operations.observations.first) + #expect(operations.observations.count == 1) + #expect(recorded.operation == "lithe/build/model") + #expect(recorded.outcome == "failed") + #expect(recorded.stage == failure.stage) + #expect(recorded.durationMs == RecordedPluginOperations.tick) + } + + @Test + func declarativeDependencyCommandRecordsItsOwnOperation() async throws { + let planner = FakeBuildPlanner() + planner.detection = BuildDetection(instances: [ + try Self.instance(modelSource: "static", model: Self.model(name: "loaded")) + ]) + let runner = FakeBuildRunner() + runner.script = .init(chunks: [], result: BuildCommandResult(termination: .exited(0), standardOutput: "[]")) + let operations = RecordedPluginOperations() + let harness = Harness(planner: planner, runner: runner, pluginOperations: operations.reporter) + defer { harness.service.stop() } + harness.service.reset(workspaceURL: Self.workspace) + #expect(await harness.waitForEntries { !$0.isEmpty }) + + harness.service.loadDependencies(Self.instanceID, project: nil) + #expect(await harness.waitForEntries { entry in + guard case .loaded = entry.first?.dependencies["app"] else { return false } + return true + }) + + #expect(operations.observations.map(\.operation) == ["lithe/build/dependencies"]) + #expect(operations.observations.map(\.outcome) == ["finished"]) + } + + /// A provider plan hands the load to the plugin's process, which reports + /// it through `lithe/log`; the host recording it too would double it. + @Test + func providerModelLoadLeavesTheOperationToThePlugin() async throws { + let planner = FakeBuildPlanner() + planner.detection = BuildDetection(instances: [try Self.instance(modelSource: "provider")]) + planner.providerRequest = Self.providerRequest(method: "lithe/build/model") + let providers = FakeBuildProviders() + providers.reply = .object(["projects": .array([.string("from provider")])]) + let operations = RecordedPluginOperations() + let harness = Harness(planner: planner, providers: providers, pluginOperations: operations.reporter) + defer { harness.service.stop() } + harness.service.reset(workspaceURL: Self.workspace) + #expect(await harness.waitForEntries { $0.first?.modelState == .notLoaded }) + + harness.service.loadModel(Self.instanceID) + #expect(await harness.waitForEntries { $0.first?.modelState == .loaded }) + + #expect(providers.sent.count == 1) + #expect(operations.observations.isEmpty) + } + + @Test + func stoppedDeclarativeModelCommandRecordsNothing() async throws { + let planner = FakeBuildPlanner() + planner.detection = BuildDetection(instances: [try Self.instance(modelSource: "command")]) + let runner = FakeBuildRunner() + runner.blocksUntilCancelled = true + let operations = RecordedPluginOperations() + let harness = Harness(planner: planner, runner: runner, pluginOperations: operations.reporter) + defer { harness.service.stop() } + harness.service.reset(workspaceURL: Self.workspace) + #expect(await harness.waitForEntries { $0.first?.modelState == .notLoaded }) + + harness.service.loadModel(Self.instanceID) + #expect(await runner.started.waitUntilOpen()) + harness.service.stop() + #expect(await runner.cancelled.waitUntilOpen()) + + #expect(await !operations.waitsForLateRecord()) + #expect(operations.observations.isEmpty) + } + // MARK: Provider @Test @@ -2516,11 +2654,13 @@ private final class Harness { providers: (any BuildProviderRequesting)? = nil, runLauncher: (any BuildRunLaunching)? = nil, settings: @escaping @MainActor (String) -> [String: ToolingJSONValue] = { _ in [:] }, - waitForRedetection: @escaping @Sendable () async throws -> Void = {} + waitForRedetection: @escaping @Sendable () async throws -> Void = {}, + pluginOperations: PluginOperationReporter = .disabled ) { let enabledSources = SourceList(sources) self.enabledSources = enabledSources service = BuildSystemService( + pluginOperations: pluginOperations, planner: planner, tools: tools, optionsStore: optionsStore, @@ -2601,6 +2741,50 @@ private final class Harness { } } +/// Where a declarative model command fails, and the stage the host records. +enum DeclarativeCommandFailure: CaseIterable, Sendable { + case plan, resolve, launch, timeout, exit, decode + + var stage: PluginOperationStage { + switch self { + case .plan: .plan + case .resolve: .resolve + case .launch: .launch + case .timeout: .timeout + case .exit: .exit + case .decode: .decode + } + } +} + +/// Records the host's declarative plugin operations. Its clock advances one +/// tick per reading, so a duration is exact without wall-clock time. +@MainActor +private final class RecordedPluginOperations { + static let tick: UInt64 = 7 + private(set) var observations: [PluginOperationObservation] = [] + private let recorded = BuildTestGate() + private var now: UInt64 = 0 + + var reporter: PluginOperationReporter { + PluginOperationReporter( + record: { [self] in + observations.append($0) + recorded.open() + }, + clock: { [self] in + now += Self.tick + return now + } + ) + } + + /// Bounded wait for a record a correct service never makes. + func waitsForLateRecord() async -> Bool { + await recorded.waitUntilOpen(timeout: .milliseconds(500)) + } +} + @MainActor private final class SourceList { var value: [BuildSystemPluginSource] @@ -2717,6 +2901,7 @@ private final class FakeBuildPlanner: BuildSystemPlanning, @unchecked Sendable { var taskPlanContexts: [BuildPlanContext] = [] var modelInputSources: [[BuildModelInputSource]] = [] var modelPlanHints: [BuildProviderHints] = [] + var modelPlanFailure: (any Error)? var dependencyPlanHints: [BuildProviderHints] = [] } @@ -2806,6 +2991,11 @@ private final class FakeBuildPlanner: BuildSystemPlanning, @unchecked Sendable { var taskPlanContexts: [BuildPlanContext] { access { $0.taskPlanContexts } } /// The provider hints of every model and dependency plan, in order. var modelPlanHints: [BuildProviderHints] { access { $0.modelPlanHints } } + /// When set, the model plan fails like a declaration Core cannot plan. + var modelPlanFailure: (any Error)? { + get { access { $0.modelPlanFailure } } + set { access { $0.modelPlanFailure = newValue } } + } var dependencyPlanHints: [BuildProviderHints] { access { $0.dependencyPlanHints } } var fingerprint: String { get { access { $0.fingerprint } } @@ -2934,6 +3124,7 @@ private final class FakeBuildPlanner: BuildSystemPlanning, @unchecked Sendable { providerHints: BuildProviderHints ) throws -> BuildOutputPlan { access { $0.modelPlanHints.append(providerHints) } + if let failure = modelPlanFailure { throw failure } if let request = providerRequest { return .provider(withInputs(request, context: context)) } return .process(plan(["model"], output: modelOutput)) } @@ -3272,12 +3463,18 @@ private final class FakeBuildRunner: BuildCommandRunning, @unchecked Sendable { private var recorded: [BuildCommandRequest] = [] private var configuredScript = Script(chunks: [], result: BuildCommandResult(termination: .exited(0))) private var blocks = false + private var configuredLaunchFailure: (any Error)? var requests: [BuildCommandRequest] { lock.withLock { recorded } } var script: Script { get { lock.withLock { configuredScript } } set { lock.withLock { configuredScript = newValue } } } + /// When set, the command fails to start. + var launchFailure: (any Error)? { + get { lock.withLock { configuredLaunchFailure } } + set { lock.withLock { configuredLaunchFailure = newValue } } + } var blocksUntilCancelled: Bool { get { lock.withLock { blocks } } set { lock.withLock { blocks = newValue } } @@ -3289,6 +3486,7 @@ private final class FakeBuildRunner: BuildCommandRunning, @unchecked Sendable { ) async throws -> BuildCommandResult { lock.withLock { recorded.append(request) } started.open() + if let launchFailure { throw launchFailure } if blocksUntilCancelled { let cancelled = cancelled await withTaskCancellationHandler { diff --git a/macos/Tests/LitheTests/MacBuildProviderSessionsTests.swift b/macos/Tests/LitheTests/MacBuildProviderSessionsTests.swift index 8accbbb5fb..1a5623b2d1 100644 --- a/macos/Tests/LitheTests/MacBuildProviderSessionsTests.swift +++ b/macos/Tests/LitheTests/MacBuildProviderSessionsTests.swift @@ -240,6 +240,130 @@ struct MacBuildProviderSessionsTests { #expect(issues.contains { $0.0 == "processStart" && $0.1 == "processFailed" }) } + // MARK: Declarative start attempt + + /// Once a launch is requested Core owns the plugin's start result, failed + /// or not; the host hands the attempt over and records nothing itself. + @Test(arguments: [false, true]) + func aLaunchHandsTheDeclarativeStartToCore(failsToStart: Bool) async throws { + let core = ScriptedProviderCore(failStart: failsToStart) + let operations = RecordedPluginOperations() + let session = LanguageServerRuntimeSession( + providerID: "fixture", executableURL: URL(fileURLWithPath: "/host/bin/server"), + arguments: [], environment: [:], core: core, pluginID: "dev.example.fixture" + ) + defer { session.stop() } + let settled = TestGate() + session.onStateChange = { state in + switch state { + case .ready, .failed: settled.open() + default: break + } + } + session.observePluginStartup(operations.reporter.begin( + pluginID: "dev.example.fixture", operation: .languageServerStart, at: .resolve, operationID: "lsp-start" + )) + + try? session.start(rootURL: URL(fileURLWithPath: "/workspace"), workspaceFingerprint: nil) + try #require(await settled.waitUntilOpen()) + + #expect(core.startupHandoffs.map(\.operationId) == ["lsp-start"]) + #expect(core.startupHandoffs.map(\.elapsedMs) == [RecordedPluginOperations.tick]) + #expect(operations.observations.isEmpty) + } + + /// A prepared launch starts on the core preparation returned, so that core + /// receives the attempt. + @Test + func aPreparedLaunchHandsTheDeclarativeStartToThePreparedCore() async throws { + let prepared = ScriptedProviderCore() + let unused = ScriptedProviderCore() + let released = TestGate() + let operations = RecordedPluginOperations() + let session = LanguageServerRuntimeSession( + providerID: "fixture", executableURL: URL(fileURLWithPath: "/unused"), arguments: [], environment: [:], + prepareProcess: { _ in + PreparedLanguageServerProcess(executableURL: URL(fileURLWithPath: "/host/bin/server"), + environment: [:], launch: .init(arguments: [], initializationOptions: nil), + core: prepared, release: { released.open() }) + }, core: unused, pluginID: "dev.example.fixture" + ) + defer { session.stop() } + session.observePluginStartup(operations.reporter.begin( + pluginID: "dev.example.fixture", operation: .languageServerStart, at: .resolve, operationID: "lsp-start" + )) + + try session.start(rootURL: URL(fileURLWithPath: "/workspace"), workspaceFingerprint: nil) + try #require(await prepared.started.waitUntilOpen()) + + #expect(prepared.startupHandoffs.map(\.operationId) == ["lsp-start"]) + #expect(unused.startupHandoffs.isEmpty) + #expect(operations.observations.isEmpty) + session.stop() + #expect(await released.waitUntilOpen()) + } + + @Test + func aFailedPreparationRecordsTheDeclarativeStartAtResolve() async throws { + struct PreparationFailure: Error {} + let core = ScriptedProviderCore() + let operations = RecordedPluginOperations() + let session = LanguageServerRuntimeSession( + providerID: "fixture", executableURL: URL(fileURLWithPath: "/unused"), arguments: [], environment: [:], + prepareProcess: { _ in throw PreparationFailure() }, core: core, pluginID: "dev.example.fixture" + ) + defer { session.stop() } + let failed = TestGate() + session.onStateChange = { state in if case .failed = state { failed.open() } } + session.observePluginStartup(operations.reporter.begin( + pluginID: "dev.example.fixture", operation: .languageServerStart, at: .resolve, operationID: "lsp-start" + )) + + try session.start(rootURL: URL(fileURLWithPath: "/workspace"), workspaceFingerprint: nil) + try #require(await failed.waitUntilOpen()) + + #expect(operations.observations == [RecordedPluginOperations.languageServerStart( + pluginID: "dev.example.fixture", failure: .resolve, operationID: "lsp-start" + )]) + #expect(core.startupHandoffs.isEmpty) + } + + /// Stopping during preparation cancels the start: a late package is released + /// unused, and neither the host nor Core records anything. + @Test + func stoppingDuringPreparationRecordsNoDeclarativeStart() async throws { + let core = ScriptedProviderCore() + let preparing = TestGate() + let resume = TestGate() + let released = TestGate() + let lateReply = Task { @MainActor in await resume.waitUntilOpen() } + let operations = RecordedPluginOperations() + let session = LanguageServerRuntimeSession( + providerID: "fixture", executableURL: URL(fileURLWithPath: "/unused"), arguments: [], environment: [:], + prepareProcess: { _ in + preparing.open() + guard await lateReply.value else { throw CancellationError() } + return PreparedLanguageServerProcess(executableURL: URL(fileURLWithPath: "/host/bin/server"), + environment: [:], launch: .init(arguments: [], initializationOptions: nil), + core: core, release: { released.open() }) + }, core: core, pluginID: "dev.example.fixture" + ) + defer { resume.open(); lateReply.cancel(); session.stop() } + session.observePluginStartup(operations.reporter.begin( + pluginID: "dev.example.fixture", operation: .languageServerStart, at: .resolve, operationID: "lsp-start" + )) + + try session.start(rootURL: URL(fileURLWithPath: "/workspace"), workspaceFingerprint: nil) + try #require(await preparing.waitUntilOpen()) + session.stop() + resume.open() + #expect(await released.waitUntilOpen()) + + #expect(operations.observations.isEmpty) + #expect(core.startupHandoffs.isEmpty) + #expect(core.startCalls.isEmpty) + } + @Test func remoteStartupReturnsBeforeTheHostRepliesAndFlushesLatestDocuments() async throws { let core = ScriptedProviderCore(backgroundStart: true) @@ -888,6 +1012,13 @@ private struct ProviderFixture { private final class ScriptedProviderCore: LanguageServerRuntimeCore, @unchecked Sendable { private var logOwners: [(LanguageServerLogRole, String?, String?)] = [] var loggingOwners: [(LanguageServerLogRole, String?, String?)] { lock.withLock { logOwners } } + private var _startupHandoffs: [PluginOperationHandoff] = [] + /// Declarative start attempts handed to this core with a start request. + var startupHandoffs: [PluginOperationHandoff] { lock.withLock { _startupHandoffs } } + func observingPluginStartup(_ handoff: PluginOperationHandoff) -> any LanguageServerRuntimeCore { + lock.withLock { _startupHandoffs.append(handoff) } + return self + } func loggingRuntime(role: LanguageServerLogRole, logSubject: String?, pluginID: String?) -> any LanguageServerRuntimeCore { lock.withLock { logOwners.append((role, logSubject, pluginID)) } return self diff --git a/macos/Tests/LitheTests/PluginDebugAdapterTests.swift b/macos/Tests/LitheTests/PluginDebugAdapterTests.swift index b435f33319..4b0528166e 100644 --- a/macos/Tests/LitheTests/PluginDebugAdapterTests.swift +++ b/macos/Tests/LitheTests/PluginDebugAdapterTests.swift @@ -158,6 +158,41 @@ struct PluginDebugAdapterTests { } } + /// A missing command fails before anything starts, so the session's start + /// attempt stays at `resolve`; once the launch is known it moves to `launch`. + @Test + func theTransportMovesTheStartAttemptToLaunchOnlyOnceTheLaunchIsKnown() async throws { + let reporter = PluginOperationReporter(record: { _ in }, clock: { 0 }) + let missing = MacPluginDebugAdapterTransport( + adapterID: "lldb", + resolve: { _ in Self.process(.commands(["lldb-dap"])) }, + makeProcess: { Issue.record("No process starts for a missing command."); fatalError() }, + core: RustCoreBridge(), + findCommand: { _ in nil } + ) + let unresolved = reporter.begin(pluginID: "acme.lldb", operation: .debugAdapterStart, at: .resolve) + missing.startupAttempt = unresolved + #expect(throws: MacPluginDebugAdapterTransport.TransportError.self) { + try missing.start(rootURL: URL(fileURLWithPath: "/tmp/workspace", isDirectory: true)) + } + #expect(unresolved.stage == .resolve) + + let probe = HostedAdapterProbe() + let hosted = MacPluginDebugAdapterTransport( + adapterID: "example", + resolve: { _ in Self.hostedLaunch() }, + makeProcess: { Issue.record("A hosted adapter starts no process of its own."); fatalError() }, + core: RustCoreBridge() + ) + defer { hosted.stop() } + hosted.onTermination = { probe.recordTermination($0) } + let resolved = reporter.begin(pluginID: "acme.example", operation: .debugAdapterStart, at: .resolve) + hosted.startupAttempt = resolved + try hosted.start(rootURL: URL(fileURLWithPath: "/tmp/hosted-adapter-stage", isDirectory: true)) + #expect(resolved.stage == .launch) + #expect(await probe.waitUntilTerminated(), "The session did not end before the local deadline") + } + // MARK: - Launch transport /// Resolves the fixture's `native` adapter, declared over `transport`. diff --git a/macos/Tests/LitheTests/PluginLanguageServerLaunchResolverTests.swift b/macos/Tests/LitheTests/PluginLanguageServerLaunchResolverTests.swift index 082c5c6051..d3cf523ac9 100644 --- a/macos/Tests/LitheTests/PluginLanguageServerLaunchResolverTests.swift +++ b/macos/Tests/LitheTests/PluginLanguageServerLaunchResolverTests.swift @@ -432,6 +432,97 @@ struct PluginLanguageServerLaunchResolverTests { #expect(issues.first?.2 == "plugin.launch.invalidRequest") } + // MARK: Declarative start attempt + + /// A launch plan Core rejects fails the plugin's start before any process + /// exists, so the host records it at `resolve`; stopping afterwards adds nothing. + @MainActor + @Test + func aFailedLaunchPlanRecordsTheDeclarativeStartAtResolve() { + let operations = RecordedPluginOperations() + let session = LanguageServerRuntimeSession( + providerID: "fixture", + executableURL: URL(fileURLWithPath: "/bin/sh"), + arguments: ["${pluginDir}/server"], + environment: [:], + launchResolver: { _ in + throw DeclarativePluginRejection( + code: "plugin.launch.invalidRequest", + message: "The launch request has no usable pluginDirectory." + ) + }, + core: RustCoreBridge() + ) + session.observePluginStartup(operations.reporter.begin( + pluginID: "dev.example.plugin", operation: .languageServerStart, at: .resolve, operationID: "lsp-start" + )) + + #expect(throws: LanguageServerSessionStartError.self) { + try session.start(rootURL: URL(fileURLWithPath: "/projects/one"), workspaceFingerprint: nil) + } + session.stop() + + #expect(operations.observations == [RecordedPluginOperations.languageServerStart( + pluginID: "dev.example.plugin", failure: .resolve, operationID: "lsp-start" + )]) + } + + /// The manager begins an attempt only for a declarative launch: a server the + /// host owns has no plugin to attribute it to. The attempt carries the + /// manager's operation ID, so it joins the session's other records. + @MainActor + @Test(arguments: [true, false]) + func aServerWithoutAnExecutableRecordsOnlyADeclarativeStart(declarative: Bool) { + let source = DeclarativeLanguageServerLaunchSource( + pluginID: "dev.example.plugin", + languageID: "fixture", + manifest: Data(), + packageURL: URL(fileURLWithPath: "/plugins/fixture") + ) + let launch = LanguageServerLaunchDescriptor( + executableNames: ["fixture-language-server"], + arguments: [], + launchSource: declarative ? source : nil + ) + let descriptor = LanguageProviderDescriptor( + id: "fixture", + displayName: "Fixture", + fileExtensions: ["fixture"], + capabilities: .languageServer, + activationPolicy: .onDemand, + languageServerLaunch: launch + ) + let runtime = StdioLanguageProviderRuntime( + descriptor: descriptor, + runtimeService: FixedLanguageToolRuntime(candidates: [:]), + languageServerLaunch: launch, + languageServerCore: RustCoreBridge() + ) + let operations = RecordedPluginOperations() + let manager = LanguageToolingSessionManager( + catalog: .init(descriptors: [descriptor]), + pluginOperations: operations.reporter, + runtimes: [runtime] + ) + defer { manager.stopAllLanguageServers() } + let operationID = UUID() + + // Only what is recorded matters here: the declarative server stops at + // discovery, while the host-owned one fails later at process start. + #expect(throws: (any Error).self) { + _ = try manager.startLanguageServer( + providerID: descriptor.id, rootURL: URL(fileURLWithPath: "/projects/one"), operationID: operationID + ) + } + + let expected = declarative + ? [RecordedPluginOperations.languageServerStart( + pluginID: "dev.example.plugin", failure: .resolve, operationID: operationID.uuidString + )] + : [] + #expect(operations.observations == expected) + } + // MARK: Fixtures private struct Fixture { diff --git a/macos/Tests/LitheTests/Support/RecordedPluginOperations.swift b/macos/Tests/LitheTests/Support/RecordedPluginOperations.swift new file mode 100644 index 0000000000..680324ffb6 --- /dev/null +++ b/macos/Tests/LitheTests/Support/RecordedPluginOperations.swift @@ -0,0 +1,28 @@ +import LitheModuleAPI + +/// Records what a `PluginOperationReporter` delivers, on a clock that advances +/// `tick` milliseconds per reading, so an attempt that is begun and ended with +/// no other reading in between lasts exactly one tick. +@MainActor +final class RecordedPluginOperations { + static let tick: UInt64 = 7 + private(set) var observations: [PluginOperationObservation] = [] + private var now: UInt64 = 0 + + var reporter: PluginOperationReporter { + PluginOperationReporter( + record: { [self] in observations.append($0) }, + clock: { [self] in now += Self.tick; return now } + ) + } + + /// A declarative language server start that failed at `stage` after one tick. + static func languageServerStart( + pluginID: String, failure stage: PluginOperationStage?, operationID: String + ) -> PluginOperationObservation { + PluginOperationObservation( + pluginID: pluginID, operation: .languageServerStart, failure: stage, + durationMs: tick, operationID: operationID + ) + } +} diff --git a/rust/lithe-core/src/diagnostics/catalog_generated.rs b/rust/lithe-core/src/diagnostics/catalog_generated.rs index 214d7f20ef..6a67a717ea 100644 --- a/rust/lithe-core/src/diagnostics/catalog_generated.rs +++ b/rust/lithe-core/src/diagnostics/catalog_generated.rs @@ -2402,11 +2402,11 @@ pub static EVENTS: &[EventMetadata] = &[ level: LogLevel::Error, message: "Plugin operation failed", fields: &[ - FieldMetadata { name: "code", field_type: FieldType::Token, required: true, description: "Stable plugin failure or recovery category, excluding upstream error messages and request contents", reason: None }, + FieldMetadata { name: "code", field_type: FieldType::Token, required: true, description: "Stable SDK failure category, or a host.* code Core maps from the declarative failure stage and lifecycle; excludes paths, upstream messages and request contents", reason: None }, FieldMetadata { name: "count", field_type: FieldType::Int, required: false, description: "Number of affected items reported by the plugin at this result boundary; absent when unknown", reason: None }, - FieldMetadata { name: "duration", field_type: FieldType::Duration, required: true, description: "Monotonic elapsed milliseconds measured by the SDK for the completed plugin operation", reason: None }, - FieldMetadata { name: "operation", field_type: FieldType::Token, required: true, description: "Registered plugin function or SDK protocol operation that owns this diagnostic result", reason: None }, - FieldMetadata { name: "plugin", field_type: FieldType::Id, required: true, description: "Installed plugin identity supplied by the owning Core session, never by the notification", reason: None }, + FieldMetadata { name: "duration", field_type: FieldType::Duration, required: true, description: "Monotonic elapsed milliseconds measured by the SDK, or by the host and Core for one declarative attempt", reason: None }, + FieldMetadata { name: "operation", field_type: FieldType::Token, required: true, description: "SDK function or protocol operation reported through lithe/log, or a declarative contribution operation from Core's contribution table, such as languageServer/start or lithe/build/model", reason: None }, + FieldMetadata { name: "plugin", field_type: FieldType::Id, required: true, description: "Installed plugin identity bound by the owning Core session or the declarative launch, never taken from plugin output", reason: None }, ], span: None, rate: 600, @@ -2434,9 +2434,9 @@ pub static EVENTS: &[EventMetadata] = &[ message: "Plugin operation finished", fields: &[ FieldMetadata { name: "count", field_type: FieldType::Int, required: false, description: "Number of affected items reported by the plugin at this result boundary; absent when unknown", reason: None }, - FieldMetadata { name: "duration", field_type: FieldType::Duration, required: true, description: "Monotonic elapsed milliseconds measured by the SDK for the completed plugin operation", reason: None }, - FieldMetadata { name: "operation", field_type: FieldType::Token, required: true, description: "Registered plugin function or SDK protocol operation that owns this diagnostic result", reason: None }, - FieldMetadata { name: "plugin", field_type: FieldType::Id, required: true, description: "Installed plugin identity supplied by the owning Core session, never by the notification", reason: None }, + FieldMetadata { name: "duration", field_type: FieldType::Duration, required: true, description: "Monotonic elapsed milliseconds measured by the SDK, or by the host and Core for one declarative attempt", reason: None }, + FieldMetadata { name: "operation", field_type: FieldType::Token, required: true, description: "SDK function or protocol operation reported through lithe/log, or a declarative contribution operation from Core's contribution table, such as languageServer/start or lithe/build/model", reason: None }, + FieldMetadata { name: "plugin", field_type: FieldType::Id, required: true, description: "Installed plugin identity bound by the owning Core session or the declarative launch, never taken from plugin output", reason: None }, ], span: None, rate: 600, diff --git a/rust/lithe-core/src/diagnostics/channel.rs b/rust/lithe-core/src/diagnostics/channel.rs index 32a76f9a7b..9363234954 100644 --- a/rust/lithe-core/src/diagnostics/channel.rs +++ b/rust/lithe-core/src/diagnostics/channel.rs @@ -2,6 +2,7 @@ use chrono::{DateTime, NaiveDateTime, Utc}; use serde::{Deserialize, Serialize}; +use sha2::{Digest, Sha256}; use std::collections::BTreeSet; /// Maximum distinct persisted channels in one session, excluding the overflow sink. @@ -141,6 +142,22 @@ pub fn validate_segment(value: &str) -> Result<(), LogError> { Ok(()) } +/// Maps an installed identity to its channel segment. A valid identity stays readable; +/// anything else becomes a stable digest, so evidence is kept and raw input never +/// reaches a path. Every writer of one plugin's channel must use this mapping. +pub fn identity_segment(raw: &str) -> String { + if validate_segment(raw).is_ok() { + raw.to_owned() + } else { + digest_segment(raw) + } +} + +/// Stable `invalid-` plus 32 hex digits, always a valid segment and never raw input. +pub fn digest_segment(raw: &str) -> String { + format!("invalid-{:x}", Sha256::digest(raw.as_bytes()))[..40].to_owned() +} + /// Returns a slash-separated file path relative to the writable session directory. /// Index zero is active; positive indices produce numbered rotation siblings. pub fn relative_log_path(channel: &LogChannel, rotation_index: u32) -> String { diff --git a/rust/lithe-core/src/diagnostics/mod.rs b/rust/lithe-core/src/diagnostics/mod.rs index 2aafaca793..4694d65f41 100644 --- a/rust/lithe-core/src/diagnostics/mod.rs +++ b/rust/lithe-core/src/diagnostics/mod.rs @@ -20,6 +20,7 @@ pub mod record; pub mod retention; pub(crate) mod helper_failures; +pub(crate) mod plugin_operations; pub(crate) mod request_trace; mod manifest; diff --git a/rust/lithe-core/src/diagnostics/plugin_operations.rs b/rust/lithe-core/src/diagnostics/plugin_operations.rs new file mode 100644 index 0000000000..9348a84675 --- /dev/null +++ b/rust/lithe-core/src/diagnostics/plugin_operations.rs @@ -0,0 +1,526 @@ +//! Core-owned `plugins.operation.*` results for declarative plugin contributions. +//! +//! A declarative contribution has no plugin process that could report through +//! `lithe/log`; the host or a Core engine runs the declared process or command +//! instead. Every such attempt is one [`DeclarativeOperation`]. Contribution kinds +//! differ only by their row in [`CONTRIBUTIONS`]: the operation token and the +//! [`Lifecycle`] that decides which failure stages exist and which `host.*` code +//! each stage means. A new declarative contract adds a row, never a code path. +//! +//! The owner of the process lifecycle records the terminal result: Core for the +//! language-server start it supervises, the host for attempts it supervises. Either +//! way the fact passes the same validation and lands on the plugin's +//! `plugins//host` channel, next to the facts its SDK-backed peers report. No +//! plugin output, path, or error text crosses this ingress. + +use super::{ + channel::{identity_segment, LogError}, + core_events, +}; +use serde::Deserialize; +use serde_json::{json, Value}; +use std::collections::BTreeMap; +use std::sync::{Arc, Mutex}; +use std::time::Instant; + +const MAX_SAFE_INTEGER: u64 = 9_007_199_254_740_991; + +/// Boundary where an attempt failed. Only the contribution's [`Lifecycle`] turns it +/// into a `host.*` code. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Deserialize)] +#[serde(rename_all = "camelCase")] +pub enum Stage { + /// The declared command plan could not be prepared. + Plan, + /// The declared executable or launch input could not be resolved. + Resolve, + /// The resolved process could not be started. + Launch, + /// The protocol handshake failed after the process started. + Initialize, + /// The attempt exceeded its host or Core deadline. + Timeout, + /// The process exited before it was ready, or a command exited nonzero. + Exit, + /// The command output was not a valid document for the contract. + Decode, +} + +/// How a declarative attempt runs. The lifecycle owns the stage-to-code table, so a +/// code keeps one meaning across every contribution that shares the lifecycle. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum Lifecycle { + /// A long-lived process that becomes ready when its protocol handshake succeeds. + ProcessStart, + /// A one-shot command whose output the host decodes into a contract document. + CommandRun, +} + +impl Lifecycle { + /// Stable code for a failed stage; `None` marks a stage this lifecycle cannot + /// reach, and such a fact is rejected instead of mapped. + pub fn code(self, stage: Stage) -> Option<&'static str> { + use Lifecycle::{CommandRun, ProcessStart}; + Some(match (self, stage) { + (_, Stage::Resolve) => "host.executableUnavailable", + (_, Stage::Launch) => "host.launchFailed", + (_, Stage::Timeout) => "host.timedOut", + (ProcessStart, Stage::Initialize) => "host.initializeFailed", + (ProcessStart, Stage::Exit) => "host.exitedEarly", + (CommandRun, Stage::Plan) => "host.planFailed", + (CommandRun, Stage::Exit) => "host.commandFailed", + (CommandRun, Stage::Decode) => "host.outputInvalid", + (ProcessStart, Stage::Plan | Stage::Decode) | (CommandRun, Stage::Initialize) => { + return None + } + }) + } +} + +/// One declarative contribution kind whose attempts the host or Core supervises. +#[derive(Debug, PartialEq, Eq)] +pub struct Contribution { + /// Wire and log token. Command contributions reuse the SDK method name, so a + /// declarative plugin and an SDK-backed one log the same work the same way. + pub operation: &'static str, + /// Decides the reachable failure stages and their codes. + pub lifecycle: Lifecycle, +} + +/// `languageServers[]`: from launch resolution to the `initialize` result. +pub static LANGUAGE_SERVER_START: Contribution = Contribution { + operation: "languageServer/start", + lifecycle: Lifecycle::ProcessStart, +}; + +/// `debugAdapters[]`: from launch resolution to the DAP `initialize` result. +pub static DEBUG_ADAPTER_START: Contribution = Contribution { + operation: "debugAdapter/start", + lifecycle: Lifecycle::ProcessStart, +}; + +/// `buildSystems[].model` with a command source: one model load. +pub static BUILD_MODEL: Contribution = Contribution { + operation: "lithe/build/model", + lifecycle: Lifecycle::CommandRun, +}; + +/// `buildSystems[].dependencies` with a command source: one dependency tree load. +pub static BUILD_DEPENDENCIES: Contribution = Contribution { + operation: "lithe/build/dependencies", + lifecycle: Lifecycle::CommandRun, +}; + +/// Every contribution kind this ingress accepts. Supporting a new declarative +/// contract means adding its row here and reporting the same token from its owner. +pub static CONTRIBUTIONS: &[&Contribution] = &[ + &LANGUAGE_SERVER_START, + &DEBUG_ADAPTER_START, + &BUILD_MODEL, + &BUILD_DEPENDENCIES, +]; + +impl Contribution { + /// Row for a wire token; unknown tokens are not host facts. + pub fn find(operation: &str) -> Option<&'static Contribution> { + CONTRIBUTIONS + .iter() + .copied() + .find(|row| row.operation == operation) + } +} + +/// One terminal result. Cancellation is never recorded: the user ended the attempt. +#[derive(Debug, Clone, PartialEq, Eq)] +pub struct DeclarativeOperation { + /// Installed plugin that declared the contribution, known from the launch source. + pub plugin_id: String, + /// Row that names the operation and maps the failed stage. + pub contribution: &'static Contribution, + /// `None` when the attempt finished; otherwise the boundary that failed. + pub failure: Option, + /// Monotonic elapsed milliseconds for the whole attempt. + pub duration_ms: u64, + /// Host operation that already correlates this attempt's lifecycle facts. + pub operation_id: Option, +} + +/// Wire form of `diagnostics.recordPluginOperation`; `stage` is required iff failed. +#[derive(Deserialize)] +#[serde(rename_all = "camelCase", deny_unknown_fields)] +struct Request { + plugin_id: String, + operation: String, + outcome: Outcome, + #[serde(default)] + stage: Option, + duration_ms: u64, + #[serde(default)] + operation_id: Option, +} + +#[derive(Deserialize)] +#[serde(rename_all = "camelCase")] +enum Outcome { + Finished, + Failed, +} + +/// Every rejected request shares one code: the request is not a valid host fact. +/// The message never echoes the rejected value. +fn invalid() -> LogError { + LogError::new(-32064, "Invalid host plugin operation") +} + +// Same token grammar as SDK `operationId`, then the persisted record identity rule. +fn valid_operation_id(value: &str) -> bool { + !value.is_empty() + && value.len() <= 128 + && value + .bytes() + .all(|b| b.is_ascii_alphanumeric() || b"._:/-$".contains(&b)) + && super::record::identity(value).is_ok() +} + +fn fact(input: &DeclarativeOperation) -> Result<(&'static str, BTreeMap), LogError> { + if input.duration_ms > MAX_SAFE_INTEGER + || input + .operation_id + .as_deref() + .is_some_and(|op| !valid_operation_id(op)) + { + return Err(invalid()); + } + let mut fields = BTreeMap::from([ + // The SDK route maps the same plugin through the same function, so both + // writers share one `plugins//host` channel. + ("plugin".into(), json!(identity_segment(&input.plugin_id))), + ("operation".into(), json!(input.contribution.operation)), + ("duration_ms".into(), json!(input.duration_ms)), + ]); + let Some(stage) = input.failure else { + return Ok(("plugins.operation.finished", fields)); + }; + let code = input + .contribution + .lifecycle + .code(stage) + .ok_or_else(invalid)?; + fields.insert("code".into(), json!(code)); + Ok(("plugins.operation.failed", fields)) +} + +/// Validates the whole fact before touching the process queue. +pub fn record(input: DeclarativeOperation) -> Result<(), LogError> { + let (event, fields) = fact(&input)?; + core_events::record(event, fields, input.operation_id) +} + +/// Engine-side recording: a rejected or dropped fact becomes the queue's drop count. +pub(crate) fn record_or_note_drop(input: DeclarativeOperation) { + #[cfg(test)] + test_capture::push(&input); + if record(input).is_err() { + core_events::note_dropped(); + } +} + +fn decode(input: Value) -> Result { + let request: Request = serde_json::from_value(input).map_err(|_| invalid())?; + let contribution = Contribution::find(&request.operation).ok_or_else(invalid)?; + let failure = match (request.outcome, request.stage) { + (Outcome::Finished, None) => None, + (Outcome::Failed, Some(stage)) => Some(stage), + _ => return Err(invalid()), + }; + Ok(DeclarativeOperation { + plugin_id: request.plugin_id, + contribution, + failure, + duration_ms: request.duration_ms, + operation_id: request.operation_id, + }) +} + +/// `diagnostics.recordPluginOperation`: strict host ingress; returns `{}` once queued. +pub fn record_request(input: Value) -> Result { + record(decode(input)?)?; + Ok(json!({})) +} + +/// Attempt the host began and handed to Core, which owns the rest of it. +/// +/// The host records only failures before the handoff; Core records the single +/// terminal result after it. Wire form: `{operationId, elapsedMs}`. +#[derive(Debug, Clone, Deserialize)] +#[serde(rename_all = "camelCase", deny_unknown_fields)] +pub struct AttemptHandoff { + /// Host operation that already correlates the attempt's lifecycle facts. + pub operation_id: String, + /// Monotonic milliseconds the host spent on the attempt before the handoff. + pub elapsed_ms: u64, +} + +/// Declarative attempt in flight inside a Core engine. +#[derive(Debug)] +pub(crate) struct Attempt { + contribution: &'static Contribution, + plugin_id: String, + operation_id: String, + host_elapsed_ms: u64, + started: Instant, +} + +/// Shared by every code path that can end one attempt. Whichever path reaches a +/// terminal result first takes the attempt, so it is recorded at most once even +/// when two paths race to end it. +pub(crate) type AttemptSlot = Arc>>; + +impl Attempt { + /// Slot holding a handed-off attempt, timed from now. + pub(crate) fn slot( + contribution: &'static Contribution, + plugin_id: String, + handoff: AttemptHandoff, + ) -> AttemptSlot { + Arc::new(Mutex::new(Some(Self { + contribution, + plugin_id, + operation_id: handoff.operation_id, + host_elapsed_ms: handoff.elapsed_ms, + started: Instant::now(), + }))) + } + + /// Slot for work that carries no declarative attempt; finishing it is a no-op. + pub(crate) fn none() -> AttemptSlot { + Arc::new(Mutex::new(None)) + } +} + +/// Records the attempt's terminal result unless another path already did. +pub(crate) fn finish(slot: &AttemptSlot, failure: Option) { + let Some(attempt) = slot.lock().unwrap_or_else(|e| e.into_inner()).take() else { + return; + }; + let core_elapsed_ms = u64::try_from(attempt.started.elapsed().as_millis()).unwrap_or(u64::MAX); + record_or_note_drop(DeclarativeOperation { + plugin_id: attempt.plugin_id, + contribution: attempt.contribution, + failure, + duration_ms: attempt.host_elapsed_ms.saturating_add(core_elapsed_ms), + operation_id: Some(attempt.operation_id), + }); +} + +/// Ends the attempt without a result: the user cancelled or stopped it. +pub(crate) fn abandon(slot: &AttemptSlot) { + slot.lock().unwrap_or_else(|e| e.into_inner()).take(); +} + +/// Engine results as recorded, for engine tests. The process queue is shared and +/// bounded, so a parallel test run can fill it; tests read their own facts back +/// by plugin ID instead. +#[cfg(test)] +pub(crate) mod test_capture { + use super::DeclarativeOperation; + use std::sync::Mutex; + + static FACTS: Mutex> = Mutex::new(Vec::new()); + + pub(super) fn push(input: &DeclarativeOperation) { + FACTS + .lock() + .unwrap_or_else(|e| e.into_inner()) + .push(input.clone()); + } + + /// Removes and returns the facts recorded for `plugin_id`, in record order. + pub(crate) fn take(plugin_id: &str) -> Vec { + let mut facts = FACTS.lock().unwrap_or_else(|e| e.into_inner()); + let (taken, kept) = facts + .drain(..) + .partition(|fact| fact.plugin_id == plugin_id); + *facts = kept; + taken + } +} + +#[cfg(test)] +mod tests { + use super::*; + + const STAGES: [&str; 7] = [ + "plan", + "resolve", + "launch", + "initialize", + "timeout", + "exit", + "decode", + ]; + + fn prepare(payload: Value) -> Result { + let input = decode(payload)?; + let (event, fields) = fact(&input)?; + core_events::prepare(event, fields, input.operation_id) + } + + // Guards the one-meaning-per-code rule: each lifecycle's stage table is pinned, + // and every unreachable pair is rejected rather than mapped. + #[test] + fn diagnostics_host_plugin_operations_map_each_stage_to_one_code() { + let expected = |lifecycle: Lifecycle, stage: &str| -> Option<&str> { + let command = lifecycle == Lifecycle::CommandRun; + match (stage, command) { + ("plan", true) => Some("host.planFailed"), + ("resolve", _) => Some("host.executableUnavailable"), + ("launch", _) => Some("host.launchFailed"), + ("initialize", false) => Some("host.initializeFailed"), + ("timeout", _) => Some("host.timedOut"), + ("exit", true) => Some("host.commandFailed"), + ("exit", false) => Some("host.exitedEarly"), + ("decode", true) => Some("host.outputInvalid"), + _ => None, + } + }; + for row in CONTRIBUTIONS { + let finished = prepare(json!({"pluginId":"io.example.contribution", + "operation":row.operation, "outcome":"finished", "durationMs":412, + "operationId":"attempt-7"})) + .unwrap(); + assert_eq!(finished.channel, "plugins/io.example.contribution/host"); + assert_eq!(finished.event, "plugins.operation.finished"); + assert_eq!(finished.fields["operation"], json!(row.operation)); + assert_eq!(finished.op.as_deref(), Some("attempt-7")); + assert!(finished.fields.get("code").is_none()); + for stage in STAGES { + let result = prepare(json!({"pluginId":"io.example.contribution", + "operation":row.operation, "outcome":"failed", "stage":stage, + "durationMs":2})); + let operation = row.operation; + match expected(row.lifecycle, stage) { + Some(code) => { + let failed = result.unwrap(); + assert_eq!(failed.event, "plugins.operation.failed"); + assert_eq!(failed.fields["code"], json!(code), "{operation} {stage}"); + } + None => assert_eq!(result.unwrap_err().code, -32064, "{operation} {stage}"), + } + } + } + } + + // Each row is one contract; the table must not map one token twice or drift + // from the manifest contribution it names. + #[test] + fn diagnostics_host_plugin_operations_table_names_each_contribution_once() { + let pinned = [ + ("languageServer/start", Lifecycle::ProcessStart), + ("debugAdapter/start", Lifecycle::ProcessStart), + ("lithe/build/model", Lifecycle::CommandRun), + ("lithe/build/dependencies", Lifecycle::CommandRun), + ]; + let rows: Vec<_> = CONTRIBUTIONS + .iter() + .map(|row| (row.operation, row.lifecycle)) + .collect(); + assert_eq!(rows, pinned); + for row in CONTRIBUTIONS { + assert!(std::ptr::eq( + Contribution::find(row.operation).unwrap(), + *row + )); + } + } + + // A manifest ID longer than one segment must land where the SDK route writes it. + #[test] + fn diagnostics_host_plugin_operations_share_the_sdk_channel_mapping() { + let long = format!("io.example.{}", "a".repeat(64)); + let fact = prepare(json!({"pluginId":long, "operation":"debugAdapter/start", + "outcome":"finished", "durationMs":1})) + .unwrap(); + assert_eq!( + fact.channel, + format!("plugins/{}/host", identity_segment(&long)) + ); + assert!(!fact.channel.contains(&long)); + } + + #[test] + fn diagnostics_host_plugin_operations_reject_private_or_invalid_input() { + let valid = json!({"pluginId":"io.example.contribution", + "operation":"languageServer/start", "outcome":"failed", "stage":"resolve", + "durationMs":2}); + for (key, value) in [ + ("operation", json!("private/query")), + ("stage", json!("private")), + ("stage", Value::Null), + ("outcome", json!("finished")), + ("outcome", json!("cancelled")), + ("message", json!("private secret")), + ("durationMs", json!(-1)), + ("durationMs", json!(MAX_SAFE_INTEGER + 1)), + ("operationId", json!("private secret")), + ("operationId", json!("")), + ] { + let mut input = valid.clone(); + input[key] = value; + let error = prepare(input).unwrap_err(); + assert_eq!(error.code, -32064, "{key}"); + assert!(!serde_json::to_string(&error).unwrap().contains("private")); + } + for key in ["pluginId", "operation", "outcome", "stage", "durationMs"] { + let mut input = valid.clone(); + input.as_object_mut().unwrap().remove(key); + assert_eq!(prepare(input).unwrap_err().code, -32064, "{key}"); + } + } + + // The first terminal path takes the attempt; later paths and abandoned slots + // record nothing. + #[test] + fn diagnostics_host_plugin_operations_attempt_slot_ends_once() { + let handoff = AttemptHandoff { + operation_id: "attempt-9".into(), + elapsed_ms: 40, + }; + let slot = Attempt::slot(&LANGUAGE_SERVER_START, "io.example.lsp".into(), handoff); + let taken = slot.lock().unwrap().take().unwrap(); + assert!(std::ptr::eq(taken.contribution, &LANGUAGE_SERVER_START)); + assert_eq!(taken.host_elapsed_ms, 40); + assert_eq!(taken.operation_id, "attempt-9"); + finish(&slot, Some(Stage::Exit)); + assert!(slot.lock().unwrap().is_none()); + + let none = Attempt::none(); + finish(&none, None); + abandon(&none); + assert!(none.lock().unwrap().is_none()); + } + + // The shared fixture is the contract example in rust-core-api.md. + #[test] + fn diagnostics_host_plugin_operations_match_shared_fixture() { + let fixture: Value = serde_json::from_str(include_str!( + "../../../../shared/fixtures/diagnostics/engine-logging-v2.json" + )) + .unwrap(); + for case in fixture["hostOperations"].as_array().unwrap() { + let result = prepare(case["payload"].clone()); + match case.get("event").and_then(Value::as_str) { + Some(event) => { + let fact = result.unwrap(); + assert_eq!(fact.event, event); + assert_eq!(fact.channel, case["channel"].as_str().unwrap()); + assert_eq!(fact.fields.get("code"), case.get("code")); + } + None => assert_eq!( + i64::from(result.unwrap_err().code), + case["rejected"].as_i64().unwrap() + ), + } + } + } +} diff --git a/rust/lithe-core/src/diagnostics/record.rs b/rust/lithe-core/src/diagnostics/record.rs index 4e6d28d2b7..76917be97e 100644 --- a/rust/lithe-core/src/diagnostics/record.rs +++ b/rust/lithe-core/src/diagnostics/record.rs @@ -143,7 +143,7 @@ fn field_key(key: &str) -> Result<(), LogError> { } Ok(()) } -fn identity(value: &str) -> Result<(), LogError> { +pub(super) fn identity(value: &str) -> Result<(), LogError> { if bare(value) { Ok(()) } else { diff --git a/rust/lithe-core/src/lsp/interface/engine.rs b/rust/lithe-core/src/lsp/interface/engine.rs index c5bd14bf10..54fae8dd34 100644 --- a/rust/lithe-core/src/lsp/interface/engine.rs +++ b/rust/lithe-core/src/lsp/interface/engine.rs @@ -16,6 +16,10 @@ use super::{ ClientShutdownRequest, FrameMessageRequest, LspClientDiagnostic, LspClientDocument, LspClientState, LspDocumentContentChange, LspPosition, LspRange, ParseServerMessagesRequest, }; +use crate::diagnostics::plugin_operations::{ + self as plugin_operations, Attempt, AttemptHandoff, AttemptSlot, Stage as AttemptStage, + LANGUAGE_SERVER_START, +}; use crate::lsp::languages::java_entrypoints::{ java_entrypoints_command, normalize_java_entrypoints, }; @@ -119,6 +123,10 @@ pub struct StartServerRequest { /// host-owned servers leave it out. #[serde(default)] pub plugin_id: Option, + /// Declarative `languageServer/start` attempt the host began; Core records its + /// result. Absent for v1 hosts and SDK-owned backend processes. + #[serde(default)] + pub startup_operation: Option, /// Host services the plugin's permissions grant the session, as the /// launch plan lists them (`backend.hostServices`). Only a plugin-owned /// session may name any; Core forwards only these `lithe/host/*` @@ -894,6 +902,8 @@ struct SessionState { } struct RuntimeSession { + /// Declarative plugin start attempt shared with `start_server`. + startup_attempt: AttemptSlot, id: String, provider_id: String, /// Plugin that owns the process, if any; see `StartServerRequest::plugin_id`. @@ -1850,6 +1860,25 @@ impl LspEngine { } fn start_server(&self, request: StartServerRequest) -> Result { + let attempt = startup_attempt(&request); + let result = self.start_server_attempt(request, &attempt); + // A session that already reached a terminal result took the attempt; + // otherwise the process never started. Cancellation is not a result. + match &result { + Err(error) if !matches!(error.code, ErrorCode::Cancelled) => { + plugin_operations::finish(&attempt, Some(AttemptStage::Launch)); + } + Err(_) => plugin_operations::abandon(&attempt), + Ok(_) => {} + } + result + } + + fn start_server_attempt( + &self, + request: StartServerRequest, + attempt: &AttemptSlot, + ) -> Result { validate_start_request(&request)?; if crate::remote::workspace::is_remote() && request.provider_id.eq_ignore_ascii_case("java") { @@ -2079,6 +2108,7 @@ impl LspEngine { .as_ref() .map(JavaPreparationDiagnostics::startup_detail); let session = Arc::new(RuntimeSession { + startup_attempt: Arc::clone(attempt), id: session_id.clone(), log_identity: SessionLogIdentity::new( request.role, @@ -3672,6 +3702,7 @@ impl RuntimeSession { clear_function_registry(self, &mut state); clear_runtime_diagnostics(self, &mut state); transition_locked(self, &mut state, LspLifecycleState::Stopping, None); + plugin_operations::abandon(&self.startup_attempt); state.initialize_deadline = None; state.shutdown_deadline = Some(Instant::now() + state.shutdown_timeout); if state.client.initialized { @@ -4045,6 +4076,7 @@ impl RuntimeSession { server_error, )); } else { + plugin_operations::finish(&self.startup_attempt, None); state.initialize_deadline = None; if waits_for_service_ready(&self.provider_id) { let now = Instant::now(); @@ -5850,6 +5882,7 @@ impl RuntimeSession { ); self.kill_process(); } else if initialize_timeout { + plugin_operations::finish(&self.startup_attempt, Some(AttemptStage::Timeout)); // Timeout termination must not wait behind a blocked stdin write; // killing the process is what releases that write. self.fail( @@ -5902,6 +5935,9 @@ impl RuntimeSession { self.process.close_input(); if let Ok(mut state) = self.lock_state() { let was_stopping = state.lifecycle == LspLifecycleState::Stopping; + if !was_stopping { + plugin_operations::finish(&self.startup_attempt, Some(AttemptStage::Exit)); + } if !state.terminal_event_emitted { let error = (!was_stopping).then(|| { runtime_error( @@ -5992,6 +6028,9 @@ impl RuntimeSession { if state.terminal_event_emitted { return; } + // Timeouts were already taken by their caller; every other terminal + // failure before `initialize` succeeded is a handshake failure. + plugin_operations::finish(&self.startup_attempt, Some(AttemptStage::Initialize)); fail_feature_requests(self, &mut state, code, stage, message, exit_code); clear_runtime_state(self, &mut state); let error = runtime_error( @@ -6761,6 +6800,18 @@ fn push_cleanup_fact( ); } +// Only a declarative language server carries a host attempt. SDK backends report +// their own operations through `lithe/log`, so a stray handoff on another role is +// ignored rather than rejecting the start. +fn startup_attempt(request: &StartServerRequest) -> AttemptSlot { + match (&request.startup_operation, &request.plugin_id) { + (Some(handoff), Some(plugin_id)) if request.role == SessionRole::LanguageServer => { + Attempt::slot(&LANGUAGE_SERVER_START, plugin_id.clone(), handoff.clone()) + } + _ => Attempt::none(), + } +} + fn transition_locked( session: &RuntimeSession, state: &mut SessionState, @@ -8215,6 +8266,7 @@ mod tests { role: SessionRole::LanguageServer, log_subject: None, plugin_id: None, + startup_operation: None, host_services: Vec::new(), toolchain_providers: Vec::new(), keymap_import_providers: Vec::new(), @@ -11507,6 +11559,56 @@ mod tests { ); } + /// A declarative plugin start handed off by the host ends in exactly one Core + /// result: `initialize` success, an exit before it, or nothing for a user stop. + /// Later exits belong to the session, not the start. + #[test] + fn declarative_plugin_start_records_one_host_operation_per_attempt() { + const PLUGIN: &str = "io.example.declarative-start"; + let handoff = |operation_id: &'static str| { + move |request: &mut StartServerRequest| { + request.plugin_id = Some(PLUGIN.to_string()); + request.startup_operation = Some(AttemptHandoff { + operation_id: operation_id.to_string(), + elapsed_ms: 5, + }); + } + }; + + let mut ready = Harness::start(handoff("declarative-ready")); + ready.server.complete_initialize(ready_capabilities()); + ready.await_state(LspLifecycleState::Ready); + ready.server.exit(Some(1)); + ready.await_state(LspLifecycleState::Failed); + + let mut exited = Harness::start(handoff("declarative-exited")); + exited.server.exit(Some(2)); + exited.await_state(LspLifecycleState::Failed); + + let mut stopped = Harness::start(handoff("declarative-stopped")); + stopped.session().stop().unwrap(); + stopped.await_state(LspLifecycleState::Stopped); + + let facts = plugin_operations::test_capture::take(PLUGIN); + assert!(facts + .iter() + .all(|fact| std::ptr::eq(fact.contribution, &LANGUAGE_SERVER_START))); + let results: Vec<_> = facts + .into_iter() + .map(|fact| (fact.operation_id, fact.failure)) + .collect(); + assert_eq!( + results, + [ + (Some("declarative-ready".to_string()), None), + ( + Some("declarative-exited".to_string()), + Some(AttemptStage::Exit) + ), + ] + ); + } + /// Criterion 10: shutdown sends exit after the response, and a shutdown that /// is never answered force-terminates. #[test] @@ -13236,6 +13338,7 @@ public class Main { role: SessionRole::LanguageServer, log_subject: None, plugin_id: None, + startup_operation: None, host_services: Vec::new(), toolchain_providers: Vec::new(), keymap_import_providers: Vec::new(), @@ -13999,6 +14102,7 @@ public class Main { role: SessionRole::LanguageServer, log_subject: None, plugin_id: None, + startup_operation: None, host_services: Vec::new(), toolchain_providers: Vec::new(), keymap_import_providers: Vec::new(), diff --git a/rust/lithe-core/src/lsp/interface/engine_logging.rs b/rust/lithe-core/src/lsp/interface/engine_logging.rs index 971d920af7..c9fac636a5 100644 --- a/rust/lithe-core/src/lsp/interface/engine_logging.rs +++ b/rust/lithe-core/src/lsp/interface/engine_logging.rs @@ -1,11 +1,10 @@ //! Catalog identities, role routing, and bounded stderr framing for managed engines. use super::engine::LspRuntimeError; -use crate::diagnostics::channel::validate_segment; +use crate::diagnostics::channel::{digest_segment, identity_segment, validate_segment}; use crate::lsp::languages::jdt::MavenProfileProjectResult; use serde::{Deserialize, Serialize}; use serde_json::{json, Value}; -use sha2::{Digest, Sha256}; use std::collections::BTreeMap; type Fields = BTreeMap; @@ -46,16 +45,11 @@ impl SessionLogIdentity { _ => plugin, }; // Language IDs such as c++ are valid process identities but unsafe path - // segments. Never reject startup or drop evidence: use a stable sha256 - // prefix of the original identity (or provider for an absent subject). - // The prefix plus 32 hex digits is valid and does not expose raw input. - let subject = match raw.filter(|id| validate_segment(id).is_ok()) { - Some(id) => id.to_owned(), - None => format!( - "invalid-{:x}", - Sha256::digest(raw.unwrap_or(provider).as_bytes()) - )[..40] - .to_owned(), + // segments. Never reject startup or drop evidence: an invalid identity, or + // the provider when the subject is absent, becomes a stable digest segment. + let subject = match raw { + Some(id) => identity_segment(id), + None => digest_segment(provider), }; debug_assert!(validate_segment(&subject).is_ok()); Self { role, subject } diff --git a/rust/lithe-core/src/lsp/interface/engine_real_jdt_tests.rs b/rust/lithe-core/src/lsp/interface/engine_real_jdt_tests.rs index 00f50e500f..1dea544533 100644 --- a/rust/lithe-core/src/lsp/interface/engine_real_jdt_tests.rs +++ b/rust/lithe-core/src/lsp/interface/engine_real_jdt_tests.rs @@ -341,6 +341,7 @@ fn real_start_request( role: SessionRole::LanguageServer, log_subject: None, plugin_id: None, + startup_operation: None, host_services: Vec::new(), toolchain_providers: Vec::new(), keymap_import_providers: Vec::new(), diff --git a/rust/lithe-core/src/protocol/command.rs b/rust/lithe-core/src/protocol/command.rs index 08553c4211..6d12924c60 100644 --- a/rust/lithe-core/src/protocol/command.rs +++ b/rust/lithe-core/src/protocol/command.rs @@ -631,6 +631,8 @@ pub enum CoreCommand { DiagnosticsDrainCoreEvents, /// Selects which DEBUG Core facts the host will write (`diagnostics.configureCoreEvents`). DiagnosticsConfigureCoreEvents, + /// Records host-observed declarative contribution outcomes (`diagnostics.recordPluginOperation`). + DiagnosticsRecordPluginOperation, /// Merges structured and legacy log evidence (`diagnostics.queryLogsV2`). DiagnosticsQueryLogsV2, /// Parses filter terms and UTF-16 diagnostics (`diagnostics.parseLogFilter`). @@ -946,6 +948,7 @@ impl CoreCommand { "diagnostics.redactText" => Some(Self::DiagnosticsRedactText), "diagnostics.prepareLogEvent" => Some(Self::DiagnosticsPrepareLogEvent), "diagnostics.queryLogs" => Some(Self::DiagnosticsQueryLogs), + "diagnostics.recordPluginOperation" => Some(Self::DiagnosticsRecordPluginOperation), "diagnostics.drainCoreEvents" => Some(Self::DiagnosticsDrainCoreEvents), "diagnostics.configureCoreEvents" => Some(Self::DiagnosticsConfigureCoreEvents), "diagnostics.encodeLogBatch" => Some(Self::DiagnosticsEncodeLogBatch), diff --git a/rust/lithe-core/src/runtime/dispatcher.rs b/rust/lithe-core/src/runtime/dispatcher.rs index 0881519e60..61b365f6d8 100644 --- a/rust/lithe-core/src/runtime/dispatcher.rs +++ b/rust/lithe-core/src/runtime/dispatcher.rs @@ -3542,6 +3542,12 @@ fn execute_parsed(parsed: CoreRequest) -> CoreResponse { ), } } + CoreCommand::DiagnosticsRecordPluginOperation => CoreResponse::success( + id, + log_v2_result(crate::diagnostics::plugin_operations::record_request( + parsed.payload, + )), + ), CoreCommand::DiagnosticsDrainCoreEvents => CoreResponse::success( id, serde_json::to_value(crate::diagnostics::core_events::drain()) diff --git a/shared/contracts/plugins/v1/README.md b/shared/contracts/plugins/v1/README.md index ab35b717d1..4fa94814a2 100644 --- a/shared/contracts/plugins/v1/README.md +++ b/shared/contracts/plugins/v1/README.md @@ -433,6 +433,32 @@ then uses the existing bounded Core handoff to the host's single writer; overload increments its dropped counter. No polling timer or extra writer is created. Fixture: `fixtures/plugin-logging.json`. +Declarative contributions have no plugin process to send `lithe/log`, so whoever +executes the declared work records the same `plugins.operation.finished` and +`plugins.operation.failed` events on the same `plugins//host` channel. A +declarative plugin writes no logging code. Each start of a `languageServers[]` or +`debugAdapters[]` entry is one `languageServer/start` or `debugAdapter/start` +operation, from launch resolution until `initialize` succeeds. Each run of a +`buildSystems[]` model or dependencies command source is one `lithe/build/model` or +`lithe/build/dependencies` operation, using the SDK request names. A failure +carries one `code`: + +| Code | Meaning | +| --- | --- | +| `host.planFailed` | The declared command could not be planned | +| `host.executableUnavailable` | The declared executable or launch input could not be resolved | +| `host.launchFailed` | The resolved process could not be started | +| `host.initializeFailed` | A started server or adapter failed its `initialize` handshake | +| `host.timedOut` | The attempt exceeded its deadline | +| `host.exitedEarly` | A server or adapter exited before `initialize` succeeded | +| `host.commandFailed` | A build command exited unsuccessfully | +| `host.outputInvalid` | A build command's output is not a valid document | + +User cancellation and superseded attempts record nothing. Plugin output, paths, +and error text never appear in these facts. The executing owner and the +host-facing command are specified as `diagnostics.recordPluginOperation` in +[`rust-core-api.md`](https://github.com/1lck/Lithe-IDEA/blob/preview/shared/contracts/rust-core-api.md). + Severity follows the actual result. An operation that failed for the user is ERROR, a recovery or fallback is WARN, and a useful successful user operation is INFO. The source stream is not a severity: unclassified stderr is DEBUG diff --git a/shared/contracts/rust-core-api.md b/shared/contracts/rust-core-api.md index 6bf1ab7bb1..6843fe715d 100644 --- a/shared/contracts/rust-core-api.md +++ b/shared/contracts/rust-core-api.md @@ -4312,6 +4312,7 @@ are unchanged: | -32061 | Invalid histogram bucket count | | -32062 | Log copy input exceeds budget | | -32063 | Expected canonical redacted log record | +| -32064 | Invalid host plugin operation | Diagnostic previews freeze the selected redacted bytes before confirmation. Windows returns a `snapshotId` from `preview_diagnostic_bundle`; export consumes @@ -5574,6 +5575,63 @@ are always admitted. Producers that build expensive fields check the gate first. {"id":null,"ok":true,"data":{}} ``` +`diagnostics.recordPluginOperation` records one terminal result of a declarative +plugin contribution: work a plugin declares in its manifest that the host or a +Core engine executes, so no plugin process can report it through `lithe/log`. It +accepts `{pluginId,operation,outcome,stage?,durationMs,operationId?}` with no other +keys and returns `data:{result:{}}` once the fact is queued, or +`data:{error:{code:-32064,reason}}`. `outcome` is `finished|failed`; `stage` is +required for `failed` and forbidden for `finished`. `durationMs` is monotonic +milliseconds up to 2^53-1. `operationId` follows the SDK `operationId` grammar +(1-128 bytes of ASCII letters, digits and `._:/-$`). The fact becomes +`plugins.operation.finished` or `plugins.operation.failed` on +`plugins/{plugin}/host`, the same events and channel an SDK-backed plugin writes, +with fields `plugin`, `operation`, `duration_ms` and, for failures, `code`. +Cancellation is never recorded. No plugin output, path or error text is accepted. + +Each accepted `operation` is one row of Core's contribution table. The row's +lifecycle decides which stages exist and which `host.*` code each stage means, so +a code has one meaning across every contribution with that lifecycle: + +| `operation` | Contribution | Lifecycle | +| --- | --- | --- | +| `languageServer/start` | `languageServers[]` | process start | +| `debugAdapter/start` | `debugAdapters[]` | process start | +| `lithe/build/model` | `buildSystems[].model` command source | command run | +| `lithe/build/dependencies` | `buildSystems[].dependencies` command source | command run | + +| `stage` | Process start | Command run | +| --- | --- | --- | +| `plan` | rejected | `host.planFailed` | +| `resolve` | `host.executableUnavailable` | `host.executableUnavailable` | +| `launch` | `host.launchFailed` | `host.launchFailed` | +| `initialize` | `host.initializeFailed` | rejected | +| `timeout` | `host.timedOut` | `host.timedOut` | +| `exit` | `host.exitedEarly` | `host.commandFailed` | +| `decode` | rejected | `host.outputInvalid` | + +An unknown operation, a stage the lifecycle cannot reach, an unknown key, an +invalid operation ID or an out-of-range duration all return -32064. Whoever +executes the attempt records it. The host records debug adapter starts and build +commands itself. A declarative language server is resolved by the host and +supervised by Core: the host records failures before launch and otherwise passes +`startupOperation:{operationId,elapsedMs}` on `lsp.startServer` (language server +role with `pluginId` only; ignored otherwise). Core then records exactly one +result: `launch` when `lsp.startServer` fails for any reason other than +cancellation, `exit` when the process exits before `initialize` succeeds, +`initialize` for any other terminal failure before then, `timeout` at the initialize +deadline, or `finished` when the `initialize` result succeeds. `durationMs` adds +the host's `elapsedMs` to Core's own monotonic time. Stopping before a result +records nothing. A fact the engine cannot queue increments the `dropped` counter. + +```json +{"version":1,"command":"diagnostics.recordPluginOperation","payload":{"pluginId":"io.example.go","operation":"debugAdapter/start","outcome":"failed","stage":"resolve","durationMs":12,"operationId":"7c0d1f0e-3f6b-4a52-9d5e-0b7c2b0b9a11"}} +``` + +```json +{"id":null,"ok":true,"data":{"result":{}}} +``` + `plugins.declarative.languageServerLaunchPlan.request.logDirectory` is an optional absolute host-owned current-session plugin files directory for `${logDir}`. Language servers and plugin backends use the same expansion. diff --git a/shared/fixtures/diagnostics/engine-logging-v2.json b/shared/fixtures/diagnostics/engine-logging-v2.json index 5fcf9c65bd..cfa50c93c0 100644 --- a/shared/fixtures/diagnostics/engine-logging-v2.json +++ b/shared/fixtures/diagnostics/engine-logging-v2.json @@ -64,5 +64,74 @@ "provider": "git", "state": "ready" } - } + }, + "hostOperations": [ + { + "payload": { + "pluginId": "io.github.lithe-idea.go-support", + "operation": "languageServer/start", + "outcome": "finished", + "durationMs": 412, + "operationId": "0F8E1C2A-7B5D-4E61-9A3C-2D4B6F8E0A1C" + }, + "event": "plugins.operation.finished", + "channel": "plugins/io.github.lithe-idea.go-support/host" + }, + { + "payload": { + "pluginId": "io.github.lithe-idea.go-support", + "operation": "languageServer/start", + "outcome": "failed", + "stage": "resolve", + "durationMs": 3 + }, + "event": "plugins.operation.failed", + "channel": "plugins/io.github.lithe-idea.go-support/host", + "code": "host.executableUnavailable" + }, + { + "payload": { + "pluginId": "io.github.lithe-idea.lldb-debug", + "operation": "debugAdapter/start", + "outcome": "failed", + "stage": "timeout", + "durationMs": 10000 + }, + "event": "plugins.operation.failed", + "channel": "plugins/io.github.lithe-idea.lldb-debug/host", + "code": "host.timedOut" + }, + { + "payload": { + "pluginId": "io.github.lithe-idea.gradle-build", + "operation": "lithe/build/model", + "outcome": "failed", + "stage": "exit", + "durationMs": 5210 + }, + "event": "plugins.operation.failed", + "channel": "plugins/io.github.lithe-idea.gradle-build/host", + "code": "host.commandFailed" + }, + { + "payload": { + "pluginId": "io.github.lithe-idea.go-support", + "operation": "languageServer/start", + "outcome": "failed", + "stage": "decode", + "durationMs": 2 + }, + "rejected": -32064 + }, + { + "payload": { + "pluginId": "io.github.lithe-idea.go-support", + "operation": "languageServer/start", + "outcome": "finished", + "durationMs": 2, + "message": "gopls: GOPROXY=https://user:secret@proxy" + }, + "rejected": -32064 + } + ] } diff --git a/shared/logging/events/plugins.json b/shared/logging/events/plugins.json index 899b1a22ef..c052e406d9 100644 --- a/shared/logging/events/plugins.json +++ b/shared/logging/events/plugins.json @@ -573,17 +573,17 @@ "plugin": { "type": "id", "required": true, - "description": "Installed plugin identity supplied by the owning Core session, never by the notification" + "description": "Installed plugin identity bound by the owning Core session or the declarative launch, never taken from plugin output" }, "operation": { "type": "token", "required": true, - "description": "Registered plugin function or SDK protocol operation that owns this diagnostic result" + "description": "SDK function or protocol operation reported through lithe/log, or a declarative contribution operation from Core's contribution table, such as languageServer/start or lithe/build/model" }, "duration": { "type": "duration", "required": true, - "description": "Monotonic elapsed milliseconds measured by the SDK for the completed plugin operation" + "description": "Monotonic elapsed milliseconds measured by the SDK, or by the host and Core for one declarative attempt" }, "count": { "type": "int", @@ -603,22 +603,22 @@ "plugin": { "type": "id", "required": true, - "description": "Installed plugin identity supplied by the owning Core session, never by the notification" + "description": "Installed plugin identity bound by the owning Core session or the declarative launch, never taken from plugin output" }, "operation": { "type": "token", "required": true, - "description": "Registered plugin function or SDK protocol operation that owns this diagnostic result" + "description": "SDK function or protocol operation reported through lithe/log, or a declarative contribution operation from Core's contribution table, such as languageServer/start or lithe/build/model" }, "duration": { "type": "duration", "required": true, - "description": "Monotonic elapsed milliseconds measured by the SDK for the completed plugin operation" + "description": "Monotonic elapsed milliseconds measured by the SDK, or by the host and Core for one declarative attempt" }, "code": { "type": "token", "required": true, - "description": "Stable plugin failure or recovery category, excluding upstream error messages and request contents" + "description": "Stable SDK failure category, or a host.* code Core maps from the declarative failure stage and lifecycle; excludes paths, upstream messages and request contents" }, "count": { "type": "int", diff --git a/shared/platform-feature-matrix/features/diagnostics-export.json b/shared/platform-feature-matrix/features/diagnostics-export.json index fef0a66de7..21a87baa08 100644 --- a/shared/platform-feature-matrix/features/diagnostics-export.json +++ b/shared/platform-feature-matrix/features/diagnostics-export.json @@ -39,7 +39,9 @@ "macos/Tests/LitheTests/LogWindowTests.swift", "macos/Sources/Lithe/Views/Diagnostics/LogChannelList.swift", "rust/lithe-core/src/lsp/interface/plugin_logging.rs", - "shared/contracts/plugins/v1/fixtures/plugin-logging.json" + "shared/contracts/plugins/v1/fixtures/plugin-logging.json", + "rust/lithe-core/src/diagnostics/plugin_operations.rs", + "macos/Tests/LitheTests/Support/RecordedPluginOperations.swift" ], "implementationStatus": "implemented", "verificationStatus": "pending" @@ -55,5 +57,5 @@ "verificationStatus": "pending" }, "owner": "Diagnostics", - "verification": "双端记录 language/git/run/performance 事件，按模块、当前/上次会话、级别、UTC 时间与文本筛选；确认诊断 15 分钟到期、过载不阻塞调用线程、日志受限额控制、目录切换后收集实际位置、嵌套与转义凭据不落盘；确认预览后修改源文件不改变导出快照，取消/失败清理暂存，并检查 macOS v1 日志不进入时间线和导出、仅按 30 天过期清理与收集缺失计数。 验证自定义目录中无关的 lithe.*.log 不被收集或删除、刷新期间修改条件后按钮恢复、UTC 小数精度及等价时区边界正确、200 文件上限在模块/会话筛选后应用且遗漏明确标记。 macOS 从齿轮菜单或快捷键进入独立日志窗口，Windows 仍从设置→工具→日志与诊断进入，核对中英文名称、顺序、实际诊断范围、清理全模块会话范围、目录/清理后刷新、预览条件冻结，以及取消/失败后按钮和快照恢复；原生 macOS 明暗页面与实际 ZIP 链路、Windows 前端界面交互分别验证。 macOS v2 按 sessions 会话目录查询并冻结导出，检查 Core 目录字段校验、100 ms/256 条批量、保留容量、log.dropped/log.repeated、32 个句柄 LRU、三段轮转、超时控制与跟随广播；Windows 仍使用 v1。 PR2b 回归覆盖合法 c++ 插件编辑器资源不受日志身份约束、点号活动通道与 ~N 轮转文件互不覆盖、控制取消不丢已接纳批次与丢弃汇总、退出无条件关闭订阅和句柄、多行错误经 Core 规范化后严格校验，以及 LSP/Git/下载/freeze 失败分类和数值证据。 验证 Windows 保留设备名被拒绝、溢出通道可写头并轮转、client_secret/auth_token 等前缀凭据在编码和查询时均被脱敏，以及按 ts/level 字段筛选。 检查多通道总量超过 10 MiB 时所有活动段优先，删除或原子替换已打开的日志后新事件仍落盘；Update 事件保留 Application 分类，浏览器 c++ 与超长语言 ID 语法失败始终保留插件证据。 PR4 B2：macOS 导出使用 Core 范围规划和精确级别过滤，确认前冻结脱敏内容，附带可选环境与有界崩溃报告；macOS 设置已移除日志与诊断页，所有导出入口先打开独立日志窗口并在窗口中确认导出，通知保留原动作并提供目录事件引用跳转。运行 DiagnosticsExportV2Tests、DiagnosticsWorkflowTests、WorkbenchNotificationTests 和 probe-macos-logging-ui.sh，核对中英文 × 深浅色窗口及导出对话框。真实应用保存面板、访达、通知定位及崩溃后验收仍 pending；Windows 仍是 v1，未迁移。 PR4 视觉收尾：日志窗口按 HTML 原型使用独立明暗调色板、可换行工具栏、原生会话路径标题和当前快捷键徽标、212pt 分组通道栏、22pt 虚拟行、自绘选中状态、Core JSON 着色详情及调用链、24pt 状态栏和 560pt 导出对话框。logWindowMatchesMockup 使用真实 MacLogStore 与目录事件渲染 1340×786，中英文×明暗、调用链和单独导出截图由本地 probe 生成；截图实机比对与原生标题栏验收保持 pending。 PR4 收尾：macOS 独立日志窗口提供未开启时的详细诊断卡片及工具栏目录与清理菜单，确认当前实际目录只读呈现、选择后切换并保存、恢复默认仅在非默认目录可用、清理全会话后刷新占用；应用菜单导出在日志窗口中呈现。 修复验收：框选窗口时间后导出当前过滤结果，验证 Core 同时应用导出范围与窗口时间范围，含带时区和不重叠的空结果；原有范围、通道、级别和表达式保持交集。 日志窗口自适应回归：调整窗口宽度，确认事件/消息/字段使用空余宽度、窄窗口可横向滚动且自动列宽不写偏好；详情和调用链左上对齐、动作说明不盖状态栏。原生发送 ⌘F 后筛选框接收焦点，⌘点击两个通道能同时保留，全部通道清除限制；ⓘ 说明表达式交集、通道选择、时间和调用链偏移。时间分布刻度含秒，日历与时分秒草稿应用后包含结束秒，清除移除范围。实时追加只更新受影响行、跟随平滑滚动，暂停不重建已有单元格；真实应用连续突发的整帧流畅度仍需验收。 官方插件日志接入：三SDK协商litheLogging 1，lithe/log由Core校验后进入统一队列，真实SDK/Core验证INFO成功、ERROR失败、WARN降级恢复、op与耗时、不含请求正文；高频成功可单次抑制。上游明确type对应ERROR/WARN/INFO/DEBUG，未分类stderr为DEBUG，进程实际失败为ERROR。检查日志窗口按插件与级别筛选；macOS整机窗口与Windows v2验收仍pending。 执行轨迹：用户动作、Core 请求与 Git 命令按同一 op 串联；用户来源的成功或取消记 INFO，后台来源只在详细诊断下记 DEBUG，失败记 WARN 并由 Git 失败通知引用，宿主不再重复记 ERROR；Core 在入队前按宿主下发的 DEBUG 门过滤，队列事实由唤醒回调安排排空。运行 core_request_traces、CoreRequestTraceTests 和 UserActionTraceTests，在日志窗口按 op 查看调用链；整机操作验收仍pending。" + "verification": "双端记录 language/git/run/performance 事件，按模块、当前/上次会话、级别、UTC 时间与文本筛选；确认诊断 15 分钟到期、过载不阻塞调用线程、日志受限额控制、目录切换后收集实际位置、嵌套与转义凭据不落盘；确认预览后修改源文件不改变导出快照，取消/失败清理暂存，并检查 macOS v1 日志不进入时间线和导出、仅按 30 天过期清理与收集缺失计数。 验证自定义目录中无关的 lithe.*.log 不被收集或删除、刷新期间修改条件后按钮恢复、UTC 小数精度及等价时区边界正确、200 文件上限在模块/会话筛选后应用且遗漏明确标记。 macOS 从齿轮菜单或快捷键进入独立日志窗口，Windows 仍从设置→工具→日志与诊断进入，核对中英文名称、顺序、实际诊断范围、清理全模块会话范围、目录/清理后刷新、预览条件冻结，以及取消/失败后按钮和快照恢复；原生 macOS 明暗页面与实际 ZIP 链路、Windows 前端界面交互分别验证。 macOS v2 按 sessions 会话目录查询并冻结导出，检查 Core 目录字段校验、100 ms/256 条批量、保留容量、log.dropped/log.repeated、32 个句柄 LRU、三段轮转、超时控制与跟随广播；Windows 仍使用 v1。 PR2b 回归覆盖合法 c++ 插件编辑器资源不受日志身份约束、点号活动通道与 ~N 轮转文件互不覆盖、控制取消不丢已接纳批次与丢弃汇总、退出无条件关闭订阅和句柄、多行错误经 Core 规范化后严格校验，以及 LSP/Git/下载/freeze 失败分类和数值证据。 验证 Windows 保留设备名被拒绝、溢出通道可写头并轮转、client_secret/auth_token 等前缀凭据在编码和查询时均被脱敏，以及按 ts/level 字段筛选。 检查多通道总量超过 10 MiB 时所有活动段优先，删除或原子替换已打开的日志后新事件仍落盘；Update 事件保留 Application 分类，浏览器 c++ 与超长语言 ID 语法失败始终保留插件证据。 PR4 B2：macOS 导出使用 Core 范围规划和精确级别过滤，确认前冻结脱敏内容，附带可选环境与有界崩溃报告；macOS 设置已移除日志与诊断页，所有导出入口先打开独立日志窗口并在窗口中确认导出，通知保留原动作并提供目录事件引用跳转。运行 DiagnosticsExportV2Tests、DiagnosticsWorkflowTests、WorkbenchNotificationTests 和 probe-macos-logging-ui.sh，核对中英文 × 深浅色窗口及导出对话框。真实应用保存面板、访达、通知定位及崩溃后验收仍 pending；Windows 仍是 v1，未迁移。 PR4 视觉收尾：日志窗口按 HTML 原型使用独立明暗调色板、可换行工具栏、原生会话路径标题和当前快捷键徽标、212pt 分组通道栏、22pt 虚拟行、自绘选中状态、Core JSON 着色详情及调用链、24pt 状态栏和 560pt 导出对话框。logWindowMatchesMockup 使用真实 MacLogStore 与目录事件渲染 1340×786，中英文×明暗、调用链和单独导出截图由本地 probe 生成；截图实机比对与原生标题栏验收保持 pending。 PR4 收尾：macOS 独立日志窗口提供未开启时的详细诊断卡片及工具栏目录与清理菜单，确认当前实际目录只读呈现、选择后切换并保存、恢复默认仅在非默认目录可用、清理全会话后刷新占用；应用菜单导出在日志窗口中呈现。 修复验收：框选窗口时间后导出当前过滤结果，验证 Core 同时应用导出范围与窗口时间范围，含带时区和不重叠的空结果；原有范围、通道、级别和表达式保持交集。 日志窗口自适应回归：调整窗口宽度，确认事件/消息/字段使用空余宽度、窄窗口可横向滚动且自动列宽不写偏好；详情和调用链左上对齐、动作说明不盖状态栏。原生发送 ⌘F 后筛选框接收焦点，⌘点击两个通道能同时保留，全部通道清除限制；ⓘ 说明表达式交集、通道选择、时间和调用链偏移。时间分布刻度含秒，日历与时分秒草稿应用后包含结束秒，清除移除范围。实时追加只更新受影响行、跟随平滑滚动，暂停不重建已有单元格；真实应用连续突发的整帧流畅度仍需验收。 官方插件日志接入：三SDK协商litheLogging 1，lithe/log由Core校验后进入统一队列，真实SDK/Core验证INFO成功、ERROR失败、WARN降级恢复、op与耗时、不含请求正文；高频成功可单次抑制。上游明确type对应ERROR/WARN/INFO/DEBUG，未分类stderr为DEBUG，进程实际失败为ERROR。检查日志窗口按插件与级别筛选；macOS整机窗口与Windows v2验收仍pending。 执行轨迹：用户动作、Core 请求与 Git 命令按同一 op 串联；用户来源的成功或取消记 INFO，后台来源只在详细诊断下记 DEBUG，失败记 WARN 并由 Git 失败通知引用，宿主不再重复记 ERROR；Core 在入队前按宿主下发的 DEBUG 门过滤，队列事实由唤醒回调安排排空。运行 core_request_traces、CoreRequestTraceTests 和 UserActionTraceTests，在日志窗口按 op 查看调用链；整机操作验收仍pending。 声明式插件代记：没有插件进程的语言服务器、调试适配器和构建命令来源，由实际执行方按 Core 贡献映射表写同一组 plugins.operation.finished/failed 到 plugins//host。调试与构建由 macOS 宿主记录，语言服务器启动通过 startupOperation 交给 Core 记录。失败只取 host.* 阶段码，取消、停止、过期结果和由插件后端提供的构建计划都不记录。运行 plugin_operations、engine 声明式启动、BuildSystemService、DebugModule、PluginDebugAdapter、PluginLanguageServerLaunchResolver 与 MacBuildProviderSessions 回归。用 Go/PHP/LLDB/Gradle 插件在真实应用中检查日志窗口插件通道的验收仍为 pending。" } From 1080b72827b88476580beeae608b7a8ad554cd4a Mon Sep 17 00:00:00 2001 From: Yao Jingxi <23722032@bjtu.edu.cn> Date: Wed, 4 Nov 2026 14:45:54 +0800 Subject: [PATCH 2/3] =?UTF-8?q?docs(logging):=20=E5=9C=A8=E4=BA=8B?= =?UTF-8?q?=E4=BB=B6=E7=9B=AE=E5=BD=95=E8=AF=B4=E6=98=8E=E5=AE=BF=E4=B8=BB?= =?UTF-8?q?=E4=BB=A3=E8=AE=B0=E7=9A=84=E5=A3=B0=E6=98=8E=E5=BC=8F=E8=B4=A1?= =?UTF-8?q?=E7=8C=AE?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit create-lithe-plugin Skill（#1713）规定，宿主替哪些声明式贡献记录结果，以 shared/logging/README.md 和 shared/logging/events/ 为准。这里在“引擎宿主”一节补上 diagnostics.recordPluginOperation 的语义、当前代记的四种贡献表（operation、声明来源、记录方、可能的失败阶段），以及新增声明式贡献时要同步做的事。 --- shared/logging/README.md | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/shared/logging/README.md b/shared/logging/README.md index c28e1f7426..b501f9bd8e 100644 --- a/shared/logging/README.md +++ b/shared/logging/README.md @@ -89,6 +89,16 @@ Swift 的事件值是**未经脱敏的内存输入**，不能自行序列化落 - stderr 读取器限制每行 4 KiB、每秒 200 行，之后再走 `text` 的 1 KiB 脱敏规范化。与 v1 相比唯一的兼容变化是从任意 trim 的读取块改为逐行文本：保留行内空格，移除 LF 和末尾 CR，并应用已声明的长度上限和限流。 - 上游明确给出的严重度通过独立的目录事件保留：`window/logMessage` 和 `window/showMessage` 的 type 1/2/3/4 分别为 ERROR/WARN/INFO/DEBUG，未知类型为 DEBUG。未分类的 stderr 是 DEBUG 排障证据，流名称不表示警告；实际的进程或协议失败由 `*.session.failed` 记录 ERROR，正常关闭仍是生命周期状态。 - 插件自身使用独立协商的 `litheLogging` 1 和 `lithe/log`，由 Core 把四种受控事实映射到插件目录事件，不能再用 stderr 或任意自由消息代替。协议字段、op、限额和 fixture 以 [插件契约](../contracts/plugins/v1/README.md#structured-plugin-diagnostics-logging-protocol-1) 为准。 +- 声明式贡献没有插件进程，不能发 `lithe/log`。实际执行它的一方通过 `diagnostics.recordPluginOperation` 代记每次尝试的一条终态，事件和通道与 SDK 插件相同：`plugins.operation.finished` 或 `plugins.operation.failed`，写入 `plugins/{plugin}/host`。平台层只上报观察到的阶段和耗时，级别和 `host.*` 失败类别只由 Core 按阶段决定；取消、停止和过期结果不记录。宿主当前代记下表四种贡献，唯一来源是 `rust/lithe-core/src/diagnostics/plugin_operations.rs` 的 `CONTRIBUTIONS`；输入、阶段到类别的对应和 -32064 见 [Rust Core API](../contracts/rust-core-api.md#engine-logging-v2-handoff-pr3)。 + + | operation | 声明来源 | 记录方 | 可能的失败阶段 | + | --- | --- | --- | --- | + | `languageServer/start` | `languageServers[]` | macOS 宿主记启动前的失败；进入启动后用 `lsp.startServer.startupOperation` 交给 Core，Core 记录唯一结果 | resolve、launch、exit、initialize、timeout | + | `debugAdapter/start` | `debugAdapters[]` | macOS 宿主 | resolve、launch、exit、initialize、timeout | + | `lithe/build/model` | `buildSystems[]` 的命令式模型 | macOS 宿主；计划由插件后端提供时由 SDK 记录 | plan、resolve、launch、timeout、exit、decode | + | `lithe/build/dependencies` | `buildSystems[]` 的命令式依赖树 | macOS 宿主；计划由插件后端提供时由 SDK 记录 | plan、resolve、launch、timeout、exit、decode | + + 新增一种声明式贡献时，在同一次改动里给 `CONTRIBUTIONS` 加一行，在执行方开始和结束一次 attempt，并更新本表；不新增事件、通道或错误码。 - 上游 trace 默认关闭。宿主通过 `lsp.setDetailedDiagnostics` 对活动会话和新会话显式开启，15 分钟后单次到期关闭。详细诊断类别与通道根的对应为 `lsp` → language、`vcs` → git、`plugins` → plugins。 - 详细诊断只接纳 `$/logTrace.message` 摘要；`verbose` 可能包含原始 RPC 载荷和文档源码，禁止进入 v2 `text`。凭据脱敏和 1 KiB 限长不代表源码可以落盘。`initialized` 之前收到的开关只保存目标状态，Core 在 `initialized` 之后发送通知。 - v1 的 detail、message、level 保持兼容原文；v2 字段通过独立的 `EngineLogInput` 传递，禁止从 detail 反解。原始通知 JSON、`projectCount=N` 和 navigation 格式不变。macOS 日志窗口统一读取 v2 会话文件和写入器的实时批次，不写 v1 文件。 From 8888fd2834d2e6f6f406a2be30fa1aa2afd2d4ad Mon Sep 17 00:00:00 2001 From: Yao Jingxi <23722032@bjtu.edu.cn> Date: Wed, 4 Nov 2026 15:50:41 +0800 Subject: [PATCH 3/3] =?UTF-8?q?fix(logging):=20=E6=8C=89=E8=AF=84=E5=AE=A1?= =?UTF-8?q?=E4=BF=AE=E6=AD=A3=E5=A3=B0=E6=98=8E=E5=BC=8F=E6=8F=92=E4=BB=B6?= =?UTF-8?q?=E6=93=8D=E4=BD=9C=E4=BA=8B=E5=AE=9E=E7=9A=84=E8=BE=B9=E7=95=8C?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - LSP：写 initialize 失败记 launch；被新索引策略淘汰的启动放弃 attempt；handoff 携带 pluginId，只在 LanguageServer 角色且会话 身份缺省或一致时接受；plugin API 1 宿主进程启动的服务器也覆盖； 启动前停止会取消 attempt。 - 构建：计划由插件后端提供时，宿主仍记录 provider 工具解析和计划 失败，发请求前再取消。 - 调试：op 用调试会话 ID；托管适配器按到达阶段记录（端口发现失败 launch、发现截止 timeout、连上后断开才是 exit）；Core 拒绝建会话 取消不记录；同步 start 抛错即使任务已取消也记失败。 - 调试日志适配器段改用 identity_segment，与插件事实同一映射。 - diagnostics.recordPluginOperation 拒绝可选字段显式 null（-32064）。 - 同步契约、事件目录说明和 Agent Note。 --- .../2026-11-03-structured-logging-channels.md | 13 +- .../MacHostedPortDebugAdapterTransport.swift | 11 ++ .../MacPluginDebugAdapterTransport.swift | 24 +++- .../Debug/MacTCPDebugAdapterTransport.swift | 7 + .../Platform/MacOS/MacServiceContainer.swift | 8 +- .../Debug/DebugAdapterContracts.swift | 9 +- .../Language/LanguageExtensionContracts.swift | 7 + .../Language/LanguageToolingContracts.swift | 4 + .../CoreDebugAdapterProtocolSession.swift | 24 ++-- .../Services/BuildSystemService.swift | 15 +- .../Runtime/LanguageServerSession.swift | 10 +- .../LanguageToolingSessionManager.swift | 6 +- .../Logging/PluginOperationReporter.swift | 4 +- .../DebugModuleTests.swift | 112 ++++++++++++++- .../BuildSystemServiceTests.swift | 27 ++++ ...nguageExtensionProcessLifecycleTests.swift | 4 + .../MacBuildProviderSessionsTests.swift | 10 +- .../LitheTests/PluginDebugAdapterTests.swift | 133 ++++++++++++++++++ ...ginLanguageServerLaunchResolverTests.swift | 54 +++++-- rust/lithe-core/src/debug/engine.rs | 17 +-- .../src/diagnostics/plugin_operations.rs | 37 ++++- rust/lithe-core/src/lsp/interface/engine.rs | 99 +++++++++++-- shared/contracts/rust-core-api.md | 41 ++++-- shared/logging/README.md | 2 +- 24 files changed, 585 insertions(+), 93 deletions(-) diff --git a/.agents/notes/implemented/architecture/2026-11-03-structured-logging-channels.md b/.agents/notes/implemented/architecture/2026-11-03-structured-logging-channels.md index 50b4bc4dee..6e8fe3345f 100644 --- a/.agents/notes/implemented/architecture/2026-11-03-structured-logging-channels.md +++ b/.agents/notes/implemented/architecture/2026-11-03-structured-logging-channels.md @@ -232,10 +232,15 @@ Swift 侧对应 `PluginOperationAttempt`。差异只在 `plugin_operations.rs` 所有权按“谁执行，谁记录”划分： - 调试适配器启动和构建命令由 macOS 宿主执行，宿主在解析、启动、初始化、超时、退出和解码的真实边界推进阶段， - 通过 `diagnostics.recordPluginOperation` 写入。 -- 语言服务器由宿主解析启动方案、由 Core 拉起和握手。宿主只记录启动前的失败；进入启动后用 - `startupOperation:{operationId,elapsedMs}` 把 attempt 交给 Core。Core 在 spawn 失败、提前退出、握手失败、 - 初始化超时或初始化成功时记录唯一结果，耗时为宿主已用时间加 Core 计时。 + 通过 `diagnostics.recordPluginOperation` 写入。调试 attempt 的 op 直接用调试会话 ID，和该会话自己的 + `DebugTransportFailed` 等记录对得上。适配器“可达”之前一直是 launch：stdio 进程在跑起来后可达，语言服务器托管的 + 适配器要等 socket 连上才可达，所以发现端口失败记 launch、发现超时记 timeout，只有可达过的适配器断开才记 exit。 + Core 拒绝创建调试会话（例如父会话已结束）是宿主结果，取消 attempt，不算插件故障。 +- 语言服务器由宿主解析启动方案、由 Core 拉起和握手。宿主只记录启动前的失败，plugin API 1 以宿主进程方式启动的 + 服务器也一样；进入启动后用 `startupOperation:{pluginId,operationId,elapsedMs}` 把 attempt 交给 Core。 + `pluginId` 放在 handoff 里而不是取自会话，因为 API 1 服务器的会话没有插件身份；会话有身份时两者必须一致， + 否则 Core 忽略这个 handoff。Core 在 spawn 失败或写 initialize 失败（launch）、提前退出、握手失败、 + 初始化超时或初始化成功时记录唯一结果，耗时为宿主已用时间加 Core 计时；被新索引策略淘汰的启动按取消处理。 - 构建计划实际由插件后端提供时，宿主取消自己的 attempt，由 SDK 记录，避免同一次工作出现两条事实。 一次 attempt 只有第一次终态生效。取消、停止、被新请求取代的过期结果都不记录，因为它们不是插件故障； diff --git a/macos/Sources/Lithe/Platform/MacOS/Debug/MacHostedPortDebugAdapterTransport.swift b/macos/Sources/Lithe/Platform/MacOS/Debug/MacHostedPortDebugAdapterTransport.swift index 061626fdde..e9ef7bca89 100644 --- a/macos/Sources/Lithe/Platform/MacOS/Debug/MacHostedPortDebugAdapterTransport.swift +++ b/macos/Sources/Lithe/Platform/MacOS/Debug/MacHostedPortDebugAdapterTransport.swift @@ -35,11 +35,21 @@ final class MacHostedPortDebugAdapterTransport: DebugAdapterDrainingTransport { get { transport.onTermination } set { transport.onTermination = newValue } } + /// The server is up, its adapter's port was found and the socket connected. + var onConnected: (() -> Void)? { + get { transport.onConnected } + set { transport.onConnected = newValue } + } + var onFailure: ((DebugTransportFailureReason) -> Void)? { + get { transport.onFailure } + set { transport.onFailure = newValue } + } init( portResolver: @escaping PortResolver, core: any DebugTransportLifecycleCore, logSink: (any LogSink)? = nil, + deadlineScheduler: (any DebugOperationDeadlineScheduling)? = nil, socketFactory: @escaping @MainActor (String, UInt16) -> any DebugAdapterSocketConnection = { NetworkDebugAdapterSocketConnection(host: $0, port: $1) } @@ -50,6 +60,7 @@ final class MacHostedPortDebugAdapterTransport: DebugAdapterDrainingTransport { return DebugAdapterEndpoint(host: "127.0.0.1", port: Int(port)) }, core: core, logSink: logSink, + deadlineScheduler: deadlineScheduler, // A cold JDT/project import is endpoint discovery, not a TCP // connect. Keep it bounded without applying the direct-host budget; // the connect to the discovered port keeps the default short budget. diff --git a/macos/Sources/Lithe/Platform/MacOS/Debug/MacPluginDebugAdapterTransport.swift b/macos/Sources/Lithe/Platform/MacOS/Debug/MacPluginDebugAdapterTransport.swift index 4d5e68a079..612f0319ba 100644 --- a/macos/Sources/Lithe/Platform/MacOS/Debug/MacPluginDebugAdapterTransport.swift +++ b/macos/Sources/Lithe/Platform/MacOS/Debug/MacPluginDebugAdapterTransport.swift @@ -36,6 +36,8 @@ final class MacPluginDebugAdapterTransport: DebugAdapterDrainingTransport, Debug private let findCommand: @MainActor ([String]) -> URL? private let startHostedPort: HostedPortStarter private let socketFactory: @MainActor (String, UInt16) -> any DebugAdapterSocketConnection + /// Runs a hosted adapter's discovery and connect deadlines; nil uses system timers. + private let deadlineScheduler: (any DebugOperationDeadlineScheduling)? private let logSink: (any LogSink)? private var transport: (any DebugAdapterTransport)? var startupAttempt: PluginOperationAttempt? @@ -56,7 +58,8 @@ final class MacPluginDebugAdapterTransport: DebugAdapterDrainingTransport, Debug }, socketFactory: @escaping @MainActor (String, UInt16) -> any DebugAdapterSocketConnection = { NetworkDebugAdapterSocketConnection(host: $0, port: $1) - } + }, + deadlineScheduler: (any DebugOperationDeadlineScheduling)? = nil ) { self.adapterID = adapterID self.findCommand = findCommand @@ -66,23 +69,38 @@ final class MacPluginDebugAdapterTransport: DebugAdapterDrainingTransport, Debug self.logSink = logSink self.startHostedPort = startHostedPort self.socketFactory = socketFactory + self.deadlineScheduler = deadlineScheduler } var isRunning: Bool { transport?.isRunning ?? false } func start(rootURL: URL) throws { let transport: any DebugAdapterTransport + let connectsLater: Bool switch try resolve(rootURL).host { case .process(let process): transport = try processTransport(for: process) + connectsLater = false case .languageServer(let languageID, let command): let startHostedPort = startHostedPort - transport = MacHostedPortDebugAdapterTransport( + let hosted = MacHostedPortDebugAdapterTransport( portResolver: { rootURL in try await startHostedPort(languageID, command, rootURL) }, core: core, logSink: logSink, + deadlineScheduler: deadlineScheduler, socketFactory: socketFactory ) + // Starting the server and finding the port outlive `start`, so the + // attempt stays at launch until the socket connects. A failure + // before then is the launch's, or the deadline's. + let attempt = startupAttempt + hosted.onConnected = { attempt?.advance(to: .initialize) } + hosted.onFailure = { reason in + guard reason == .startupTimedOut, attempt?.stage == .launch else { return } + attempt?.advance(to: .timeout) + } + transport = hosted + connectsLater = true } transport.onData = { [weak self] in self?.onData?($0) } transport.onErrorOutput = { [weak self] in self?.onErrorOutput?($0) } @@ -92,6 +110,8 @@ final class MacPluginDebugAdapterTransport: DebugAdapterDrainingTransport, Debug // fails from here is starting the adapter. startupAttempt?.advance(to: .launch) try transport.start(rootURL: rootURL) + // A process adapter is reachable once it runs; what fails next is the handshake. + if !connectsLater { startupAttempt?.advance(to: .initialize) } } private func processTransport( diff --git a/macos/Sources/Lithe/Platform/MacOS/Debug/MacTCPDebugAdapterTransport.swift b/macos/Sources/Lithe/Platform/MacOS/Debug/MacTCPDebugAdapterTransport.swift index ae3bf9f722..ab4b8268c0 100644 --- a/macos/Sources/Lithe/Platform/MacOS/Debug/MacTCPDebugAdapterTransport.swift +++ b/macos/Sources/Lithe/Platform/MacOS/Debug/MacTCPDebugAdapterTransport.swift @@ -73,6 +73,10 @@ final class MacTCPDebugAdapterTransport: DebugAdapterDrainingTransport { var onData: ((Data) -> Void)? var onErrorOutput: ((Data) -> Void)? var onTermination: ((Int) -> Void)? + /// The stream reached the adapter: Core's first `ready` after a start. + var onConnected: (() -> Void)? + /// Why Core failed the stream, reported just before its error output. + var onFailure: ((DebugTransportFailureReason) -> Void)? init( endpointResolver: @escaping EndpointResolver, @@ -146,10 +150,12 @@ final class MacTCPDebugAdapterTransport: DebugAdapterDrainingTransport { private func apply(_ step: DebugTransportStep, inbound: Data? = nil) { let registrationID = transportID + let connected = phase != .ready && step.phase == .ready generation = step.generation phase = step.phase effectDepth += 1 defer { effectDepth -= 1 } + if connected { onConnected?() } for effect in step.effects { // A callback or an observer may have stopped or restarted the stream // while an earlier effect ran; the rest of this step is stale. @@ -175,6 +181,7 @@ final class MacTCPDebugAdapterTransport: DebugAdapterDrainingTransport { case .close: closeConnection() case .reportFailure(let reason, let message): + onFailure?(reason) onErrorOutput?(Data((failureText(reason, message: message) + "\n").utf8)) case .notifyTermination(let exitCode): onTermination?(exitCode) diff --git a/macos/Sources/Lithe/Platform/MacOS/MacServiceContainer.swift b/macos/Sources/Lithe/Platform/MacOS/MacServiceContainer.swift index 02f59be265..5280eaa2d1 100644 --- a/macos/Sources/Lithe/Platform/MacOS/MacServiceContainer.swift +++ b/macos/Sources/Lithe/Platform/MacOS/MacServiceContainer.swift @@ -856,8 +856,11 @@ final class MacServiceContainer { ), core: rustCore, deadlineScheduler: MacDebugOperationDeadlineScheduler(), - beginPluginStartup: { - pluginOperations.begin(pluginID: pluginID, operation: .debugAdapterStart, at: .resolve) + beginPluginStartup: { operationID in + pluginOperations.begin( + pluginID: pluginID, operation: .debugAdapterStart, at: .resolve, + operationID: operationID + ) } ) // Remembered so withdrawing this plugin ends this session @@ -1484,6 +1487,7 @@ final class MacServiceContainer { } ?? probe.packagedRuntimeURL, languageIdentifier: server.languageIdentifier, launchSource: launchSource, + pluginID: descriptor.id.rawValue, executableVersionRequirement: probe.versionRequirement, hostIntegrationID: server.hostIntegrationID, launchRuntimeTool: server.launchRuntimeTool diff --git a/macos/Sources/LitheCoreContracts/Debug/DebugAdapterContracts.swift b/macos/Sources/LitheCoreContracts/Debug/DebugAdapterContracts.swift index b25a3ae973..0b6135c543 100644 --- a/macos/Sources/LitheCoreContracts/Debug/DebugAdapterContracts.swift +++ b/macos/Sources/LitheCoreContracts/Debug/DebugAdapterContracts.swift @@ -20,9 +20,12 @@ public protocol DebugAdapterTransport: AnyObject { func stop() } -/// A transport that resolves a declared launch when it starts. It advances the -/// session's start attempt from `resolve` to `launch` once the launch is known, -/// so a start error is attributed to the stage that failed. +/// A transport that resolves a declared launch when it starts. It owns the +/// session's start attempt until the adapter is reachable: `resolve` until the +/// launch is known, then `launch`, then `initialize` once the adapter can take +/// the handshake, or `timeout` when its own startup deadline ends the launch. +/// A transport that connects after `start` returns keeps the attempt it was +/// lent until then; the session ends the attempt and never moves it back. @MainActor public protocol DebugAdapterLaunchResolvingTransport: DebugAdapterTransport { var startupAttempt: PluginOperationAttempt? { get set } diff --git a/macos/Sources/LitheCoreContracts/Language/LanguageExtensionContracts.swift b/macos/Sources/LitheCoreContracts/Language/LanguageExtensionContracts.swift index fd24b6f920..b90c88fbf0 100644 --- a/macos/Sources/LitheCoreContracts/Language/LanguageExtensionContracts.swift +++ b/macos/Sources/LitheCoreContracts/Language/LanguageExtensionContracts.swift @@ -105,6 +105,11 @@ public struct LanguageServerExtensionConfiguration: Equatable, Sendable { /// starts. When set, `arguments` are templates and are never passed to /// the process as written. public let launchSource: DeclarativeLanguageServerLaunchSource? + /// Plugin whose declaration contributes the server, at any plugin API + /// version; nil for a server the host itself provides. It only attributes + /// the start to the plugin: a plugin API 1 server has no `launchSource` + /// and still starts as a host-owned process. + public let pluginID: String? /// Minimum version a discovered executable must report, for a server /// started by a runtime such as `java`. public let executableVersionRequirement: LanguageServerExecutableVersionRequirement? @@ -126,6 +131,7 @@ public struct LanguageServerExtensionConfiguration: Equatable, Sendable { executableURL: URL? = nil, languageIdentifier: String, launchSource: DeclarativeLanguageServerLaunchSource? = nil, + pluginID: String? = nil, executableVersionRequirement: LanguageServerExecutableVersionRequirement? = nil, hostIntegrationID: String? = nil, launchRuntimeTool: String? = nil @@ -140,6 +146,7 @@ public struct LanguageServerExtensionConfiguration: Equatable, Sendable { self.executableURL = executableURL self.languageIdentifier = languageIdentifier self.launchSource = launchSource + self.pluginID = pluginID ?? launchSource?.pluginID self.executableVersionRequirement = executableVersionRequirement self.hostIntegrationID = hostIntegrationID self.launchRuntimeTool = launchRuntimeTool diff --git a/macos/Sources/LitheCoreContracts/Language/LanguageToolingContracts.swift b/macos/Sources/LitheCoreContracts/Language/LanguageToolingContracts.swift index 4018957b18..8734842ff1 100644 --- a/macos/Sources/LitheCoreContracts/Language/LanguageToolingContracts.swift +++ b/macos/Sources/LitheCoreContracts/Language/LanguageToolingContracts.swift @@ -72,6 +72,8 @@ package struct LanguageServerLaunchDescriptor: Hashable, Sendable { package let initializationOptions: ToolingJSONValue? /// See `LanguageServerExtensionConfiguration.launchSource`. package let launchSource: DeclarativeLanguageServerLaunchSource? + /// See `LanguageServerExtensionConfiguration.pluginID`. + package let pluginID: String? /// See `LanguageServerExtensionConfiguration.executableVersionRequirement`. package let executableVersionRequirement: LanguageServerExecutableVersionRequirement? /// Native host integration the provider declares, such as `jdt`. @@ -88,6 +90,7 @@ package struct LanguageServerLaunchDescriptor: Hashable, Sendable { executableURL: URL? = nil, initializationOptions: ToolingJSONValue? = nil, launchSource: DeclarativeLanguageServerLaunchSource? = nil, + pluginID: String? = nil, executableVersionRequirement: LanguageServerExecutableVersionRequirement? = nil, hostIntegrationID: String? = nil, launchRuntimeTool: String? = nil @@ -100,6 +103,7 @@ package struct LanguageServerLaunchDescriptor: Hashable, Sendable { self.executableURL = executableURL self.initializationOptions = initializationOptions self.launchSource = launchSource + self.pluginID = pluginID ?? launchSource?.pluginID self.executableVersionRequirement = executableVersionRequirement self.hostIntegrationID = hostIntegrationID self.launchRuntimeTool = launchRuntimeTool diff --git a/macos/Sources/LitheDebugModule/Runtime/CoreDebugAdapterProtocolSession.swift b/macos/Sources/LitheDebugModule/Runtime/CoreDebugAdapterProtocolSession.swift index 8e2e29b0a1..20ed5c7f2b 100644 --- a/macos/Sources/LitheDebugModule/Runtime/CoreDebugAdapterProtocolSession.swift +++ b/macos/Sources/LitheDebugModule/Runtime/CoreDebugAdapterProtocolSession.swift @@ -45,8 +45,9 @@ public final class CoreDebugAdapterProtocolSession: DebugAdapterControllingSessi private var errorOutputDecoder = StreamingUTF8Decoder() private var ownsCoreSession = false private var isStopping = false - /// Begins a declarative adapter's start attempt; nil for host-owned adapters. - private let beginPluginStartup: (@MainActor () -> PluginOperationAttempt)? + /// Begins a declarative adapter's start attempt under the session's ID, the + /// operation of the session's own debug records; nil for host-owned adapters. + private let beginPluginStartup: (@MainActor (_ operationID: String) -> PluginOperationAttempt)? /// Ends when the adapter leaves `initializing`, fails, or the session stops. private var startupAttempt: PluginOperationAttempt? @@ -79,7 +80,7 @@ public final class CoreDebugAdapterProtocolSession: DebugAdapterControllingSessi deadlineScheduler: any DebugOperationDeadlineScheduling, operationTimeoutMilliseconds: Int = 10_000, initializationTimeoutMilliseconds: Int? = nil, - beginPluginStartup: (@MainActor () -> PluginOperationAttempt)? = nil + beginPluginStartup: (@MainActor (_ operationID: String) -> PluginOperationAttempt)? = nil ) { self.beginPluginStartup = beginPluginStartup self.logSink = logSink @@ -107,17 +108,20 @@ public final class CoreDebugAdapterProtocolSession: DebugAdapterControllingSessi discardPendingStartDebuggingRequests() capabilities = .unknown startupAttempt?.cancel() - startupAttempt = beginPluginStartup?() + startupAttempt = beginPluginStartup?(sessionID) let resolving = transport as? any DebugAdapterLaunchResolvingTransport resolving?.startupAttempt = startupAttempt defer { resolving?.startupAttempt = nil } do { try transport.start(rootURL: rootURL.standardizedFileURL) } catch { - startupAttempt?.end(throwing: error) + // A synchronous start is not cancelled by its caller's task, so + // its error is a failure even when that task was cancelled. + startupAttempt?.fail() logSink?.emit(DebugTransportFailed(stage: "process-start", operationID: sessionID)) throw error } - startupAttempt?.advance(to: .initialize) + // A resolving transport moves the attempt itself once the adapter is reachable. + if resolving == nil { startupAttempt?.advance(to: .initialize) } if let initializationTimeoutMilliseconds { let token = UUID() initializationToken = token @@ -143,7 +147,9 @@ public final class CoreDebugAdapterProtocolSession: DebugAdapterControllingSessi ownsCoreSession = true try apply(update) } catch { - startupAttempt?.fail() + // Core refused the session before the adapter saw a byte, such as + // a parent that already ended: a host outcome, not the plugin's. + startupAttempt?.cancel() cancelInitializationDeadline() transport.stop() releaseCoreSession() @@ -878,7 +884,9 @@ public final class CoreDebugAdapterProtocolSession: DebugAdapterControllingSessi private func transportTerminated(exitCode: Int) { guard !isStopping else { return } - startupAttempt?.advance(to: .exit) + // Only an adapter that was reachable exited; before that the launch + // failed, and after a deadline the timeout stands. + if startupAttempt?.stage == .initialize { startupAttempt?.advance(to: .exit) } if exitCode != 0 && state != .failed { logSink?.emit(DebugTransportFailed(exitCode: Int64(exitCode), stage: "transport-exit", operationID: sessionID)) } diff --git a/macos/Sources/LitheExecutionModule/Services/BuildSystemService.swift b/macos/Sources/LitheExecutionModule/Services/BuildSystemService.swift index eb56fe7dac..00b8f98e9a 100644 --- a/macos/Sources/LitheExecutionModule/Services/BuildSystemService.swift +++ b/macos/Sources/LitheExecutionModule/Services/BuildSystemService.swift @@ -1728,8 +1728,8 @@ package final class BuildSystemService: ObservableObject { /// The tool is only resolved once Core says the source is a provider; a /// command plan resolves it when it runs. /// - /// The host reports `attempt` only while it does the work itself: a - /// provider plan hands the load to the plugin's process, which reports it. + /// The tool lookup and the second plan are still host work, so their + /// failures stay on `attempt`; the provider owns the load once it is sent. private func outputPlan( _ entry: BuildSystemEntry, workspaceURL: URL, @@ -1740,10 +1740,10 @@ package final class BuildSystemService: ObservableObject { ) async throws -> BuildOutputPlan { let planned = try plan(BuildProviderHints(reason: reason)) guard case .provider = planned else { return planned } - attempt.cancel() - guard let executable = try await providerTool(entry, workspaceURL: workspaceURL, owner: owner) else { - return planned - } + attempt.advance(to: .resolve) + let executable = try await providerTool(entry, workspaceURL: workspaceURL, owner: owner) + attempt.advance(to: .plan) + guard let executable else { return planned } return try plan(BuildProviderHints(reason: reason, toolExecutable: executable)) } @@ -1804,6 +1804,9 @@ package final class BuildSystemService: ObservableObject { } let target = Self.providerTarget(entry, workspaceURL: workspaceURL) guard modelInputsAreCurrent(request), canAppend(owner) else { throw CancellationError() } + // The plugin's process reports the load through `lithe/log` from + // here on; the host recording it too would double it. + attempt.cancel() let result = try await providers.send(request, to: target, timeout: timeout) guard modelInputsAreCurrent(request), canAppend(owner), !Task.isCancelled else { throw CancellationError() } return .providerResult(result) diff --git a/macos/Sources/LitheLanguageIntelligenceModule/Runtime/LanguageServerSession.swift b/macos/Sources/LitheLanguageIntelligenceModule/Runtime/LanguageServerSession.swift index a3b40ac438..4866e51510 100644 --- a/macos/Sources/LitheLanguageIntelligenceModule/Runtime/LanguageServerSession.swift +++ b/macos/Sources/LitheLanguageIntelligenceModule/Runtime/LanguageServerSession.swift @@ -41,7 +41,10 @@ package final class LanguageServerRuntimeSession: LanguageServerSession { private var startingPreparedProcess = false /// Held until launch: a preparation failure ends it here, a launch hands it to Core. private var startupAttempt: PluginOperationAttempt? - package func observePluginStartup(_ attempt: PluginOperationAttempt) { startupAttempt = attempt } + package func observePluginStartup(_ attempt: PluginOperationAttempt) { + startupAttempt?.cancel() + startupAttempt = attempt + } private func endStartupAttempt(throwing error: any Error) { startupAttempt?.end(throwing: error) startupAttempt = nil @@ -1331,12 +1334,13 @@ package final class LanguageServerRuntimeSession: LanguageServerSession { } package func stop() { - startupAttempt?.cancel() - startupAttempt = nil beginStop(inBackground: false) } private func beginStop(inBackground: Bool) { + // A stopped start is cancelled; a later start must not report it. + startupAttempt?.cancel() + startupAttempt = nil let wasStarting = startupGeneration != nil preparationTask?.cancel() preparationTask = nil diff --git a/macos/Sources/LitheLanguageIntelligenceModule/Services/LanguageToolingSessionManager.swift b/macos/Sources/LitheLanguageIntelligenceModule/Services/LanguageToolingSessionManager.swift index 76e23916ff..9707519564 100644 --- a/macos/Sources/LitheLanguageIntelligenceModule/Services/LanguageToolingSessionManager.swift +++ b/macos/Sources/LitheLanguageIntelligenceModule/Services/LanguageToolingSessionManager.swift @@ -318,6 +318,7 @@ package final class LanguageToolingSessionManager: ObservableObject, runtimeTools: configuration.runtimeTools, executableURL: configuration.executableURL, launchSource: configuration.launchSource, + pluginID: configuration.pluginID, executableVersionRequirement: configuration.executableVersionRequirement, hostIntegrationID: configuration.hostIntegrationID, launchRuntimeTool: configuration.launchRuntimeTool @@ -1696,8 +1697,9 @@ package final class LanguageToolingSessionManager: ObservableObject, } languageServerStartupAttempts[descriptor.id] = (rootURL, attempts + 1) let operationID = requestedOperationID ?? UUID() - // Only a declarative launch has no plugin process to report its start. - let startupAttempt = (descriptor.languageServerLaunch?.launchSource?.pluginID).map { + // Only a declarative launch has no plugin process to report its start; + // a plugin API 1 server is one too, though it has no launch templates. + let startupAttempt = descriptor.languageServerLaunch?.pluginID.map { pluginOperations.begin( pluginID: $0, operation: .languageServerStart, at: .resolve, operationID: operationID.uuidString ) diff --git a/macos/Sources/LitheModuleAPI/Logging/PluginOperationReporter.swift b/macos/Sources/LitheModuleAPI/Logging/PluginOperationReporter.swift index f5ccf575c4..26868e183e 100644 --- a/macos/Sources/LitheModuleAPI/Logging/PluginOperationReporter.swift +++ b/macos/Sources/LitheModuleAPI/Logging/PluginOperationReporter.swift @@ -63,6 +63,8 @@ public struct PluginOperationObservation: Encodable, Sendable, Equatable { /// An attempt passed to Core with the request that starts the process. Core /// then records its result, adding its own time to `elapsedMs`. public struct PluginOperationHandoff: Encodable, Sendable, Equatable { + /// Named here because a plugin API 1 server starts with no plugin identity. + public let pluginId: String public let operationId: String public let elapsedMs: UInt64 } @@ -158,7 +160,7 @@ public final class PluginOperationAttempt { guard !isEnded else { return nil } isEnded = true guard reporter.record != nil else { return nil } - return PluginOperationHandoff(operationId: operationID, elapsedMs: elapsedMilliseconds) + return PluginOperationHandoff(pluginId: pluginID, operationId: operationID, elapsedMs: elapsedMilliseconds) } private func end(failure: PluginOperationStage?) { diff --git a/macos/Tests/LitheDebugModuleTests/DebugModuleTests.swift b/macos/Tests/LitheDebugModuleTests/DebugModuleTests.swift index d13135a56b..c1dfd703b4 100644 --- a/macos/Tests/LitheDebugModuleTests/DebugModuleTests.swift +++ b/macos/Tests/LitheDebugModuleTests/DebugModuleTests.swift @@ -4977,7 +4977,10 @@ struct DebugModuleTests { try session.start(rootURL: URL(fileURLWithPath: "/tmp/declarative-adapter")) #expect(operations.observations.isEmpty) - core.enqueueReceive(state: "ready", events: [["sequence": 2, "type": "stateChanged", "state": "ready"]]) + core.enqueueReceive( + sessionID: RecordedDebugStartOperations.operationID, state: "ready", + events: [["sequence": 2, "type": "stateChanged", "state": "ready"]] + ) transport.emitData(Data("initialize-response".utf8)) #expect(session.state == .ready) // An adapter that exits after its start finished does not end the start again. @@ -5064,11 +5067,72 @@ struct DebugModuleTests { // The next start is a new attempt of its own. try session.start(rootURL: URL(fileURLWithPath: "/tmp/declarative-adapter")) - core.enqueueReceive(state: "ready", events: [["sequence": 2, "type": "stateChanged", "state": "ready"]]) + core.enqueueReceive( + sessionID: RecordedDebugStartOperations.operationID, state: "ready", + events: [["sequence": 2, "type": "stateChanged", "state": "ready"]] + ) transport.emitData(Data("initialize-response".utf8)) #expect(operations.observations == [RecordedDebugStartOperations.expected(failure: nil)]) } + /// An adapter that connects after `start` returns, like one a language + /// server hosts, is still launching until it connects; ending before then + /// is a launch failure, and only a connected adapter can exit. + @Test(arguments: [false, true]) + func aDeclarativeAdapterThatConnectsLaterIsLaunchingUntilItConnects(connected: Bool) throws { + let transport = LaterConnectingTransport() + let operations = RecordedDebugStartOperations() + let session = declarativeAdapterSession( + transport: transport, core: RecordingDebugProtocolCore(), operations: operations + ) + + try session.start(rootURL: URL(fileURLWithPath: "/tmp/declarative-adapter")) + if connected { transport.connect() } + transport.terminate(1) + + #expect(operations.observations == [RecordedDebugStartOperations.expected(failure: connected ? .exit : .launch)]) + } + + @Test + func aSessionCoreRefusesIsNotRecordedAsThePlugins() { + let core = RecordingDebugProtocolCore() + core.refusesSessions = true + let operations = RecordedDebugStartOperations() + let session = declarativeAdapterSession(transport: RecordingTransport(), core: core, operations: operations) + + #expect(throws: RecordingDebugProtocolCore.SessionRefused.self) { + try session.start(rootURL: URL(fileURLWithPath: "/tmp/declarative-adapter")) + } + + #expect(session.state == .failed) + #expect(operations.observations.isEmpty) + } + + /// The start is synchronous, so a cancelled caller does not turn the + /// adapter's own failure into a cancellation. + @Test + func aStartThatFailsInACancelledTaskIsStillRecorded() async { + let transport = RecordingTransport() + transport.failsToStart = true + let operations = RecordedDebugStartOperations() + let session = declarativeAdapterSession( + transport: transport, core: RecordingDebugProtocolCore(), operations: operations + ) + + // The task cannot run before this main-actor test suspends, so it is + // already cancelled when it starts the session. + let start = Task { @MainActor in + #expect(Task.isCancelled) + #expect(throws: RecordingTransport.StartFailure.self) { + try session.start(rootURL: URL(fileURLWithPath: "/tmp/declarative-adapter")) + } + } + start.cancel() + await start.value + + #expect(operations.observations == [RecordedDebugStartOperations.expected(failure: .resolve)]) + } + private func declarativeAdapterSession( transport: any DebugAdapterTransport, core: RecordingDebugProtocolCore, @@ -5080,10 +5144,10 @@ struct DebugModuleTests { adapterID: "lldb-dap", transport: transport, core: core, - sessionID: "java-session", + sessionID: RecordedDebugStartOperations.operationID, deadlineScheduler: deadlines, initializationTimeoutMilliseconds: initializationTimeoutMilliseconds, - beginPluginStartup: { operations.begin() } + beginPluginStartup: { operations.begin(operationID: $0) } ) } @@ -5586,6 +5650,9 @@ private final class DeferredInspectionDebugSession: DebugAdapterControllingSessi @MainActor private final class RecordingDebugProtocolCore: DebugProtocolCore { + struct SessionRefused: Error {} + /// When set, `createDebugSession` throws, as Core does for a parent that already ended. + var refusesSessions = false private var receiveUpdates: [DebugCoreUpdate] = [] private(set) var lastInspectionOperationID: String? private(set) var lastDataBreakpointInfoOperationID: String? @@ -5632,6 +5699,7 @@ private final class RecordingDebugProtocolCore: DebugProtocolCore { disabledCapabilities: [String], parentSessionID: String? ) throws -> DebugCoreUpdate { + if refusesSessions { throw SessionRefused() } lastDisabledCapabilities = disabledCapabilities lastParentSessionID = parentSessionID lastSupportsRunInTerminalRequest = supportsRunInTerminalRequest @@ -5870,19 +5938,21 @@ private struct RecordingRunInTerminalCompletion: Equatable { /// Records the start attempts a session reports, on a clock that advances /// `tick` milliseconds per reading, so every attempt lasts exactly one tick. +/// The session under test is `operationID`, so `expected` also proves the +/// attempt is recorded under the session's ID. @MainActor private final class RecordedDebugStartOperations { static let pluginID = "io.example.debug" - static let operationID = "debug-start" + static let operationID = "debug-start-session" static let tick: UInt64 = 7 private(set) var observations: [PluginOperationObservation] = [] private var now: UInt64 = 0 - func begin() -> PluginOperationAttempt { + func begin(operationID: String) -> PluginOperationAttempt { PluginOperationReporter( record: { [self] in observations.append($0) }, clock: { [self] in now += Self.tick; return now } - ).begin(pluginID: Self.pluginID, operation: .debugAdapterStart, at: .resolve, operationID: Self.operationID) + ).begin(pluginID: Self.pluginID, operation: .debugAdapterStart, at: .resolve, operationID: operationID) } static func expected(failure: PluginOperationStage?) -> PluginOperationObservation { @@ -5912,6 +5982,34 @@ private final class LaunchFailingTransport: DebugAdapterLaunchResolvingTransport func stop() {} } +/// Resolves its launch, returns from `start`, and connects only later, like a +/// transport to an adapter that a language server hosts. +@MainActor +private final class LaterConnectingTransport: DebugAdapterLaunchResolvingTransport { + var startupAttempt: PluginOperationAttempt? + private var lentAttempt: PluginOperationAttempt? + private(set) var isRunning = false + var onData: ((Data) -> Void)? + var onErrorOutput: ((Data) -> Void)? + var onTermination: ((Int) -> Void)? + + func start(rootURL _: URL) throws { + startupAttempt?.advance(to: .launch) + lentAttempt = startupAttempt + isRunning = true + } + + func connect() { lentAttempt?.advance(to: .initialize) } + + func terminate(_ exitCode: Int) { + isRunning = false + onTermination?(exitCode) + } + + func send(_: Data) throws {} + func stop() { isRunning = false } +} + @MainActor private final class RecordingDebugDeadlineScheduler: DebugOperationDeadlineScheduling { private var deadlines: [RecordingDebugDeadline] = [] diff --git a/macos/Tests/LitheExecutionModuleTests/BuildSystemServiceTests.swift b/macos/Tests/LitheExecutionModuleTests/BuildSystemServiceTests.swift index f8fed56ce2..0ccaf0a291 100644 --- a/macos/Tests/LitheExecutionModuleTests/BuildSystemServiceTests.swift +++ b/macos/Tests/LitheExecutionModuleTests/BuildSystemServiceTests.swift @@ -2050,6 +2050,33 @@ struct BuildSystemServiceTests { #expect(operations.observations.isEmpty) } + /// The host resolves the provider's tool before it sends anything; when + /// that fails the provider never sees the load, so the host records it. + @Test + func providerToolFailureBeforeTheRequestIsRecordedByTheHost() async throws { + let planner = FakeBuildPlanner() + planner.detection = BuildDetection(instances: [try Self.instance(modelSource: "provider")]) + planner.providerRequest = Self.providerRequest(method: "lithe/build/model") + let providers = FakeBuildProviders() + let operations = RecordedPluginOperations() + let harness = Harness( + planner: planner, providers: providers, + settings: { _ in ["toolPath": .string("/custom tools/build")] }, + pluginOperations: operations.reporter + ) + harness.tools.failure = BuildToolResolutionError("Selected executable is unavailable.", terminal: true) + defer { harness.service.stop() } + harness.service.reset(workspaceURL: Self.workspace) + #expect(await harness.waitForEntries { $0.first?.modelState == .notLoaded }) + + harness.service.loadModel(Self.instanceID) + #expect(await harness.waitForEntries { if case .failed = $0.first?.modelState { return true }; return false }) + + #expect(providers.sent.isEmpty) + #expect(operations.observations.map(\.operation) == ["lithe/build/model"]) + #expect(operations.observations.map(\.stage) == [.resolve]) + } + @Test func stoppedDeclarativeModelCommandRecordsNothing() async throws { let planner = FakeBuildPlanner() diff --git a/macos/Tests/LitheTests/LanguageExtensionProcessLifecycleTests.swift b/macos/Tests/LitheTests/LanguageExtensionProcessLifecycleTests.swift index 49d6cbd968..cb42d43f9d 100644 --- a/macos/Tests/LitheTests/LanguageExtensionProcessLifecycleTests.swift +++ b/macos/Tests/LitheTests/LanguageExtensionProcessLifecycleTests.swift @@ -78,6 +78,10 @@ struct LanguageExtensionProcessLifecycleTests { #expect(provider.configuration.executableNames == ["gopls"]) #expect(provider.configuration.validationArguments == ["version"]) #expect(provider.configuration.runtimeTools == ["go"]) + // A plugin API 1 launch is literal, yet the start is still the + // plugin's, so the host can record it on the plugin's channel. + #expect(provider.configuration.launchSource == nil) + #expect(provider.configuration.pluginID == "dev.lithe.plugin.go-support") try await runtime.setEnabled(false, for: moduleID) } diff --git a/macos/Tests/LitheTests/MacBuildProviderSessionsTests.swift b/macos/Tests/LitheTests/MacBuildProviderSessionsTests.swift index 1a5623b2d1..e8fa7b7f7a 100644 --- a/macos/Tests/LitheTests/MacBuildProviderSessionsTests.swift +++ b/macos/Tests/LitheTests/MacBuildProviderSessionsTests.swift @@ -244,13 +244,16 @@ struct MacBuildProviderSessionsTests { /// Once a launch is requested Core owns the plugin's start result, failed /// or not; the host hands the attempt over and records nothing itself. - @Test(arguments: [false, true]) - func aLaunchHandsTheDeclarativeStartToCore(failsToStart: Bool) async throws { + /// A plugin API 1 server starts as a host-owned process, so the handoff, + /// not the session, names the plugin. + @Test(arguments: [false, true], [false, true]) + func aLaunchHandsTheDeclarativeStartToCore(failsToStart: Bool, pluginOwnsTheProcess: Bool) async throws { let core = ScriptedProviderCore(failStart: failsToStart) let operations = RecordedPluginOperations() let session = LanguageServerRuntimeSession( providerID: "fixture", executableURL: URL(fileURLWithPath: "/host/bin/server"), - arguments: [], environment: [:], core: core, pluginID: "dev.example.fixture" + arguments: [], environment: [:], core: core, + pluginID: pluginOwnsTheProcess ? "dev.example.fixture" : nil ) defer { session.stop() } let settled = TestGate() @@ -267,6 +270,7 @@ struct MacBuildProviderSessionsTests { try? session.start(rootURL: URL(fileURLWithPath: "/workspace"), workspaceFingerprint: nil) try #require(await settled.waitUntilOpen()) + #expect(core.startupHandoffs.map(\.pluginId) == ["dev.example.fixture"]) #expect(core.startupHandoffs.map(\.operationId) == ["lsp-start"]) #expect(core.startupHandoffs.map(\.elapsedMs) == [RecordedPluginOperations.tick]) #expect(operations.observations.isEmpty) diff --git a/macos/Tests/LitheTests/PluginDebugAdapterTests.swift b/macos/Tests/LitheTests/PluginDebugAdapterTests.swift index 4b0528166e..87d73374ff 100644 --- a/macos/Tests/LitheTests/PluginDebugAdapterTests.swift +++ b/macos/Tests/LitheTests/PluginDebugAdapterTests.swift @@ -191,6 +191,75 @@ struct PluginDebugAdapterTests { try hosted.start(rootURL: URL(fileURLWithPath: "/tmp/hosted-adapter-stage", isDirectory: true)) #expect(resolved.stage == .launch) #expect(await probe.waitUntilTerminated(), "The session did not end before the local deadline") + // The server never hosted the adapter, so the launch is what failed. + #expect(resolved.stage == .launch) + } + + /// A hosted adapter is launching until its socket connects: a start that + /// ends before then is the launch's, or the discovery deadline's, and only + /// an adapter that was reached exits. Real Core runs both the session and + /// the socket lifecycle; the server, the socket and the clock are fakes. + @Test(arguments: ["connects", "fails", "timesOut"]) + func aHostedAdapterStartIsRecordedAtTheStageItReached(_ end: String) async throws { + struct Unavailable: LocalizedError { var errorDescription: String? { "The Example language server did not start." } } + let probe = HostedAdapterProbe() + let deadlines = HostedAdapterDeadlines() + let observations = HostedStartObservations() + let unanswered = UnansweredPortRequest() + let reporter = PluginOperationReporter(record: { observations.append($0) }, clock: { 0 }) + let core = RustCoreBridge() + let transport = MacPluginDebugAdapterTransport( + adapterID: "example", + resolve: { _ in Self.hostedLaunch() }, + makeProcess: { Issue.record("A hosted adapter starts no process of its own."); fatalError() }, + core: core, + startHostedPort: { _, _, _ in + switch end { + case "fails": throw Unavailable() + // Never answers, like a server that never hosts the adapter. + // test-stability: allow(swift-unbounded-wait) reason: the test fires the discovery deadline, which closes the transport and cancels this wait; the session.stop() defer cancels it if any expectation fails first. + case "timesOut": return try await unanswered.wait() + default: return 4711 + } + }, + socketFactory: { host, port in probe.makeSocket(host: host, port: port) }, + deadlineScheduler: deadlines + ) + let sessionID = "hosted-start-\(end)-\(UUID().uuidString)" + let session = CoreDebugAdapterProtocolSession( + adapterID: "example-dap", transport: transport, core: core, sessionID: sessionID, + deadlineScheduler: deadlines, + beginPluginStartup: { + reporter.begin(pluginID: "acme.example", operation: .debugAdapterStart, at: .resolve, operationID: $0) + } + ) + defer { session.stop() } + session.onEvent = { if case .terminated(let code) = $0 { probe.recordTermination(code ?? 0) } } + + try session.start(rootURL: URL(fileURLWithPath: "/tmp/hosted-adapter-\(end)", isDirectory: true)) + switch end { + case "connects": + #expect(await probe.waitUntilConnected(), "The socket was not opened before the local deadline") + #expect(observations.recorded.isEmpty) + probe.socket.onReady?() + probe.socket.onComplete?() + case "timesOut": + let discovery = try #require(deadlines.pending.first { $0.milliseconds == 120_000 }) + discovery.fire() + default: + break + } + #expect(await probe.waitUntilTerminated(), "The session did not end before the local deadline") + + let stage: PluginOperationStage = switch end { + case "connects": .exit + case "timesOut": .timeout + default: .launch + } + #expect(observations.recorded == [PluginOperationObservation( + pluginID: "acme.example", operation: .debugAdapterStart, failure: stage, + durationMs: 0, operationID: sessionID + )]) } // MARK: - Launch transport @@ -565,6 +634,70 @@ private final class HostedAdapterSocket: DebugAdapterSocketConnection { func stop() { stopCount += 1 } } +/// The plugin operations a session recorded, in order. +@MainActor +private final class HostedStartObservations { + private(set) var recorded: [PluginOperationObservation] = [] + func append(_ observation: PluginOperationObservation) { recorded.append(observation) } +} + +/// A port request the server never answers. Only cancelling the waiting task +/// ends it, so a test that needs the discovery deadline never races a reply. +@MainActor +private final class UnansweredPortRequest { + private var waiter: CheckedContinuation? + private var isCancelled = false + + func wait() async throws -> UInt16 { + try await withTaskCancellationHandler { + try await withCheckedThrowingContinuation { continuation in + if isCancelled { continuation.resume(throwing: CancellationError()) } else { waiter = continuation } + } + } onCancel: { + Task { @MainActor in self.cancel() } + } + } + + private func cancel() { + isCancelled = true + waiter?.resume(throwing: CancellationError()) + waiter = nil + } +} + +/// Deadlines that fire only when a test fires them, so no test waits on a clock. +@MainActor +private final class HostedAdapterDeadlines: DebugOperationDeadlineScheduling { + private(set) var scheduled: [HostedAdapterDeadline] = [] + var pending: [HostedAdapterDeadline] { scheduled.filter { !$0.isCancelled } } + + func schedule(afterMilliseconds milliseconds: Int, action: @escaping @MainActor () -> Void) -> any DebugOperationDeadline { + let deadline = HostedAdapterDeadline(milliseconds: milliseconds, action: action) + scheduled.append(deadline) + return deadline + } +} + +@MainActor +private final class HostedAdapterDeadline: DebugOperationDeadline { + let milliseconds: Int + private var action: (@MainActor () -> Void)? + var isCancelled: Bool { action == nil } + + init(milliseconds: Int, action: @escaping @MainActor () -> Void) { + self.milliseconds = milliseconds + self.action = action + } + + func cancel() { action = nil } + + func fire() { + let action = action + self.action = nil + action?() + } +} + /// Remembers that an event happened and resumes one waiter when it does. Both /// the event and the local deadline arrive on the main actor, so a passing run /// returns on the event and the deadline only bounds a failing one. diff --git a/macos/Tests/LitheTests/PluginLanguageServerLaunchResolverTests.swift b/macos/Tests/LitheTests/PluginLanguageServerLaunchResolverTests.swift index d3cf523ac9..c29ac8075e 100644 --- a/macos/Tests/LitheTests/PluginLanguageServerLaunchResolverTests.swift +++ b/macos/Tests/LitheTests/PluginLanguageServerLaunchResolverTests.swift @@ -467,22 +467,57 @@ struct PluginLanguageServerLaunchResolverTests { )]) } - /// The manager begins an attempt only for a declarative launch: a server the - /// host owns has no plugin to attribute it to. The attempt carries the - /// manager's operation ID, so it joins the session's other records. + /// Stopping cancels the attempt on every stop path, so a later start of the + /// same session cannot report the stopped one. @MainActor - @Test(arguments: [true, false]) - func aServerWithoutAnExecutableRecordsOnlyADeclarativeStart(declarative: Bool) { + @Test + func aStartStoppedBeforeLaunchIsNotReportedByALaterStart() async { + let operations = RecordedPluginOperations() + let session = LanguageServerRuntimeSession( + providerID: "fixture", + executableURL: URL(fileURLWithPath: "/bin/sh"), + arguments: ["${pluginDir}/server"], + environment: [:], + launchResolver: { _ in + throw DeclarativePluginRejection( + code: "plugin.launch.invalidRequest", + message: "The launch request has no usable pluginDirectory." + ) + }, + core: RustCoreBridge() + ) + session.observePluginStartup(operations.reporter.begin( + pluginID: "dev.example.plugin", operation: .languageServerStart, at: .resolve, operationID: "lsp-start" + )) + + #expect(await session.stopAndWait()) + #expect(throws: LanguageServerSessionStartError.self) { + try session.start(rootURL: URL(fileURLWithPath: "/projects/one"), workspaceFingerprint: nil) + } + + #expect(operations.observations.isEmpty) + } + + /// The manager begins an attempt only for a server a plugin declares, + /// whether its launch is templated (plugin API 2 and later) or literal + /// (plugin API 1): a server the host owns has no plugin to attribute it to. + /// The attempt carries the manager's operation ID, so it joins the + /// session's other records. + @MainActor + @Test(arguments: ["launchTemplates", "pluginAPI1", "hostOwned"]) + func aServerWithoutAnExecutableRecordsOnlyADeclarativeStart(owner: String) { let source = DeclarativeLanguageServerLaunchSource( pluginID: "dev.example.plugin", languageID: "fixture", manifest: Data(), packageURL: URL(fileURLWithPath: "/plugins/fixture") ) + let declarative = owner != "hostOwned" let launch = LanguageServerLaunchDescriptor( executableNames: ["fixture-language-server"], arguments: [], - launchSource: declarative ? source : nil + launchSource: owner == "launchTemplates" ? source : nil, + pluginID: owner == "pluginAPI1" ? "dev.example.plugin" : nil ) let descriptor = LanguageProviderDescriptor( id: "fixture", @@ -496,7 +531,8 @@ struct PluginLanguageServerLaunchResolverTests { descriptor: descriptor, runtimeService: FixedLanguageToolRuntime(candidates: [:]), languageServerLaunch: launch, - languageServerCore: RustCoreBridge() + languageServerCore: RustCoreBridge(), + languageServerExecutableResolver: { _ in nil } ) let operations = RecordedPluginOperations() let manager = LanguageToolingSessionManager( @@ -507,8 +543,8 @@ struct PluginLanguageServerLaunchResolverTests { defer { manager.stopAllLanguageServers() } let operationID = UUID() - // Only what is recorded matters here: the declarative server stops at - // discovery, while the host-owned one fails later at process start. + // Only what is recorded matters here: with no executable every server + // stops at discovery, and only a plugin's server has an attempt to end. #expect(throws: (any Error).self) { _ = try manager.startLanguageServer( providerID: descriptor.id, rootURL: URL(fileURLWithPath: "/projects/one"), operationID: operationID diff --git a/rust/lithe-core/src/debug/engine.rs b/rust/lithe-core/src/debug/engine.rs index 1e4e523561..2792077ed7 100644 --- a/rust/lithe-core/src/debug/engine.rs +++ b/rust/lithe-core/src/debug/engine.rs @@ -8,11 +8,11 @@ use super::projection_v2::{ }; use super::protocol::{frame_message, parse_messages}; use super::types::*; +use crate::diagnostics::channel::identity_segment; use crate::protocol::{CoreError, ErrorCode}; use base64::engine::general_purpose::STANDARD as BASE64; use base64::Engine as _; use serde_json::{json, Map, Value}; -use sha2::{Digest, Sha256}; use std::collections::{BTreeMap, BTreeSet, HashMap}; use std::sync::{Mutex, OnceLock}; @@ -144,7 +144,8 @@ pub(crate) fn create_session( } let mut session = DebugSession { id: request.session_id.clone(), - log_adapter: debug_log_adapter(&request.adapter_id), + // Same mapping as plugin facts, so one adapter id names one channel. + log_adapter: identity_segment(&request.adapter_id), logged_terminal_failure: false, adapter_id: request.adapter_id, root_path: request.root_path, @@ -1946,14 +1947,6 @@ impl DebugSession { } } -fn debug_log_adapter(adapter: &str) -> String { - if crate::diagnostics::channel::validate_segment(adapter).is_ok() { - adapter.to_owned() - } else { - format!("invalid-{:x}", Sha256::digest(adapter.as_bytes()))[..40].to_owned() - } -} - impl PendingRequest { fn command(&self) -> &'static str { match self { @@ -3152,9 +3145,9 @@ mod tests { #[test] fn dap_logging_keeps_catalog_identity_and_cancellation_private() { let adapter = "lldb+private-adapter"; - let subject = debug_log_adapter(adapter); + let subject = identity_segment(adapter); assert!(subject.starts_with("invalid-")); - assert_eq!(subject, debug_log_adapter(adapter)); + assert_eq!(subject, identity_segment(adapter)); assert!(!subject.contains("private")); let mut fact = crate::diagnostics::record::StructuredLogEvent { ts: "2026-11-04T00:00:00.000Z".into(), diff --git a/rust/lithe-core/src/diagnostics/plugin_operations.rs b/rust/lithe-core/src/diagnostics/plugin_operations.rs index 9348a84675..d564d56554 100644 --- a/rust/lithe-core/src/diagnostics/plugin_operations.rs +++ b/rust/lithe-core/src/diagnostics/plugin_operations.rs @@ -17,7 +17,7 @@ use super::{ channel::{identity_segment, LogError}, core_events, }; -use serde::Deserialize; +use serde::{Deserialize, Deserializer}; use serde_json::{json, Value}; use std::collections::BTreeMap; use std::sync::{Arc, Mutex}; @@ -152,13 +152,22 @@ struct Request { plugin_id: String, operation: String, outcome: Outcome, - #[serde(default)] + #[serde(default, deserialize_with = "present")] stage: Option, duration_ms: u64, - #[serde(default)] + #[serde(default, deserialize_with = "present")] operation_id: Option, } +/// An optional field is either absent or a value; an explicit `null` is rejected. +fn present<'de, D, T>(deserializer: D) -> Result, D::Error> +where + D: Deserializer<'de>, + T: Deserialize<'de>, +{ + T::deserialize(deserializer).map(Some) +} + #[derive(Deserialize)] #[serde(rename_all = "camelCase")] enum Outcome { @@ -251,10 +260,14 @@ pub fn record_request(input: Value) -> Result { /// Attempt the host began and handed to Core, which owns the rest of it. /// /// The host records only failures before the handoff; Core records the single -/// terminal result after it. Wire form: `{operationId, elapsedMs}`. +/// terminal result after it. Wire form: `{pluginId, operationId, elapsedMs}`. #[derive(Debug, Clone, Deserialize)] #[serde(rename_all = "camelCase", deny_unknown_fields)] pub struct AttemptHandoff { + /// Plugin whose declaration the attempt runs. It is named here rather than + /// taken from the session, because a plugin API 1 server is launched as a + /// host-owned process with no plugin identity of its own. + pub plugin_id: String, /// Host operation that already correlates the attempt's lifecycle facts. pub operation_id: String, /// Monotonic milliseconds the host spent on the attempt before the handoff. @@ -280,12 +293,11 @@ impl Attempt { /// Slot holding a handed-off attempt, timed from now. pub(crate) fn slot( contribution: &'static Contribution, - plugin_id: String, handoff: AttemptHandoff, ) -> AttemptSlot { Arc::new(Mutex::new(Some(Self { contribution, - plugin_id, + plugin_id: handoff.plugin_id, operation_id: handoff.operation_id, host_elapsed_ms: handoff.elapsed_ms, started: Instant::now(), @@ -476,6 +488,15 @@ mod tests { input.as_object_mut().unwrap().remove(key); assert_eq!(prepare(input).unwrap_err().code, -32064, "{key}"); } + // Optional fields are absent or a value; `null` is neither. + let finished = json!({"pluginId":"io.example.contribution", + "operation":"languageServer/start", "outcome":"finished", "durationMs":2}); + assert!(prepare(finished.clone()).is_ok()); + for key in ["stage", "operationId"] { + let mut input = finished.clone(); + input[key] = Value::Null; + assert_eq!(prepare(input).unwrap_err().code, -32064, "{key}"); + } } // The first terminal path takes the attempt; later paths and abandoned slots @@ -483,12 +504,14 @@ mod tests { #[test] fn diagnostics_host_plugin_operations_attempt_slot_ends_once() { let handoff = AttemptHandoff { + plugin_id: "io.example.lsp".into(), operation_id: "attempt-9".into(), elapsed_ms: 40, }; - let slot = Attempt::slot(&LANGUAGE_SERVER_START, "io.example.lsp".into(), handoff); + let slot = Attempt::slot(&LANGUAGE_SERVER_START, handoff); let taken = slot.lock().unwrap().take().unwrap(); assert!(std::ptr::eq(taken.contribution, &LANGUAGE_SERVER_START)); + assert_eq!(taken.plugin_id, "io.example.lsp"); assert_eq!(taken.host_elapsed_ms, 40); assert_eq!(taken.operation_id, "attempt-9"); finish(&slot, Some(Stage::Exit)); diff --git a/rust/lithe-core/src/lsp/interface/engine.rs b/rust/lithe-core/src/lsp/interface/engine.rs index 54fae8dd34..a98d089a3c 100644 --- a/rust/lithe-core/src/lsp/interface/engine.rs +++ b/rust/lithe-core/src/lsp/interface/engine.rs @@ -2260,6 +2260,8 @@ impl LspEngine { if let Err(error) = check_indexing() { self.lock_sessions()?.remove(&session_id); session.active.store(false, Ordering::Release); + // A retired start is cancelled; the process exit must not record it. + plugin_operations::abandon(attempt); session.kill_process(); return Err(error); } @@ -2268,6 +2270,8 @@ impl LspEngine { session.spawn_outbound_maintenance(); let outbound_order = session.lock_outbound_order()?; if let Err(error) = session.send_messages(&outbound_order, initialize.messages) { + // startServer fails here, so the attempt failed to launch. + plugin_operations::finish(attempt, Some(AttemptStage::Launch)); session.fail( "transportFailed", "initialize", @@ -2282,6 +2286,9 @@ impl LspEngine { if let Err(error) = check_indexing() { self.lock_sessions()?.remove(&session_id); session.active.store(false, Ordering::Release); + // The readers already run; abandon before the kill so the exit + // they observe finds no attempt to record. + plugin_operations::abandon(attempt); session.kill_process(); return Err(error); } @@ -5655,6 +5662,9 @@ impl RuntimeSession { { state.initialize_deadline = None; initialize_timeout = true; + // Decided under the state lock, like the initialize response, + // so exactly one of the two records the attempt. + plugin_operations::finish(&self.startup_attempt, Some(AttemptStage::Timeout)); } let applying_maven_context = state .pending @@ -5882,7 +5892,6 @@ impl RuntimeSession { ); self.kill_process(); } else if initialize_timeout { - plugin_operations::finish(&self.startup_attempt, Some(AttemptStage::Timeout)); // Timeout termination must not wait behind a blocked stdin write; // killing the process is what releases that write. self.fail( @@ -6802,11 +6811,19 @@ fn push_cleanup_fact( // Only a declarative language server carries a host attempt. SDK backends report // their own operations through `lithe/log`, so a stray handoff on another role is -// ignored rather than rejecting the start. +// ignored rather than rejecting the start. The handoff names its plugin, since a +// plugin API 1 server starts with no session plugin; a session another plugin +// owns never takes the attempt, so no fact lands on a plugin that did not run. fn startup_attempt(request: &StartServerRequest) -> AttemptSlot { - match (&request.startup_operation, &request.plugin_id) { - (Some(handoff), Some(plugin_id)) if request.role == SessionRole::LanguageServer => { - Attempt::slot(&LANGUAGE_SERVER_START, plugin_id.clone(), handoff.clone()) + match &request.startup_operation { + Some(handoff) + if request.role == SessionRole::LanguageServer + && request + .plugin_id + .as_ref() + .is_none_or(|owner| *owner == handoff.plugin_id) => + { + Attempt::slot(&LANGUAGE_SERVER_START, handoff.clone()) } _ => Attempt::none(), } @@ -11561,34 +11578,43 @@ mod tests { /// A declarative plugin start handed off by the host ends in exactly one Core /// result: `initialize` success, an exit before it, or nothing for a user stop. - /// Later exits belong to the session, not the start. + /// Later exits belong to the session, not the start. A plugin API 1 server + /// starts host-owned, so the handoff alone names the plugin; a session owned + /// by a different plugin records nothing. #[test] fn declarative_plugin_start_records_one_host_operation_per_attempt() { const PLUGIN: &str = "io.example.declarative-start"; - let handoff = |operation_id: &'static str| { + const OTHER: &str = "io.example.declarative-start-other"; + let handoff = |operation_id: &'static str, owner: Option<&'static str>| { move |request: &mut StartServerRequest| { - request.plugin_id = Some(PLUGIN.to_string()); + request.plugin_id = owner.map(str::to_string); request.startup_operation = Some(AttemptHandoff { + plugin_id: PLUGIN.to_string(), operation_id: operation_id.to_string(), elapsed_ms: 5, }); } }; - let mut ready = Harness::start(handoff("declarative-ready")); + let mut ready = Harness::start(handoff("declarative-ready", Some(PLUGIN))); ready.server.complete_initialize(ready_capabilities()); ready.await_state(LspLifecycleState::Ready); ready.server.exit(Some(1)); ready.await_state(LspLifecycleState::Failed); - let mut exited = Harness::start(handoff("declarative-exited")); + let mut exited = Harness::start(handoff("declarative-exited", None)); exited.server.exit(Some(2)); exited.await_state(LspLifecycleState::Failed); - let mut stopped = Harness::start(handoff("declarative-stopped")); + let mut stopped = Harness::start(handoff("declarative-stopped", Some(PLUGIN))); stopped.session().stop().unwrap(); stopped.await_state(LspLifecycleState::Stopped); + let mut foreign = Harness::start(handoff("declarative-foreign", Some(OTHER))); + foreign.server.exit(Some(3)); + foreign.await_state(LspLifecycleState::Failed); + assert!(plugin_operations::test_capture::take(OTHER).is_empty()); + let facts = plugin_operations::test_capture::take(PLUGIN); assert!(facts .iter() @@ -11609,6 +11635,57 @@ mod tests { ); } + /// startServer failing after spawn is a `launch` failure, and an initialize + /// timeout decided under the state lock is the only result even when the + /// response arrives afterwards. + #[test] + fn declarative_plugin_start_attributes_write_failure_and_timeout() { + const PLUGIN: &str = "io.example.declarative-start-failures"; + let handoff = |operation_id: &str, request: &mut StartServerRequest| { + request.plugin_id = Some(PLUGIN.to_string()); + request.startup_operation = Some(AttemptHandoff { + plugin_id: PLUGIN.to_string(), + operation_id: operation_id.to_string(), + elapsed_ms: 5, + }); + }; + + let broken = ScriptedServer::new(); + broken.break_input(); + let engine = LspEngine::with_launcher(broken.launcher()); + let mut request = start_request(&broken); + handoff("declarative-write-failed", &mut request); + assert!(engine.start_server(request).is_err()); + + let mut timed_out = Harness::start(|request| { + handoff("declarative-timed-out", request); + request.initialize_timeout_milliseconds = 60_000; + }); + timed_out + .session() + .expire_deadlines_at(Instant::now() + Duration::from_secs(61)); + timed_out.await_state(LspLifecycleState::Failed); + timed_out.server.complete_initialize(ready_capabilities()); + + let results: Vec<_> = plugin_operations::test_capture::take(PLUGIN) + .into_iter() + .map(|fact| (fact.operation_id, fact.failure)) + .collect(); + assert_eq!( + results, + [ + ( + Some("declarative-write-failed".to_string()), + Some(AttemptStage::Launch) + ), + ( + Some("declarative-timed-out".to_string()), + Some(AttemptStage::Timeout) + ), + ] + ); + } + /// Criterion 10: shutdown sends exit after the response, and a shutdown that /// is never answered force-terminates. #[test] diff --git a/shared/contracts/rust-core-api.md b/shared/contracts/rust-core-api.md index 6843fe715d..014f5f12e3 100644 --- a/shared/contracts/rust-core-api.md +++ b/shared/contracts/rust-core-api.md @@ -5611,18 +5611,35 @@ a code has one meaning across every contribution with that lifecycle: | `decode` | rejected | `host.outputInvalid` | An unknown operation, a stage the lifecycle cannot reach, an unknown key, an -invalid operation ID or an out-of-range duration all return -32064. Whoever -executes the attempt records it. The host records debug adapter starts and build -commands itself. A declarative language server is resolved by the host and -supervised by Core: the host records failures before launch and otherwise passes -`startupOperation:{operationId,elapsedMs}` on `lsp.startServer` (language server -role with `pluginId` only; ignored otherwise). Core then records exactly one -result: `launch` when `lsp.startServer` fails for any reason other than -cancellation, `exit` when the process exits before `initialize` succeeds, -`initialize` for any other terminal failure before then, `timeout` at the initialize -deadline, or `finished` when the `initialize` result succeeds. `durationMs` adds -the host's `elapsedMs` to Core's own monotonic time. Stopping before a result -records nothing. A fact the engine cannot queue increments the `dropped` counter. +explicit `null` for an optional key, an invalid operation ID or an out-of-range +duration all return -32064. Whoever executes the attempt records it. The host +records debug adapter starts and build commands itself. A debug adapter start +uses the debug session ID as `operationId`, so it correlates with that session's +own debug records. It stays at `launch` until the adapter is reachable: a stdio +process once it runs, a language server hosted adapter once its socket connects. +A failure before then is `launch`, or `timeout` when the hosted adapter's +discovery deadline fires. `exit` applies only to an adapter that was reached. +Core refusing the debug session is a host outcome and is not recorded. + +A declarative language server is resolved by the host and supervised by Core. +The host records failures before launch, including plugin API 1 servers that +launch as host-owned processes. Otherwise it passes +`startupOperation:{pluginId,operationId,elapsedMs}` on `lsp.startServer`. Core +accepts the handoff only for the language server role, and only when the +request's `pluginId` is absent or equals the handoff's `pluginId`; it ignores the +handoff otherwise. Core then records exactly one result: + +- `launch` when `lsp.startServer` fails for any reason other than cancellation, + including a failure to write the `initialize` request to the started process; +- `exit` when the process exits before `initialize` succeeds; +- `initialize` for any other terminal failure before then; +- `timeout` at the initialize deadline; +- `finished` when the `initialize` result succeeds. + +A start that a newer indexing policy retires is cancelled and records nothing, +even after its process started. `durationMs` adds the host's `elapsedMs` to Core's own monotonic +time. Stopping before a result records nothing. A fact the engine cannot queue +increments the `dropped` counter. ```json {"version":1,"command":"diagnostics.recordPluginOperation","payload":{"pluginId":"io.example.go","operation":"debugAdapter/start","outcome":"failed","stage":"resolve","durationMs":12,"operationId":"7c0d1f0e-3f6b-4a52-9d5e-0b7c2b0b9a11"}} diff --git a/shared/logging/README.md b/shared/logging/README.md index b501f9bd8e..0ed1d3b5f2 100644 --- a/shared/logging/README.md +++ b/shared/logging/README.md @@ -94,7 +94,7 @@ Swift 的事件值是**未经脱敏的内存输入**，不能自行序列化落 | operation | 声明来源 | 记录方 | 可能的失败阶段 | | --- | --- | --- | --- | | `languageServer/start` | `languageServers[]` | macOS 宿主记启动前的失败；进入启动后用 `lsp.startServer.startupOperation` 交给 Core，Core 记录唯一结果 | resolve、launch、exit、initialize、timeout | - | `debugAdapter/start` | `debugAdapters[]` | macOS 宿主 | resolve、launch、exit、initialize、timeout | + | `debugAdapter/start` | `debugAdapters[]` | macOS 宿主；op 为调试会话 ID，Core 拒绝建会话不记录 | resolve、launch、exit、initialize、timeout | | `lithe/build/model` | `buildSystems[]` 的命令式模型 | macOS 宿主；计划由插件后端提供时由 SDK 记录 | plan、resolve、launch、timeout、exit、decode | | `lithe/build/dependencies` | `buildSystems[]` 的命令式依赖树 | macOS 宿主；计划由插件后端提供时由 SDK 记录 | plan、resolve、launch、timeout、exit、decode |