From 655a93f05a39da5774098df5cbc1dae523b5ac86 Mon Sep 17 00:00:00 2001 From: Alex Hoppen Date: Fri, 28 Feb 2025 14:42:51 -0800 Subject: [PATCH] Add structure to the index logs When the client supports it, communicate the structure of tasks that were stared during background indexing or by the build server to the client. If there are multiple operations happening in parallel, this allows the client to display them in separate log tracks instead of interspersing them with the emoji prefixes like we do today. --- Contributor Documentation/LSP Extensions.md | 56 +++++- Documentation/Configuration File.md | 2 +- .../OnBuildLogMessageNotification.swift | 13 +- .../BuildSystemManager.swift | 19 +- .../BuildSystemManagerDelegate.swift | 3 + Sources/BuildSystemIntegration/CMakeLists.txt | 1 - .../SwiftPMBuildSystem.swift | 67 +++++-- .../LogMessageNotification.swift | 163 +++++++++++++++++- Sources/SKOptions/ExperimentalFeatures.swift | 3 + ...BuildSystemManagerConnectionToClient.swift | 6 +- .../PreparationTaskDescription.swift | 7 +- .../SemanticIndex/SemanticIndexManager.swift | 7 +- .../UpdateIndexStoreTaskDescription.swift | 35 ++-- Sources/SourceKitLSP/CMakeLists.txt | 1 + .../SourceKitLSP/IndexProgressManager.swift | 2 +- ...tructureUsingEmojiPrefixIfNecessary.swift} | 28 ++- .../SharedWorkDoneProgressManager.swift | 2 +- Sources/SourceKitLSP/SourceKitLSPServer.swift | 30 ++-- Sources/SourceKitLSP/Workspace.swift | 12 +- .../SwitchableProcessResultExitStatus.swift | 6 +- .../BackgroundIndexingTests.swift | 41 +++++ config.schema.json | 6 +- 22 files changed, 441 insertions(+), 69 deletions(-) rename Sources/{BuildSystemIntegration/PrefixMessageWithTaskEmoji.swift => SourceKitLSP/LogMessageNotification+representingStructureUsingEmojiPrefixIfNecessary.swift} (63%) diff --git a/Contributor Documentation/LSP Extensions.md b/Contributor Documentation/LSP Extensions.md index 19f91ab2..00b960ec 100644 --- a/Contributor Documentation/LSP Extensions.md +++ b/Contributor Documentation/LSP Extensions.md @@ -481,7 +481,7 @@ export interface DidChangeActiveDocumentParams { ## `window/logMessage` -Added field: +Added fields: ```ts /** @@ -490,6 +490,60 @@ Added field: * Clients may ignore this parameter and add the message to the global log */ logName?: string; + + +/** + * If specified, allows grouping log messages that belong to the same originating task together instead of logging + * them in chronological order in which they were produced. + * + * LSP Extension guarded by the experimental `structured-logs` feature. + */ +structure?: StructuredLogBegin | StructuredLogReport | StructuredLogEnd; +``` + +With + +```ts +/** + * Indicates the beginning of a new task that may receive updates with `StructuredLogReport` or `StructuredLogEnd` + * payloads. + */ +export interface StructuredLogBegin { + kind: 'begin' + + /** + * A succinct title that can be used to describe the task that started this structured. + */ + title: string; + + /** + * A unique identifier, identifying the task this structured log message belongs to. + */ + taskID: string; +} + + +/** + * Adds a new log message to a structured log without ending it. + */ +export interface StructuredLogReport { + /* + * A unique identifier, identifying the task this structured log message belongs to. + */ + taskID: string; +} + +/** + * Ends a structured log. No more `StructuredLogReport` updates should be sent for this task ID. + * + * The task ID may be re-used for new structured logs by beginning a new structured log for that task. + */ +export interface StructuredLogEnd { + /* + * A unique identifier, identifying the task this structured log message belongs to. + */ + taskID: string; +} ``` ## `workspace/_pollIndex` diff --git a/Documentation/Configuration File.md b/Documentation/Configuration File.md index 9dcb13d8..ac275050 100644 --- a/Documentation/Configuration File.md +++ b/Documentation/Configuration File.md @@ -53,7 +53,7 @@ The structure of the file is currently not guaranteed to be stable. Options may - `noLazy`: Prepare a target without generating object files but do not do lazy type checking and function body skipping. This uses SwiftPM's `--experimental-prepare-for-indexing-no-lazy` flag. - `enabled`: Prepare a target without generating object files. - `cancelTextDocumentRequestsOnEditAndClose: boolean`: Whether sending a `textDocument/didChange` or `textDocument/didClose` notification for a document should cancel all pending requests for that document. -- `experimentalFeatures: ("on-type-formatting"|"set-options-request"|"sourcekit-options-request"|"is-indexing-request")[]`: Experimental features that are enabled. +- `experimentalFeatures: ("on-type-formatting"|"set-options-request"|"sourcekit-options-request"|"is-indexing-request"|"structured-logs")[]`: Experimental features that are enabled. - `swiftPublishDiagnosticsDebounceDuration: number`: The time that `SwiftLanguageService` should wait after an edit before starting to compute diagnostics and sending a `PublishDiagnosticsNotification`. - `workDoneProgressDebounceDuration: number`: When a task is started that should be displayed to the client as a work done progress, how many milliseconds to wait before actually starting the work done progress. This prevents flickering of the work done progress in the client for short-lived index tasks which end within this duration. - `sourcekitdRequestTimeout: number`: The maximum duration that a sourcekitd request should be allowed to execute before being declared as timed out. In general, editors should cancel requests that they are no longer interested in, but in case editors don't cancel requests, this ensures that a long-running non-cancelled request is not blocking sourcekitd and thus most semantic functionality. In particular, VS Code does not cancel the semantic tokens request, which can cause a long-running AST build that blocks sourcekitd. diff --git a/Sources/BuildServerProtocol/Messages/OnBuildLogMessageNotification.swift b/Sources/BuildServerProtocol/Messages/OnBuildLogMessageNotification.swift index de43c64f..f5aaa45f 100644 --- a/Sources/BuildServerProtocol/Messages/OnBuildLogMessageNotification.swift +++ b/Sources/BuildServerProtocol/Messages/OnBuildLogMessageNotification.swift @@ -18,22 +18,23 @@ import LanguageServerProtocol /// The log message notification is sent from a server to a client to ask the client to log a particular message in its console. /// -/// A `build/logMessage`` notification is similar to LSP's `window/logMessage``, except for a few additions like id and originId. +/// A `build/logMessage`` notification is similar to LSP's `window/logMessage``. public struct OnBuildLogMessageNotification: NotificationType { public static let method: String = "build/logMessage" /// The message type. public var type: MessageType - /// The task id if any. - public var task: TaskId? - /// The actual message. public var message: String - public init(type: MessageType, task: TaskId? = nil, message: String) { + /// If specified, allows grouping log messages that belong to the same originating task together instead of logging + /// them in chronological order in which they were produced. + public var structure: StructuredLogKind? + + public init(type: MessageType, message: String, structure: StructuredLogKind?) { self.type = type - self.task = task self.message = message + self.structure = structure } } diff --git a/Sources/BuildSystemIntegration/BuildSystemManager.swift b/Sources/BuildSystemIntegration/BuildSystemManager.swift index 54d896ba..d4571b5b 100644 --- a/Sources/BuildSystemIntegration/BuildSystemManager.swift +++ b/Sources/BuildSystemIntegration/BuildSystemManager.swift @@ -631,15 +631,18 @@ package actor BuildSystemManager: QueueBasedMessageHandler { } private func logMessage(notification: BuildServerProtocol.OnBuildLogMessageNotification) async { - let message = - if let taskID = notification.task?.id { - prefixMessageWithTaskEmoji(taskID: taskID, message: notification.message) - } else { - notification.message - } await connectionToClient.waitUntilInitialized() - connectionToClient.send( - LanguageServerProtocol.LogMessageNotification(type: .info, message: message, logName: "SourceKit-LSP: Indexing") + let type: WindowMessageType = + switch notification.type { + case .error: .error + case .warning: .warning + case .info: .info + case .log: .log + } + connectionToClient.logMessageToIndexLog( + message: notification.message, + type: type, + structure: notification.structure ) } diff --git a/Sources/BuildSystemIntegration/BuildSystemManagerDelegate.swift b/Sources/BuildSystemIntegration/BuildSystemManagerDelegate.swift index 67931a6a..9cfcfad6 100644 --- a/Sources/BuildSystemIntegration/BuildSystemManagerDelegate.swift +++ b/Sources/BuildSystemIntegration/BuildSystemManagerDelegate.swift @@ -53,4 +53,7 @@ package protocol BuildSystemManagerConnectionToClient: Sendable, Connection { /// Start watching for file changes with the given glob patterns. func watchFiles(_ fileWatchers: [FileSystemWatcher]) async + + /// Log a message in the client's index log. + func logMessageToIndexLog(message: String, type: WindowMessageType, structure: StructuredLogKind?) } diff --git a/Sources/BuildSystemIntegration/CMakeLists.txt b/Sources/BuildSystemIntegration/CMakeLists.txt index c9185665..cd00ff1d 100644 --- a/Sources/BuildSystemIntegration/CMakeLists.txt +++ b/Sources/BuildSystemIntegration/CMakeLists.txt @@ -18,7 +18,6 @@ add_library(BuildSystemIntegration STATIC JSONCompilationDatabaseBuildSystem.swift LegacyBuildServerBuildSystem.swift MainFilesProvider.swift - PrefixMessageWithTaskEmoji.swift SplitShellCommand.swift SwiftPMBuildSystem.swift TestBuildSystem.swift) diff --git a/Sources/BuildSystemIntegration/SwiftPMBuildSystem.swift b/Sources/BuildSystemIntegration/SwiftPMBuildSystem.swift index 31c9d5e6..98e0eb01 100644 --- a/Sources/BuildSystemIntegration/SwiftPMBuildSystem.swift +++ b/Sources/BuildSystemIntegration/SwiftPMBuildSystem.swift @@ -188,9 +188,23 @@ package actor SwiftPMBuildSystem: BuiltInBuildSystem { self.testHooks = testHooks self.connectionToSourceKitLSP = connectionToSourceKitLSP + // Start an open-ended log for messages that we receive during package loading. We never end this log. + let logTaskID = "swiftpm-log-\(UUID())" + connectionToSourceKitLSP.send( + OnBuildLogMessageNotification( + type: .info, + message: "", + structure: .begin(StructuredLogBegin(title: "SwiftPM log for \(projectRoot.path)", taskID: logTaskID)) + ) + ) + self.observabilitySystem = ObservabilitySystem({ scope, diagnostic in connectionToSourceKitLSP.send( - OnBuildLogMessageNotification(type: .info, task: TaskId(id: "swiftpm-log"), message: diagnostic.description) + OnBuildLogMessageNotification( + type: .info, + message: diagnostic.description, + structure: .report(StructuredLogReport(taskID: logTaskID)) + ) ) logger.log(level: diagnostic.severity.asLogLevel, "SwiftPM log: \(diagnostic.description)") }) @@ -638,12 +652,6 @@ package actor SwiftPMBuildSystem: BuiltInBuildSystem { return VoidResponse() } - private nonisolated func logMessageToIndexLog(_ taskID: TaskId, _ message: String) { - connectionToSourceKitLSP.send( - BuildServerProtocol.OnBuildLogMessageNotification(type: .info, task: taskID, message: message) - ) - } - private func prepare(singleTarget target: BuildTargetIdentifier) async throws { if target == .forPackageManifest { // Nothing to prepare for package manifests. @@ -698,15 +706,36 @@ package actor SwiftPMBuildSystem: BuiltInBuildSystem { let start = ContinuousClock.now let taskID: TaskId = TaskId(id: "preparation-\(preparationTaskID.fetchAndIncrement())") - logMessageToIndexLog( - taskID, - """ - Preparing \(self.swiftPMTargets[target]?.name ?? target.uri.stringValue) - \(arguments.joined(separator: " ")) - """ + connectionToSourceKitLSP.send( + BuildServerProtocol.OnBuildLogMessageNotification( + type: .info, + message: "\(arguments.joined(separator: " "))", + structure: .begin( + StructuredLogBegin( + title: "Preparing \(self.swiftPMTargets[target]?.name ?? target.uri.stringValue)", + taskID: taskID.id + ) + ) + ) ) - let stdoutHandler = PipeAsStringHandler { self.logMessageToIndexLog(taskID, $0) } - let stderrHandler = PipeAsStringHandler { self.logMessageToIndexLog(taskID, $0) } + let stdoutHandler = PipeAsStringHandler { message in + self.connectionToSourceKitLSP.send( + BuildServerProtocol.OnBuildLogMessageNotification( + type: .info, + message: message, + structure: .report(StructuredLogReport(taskID: taskID.id)) + ) + ) + } + let stderrHandler = PipeAsStringHandler { message in + self.connectionToSourceKitLSP.send( + BuildServerProtocol.OnBuildLogMessageNotification( + type: .info, + message: message, + structure: .report(StructuredLogReport(taskID: taskID.id)) + ) + ) + } let result = try await Process.run( arguments: arguments, @@ -717,7 +746,13 @@ package actor SwiftPMBuildSystem: BuiltInBuildSystem { ) ) let exitStatus = result.exitStatus.exhaustivelySwitchable - logMessageToIndexLog(taskID, "Finished with \(exitStatus.description) in \(start.duration(to: .now))") + self.connectionToSourceKitLSP.send( + BuildServerProtocol.OnBuildLogMessageNotification( + type: exitStatus.isSuccess ? .info : .error, + message: "Finished with \(exitStatus.description) in \(start.duration(to: .now))", + structure: .end(StructuredLogEnd(taskID: taskID.id)) + ) + ) switch exitStatus { case .terminated(code: 0): break diff --git a/Sources/LanguageServerProtocol/Notifications/LogMessageNotification.swift b/Sources/LanguageServerProtocol/Notifications/LogMessageNotification.swift index 0e3deebb..eee2f466 100644 --- a/Sources/LanguageServerProtocol/Notifications/LogMessageNotification.swift +++ b/Sources/LanguageServerProtocol/Notifications/LogMessageNotification.swift @@ -30,9 +30,170 @@ public struct LogMessageNotification: NotificationType, Hashable { /// **(LSP Extension)** public var logName: String? - public init(type: WindowMessageType, message: String, logName: String?) { + /// If specified, allows grouping log messages that belong to the same originating task together, instead of logging + /// them in chronological order in which they were produced. + /// + /// **(LSP Extension)** guarded by the experimental `structured-logs` feature. + public var structure: StructuredLogKind? + + public init(type: WindowMessageType, message: String, logName: String? = nil, structure: StructuredLogKind? = nil) { self.type = type self.message = message self.logName = logName + self.structure = structure + } +} + +public enum StructuredLogKind: Codable, Hashable, Sendable { + case begin(StructuredLogBegin) + case report(StructuredLogReport) + case end(StructuredLogEnd) + + public var taskID: String { + switch self { + case .begin(let begin): return begin.taskID + case .report(let report): return report.taskID + case .end(let end): return end.taskID + } + } + + public init(from decoder: Decoder) throws { + if let begin = try? StructuredLogBegin(from: decoder) { + self = .begin(begin) + } else if let report = try? StructuredLogReport(from: decoder) { + self = .report(report) + } else if let end = try? StructuredLogEnd(from: decoder) { + self = .end(end) + } else { + let context = DecodingError.Context( + codingPath: decoder.codingPath, + debugDescription: "Expected StructuredLogBegin, StructuredLogReport, or StructuredLogEnd" + ) + throw DecodingError.dataCorrupted(context) + } + } + + public func encode(to encoder: Encoder) throws { + switch self { + case .begin(let begin): + try begin.encode(to: encoder) + case .report(let report): + try report.encode(to: encoder) + case .end(let end): + try end.encode(to: encoder) + } + } +} + +/// Indicates the beginning of a new task that may receive updates with `StructuredLogReport` or `StructuredLogEnd` +/// payloads. +public struct StructuredLogBegin: Codable, Hashable, Sendable { + /// A succinct title that can be used to describe the task that started this structured. + public var title: String + + /// A unique identifier, identifying the task this structured log message belongs to. + public var taskID: String + + private enum CodingKeys: CodingKey { + case kind + case title + case taskID + } + + public init(title: String, taskID: String) { + self.title = title + self.taskID = taskID + } + + public init(from decoder: any Decoder) throws { + let container = try decoder.container(keyedBy: CodingKeys.self) + guard try container.decode(String.self, forKey: .kind) == "begin" else { + throw DecodingError.dataCorruptedError( + forKey: .kind, + in: container, + debugDescription: "Kind of StructuredLogBegin is not 'begin'" + ) + } + + self.title = try container.decode(String.self, forKey: .title) + self.taskID = try container.decode(String.self, forKey: .taskID) + + } + + public func encode(to encoder: any Encoder) throws { + var container = encoder.container(keyedBy: CodingKeys.self) + try container.encode("begin", forKey: .kind) + try container.encode(self.title, forKey: .title) + try container.encode(self.taskID, forKey: .taskID) + } +} + +/// Adds a new log message to a structured log without ending it. +public struct StructuredLogReport: Codable, Hashable, Sendable { + /// A unique identifier, identifying the task this structured log message belongs to. + public var taskID: String + + private enum CodingKeys: CodingKey { + case kind + case taskID + } + + public init(taskID: String) { + self.taskID = taskID + } + + public init(from decoder: any Decoder) throws { + let container = try decoder.container(keyedBy: CodingKeys.self) + guard try container.decode(String.self, forKey: .kind) == "report" else { + throw DecodingError.dataCorruptedError( + forKey: .kind, + in: container, + debugDescription: "Kind of StructuredLogReport is not 'report'" + ) + } + + self.taskID = try container.decode(String.self, forKey: .taskID) + } + + public func encode(to encoder: any Encoder) throws { + var container = encoder.container(keyedBy: CodingKeys.self) + try container.encode("report", forKey: .kind) + try container.encode(self.taskID, forKey: .taskID) + } +} + +/// Ends a structured log. No more `StructuredLogReport` updates should be sent for this task ID. +/// +/// The task ID may be re-used for new structured logs by beginning a new structured log for that task. +public struct StructuredLogEnd: Codable, Hashable, Sendable { + /// A unique identifier, identifying the task this structured log message belongs to. + public var taskID: String + + private enum CodingKeys: CodingKey { + case kind + case taskID + } + + public init(taskID: String) { + self.taskID = taskID + } + + public init(from decoder: any Decoder) throws { + let container = try decoder.container(keyedBy: CodingKeys.self) + guard try container.decode(String.self, forKey: .kind) == "end" else { + throw DecodingError.dataCorruptedError( + forKey: .kind, + in: container, + debugDescription: "Kind of StructuredLogEnd is not 'end'" + ) + } + + self.taskID = try container.decode(String.self, forKey: .taskID) + } + + public func encode(to encoder: any Encoder) throws { + var container = encoder.container(keyedBy: CodingKeys.self) + try container.encode("end", forKey: .kind) + try container.encode(self.taskID, forKey: .taskID) } } diff --git a/Sources/SKOptions/ExperimentalFeatures.swift b/Sources/SKOptions/ExperimentalFeatures.swift index 3e870863..5af5abff 100644 --- a/Sources/SKOptions/ExperimentalFeatures.swift +++ b/Sources/SKOptions/ExperimentalFeatures.swift @@ -25,4 +25,7 @@ public enum ExperimentalFeature: String, Codable, Sendable, CaseIterable { /// Enable the `sourceKit/_isIndexing` request. case isIndexingRequest = "is-indexing-request" + + /// Indicate that the client can handle the experimental `structure` field in the `window/logMessage` notification. + case structuredLogs = "structured-logs" } diff --git a/Sources/SKTestSupport/DummyBuildSystemManagerConnectionToClient.swift b/Sources/SKTestSupport/DummyBuildSystemManagerConnectionToClient.swift index 2014d554..d1e770d5 100644 --- a/Sources/SKTestSupport/DummyBuildSystemManagerConnectionToClient.swift +++ b/Sources/SKTestSupport/DummyBuildSystemManagerConnectionToClient.swift @@ -27,7 +27,7 @@ package struct DummyBuildSystemManagerConnectionToClient: BuildSystemManagerConn package func waitUntilInitialized() async {} - package func send(_ notification: some LanguageServerProtocol.NotificationType) {} + package func send(_ notification: some NotificationType) {} package func nextRequestID() -> RequestID { return .string(UUID().uuidString) @@ -41,5 +41,7 @@ package struct DummyBuildSystemManagerConnectionToClient: BuildSystemManagerConn reply(.failure(ResponseError.unknown("Not implemented"))) } - package func watchFiles(_ fileWatchers: [LanguageServerProtocol.FileSystemWatcher]) async {} + package func watchFiles(_ fileWatchers: [FileSystemWatcher]) async {} + + func logMessageToIndexLog(message: String, type: WindowMessageType, structure: StructuredLogKind?) {} } diff --git a/Sources/SemanticIndex/PreparationTaskDescription.swift b/Sources/SemanticIndex/PreparationTaskDescription.swift index 397ff3e0..08014328 100644 --- a/Sources/SemanticIndex/PreparationTaskDescription.swift +++ b/Sources/SemanticIndex/PreparationTaskDescription.swift @@ -53,7 +53,8 @@ package struct PreparationTaskDescription: IndexTaskDescription { private let preparationUpToDateTracker: UpToDateTracker /// See `SemanticIndexManager.logMessageToIndexLog`. - private let logMessageToIndexLog: @Sendable (_ taskID: String, _ message: String) -> Void + private let logMessageToIndexLog: + @Sendable (_ message: String, _ type: WindowMessageType, _ structure: StructuredLogKind) -> Void /// Hooks that should be called when the preparation task finishes. private let hooks: IndexHooks @@ -75,7 +76,9 @@ package struct PreparationTaskDescription: IndexTaskDescription { targetsToPrepare: [BuildTargetIdentifier], buildSystemManager: BuildSystemManager, preparationUpToDateTracker: UpToDateTracker, - logMessageToIndexLog: @escaping @Sendable (_ taskID: String, _ message: String) -> Void, + logMessageToIndexLog: @escaping @Sendable ( + _ message: String, _ type: WindowMessageType, _ structure: StructuredLogKind + ) -> Void, hooks: IndexHooks ) { self.targetsToPrepare = targetsToPrepare diff --git a/Sources/SemanticIndex/SemanticIndexManager.swift b/Sources/SemanticIndex/SemanticIndexManager.swift index d86e405f..36833b62 100644 --- a/Sources/SemanticIndex/SemanticIndexManager.swift +++ b/Sources/SemanticIndex/SemanticIndexManager.swift @@ -217,7 +217,8 @@ package final actor SemanticIndexManager { private let indexTaskScheduler: TaskScheduler /// Callback that is called when an indexing task produces output it wants to log to the index log. - private let logMessageToIndexLog: @Sendable (_ taskID: String, _ message: String) -> Void + private let logMessageToIndexLog: + @Sendable (_ message: String, _ type: WindowMessageType, _ structure: StructuredLogKind) -> Void /// Called when files are scheduled to be indexed. /// @@ -260,7 +261,9 @@ package final actor SemanticIndexManager { updateIndexStoreTimeout: Duration, hooks: IndexHooks, indexTaskScheduler: TaskScheduler, - logMessageToIndexLog: @escaping @Sendable (_ taskID: String, _ message: String) -> Void, + logMessageToIndexLog: @escaping @Sendable ( + _ message: String, _ type: WindowMessageType, _ structure: StructuredLogKind + ) -> Void, indexTasksWereScheduled: @escaping @Sendable (Int) -> Void, indexProgressStatusDidChange: @escaping @Sendable () -> Void ) { diff --git a/Sources/SemanticIndex/UpdateIndexStoreTaskDescription.swift b/Sources/SemanticIndex/UpdateIndexStoreTaskDescription.swift index 6402d872..b53b2ae9 100644 --- a/Sources/SemanticIndex/UpdateIndexStoreTaskDescription.swift +++ b/Sources/SemanticIndex/UpdateIndexStoreTaskDescription.swift @@ -122,7 +122,8 @@ package struct UpdateIndexStoreTaskDescription: IndexTaskDescription { private let indexFilesWithUpToDateUnit: Bool /// See `SemanticIndexManager.logMessageToIndexLog`. - private let logMessageToIndexLog: @Sendable (_ taskID: String, _ message: String) -> Void + private let logMessageToIndexLog: + @Sendable (_ message: String, _ type: WindowMessageType, _ structure: StructuredLogKind) -> Void /// How long to wait until we cancel an update indexstore task. This timeout should be long enough that all /// `swift-frontend` tasks finish within it. It prevents us from blocking the index if the type checker gets stuck on @@ -155,7 +156,9 @@ package struct UpdateIndexStoreTaskDescription: IndexTaskDescription { index: UncheckedIndex, indexStoreUpToDateTracker: UpToDateTracker, indexFilesWithUpToDateUnit: Bool, - logMessageToIndexLog: @escaping @Sendable (_ taskID: String, _ message: String) -> Void, + logMessageToIndexLog: @escaping @Sendable ( + _ message: String, _ type: WindowMessageType, _ structure: StructuredLogKind + ) -> Void, timeout: Duration, hooks: IndexHooks ) { @@ -402,15 +405,17 @@ package struct UpdateIndexStoreTaskDescription: IndexTaskDescription { } let taskId = "indexing-\(id)" logMessageToIndexLog( - taskId, - """ - Indexing \(indexFile.pseudoPath) - \(processArguments.joined(separator: " ")) - """ + processArguments.joined(separator: " "), + .info, + .begin(StructuredLogBegin(title: "Indexing \(indexFile.pseudoPath)", taskID: taskId)) ) - let stdoutHandler = PipeAsStringHandler { logMessageToIndexLog(taskId, $0) } - let stderrHandler = PipeAsStringHandler { logMessageToIndexLog(taskId, $0) } + let stdoutHandler = PipeAsStringHandler { + logMessageToIndexLog($0, .info, .report(StructuredLogReport(taskID: taskId))) + } + let stderrHandler = PipeAsStringHandler { + logMessageToIndexLog($0, .info, .report(StructuredLogReport(taskID: taskId))) + } let result: ProcessResult do { @@ -425,11 +430,19 @@ package struct UpdateIndexStoreTaskDescription: IndexTaskDescription { ) } } catch { - logMessageToIndexLog(taskId, "Finished error in \(start.duration(to: .now)): \(error)") + logMessageToIndexLog( + "Finished with error in \(start.duration(to: .now)): \(error)", + .error, + .end(StructuredLogEnd(taskID: taskId)) + ) throw error } let exitStatus = result.exitStatus.exhaustivelySwitchable - logMessageToIndexLog(taskId, "Finished with \(exitStatus.description) in \(start.duration(to: .now))") + logMessageToIndexLog( + "Finished with \(exitStatus.description) in \(start.duration(to: .now))", + exitStatus.isSuccess ? .info : .error, + .end(StructuredLogEnd(taskID: taskId)) + ) switch exitStatus { case .terminated(code: 0): break diff --git a/Sources/SourceKitLSP/CMakeLists.txt b/Sources/SourceKitLSP/CMakeLists.txt index 487b988f..cbe4241d 100644 --- a/Sources/SourceKitLSP/CMakeLists.txt +++ b/Sources/SourceKitLSP/CMakeLists.txt @@ -8,6 +8,7 @@ add_library(SourceKitLSP STATIC IndexStoreDB+MainFilesProvider.swift LanguageServerType.swift LanguageService.swift + LogMessageNotification+representingStructureUsingEmojiPrefixIfNecessary.swift MessageHandlingDependencyTracker.swift Rename.swift SemanticTokensLegend+SourceKitLSPLegend.swift diff --git a/Sources/SourceKitLSP/IndexProgressManager.swift b/Sources/SourceKitLSP/IndexProgressManager.swift index 19356f45..b03c796a 100644 --- a/Sources/SourceKitLSP/IndexProgressManager.swift +++ b/Sources/SourceKitLSP/IndexProgressManager.swift @@ -125,7 +125,7 @@ actor IndexProgressManager { if let workDoneProgress { await workDoneProgress.update(message: message, percentage: percentage) } else { - workDoneProgress = await WorkDoneProgressManager( + workDoneProgress = WorkDoneProgressManager( server: sourceKitLSPServer, capabilityRegistry: await sourceKitLSPServer.capabilityRegistry, tokenPrefix: "indexing", diff --git a/Sources/BuildSystemIntegration/PrefixMessageWithTaskEmoji.swift b/Sources/SourceKitLSP/LogMessageNotification+representingStructureUsingEmojiPrefixIfNecessary.swift similarity index 63% rename from Sources/BuildSystemIntegration/PrefixMessageWithTaskEmoji.swift rename to Sources/SourceKitLSP/LogMessageNotification+representingStructureUsingEmojiPrefixIfNecessary.swift index fd21c3db..0fa20b78 100644 --- a/Sources/BuildSystemIntegration/PrefixMessageWithTaskEmoji.swift +++ b/Sources/SourceKitLSP/LogMessageNotification+representingStructureUsingEmojiPrefixIfNecessary.swift @@ -10,6 +10,9 @@ // //===----------------------------------------------------------------------===// +import LanguageServerProtocol +import SKOptions + import struct TSCBasic.ProcessResult private func numberToEmojis(_ number: Int, numEmojis: Int) -> String { @@ -35,7 +38,7 @@ fileprivate extension String { } /// Add an emoji hash of the given `taskID` to the start of every line in `message`. -package func prefixMessageWithTaskEmoji(taskID: String, message: String) -> String { +private func prefixMessageWithTaskEmoji(taskID: String, message: String) -> String { var message: Substring = message[...] while message.last?.isNewline ?? false { message = message.dropLast(1) @@ -45,3 +48,26 @@ package func prefixMessageWithTaskEmoji(taskID: String, message: String) -> Stri }.joined(separator: "\n") return messageWithEmojiLinePrefixes } + +extension LogMessageNotification { + /// If the client does not support the experimental structured logs capability and the `LogMessageNotification` + /// contains structure, clear it and instead prefix the message with a an emoji sequence that indicates the task it + /// belongs to. + func representingTaskIDUsingEmojiPrefixIfNecessary( + options: SourceKitLSPOptions + ) -> LogMessageNotification { + if options.hasExperimentalFeature(.structuredLogs) { + // Client supports structured logs, nothing to do. + return self + } + var transformed = self + if let structure = transformed.structure { + if case .begin(let begin) = structure { + transformed.message = "\(begin.title)\n\(message)" + } + transformed.message = prefixMessageWithTaskEmoji(taskID: structure.taskID, message: transformed.message) + transformed.structure = nil + } + return transformed + } +} diff --git a/Sources/SourceKitLSP/SharedWorkDoneProgressManager.swift b/Sources/SourceKitLSP/SharedWorkDoneProgressManager.swift index e541ff0d..2c586fc1 100644 --- a/Sources/SourceKitLSP/SharedWorkDoneProgressManager.swift +++ b/Sources/SourceKitLSP/SharedWorkDoneProgressManager.swift @@ -76,7 +76,7 @@ actor SharedWorkDoneProgressManager { } // Do all asynchronous operations up-front so that incrementing `inProgressOperations` and setting `workDoneProgress` // cannot be interrupted by an `await` call - let initialDebounceDuration = await sourceKitLSPServer.options.workDoneProgressDebounceDurationOrDefault + let initialDebounceDuration = sourceKitLSPServer.options.workDoneProgressDebounceDurationOrDefault let capabilityRegistry = await sourceKitLSPServer.capabilityRegistry inProgressOperations += 1 diff --git a/Sources/SourceKitLSP/SourceKitLSPServer.swift b/Sources/SourceKitLSP/SourceKitLSPServer.swift index 59a7c572..d0263e14 100644 --- a/Sources/SourceKitLSP/SourceKitLSPServer.swift +++ b/Sources/SourceKitLSP/SourceKitLSPServer.swift @@ -80,7 +80,10 @@ package actor SourceKitLSPServer { /// Initialization can be awaited using `waitUntilInitialized`. private var initialized: Bool = false - var options: SourceKitLSPOptions + private let _options: ThreadSafeBox + nonisolated var options: SourceKitLSPOptions { + _options.value + } let hooks: Hooks @@ -188,7 +191,7 @@ package actor SourceKitLSPServer { onExit: @escaping () -> Void = {} ) { self.toolchainRegistry = toolchainRegistry - self.options = options + self._options = ThreadSafeBox(initialValue: options) self.hooks = hooks self.onExit = onExit @@ -862,13 +865,18 @@ extension SourceKitLSPServer: QueueBasedMessageHandler { } extension SourceKitLSPServer { - nonisolated package func logMessageToIndexLog(taskID: String, message: String) { + nonisolated package func logMessageToIndexLog( + message: String, + type: WindowMessageType, + structure: StructuredLogKind? + ) { self.sendNotificationToClient( LogMessageNotification( - type: .info, - message: prefixMessageWithTaskEmoji(taskID: taskID, message: message), - logName: "SourceKit-LSP: Indexing" - ) + type: type, + message: message, + logName: "SourceKit-LSP: Indexing", + structure: structure + ).representingTaskIDUsingEmojiPrefixIfNecessary(options: options) ) } @@ -985,10 +993,10 @@ extension SourceKitLSPServer { capabilityRegistry = CapabilityRegistry(clientCapabilities: clientCapabilities) - self.options = SourceKitLSPOptions.merging( - base: self.options, - override: orLog("Parsing SourceKitLSPOptions", { try SourceKitLSPOptions(fromLSPAny: req.initializationOptions) }) - ) + let initializeOptions = orLog("Parsing options") { try SourceKitLSPOptions(fromLSPAny: req.initializationOptions) } + _options.withLock { options in + options = SourceKitLSPOptions.merging(base: options, override: initializeOptions) + } logger.log("Initialized SourceKit-LSP") logger.logFullObjectInMultipleLogMessages(header: "SourceKit-LSP Options", options.loggingProxy) diff --git a/Sources/SourceKitLSP/Workspace.swift b/Sources/SourceKitLSP/Workspace.swift index f2148c2f..6adf4162 100644 --- a/Sources/SourceKitLSP/Workspace.swift +++ b/Sources/SourceKitLSP/Workspace.swift @@ -168,7 +168,7 @@ package final class Workspace: Sendable, BuildSystemManagerDelegate { hooks: hooks.indexHooks, indexTaskScheduler: indexTaskScheduler, logMessageToIndexLog: { [weak sourceKitLSPServer] in - sourceKitLSPServer?.logMessageToIndexLog(taskID: $0, message: $1) + sourceKitLSPServer?.logMessageToIndexLog(message: $0, type: $1, structure: $2) }, indexTasksWereScheduled: { [weak sourceKitLSPServer] in sourceKitLSPServer?.indexProgressManager.indexTasksWereScheduled(count: $0) @@ -261,6 +261,16 @@ package final class Workspace: Sendable, BuildSystemManagerDelegate { func watchFiles(_ fileWatchers: [FileSystemWatcher]) async { await sourceKitLSPServer?.watchFiles(fileWatchers) } + + func logMessageToIndexLog(message: String, type: WindowMessageType, structure: StructuredLogKind?) { + guard let sourceKitLSPServer else { + // `SourceKitLSPServer` has been destructed. We are tearing down the + // language server. Nothing left to do. + logger.error("Ignoring index log notification because connection to editor has been closed") + return + } + sourceKitLSPServer.logMessageToIndexLog(message: message, type: type, structure: structure) + } } let buildSystemManager = await BuildSystemManager( diff --git a/Sources/TSCExtensions/SwitchableProcessResultExitStatus.swift b/Sources/TSCExtensions/SwitchableProcessResultExitStatus.swift index c3a55f0a..900d75d3 100644 --- a/Sources/TSCExtensions/SwitchableProcessResultExitStatus.swift +++ b/Sources/TSCExtensions/SwitchableProcessResultExitStatus.swift @@ -14,7 +14,7 @@ import struct TSCBasic.ProcessResult /// Same as `ProcessResult.ExitStatus` in tools-support-core but has the same cases on all platforms and is thus easier /// to switch over -package enum SwitchableProcessResultExitStatus { +package enum SwitchableProcessResultExitStatus: Equatable { /// The process was terminated normally with a exit code. case terminated(code: Int32) /// The process was terminated abnormally. @@ -33,6 +33,10 @@ package enum SwitchableProcessResultExitStatus { "signal \(signal)" } } + + package var isSuccess: Bool { + return self == .terminated(code: 0) + } } extension ProcessResult.ExitStatus { diff --git a/Tests/SourceKitLSPTests/BackgroundIndexingTests.swift b/Tests/SourceKitLSPTests/BackgroundIndexingTests.swift index abcf4e67..85ed6766 100644 --- a/Tests/SourceKitLSPTests/BackgroundIndexingTests.swift +++ b/Tests/SourceKitLSPTests/BackgroundIndexingTests.swift @@ -770,6 +770,47 @@ final class BackgroundIndexingTests: XCTestCase { try updateIndexStoreTaskDidFinish.waitOrThrow() } + func testProduceIndexLogWithTaskID() async throws { + let project = try await SwiftPMTestProject( + files: ["MyFile.swift": ""], + options: .testDefault(experimentalFeatures: [.structuredLogs]), + enableBackgroundIndexing: true, + pollIndex: false + ) + + var inProgressMessagesByTaskID: [String: String] = [:] + var finishedMessagesByTaskID: [String: String] = [:] + while true { + let notification = try await project.testClient.nextNotification( + ofType: LogMessageNotification.self, + satisfying: { $0.logName == "SourceKit-LSP: Indexing" } + ) + switch notification.structure { + case .begin(let begin): + XCTAssertNil(inProgressMessagesByTaskID[begin.taskID]) + inProgressMessagesByTaskID[begin.taskID] = begin.title + "\n" + notification.message + "\n" + case .report(let report): + XCTAssertNotNil(inProgressMessagesByTaskID[report.taskID]) + inProgressMessagesByTaskID[report.taskID]?.append(notification.message + "\n") + case .end(let end): + finishedMessagesByTaskID[end.taskID] = + try XCTUnwrap(inProgressMessagesByTaskID[end.taskID]) + notification.message + inProgressMessagesByTaskID[end.taskID] = nil + case nil: + break + } + + if let indexingTask = finishedMessagesByTaskID.values.first(where: { $0.contains("Indexing ") }), + let prepareTask = finishedMessagesByTaskID.values.first(where: { $0.contains("Preparing ") }), + indexingTask.contains("Finished"), + prepareTask.contains("Finished") + { + // We have two finished tasks, one for preparation, one for indexing, which is what we expect. + break + } + } + } + func testIndexingHappensInParallel() async throws { let fileAIndexingStarted = WrappedSemaphore(name: "FileA indexing started") let fileBIndexingStarted = WrappedSemaphore(name: "FileB indexing started") diff --git a/config.schema.json b/config.schema.json index 1b7e76e7..d115373c 100644 --- a/config.schema.json +++ b/config.schema.json @@ -72,13 +72,15 @@ "on-type-formatting", "set-options-request", "sourcekit-options-request", - "is-indexing-request" + "is-indexing-request", + "structured-logs" ], "markdownEnumDescriptions" : [ "Enable support for the `textDocument/onTypeFormatting` request.", "Enable support for the `workspace/_setOptions` request.", "Enable the `workspace/_sourceKitOptions` request.", - "Enable the `sourceKit/_isIndexing` request." + "Enable the `sourceKit/_isIndexing` request.", + "Indicate that the client can handle the experimental `structure` field in the `window/logMessage` notification." ], "type" : "string" },