From 09ad77ba8d57947350855ec40c8d30ff4b91307d Mon Sep 17 00:00:00 2001 From: Alex Hoppen Date: Fri, 31 May 2024 09:51:15 -0700 Subject: [PATCH] Instead of sending a message to the index log when an indexing task finishes, stream results as they come in This also means that you can use the index log to view which tasks are currently being executed. Since we only have a single log stream we can write to, I decided to prefix every line in the index log with two colored emojis that an easy visual association of every log line to the task that generated them. --- Sources/CAtomics/include/CAtomics.h | 2 +- Sources/SKCore/BuildServerBuildSystem.swift | 2 +- Sources/SKCore/BuildSystem.swift | 2 +- Sources/SKCore/BuildSystemManager.swift | 4 +- Sources/SKCore/CMakeLists.txt | 2 +- .../CompilationDatabaseBuildSystem.swift | 2 +- Sources/SKCore/IndexProcessResult.swift | 71 ------------------- Sources/SKCore/IndexTaskID.swift | 46 ++++++++++++ Sources/SKSupport/CMakeLists.txt | 1 + Sources/SKSupport/PipeAsStringHandler.swift | 49 +++++++++++++ ...LaunchWithWorkingDirectoryIfPossible.swift | 4 ++ .../SwiftPMBuildSystem.swift | 38 +++++++--- .../TestSourceKitLSPClient.swift | 4 +- .../PreparationTaskDescription.swift | 10 +-- .../SemanticIndex/SemanticIndexManager.swift | 15 ++-- .../UpdateIndexStoreTaskDescription.swift | 34 +++++---- .../Clang/ClangLanguageService.swift | 35 ++------- Sources/SourceKitLSP/SourceKitLSPServer.swift | 25 ++++--- Sources/SourceKitLSP/Workspace.swift | 8 +-- .../SKCoreTests/BuildSystemManagerTests.swift | 2 +- .../BackgroundIndexingTests.swift | 40 ++++++++--- .../SourceKitLSPTests/BuildSystemTests.swift | 4 +- 22 files changed, 226 insertions(+), 174 deletions(-) delete mode 100644 Sources/SKCore/IndexProcessResult.swift create mode 100644 Sources/SKCore/IndexTaskID.swift create mode 100644 Sources/SKSupport/PipeAsStringHandler.swift diff --git a/Sources/CAtomics/include/CAtomics.h b/Sources/CAtomics/include/CAtomics.h index a5d27364..16b797a5 100644 --- a/Sources/CAtomics/include/CAtomics.h +++ b/Sources/CAtomics/include/CAtomics.h @@ -70,7 +70,7 @@ typedef struct { } AtomicUInt32; __attribute__((swift_name("AtomicUInt32.init(initialValue:)"))) -static inline AtomicUInt32 atomic_int_create(uint8_t initialValue) { +static inline AtomicUInt32 atomic_int_create(uint32_t initialValue) { AtomicUInt32 atomic; atomic.value = initialValue; return atomic; diff --git a/Sources/SKCore/BuildServerBuildSystem.swift b/Sources/SKCore/BuildServerBuildSystem.swift index 5f19066a..5fa36777 100644 --- a/Sources/SKCore/BuildServerBuildSystem.swift +++ b/Sources/SKCore/BuildServerBuildSystem.swift @@ -293,7 +293,7 @@ extension BuildServerBuildSystem: BuildSystem { public func prepare( targets: [ConfiguredTarget], - indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void + logMessageToIndexLog: @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void ) async throws { throw PrepareNotSupportedError() } diff --git a/Sources/SKCore/BuildSystem.swift b/Sources/SKCore/BuildSystem.swift index 204dbefc..f409c1ab 100644 --- a/Sources/SKCore/BuildSystem.swift +++ b/Sources/SKCore/BuildSystem.swift @@ -169,7 +169,7 @@ public protocol BuildSystem: AnyObject, Sendable { /// dependencies. func prepare( targets: [ConfiguredTarget], - indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void + logMessageToIndexLog: @escaping @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void ) async throws /// If the build system has knowledge about the language that this document should be compiled in, return it. diff --git a/Sources/SKCore/BuildSystemManager.swift b/Sources/SKCore/BuildSystemManager.swift index 134453ed..415e98fc 100644 --- a/Sources/SKCore/BuildSystemManager.swift +++ b/Sources/SKCore/BuildSystemManager.swift @@ -237,9 +237,9 @@ extension BuildSystemManager { public func prepare( targets: [ConfiguredTarget], - indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void + logMessageToIndexLog: @escaping @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void ) async throws { - try await buildSystem?.prepare(targets: targets, indexProcessDidProduceResult: indexProcessDidProduceResult) + try await buildSystem?.prepare(targets: targets, logMessageToIndexLog: logMessageToIndexLog) } public func registerForChangeNotifications(for uri: DocumentURI, language: Language) async { diff --git a/Sources/SKCore/CMakeLists.txt b/Sources/SKCore/CMakeLists.txt index 913e1e08..a0653fa6 100644 --- a/Sources/SKCore/CMakeLists.txt +++ b/Sources/SKCore/CMakeLists.txt @@ -10,7 +10,7 @@ add_library(SKCore STATIC Debouncer.swift FallbackBuildSystem.swift FileBuildSettings.swift - IndexProcessResult.swift + IndexTaskID.swift MainFilesProvider.swift PathPrefixMapping.swift SplitShellCommand.swift diff --git a/Sources/SKCore/CompilationDatabaseBuildSystem.swift b/Sources/SKCore/CompilationDatabaseBuildSystem.swift index d601bd09..c906336b 100644 --- a/Sources/SKCore/CompilationDatabaseBuildSystem.swift +++ b/Sources/SKCore/CompilationDatabaseBuildSystem.swift @@ -129,7 +129,7 @@ extension CompilationDatabaseBuildSystem: BuildSystem { public func prepare( targets: [ConfiguredTarget], - indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void + logMessageToIndexLog: @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void ) async throws { throw PrepareNotSupportedError() } diff --git a/Sources/SKCore/IndexProcessResult.swift b/Sources/SKCore/IndexProcessResult.swift deleted file mode 100644 index 07b71c7c..00000000 --- a/Sources/SKCore/IndexProcessResult.swift +++ /dev/null @@ -1,71 +0,0 @@ -//===----------------------------------------------------------------------===// -// -// This source file is part of the Swift.org open source project -// -// Copyright (c) 2014 - 2020 Apple Inc. and the Swift project authors -// Licensed under Apache License v2.0 with Runtime Library Exception -// -// See https://swift.org/LICENSE.txt for license information -// See https://swift.org/CONTRIBUTORS.txt for the list of Swift project authors -// -//===----------------------------------------------------------------------===// - -import struct TSCBasic.ProcessResult - -/// Result of a process that prepares a target or updates the index store. To be shown in the build log. -/// -/// Abstracted over a `ProcessResult` to facilitate build systems that don't spawn a new process to prepare a target but -/// prepare it from a build graph they have loaded in-process. -public struct IndexProcessResult { - /// A human-readable description of what the process was trying to achieve, like `Preparing MyTarget` - public let taskDescription: String - - /// The command that was run to produce the result. - public let command: String - - /// The output that the process produced. - public let output: String - - /// Whether the process failed. - public let failed: Bool - - /// The duration it took for the process to execute. - public let duration: Duration - - public init(taskDescription: String, command: String, output: String, failed: Bool, duration: Duration) { - self.taskDescription = taskDescription - self.command = command - self.output = output - self.failed = failed - self.duration = duration - } - - public init(taskDescription: String, processResult: ProcessResult, start: ContinuousClock.Instant) { - let stdout = (try? String(bytes: processResult.output.get(), encoding: .utf8)) ?? "" - let stderr = (try? String(bytes: processResult.stderrOutput.get(), encoding: .utf8)) ?? "" - var outputComponents: [String] = [] - if !stdout.isEmpty { - outputComponents.append( - """ - Stdout: - \(stdout) - """ - ) - } - if !stderr.isEmpty { - outputComponents.append( - """ - Stderr: - \(stderr) - """ - ) - } - self.init( - taskDescription: taskDescription, - command: processResult.arguments.joined(separator: " "), - output: outputComponents.joined(separator: "\n\n"), - failed: processResult.exitStatus != .terminated(code: 0), - duration: start.duration(to: .now) - ) - } -} diff --git a/Sources/SKCore/IndexTaskID.swift b/Sources/SKCore/IndexTaskID.swift new file mode 100644 index 00000000..4ca4564b --- /dev/null +++ b/Sources/SKCore/IndexTaskID.swift @@ -0,0 +1,46 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift.org open source project +// +// Copyright (c) 2014 - 2020 Apple Inc. and the Swift project authors +// Licensed under Apache License v2.0 with Runtime Library Exception +// +// See https://swift.org/LICENSE.txt for license information +// See https://swift.org/CONTRIBUTORS.txt for the list of Swift project authors +// +//===----------------------------------------------------------------------===// + +import struct TSCBasic.ProcessResult + +/// The ID of a preparation or update indexstore task. This allows us to log messages from multiple concurrently running +/// indexing tasks to the index log while still being able to differentiate them. +public enum IndexTaskID: Sendable { + case preparation(id: UInt32) + case updateIndexStore(id: UInt32) + + private static func numberToEmojis(_ number: Int, numEmojis: Int) -> String { + let emojis = ["🟥", "🟩", "🟦", "🟧", "⬜️", "🟪", "⬛️", "🟨", "🟫"] + var number = abs(number) + var result = "" + for _ in 0..() + private var buffer = Data() + + /// The closure that actually handles + private let handler: @Sendable (String) -> Void + + public init(handler: @escaping @Sendable (String) -> Void) { + self.handler = handler + } + + private func handleDataFromPipeImpl(_ newData: Data) { + self.buffer += newData + while let newlineIndex = self.buffer.firstIndex(of: UInt8(ascii: "\n")) { + // Output a separate log message for every line in the pipe. + // The reason why we don't output multiple lines in a single log message is that + // a) os_log truncates log messages at about 1000 bytes. The assumption is that a single line is usually less + // than 1000 bytes long but if we merge multiple lines into one message, we might easily exceed this limit. + // b) It might be confusing why sometimes a single log message contains one line while sometimes it contains + // multiple. + handler(String(data: self.buffer[...newlineIndex], encoding: .utf8) ?? "") + buffer = buffer[buffer.index(after: newlineIndex)...] + } + } + + public nonisolated func handleDataFromPipe(_ newData: Data) { + queue.async { + await self.handleDataFromPipeImpl(newData) + } + } +} diff --git a/Sources/SKSupport/Process+LaunchWithWorkingDirectoryIfPossible.swift b/Sources/SKSupport/Process+LaunchWithWorkingDirectoryIfPossible.swift index f57f905a..45e51305 100644 --- a/Sources/SKSupport/Process+LaunchWithWorkingDirectoryIfPossible.swift +++ b/Sources/SKSupport/Process+LaunchWithWorkingDirectoryIfPossible.swift @@ -26,6 +26,7 @@ extension Process { arguments: [String], environmentBlock: ProcessEnvironmentBlock = ProcessEnv.block, workingDirectory: AbsolutePath?, + outputRedirection: OutputRedirection = .collect, startNewProcessGroup: Bool = true, loggingHandler: LoggingHandler? = .none ) throws -> Process { @@ -35,6 +36,7 @@ extension Process { arguments: arguments, environmentBlock: environmentBlock, workingDirectory: workingDirectory, + outputRedirection: outputRedirection, startNewProcessGroup: startNewProcessGroup, loggingHandler: loggingHandler ) @@ -42,6 +44,7 @@ extension Process { Process( arguments: arguments, environmentBlock: environmentBlock, + outputRedirection: outputRedirection, startNewProcessGroup: startNewProcessGroup, loggingHandler: loggingHandler ) @@ -57,6 +60,7 @@ extension Process { arguments: arguments, environmentBlock: environmentBlock, workingDirectory: nil, + outputRedirection: outputRedirection, startNewProcessGroup: startNewProcessGroup, loggingHandler: loggingHandler ) diff --git a/Sources/SKSwiftPMWorkspace/SwiftPMBuildSystem.swift b/Sources/SKSwiftPMWorkspace/SwiftPMBuildSystem.swift index c3a24b45..6ddab50b 100644 --- a/Sources/SKSwiftPMWorkspace/SwiftPMBuildSystem.swift +++ b/Sources/SKSwiftPMWorkspace/SwiftPMBuildSystem.swift @@ -13,7 +13,9 @@ import Basics import Build import BuildServerProtocol +import CAtomics import Dispatch +import Foundation import LSPLogging import LanguageServerProtocol import PackageGraph @@ -71,6 +73,9 @@ fileprivate extension ConfiguredTarget { static let forPackageManifest = ConfiguredTarget(targetID: "", runDestinationID: "") } +/// `nonisolated(unsafe)` is fine because `preparationTaskID` is atomic. +fileprivate nonisolated(unsafe) var preparationTaskID: AtomicUInt32 = AtomicUInt32(initialValue: 0) + /// Swift Package Manager build system and workspace support. /// /// This class implements the `BuildSystem` interface to provide the build settings for a Swift @@ -535,12 +540,12 @@ extension SwiftPMBuildSystem: SKCore.BuildSystem { public func prepare( targets: [ConfiguredTarget], - indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void + logMessageToIndexLog: @escaping @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void ) async throws { // TODO (indexing): Support preparation of multiple targets at once. // https://github.com/apple/sourcekit-lsp/issues/1262 for target in targets { - try await prepare(singleTarget: target, indexProcessDidProduceResult: indexProcessDidProduceResult) + try await prepare(singleTarget: target, logMessageToIndexLog: logMessageToIndexLog) } let filesInPreparedTargets = targets.flatMap { self.targets[$0]?.buildTarget.sources ?? [] } await fileDependenciesUpdatedDebouncer.scheduleCall(Set(filesInPreparedTargets.map(DocumentURI.init))) @@ -548,7 +553,7 @@ extension SwiftPMBuildSystem: SKCore.BuildSystem { private func prepare( singleTarget target: ConfiguredTarget, - indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void + logMessageToIndexLog: @escaping @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void ) async throws { if target == .forPackageManifest { // Nothing to prepare for package manifests. @@ -581,15 +586,28 @@ extension SwiftPMBuildSystem: SKCore.BuildSystem { return } let start = ContinuousClock.now - let process = try Process.launch(arguments: arguments, workingDirectory: nil) - let result = try await process.waitUntilExitSendingSigIntOnTaskCancellation() - indexProcessDidProduceResult( - IndexProcessResult( - taskDescription: "Preparing \(target.targetID) for \(target.runDestinationID)", - processResult: result, - start: start + + let logID = IndexTaskID.preparation(id: preparationTaskID.fetchAndIncrement()) + logMessageToIndexLog( + logID, + """ + Preparing \(target.targetID) for \(target.runDestinationID) + \(arguments.joined(separator: " ")) + """ + ) + let stdoutHandler = PipeAsStringHandler { logMessageToIndexLog(logID, $0) } + let stderrHandler = PipeAsStringHandler { logMessageToIndexLog(logID, $0) } + + let process = try Process.launch( + arguments: arguments, + workingDirectory: nil, + outputRedirection: .stream( + stdout: { stdoutHandler.handleDataFromPipe(Data($0)) }, + stderr: { stderrHandler.handleDataFromPipe(Data($0)) } ) ) + let result = try await process.waitUntilExitSendingSigIntOnTaskCancellation() + logMessageToIndexLog(logID, "Finished in \(start.duration(to: .now))") switch result.exitStatus.exhaustivelySwitchable { case .terminated(code: 0): break diff --git a/Sources/SKTestSupport/TestSourceKitLSPClient.swift b/Sources/SKTestSupport/TestSourceKitLSPClient.swift index eedf51d8..03cacd18 100644 --- a/Sources/SKTestSupport/TestSourceKitLSPClient.swift +++ b/Sources/SKTestSupport/TestSourceKitLSPClient.swift @@ -273,12 +273,12 @@ public final class TestSourceKitLSPClient: MessageHandler { /// Ignores any notifications that are of a different type or that don't satisfy the predicate. public func nextNotification( ofType: ExpectedNotificationType.Type, - satisfying predicate: (ExpectedNotificationType) -> Bool = { _ in true }, + satisfying predicate: (ExpectedNotificationType) throws -> Bool = { _ in true }, timeout: Duration = .seconds(defaultTimeout) ) async throws -> ExpectedNotificationType { while true { let nextNotification = try await nextNotification(timeout: timeout) - if let notification = nextNotification as? ExpectedNotificationType, predicate(notification) { + if let notification = nextNotification as? ExpectedNotificationType, try predicate(notification) { return notification } } diff --git a/Sources/SemanticIndex/PreparationTaskDescription.swift b/Sources/SemanticIndex/PreparationTaskDescription.swift index c0adfeb3..db854e92 100644 --- a/Sources/SemanticIndex/PreparationTaskDescription.swift +++ b/Sources/SemanticIndex/PreparationTaskDescription.swift @@ -37,8 +37,8 @@ public struct PreparationTaskDescription: IndexTaskDescription { private let preparationUpToDateTracker: UpToDateTracker - /// See `SemanticIndexManager.indexProcessDidProduceResult` - private let indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void + /// See `SemanticIndexManager.logMessageToIndexLog`. + private let logMessageToIndexLog: @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void /// Test hooks that should be called when the preparation task finishes. private let testHooks: IndexTestHooks @@ -60,13 +60,13 @@ public struct PreparationTaskDescription: IndexTaskDescription { targetsToPrepare: [ConfiguredTarget], buildSystemManager: BuildSystemManager, preparationUpToDateTracker: UpToDateTracker, - indexProcessDidProduceResult: @escaping @Sendable (IndexProcessResult) -> Void, + logMessageToIndexLog: @escaping @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void, testHooks: IndexTestHooks ) { self.targetsToPrepare = targetsToPrepare self.buildSystemManager = buildSystemManager self.preparationUpToDateTracker = preparationUpToDateTracker - self.indexProcessDidProduceResult = indexProcessDidProduceResult + self.logMessageToIndexLog = logMessageToIndexLog self.testHooks = testHooks } @@ -105,7 +105,7 @@ public struct PreparationTaskDescription: IndexTaskDescription { do { try await buildSystemManager.prepare( targets: targetsToPrepare, - indexProcessDidProduceResult: indexProcessDidProduceResult + logMessageToIndexLog: logMessageToIndexLog ) } catch { logger.error( diff --git a/Sources/SemanticIndex/SemanticIndexManager.swift b/Sources/SemanticIndex/SemanticIndexManager.swift index dc2b663c..2cea6efd 100644 --- a/Sources/SemanticIndex/SemanticIndexManager.swift +++ b/Sources/SemanticIndex/SemanticIndexManager.swift @@ -160,11 +160,8 @@ public final actor SemanticIndexManager { /// workspaces. private let indexTaskScheduler: TaskScheduler - /// Callback to be called when the process to prepare a target finishes. - /// - /// Allows an index log to be displayed to the user that includes the command line invocations of all index-related - /// process launches, as well as their output. - private let indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void + /// Callback that is called when an indexing task produces output it wants to log to the index log. + private let logMessageToIndexLog: @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void /// Called when files are scheduled to be indexed. /// @@ -206,7 +203,7 @@ public final actor SemanticIndexManager { buildSystemManager: BuildSystemManager, testHooks: IndexTestHooks, indexTaskScheduler: TaskScheduler, - indexProcessDidProduceResult: @escaping @Sendable (IndexProcessResult) -> Void, + logMessageToIndexLog: @escaping @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void, indexTasksWereScheduled: @escaping @Sendable (Int) -> Void, indexProgressStatusDidChange: @escaping @Sendable () -> Void ) { @@ -214,7 +211,7 @@ public final actor SemanticIndexManager { self.buildSystemManager = buildSystemManager self.testHooks = testHooks self.indexTaskScheduler = indexTaskScheduler - self.indexProcessDidProduceResult = indexProcessDidProduceResult + self.logMessageToIndexLog = logMessageToIndexLog self.indexTasksWereScheduled = indexTasksWereScheduled self.indexProgressStatusDidChange = indexProgressStatusDidChange } @@ -467,7 +464,7 @@ public final actor SemanticIndexManager { targetsToPrepare: targetsToPrepare, buildSystemManager: self.buildSystemManager, preparationUpToDateTracker: preparationUpToDateTracker, - indexProcessDidProduceResult: indexProcessDidProduceResult, + logMessageToIndexLog: logMessageToIndexLog, testHooks: testHooks ) ) @@ -514,7 +511,7 @@ public final actor SemanticIndexManager { buildSystemManager: self.buildSystemManager, index: index, indexStoreUpToDateTracker: indexStoreUpToDateTracker, - indexProcessDidProduceResult: indexProcessDidProduceResult, + logMessageToIndexLog: logMessageToIndexLog, testHooks: testHooks ) ) diff --git a/Sources/SemanticIndex/UpdateIndexStoreTaskDescription.swift b/Sources/SemanticIndex/UpdateIndexStoreTaskDescription.swift index 54d7dbea..4ee76e59 100644 --- a/Sources/SemanticIndex/UpdateIndexStoreTaskDescription.swift +++ b/Sources/SemanticIndex/UpdateIndexStoreTaskDescription.swift @@ -111,8 +111,8 @@ public struct UpdateIndexStoreTaskDescription: IndexTaskDescription { /// case we don't need to index it again. private let index: UncheckedIndex - /// See `SemanticIndexManager.indexProcessDidProduceResult` - private let indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void + /// See `SemanticIndexManager.logMessageToIndexLog`. + private let logMessageToIndexLog: @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void /// Test hooks that should be called when the index task finishes. private let testHooks: IndexTestHooks @@ -139,14 +139,14 @@ public struct UpdateIndexStoreTaskDescription: IndexTaskDescription { buildSystemManager: BuildSystemManager, index: UncheckedIndex, indexStoreUpToDateTracker: UpToDateTracker, - indexProcessDidProduceResult: @escaping @Sendable (IndexProcessResult) -> Void, + logMessageToIndexLog: @escaping @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void, testHooks: IndexTestHooks ) { self.filesToIndex = filesToIndex self.buildSystemManager = buildSystemManager self.index = index self.indexStoreUpToDateTracker = indexStoreUpToDateTracker - self.indexProcessDidProduceResult = indexProcessDidProduceResult + self.logMessageToIndexLog = logMessageToIndexLog self.testHooks = testHooks } @@ -337,9 +337,25 @@ public struct UpdateIndexStoreTaskDescription: IndexTaskDescription { defer { signposter.endInterval("Indexing", state) } + let logID = IndexTaskID.updateIndexStore(id: id) + logMessageToIndexLog( + logID, + """ + Indexing \(indexFile.pseudoPath) + \(processArguments.joined(separator: " ")) + """ + ) + + let stdoutHandler = PipeAsStringHandler { logMessageToIndexLog(logID, $0) } + let stderrHandler = PipeAsStringHandler { logMessageToIndexLog(logID, $0) } + let process = try Process.launch( arguments: processArguments, - workingDirectory: workingDirectory + workingDirectory: workingDirectory, + outputRedirection: .stream( + stdout: { stdoutHandler.handleDataFromPipe(Data($0)) }, + stderr: { stderrHandler.handleDataFromPipe(Data($0)) } + ) ) // Time out updating of the index store after 2 minutes. We don't expect any single file compilation to take longer // than 2 minutes in practice, so this indicates that the compiler has entered a loop and we probably won't make any @@ -349,13 +365,7 @@ public struct UpdateIndexStoreTaskDescription: IndexTaskDescription { try await process.waitUntilExitSendingSigIntOnTaskCancellation() } - indexProcessDidProduceResult( - IndexProcessResult( - taskDescription: "Indexing \(indexFile.pseudoPath)", - processResult: result, - start: start - ) - ) + logMessageToIndexLog(logID, "Finished in \(start.duration(to: .now))") switch result.exitStatus.exhaustivelySwitchable { case .terminated(code: 0): diff --git a/Sources/SourceKitLSP/Clang/ClangLanguageService.swift b/Sources/SourceKitLSP/Clang/ClangLanguageService.swift index 965d7b01..b5b8efd0 100644 --- a/Sources/SourceKitLSP/Clang/ClangLanguageService.swift +++ b/Sources/SourceKitLSP/Clang/ClangLanguageService.swift @@ -32,35 +32,6 @@ extension NSLock { } } -/// Gathers data from clangd's stderr pipe. When it has accumulated a full line, writes the the line to the logger. -fileprivate actor ClangdStderrLogForwarder { - /// Queue on which all data from `clangd`’s stderr will be forwarded to `stderr`. This allows us to have a - /// nonisolated `handle` function but ensure that data gets processed in order. - private let queue = AsyncQueue() - private var buffer = Data() - - private func handleImpl(_ newData: Data) { - self.buffer += newData - while let newlineIndex = self.buffer.firstIndex(of: UInt8(ascii: "\n")) { - // Output a separate log message for every line in clangd's stderr. - // The reason why we don't output multiple lines in a single log message is that - // a) os_log truncates log messages at about 1000 bytes. The assumption is that a single line is usually less - // than 1000 bytes long but if we merge multiple lines into one message, we might easily exceed this limit. - // b) It might be confusing why sometimes a single log message contains one line while sometimes it contains - // multiple. - let logger = Logger(subsystem: LoggingScope.subsystem, category: "clangd-stderr") - logger.info("\(String(data: self.buffer[...newlineIndex], encoding: .utf8) ?? "")") - buffer = buffer[buffer.index(after: newlineIndex)...] - } - } - - nonisolated func handle(_ newData: Data) { - queue.async { - await self.handleImpl(newData) - } - } -} - /// A thin wrapper over a connection to a clangd server providing build setting handling. /// /// In addition, it also intercepts notifications and replies from clangd in order to do things @@ -233,14 +204,16 @@ actor ClangLanguageService: LanguageService, MessageHandler { process.standardOutput = clangdToUs process.standardInput = usToClangd - let logForwarder = ClangdStderrLogForwarder() + let logForwarder = PipeAsStringHandler { + Logger(subsystem: LoggingScope.subsystem, category: "clangd-stderr").info("\($0)") + } let stderrHandler = Pipe() stderrHandler.fileHandleForReading.readabilityHandler = { fileHandle in let newData = fileHandle.availableData if newData.count == 0 { stderrHandler.fileHandleForReading.readabilityHandler = nil } else { - logForwarder.handle(newData) + logForwarder.handleDataFromPipe(newData) } } process.standardError = stderrHandler diff --git a/Sources/SourceKitLSP/SourceKitLSPServer.swift b/Sources/SourceKitLSP/SourceKitLSPServer.swift index 8c11b407..e96623e3 100644 --- a/Sources/SourceKitLSP/SourceKitLSPServer.swift +++ b/Sources/SourceKitLSP/SourceKitLSPServer.swift @@ -837,15 +837,18 @@ private extension LanguageServerProtocol.WorkspaceType { } extension SourceKitLSPServer { - nonisolated func indexTaskDidProduceResult(_ result: IndexProcessResult) { + nonisolated func logMessageToIndexLog(taskID: IndexTaskID, message: String) { + var message: Substring = message[...] + while message.last?.isNewline ?? false { + message = message.dropLast(1) + } + let messageWithEmojiLinePrefixes = message.split(separator: "\n", omittingEmptySubsequences: false).map { + "\(taskID.emojiRepresentation) \($0)" + }.joined(separator: "\n") self.sendNotificationToClient( LogMessageNotification( - type: result.failed ? .warning : .info, - message: """ - \(result.taskDescription) finished in \(result.duration) - \(result.command) - \(result.output) - """, + type: .info, + message: messageWithEmojiLinePrefixes, logName: "SourceKit-LSP: Indexing" ) ) @@ -932,8 +935,8 @@ extension SourceKitLSPServer { options: options, indexOptions: self.options.indexOptions, indexTaskScheduler: indexTaskScheduler, - indexProcessDidProduceResult: { [weak self] in - self?.indexTaskDidProduceResult($0) + logMessageToIndexLog: { [weak self] taskID, message in + self?.logMessageToIndexLog(taskID: taskID, message: message) }, indexTasksWereScheduled: { [weak self] count in self?.indexProgressManager.indexTasksWereScheduled(count: count) @@ -1013,8 +1016,8 @@ extension SourceKitLSPServer { index: nil, indexDelegate: nil, indexTaskScheduler: self.indexTaskScheduler, - indexProcessDidProduceResult: { [weak self] in - self?.indexTaskDidProduceResult($0) + logMessageToIndexLog: { [weak self] taskID, message in + self?.logMessageToIndexLog(taskID: taskID, message: message) }, indexTasksWereScheduled: { [weak self] count in self?.indexProgressManager.indexTasksWereScheduled(count: count) diff --git a/Sources/SourceKitLSP/Workspace.swift b/Sources/SourceKitLSP/Workspace.swift index 43672de5..848324a2 100644 --- a/Sources/SourceKitLSP/Workspace.swift +++ b/Sources/SourceKitLSP/Workspace.swift @@ -93,7 +93,7 @@ public final class Workspace: Sendable { index uncheckedIndex: UncheckedIndex?, indexDelegate: SourceKitIndexDelegate?, indexTaskScheduler: TaskScheduler, - indexProcessDidProduceResult: @escaping @Sendable (IndexProcessResult) -> Void, + logMessageToIndexLog: @escaping @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void, indexTasksWereScheduled: @escaping @Sendable (Int) -> Void, indexProgressStatusDidChange: @escaping @Sendable () -> Void ) async { @@ -117,7 +117,7 @@ public final class Workspace: Sendable { buildSystemManager: buildSystemManager, testHooks: options.indexTestHooks, indexTaskScheduler: indexTaskScheduler, - indexProcessDidProduceResult: indexProcessDidProduceResult, + logMessageToIndexLog: logMessageToIndexLog, indexTasksWereScheduled: indexTasksWereScheduled, indexProgressStatusDidChange: indexProgressStatusDidChange ) @@ -155,7 +155,7 @@ public final class Workspace: Sendable { options: SourceKitLSPServer.Options, indexOptions: IndexOptions = IndexOptions(), indexTaskScheduler: TaskScheduler, - indexProcessDidProduceResult: @escaping @Sendable (IndexProcessResult) -> Void, + logMessageToIndexLog: @escaping @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void, indexTasksWereScheduled: @Sendable @escaping (Int) -> Void, indexProgressStatusDidChange: @Sendable @escaping () -> Void ) async throws { @@ -196,7 +196,7 @@ public final class Workspace: Sendable { index: UncheckedIndex(index), indexDelegate: indexDelegate, indexTaskScheduler: indexTaskScheduler, - indexProcessDidProduceResult: indexProcessDidProduceResult, + logMessageToIndexLog: logMessageToIndexLog, indexTasksWereScheduled: indexTasksWereScheduled, indexProgressStatusDidChange: indexProgressStatusDidChange ) diff --git a/Tests/SKCoreTests/BuildSystemManagerTests.swift b/Tests/SKCoreTests/BuildSystemManagerTests.swift index 10583e94..ab894d5e 100644 --- a/Tests/SKCoreTests/BuildSystemManagerTests.swift +++ b/Tests/SKCoreTests/BuildSystemManagerTests.swift @@ -471,7 +471,7 @@ class ManualBuildSystem: BuildSystem { public func prepare( targets: [ConfiguredTarget], - indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void + logMessageToIndexLog: @escaping @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void ) async throws { throw PrepareNotSupportedError() } diff --git a/Tests/SourceKitLSPTests/BackgroundIndexingTests.swift b/Tests/SourceKitLSPTests/BackgroundIndexingTests.swift index 6e5ed554..81c41901 100644 --- a/Tests/SourceKitLSPTests/BackgroundIndexingTests.swift +++ b/Tests/SourceKitLSPTests/BackgroundIndexingTests.swift @@ -709,22 +709,44 @@ final class BackgroundIndexingTests: XCTestCase { } public func testProduceIndexLog() async throws { + let didReceivePreparationIndexLogMessage = self.expectation(description: "Did receive preparation log message") + let didReceiveIndexingLogMessage = self.expectation(description: "Did receive indexing log message") + let updateIndexStoreTaskDidFinish = self.expectation(description: "Update index store task did finish") + + // Block the index tasks until we have received a log notification to make sure we stream out results as they come + // in and not only when the indexing task has finished + var serverOptions = SourceKitLSPServer.Options.testDefault + serverOptions.indexTestHooks.preparationTaskDidFinish = { _ in + await self.fulfillment(of: [didReceivePreparationIndexLogMessage], timeout: defaultTimeout) + } + serverOptions.indexTestHooks.updateIndexStoreTaskDidFinish = { _ in + await self.fulfillment(of: [didReceiveIndexingLogMessage], timeout: defaultTimeout) + updateIndexStoreTaskDidFinish.fulfill() + } + let project = try await SwiftPMTestProject( files: [ "MyFile.swift": "" ], - enableBackgroundIndexing: true + serverOptions: serverOptions, + enableBackgroundIndexing: true, + pollIndex: false ) - let targetPrepareNotification = try await project.testClient.nextNotification(ofType: LogMessageNotification.self) - XCTAssert( - targetPrepareNotification.message.hasPrefix("Preparing MyLibrary"), - "\(targetPrepareNotification.message) does not have the expected prefix" + _ = try await project.testClient.nextNotification( + ofType: LogMessageNotification.self, + satisfying: { notification in + return notification.message.contains("Preparing MyLibrary") + } ) - let indexFileNotification = try await project.testClient.nextNotification(ofType: LogMessageNotification.self) - XCTAssert( - indexFileNotification.message.hasPrefix("Indexing \(try project.uri(for: "MyFile.swift").pseudoPath)"), - "\(indexFileNotification.message) does not have the expected prefix" + didReceivePreparationIndexLogMessage.fulfill() + _ = try await project.testClient.nextNotification( + ofType: LogMessageNotification.self, + satisfying: { notification in + notification.message.contains("Indexing \(try project.uri(for: "MyFile.swift").pseudoPath)") + } ) + didReceiveIndexingLogMessage.fulfill() + try await fulfillmentOfOrThrow([updateIndexStoreTaskDidFinish]) } func testIndexingHappensInParallel() async throws { diff --git a/Tests/SourceKitLSPTests/BuildSystemTests.swift b/Tests/SourceKitLSPTests/BuildSystemTests.swift index 44c4031e..c5439ca6 100644 --- a/Tests/SourceKitLSPTests/BuildSystemTests.swift +++ b/Tests/SourceKitLSPTests/BuildSystemTests.swift @@ -63,7 +63,7 @@ actor TestBuildSystem: BuildSystem { public func prepare( targets: [ConfiguredTarget], - indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void + logMessageToIndexLog: @escaping @Sendable (_ taskID: IndexTaskID, _ message: String) -> Void ) async throws { throw PrepareNotSupportedError() } @@ -141,7 +141,7 @@ final class BuildSystemTests: XCTestCase { index: nil, indexDelegate: nil, indexTaskScheduler: .forTesting, - indexProcessDidProduceResult: { _ in }, + logMessageToIndexLog: { _, _ in }, indexTasksWereScheduled: { _ in }, indexProgressStatusDidChange: {} )