Produce an index log for the client

This allows a user of SourceKit-LSP to inspect the result of background indexing. This allows a user of SourceKit-LSP to inspect the result of background indexing. I think this gives useful insights into what SourceKit-LSP is indexing and why/how it fails, if it fails, also for users of SourceKit-LSP.

rdar://127474136
Fixes #1265

Author: ahoppen

Sources/SKCore/BuildServerBuildSystem.swift

@@ -289,7 +289,10 @@ extension BuildServerBuildSystem: BuildSystem {
     return nil
   }
 
-  public func prepare(targets: [ConfiguredTarget]) async throws {
+  public func prepare(
+    targets: [ConfiguredTarget],
+    indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void
+  ) async throws {
     throw PrepareNotSupportedError()
   }
 

Sources/SKCore/BuildSystem.swift

@@ -158,7 +158,10 @@ public protocol BuildSystem: AnyObject, Sendable {
 
   /// Prepare the given targets for indexing and semantic functionality. This should build all swift modules of target
   /// dependencies.
-  func prepare(targets: [ConfiguredTarget]) async throws
+  func prepare(
+    targets: [ConfiguredTarget],
+    indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void
+  ) async throws
 
   /// If the build system has knowledge about the language that this document should be compiled in, return it.
   ///

Sources/SKCore/BuildSystemManager.swift

@@ -231,8 +231,11 @@ extension BuildSystemManager {
     return await buildSystem?.targets(dependingOn: targets)
   }
 
-  public func prepare(targets: [ConfiguredTarget]) async throws {
-    try await buildSystem?.prepare(targets: targets)
+  public func prepare(
+    targets: [ConfiguredTarget],
+    indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void
+  ) async throws {
+    try await buildSystem?.prepare(targets: targets, indexProcessDidProduceResult: indexProcessDidProduceResult)
   }
 
   public func registerForChangeNotifications(for uri: DocumentURI, language: Language) async {

Sources/SKCore/CMakeLists.txt

@@ -10,6 +10,7 @@ add_library(SKCore STATIC
   Debouncer.swift
   FallbackBuildSystem.swift
   FileBuildSettings.swift
+  IndexProcessResult.swift
   MainFilesProvider.swift
   PathPrefixMapping.swift
   SplitShellCommand.swift

Sources/SKCore/CompilationDatabaseBuildSystem.swift

@@ -125,7 +125,10 @@ extension CompilationDatabaseBuildSystem: BuildSystem {
     return [ConfiguredTarget(targetID: "dummy", runDestinationID: "dummy")]
   }
 
-  public func prepare(targets: [ConfiguredTarget]) async throws {
+  public func prepare(
+    targets: [ConfiguredTarget],
+    indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void
+  ) async throws {
     throw PrepareNotSupportedError()
   }
 

Sources/SKCore/IndexProcessResult.swift

@@ -0,0 +1,71 @@
+//===----------------------------------------------------------------------===//
+//
+// 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)) ?? "<failed to decode stdout>"
+    let stderr = (try? String(bytes: processResult.stderrOutput.get(), encoding: .utf8)) ?? "<failed to decode stderr>"
+    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)
+    )
+  }
+}

Sources/SKSwiftPMWorkspace/SwiftPMBuildSystem.swift

@@ -459,17 +459,23 @@ extension SwiftPMBuildSystem: SKCore.BuildSystem {
     }
   }
 
-  public func prepare(targets: [ConfiguredTarget]) async throws {
+  public func prepare(
+    targets: [ConfiguredTarget],
+    indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> 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)
+      try await prepare(singleTarget: target, indexProcessDidProduceResult: indexProcessDidProduceResult)
     }
     let filesInPreparedTargets = targets.flatMap { self.targets[$0]?.buildTarget.sources ?? [] }
     await fileDependenciesUpdatedDebouncer.scheduleCall(Set(filesInPreparedTargets.map(DocumentURI.init)))
   }
 
-  private func prepare(singleTarget target: ConfiguredTarget) async throws {
+  private func prepare(
+    singleTarget target: ConfiguredTarget,
+    indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void
+  ) async throws {
     // TODO (indexing): Add a proper 'prepare' job in SwiftPM instead of building the target.
     // https://github.com/apple/sourcekit-lsp/issues/1254
     guard let toolchain = await toolchainRegistry.default else {
@@ -492,8 +498,16 @@ extension SwiftPMBuildSystem: SKCore.BuildSystem {
     if Task.isCancelled {
       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
+      )
+    )
     switch result.exitStatus.exhaustivelySwitchable {
     case .terminated(code: 0):
       break

Sources/SKTestSupport/TestSourceKitLSPClient.swift

@@ -243,25 +243,18 @@ public final class TestSourceKitLSPClient: MessageHandler {
     return try await nextNotification(ofType: PublishDiagnosticsNotification.self, timeout: timeout)
   }
 
-  private struct CastError: Error, CustomStringConvertible {
-    let expectedType: any NotificationType.Type
-    let actualType: any NotificationType.Type
-
-    var description: String { "Expected a \(expectedType) but got '\(actualType)'" }
-  }
-
-  /// Await the next diagnostic notification sent to the client.
-  ///
-  /// If the next notification is not of the expected type, this methods throws.
+  /// Waits for the next notification of the given type to be sent to the client. Ignores any notifications that are of
+  /// a different type.
   public func nextNotification<ExpectedNotificationType: NotificationType>(
     ofType: ExpectedNotificationType.Type,
     timeout: TimeInterval = defaultTimeout
   ) async throws -> ExpectedNotificationType {
-    let nextNotification = try await nextNotification(timeout: timeout)
-    guard let notification = nextNotification as? ExpectedNotificationType else {
-      throw CastError(expectedType: ExpectedNotificationType.self, actualType: type(of: nextNotification))
+    while true {
+      let nextNotification = try await nextNotification(timeout: timeout)
+      if let notification = nextNotification as? ExpectedNotificationType {
+        return notification
+      }
     }
-    return notification
   }
 
   /// Handle the next request that is sent to the client with the given handler.

Sources/SemanticIndex/PreparationTaskDescription.swift

@@ -37,6 +37,9 @@ public struct PreparationTaskDescription: IndexTaskDescription {
 
   private let preparationUpToDateStatus: IndexUpToDateStatusManager<ConfiguredTarget>
 
+  /// See `SemanticIndexManager.indexProcessDidProduceResult`
+  private let indexProcessDidProduceResult: @Sendable (IndexProcessResult) -> Void
+
   /// Test hooks that should be called when the preparation task finishes.
   private let testHooks: IndexTestHooks
 
@@ -57,11 +60,13 @@ public struct PreparationTaskDescription: IndexTaskDescription {
     targetsToPrepare: [ConfiguredTarget],
     buildSystemManager: BuildSystemManager,
     preparationUpToDateStatus: IndexUpToDateStatusManager<ConfiguredTarget>,
+    indexProcessDidProduceResult: @escaping @Sendable (IndexProcessResult) -> Void,
     testHooks: IndexTestHooks
   ) {
     self.targetsToPrepare = targetsToPrepare
     self.buildSystemManager = buildSystemManager
     self.preparationUpToDateStatus = preparationUpToDateStatus
+    self.indexProcessDidProduceResult = indexProcessDidProduceResult
     self.testHooks = testHooks
   }
 
@@ -89,7 +94,10 @@ public struct PreparationTaskDescription: IndexTaskDescription {
       )
       let startDate = Date()
       do {
-        try await buildSystemManager.prepare(targets: targetsToPrepare)
+        try await buildSystemManager.prepare(
+          targets: targetsToPrepare,
+          indexProcessDidProduceResult: indexProcessDidProduceResult
+        )
       } catch {
         logger.error(
           "Preparation failed: \(error.forLogging)"

Sources/SemanticIndex/SemanticIndexManager.swift

@@ -108,6 +108,12 @@ public final actor SemanticIndexManager {
   /// workspaces.
   private let indexTaskScheduler: TaskScheduler<AnyIndexTaskDescription>
 
+  /// 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
+
   /// Called when files are scheduled to be indexed.
   ///
   /// The parameter is the number of files that were scheduled to be indexed.
@@ -150,13 +156,15 @@ public final actor SemanticIndexManager {
     buildSystemManager: BuildSystemManager,
     testHooks: IndexTestHooks,
     indexTaskScheduler: TaskScheduler<AnyIndexTaskDescription>,
+    indexProcessDidProduceResult: @escaping @Sendable (IndexProcessResult) -> Void,
     indexTasksWereScheduled: @escaping @Sendable (Int) -> Void,
     indexStatusDidChange: @escaping @Sendable () -> Void
   ) {
     self.index = index
     self.buildSystemManager = buildSystemManager
     self.testHooks = testHooks
     self.indexTaskScheduler = indexTaskScheduler
+    self.indexProcessDidProduceResult = indexProcessDidProduceResult
     self.indexTasksWereScheduled = indexTasksWereScheduled
     self.indexStatusDidChange = indexStatusDidChange
   }
@@ -350,6 +358,7 @@ public final actor SemanticIndexManager {
         targetsToPrepare: targetsToPrepare,
         buildSystemManager: self.buildSystemManager,
         preparationUpToDateStatus: preparationUpToDateStatus,
+        indexProcessDidProduceResult: indexProcessDidProduceResult,
         testHooks: testHooks
       )
     )
@@ -396,6 +405,7 @@ public final actor SemanticIndexManager {
         buildSystemManager: self.buildSystemManager,
         index: index,
         indexStoreUpToDateStatus: indexStoreUpToDateStatus,
+        indexProcessDidProduceResult: indexProcessDidProduceResult,
         testHooks: testHooks
       )
     )

Sources/SemanticIndex/UpdateIndexStoreTaskDescription.swift

@@ -95,6 +95,9 @@ 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
+
   /// Test hooks that should be called when the index task finishes.
   private let testHooks: IndexTestHooks
 
@@ -116,12 +119,14 @@ public struct UpdateIndexStoreTaskDescription: IndexTaskDescription {
     buildSystemManager: BuildSystemManager,
     index: UncheckedIndex,
     indexStoreUpToDateStatus: IndexUpToDateStatusManager<DocumentURI>,
+    indexProcessDidProduceResult: @escaping @Sendable (IndexProcessResult) -> Void,
     testHooks: IndexTestHooks
   ) {
     self.filesToIndex = filesToIndex
     self.buildSystemManager = buildSystemManager
     self.index = index
     self.indexStoreUpToDateStatus = indexStoreUpToDateStatus
+    self.indexProcessDidProduceResult = indexProcessDidProduceResult
     self.testHooks = testHooks
   }
 
@@ -304,18 +309,28 @@ public struct UpdateIndexStoreTaskDescription: IndexTaskDescription {
     if Task.isCancelled {
       return
     }
+    let start = ContinuousClock.now
     let process = try Process.launch(
       arguments: processArguments,
       workingDirectory: workingDirectory
     )
     let result = try await process.waitUntilExitSendingSigIntOnTaskCancellation()
+
+    indexProcessDidProduceResult(
+      IndexProcessResult(
+        taskDescription: "Indexing \(indexFile.pseudoPath)",
+        processResult: result,
+        start: start
+      )
+    )
+
     switch result.exitStatus.exhaustivelySwitchable {
     case .terminated(code: 0):
       break
     case .terminated(code: let code):
       // This most likely happens if there are compilation errors in the source file. This is nothing to worry about.
-      let stdout = (try? String(bytes: result.output.get(), encoding: .utf8)) ?? "<no stderr>"
-      let stderr = (try? String(bytes: result.stderrOutput.get(), encoding: .utf8)) ?? "<no stderr>"
+      let stdout = (try? String(bytes: result.output.get(), encoding: .utf8)) ?? "<failed to decode stdout>"
+      let stderr = (try? String(bytes: result.stderrOutput.get(), encoding: .utf8)) ?? "<failed to decode stderr>"
       // Indexing will frequently fail if the source code is in an invalid state. Thus, log the failure at a low level.
       logger.debug(
         """

Sources/SourceKitLSP/SourceKitLSPServer.swift

@@ -698,7 +698,7 @@ public actor SourceKitLSPServer {
   }
 
   /// Send the given notification to the editor.
-  public func sendNotificationToClient(_ notification: some NotificationType) {
+  public nonisolated func sendNotificationToClient(_ notification: some NotificationType) {
     client.send(notification)
   }
 
@@ -1177,6 +1177,21 @@ private extension LanguageServerProtocol.WorkspaceType {
   }
 }
 
+extension SourceKitLSPServer {
+  nonisolated func indexTaskDidProduceResult(_ result: IndexProcessResult) {
+    self.sendNotificationToClient(
+      LogMessageNotification(
+        type: result.failed ? .info : .warning,
+        message: """
+          \(result.taskDescription) finished in \(result.duration)
+          \(result.command)
+          \(result.output)
+          """
+      )
+    )
+  }
+}
+
 // MARK: - Request and notification handling
 
 extension SourceKitLSPServer {
@@ -1223,6 +1238,9 @@ extension SourceKitLSPServer {
       compilationDatabaseSearchPaths: self.options.compilationDatabaseSearchPaths,
       indexOptions: self.options.indexOptions,
       indexTaskScheduler: indexTaskScheduler,
+      indexProcessDidProduceResult: { [weak self] in
+        self?.indexTaskDidProduceResult($0)
+      },
       reloadPackageStatusCallback: { [weak self] status in
         guard let self else { return }
         switch status {
@@ -1295,6 +1313,9 @@ extension SourceKitLSPServer {
           index: nil,
           indexDelegate: nil,
           indexTaskScheduler: self.indexTaskScheduler,
+          indexProcessDidProduceResult: { [weak self] in
+            self?.indexTaskDidProduceResult($0)
+          },
           indexTasksWereScheduled: { [weak self] count in
             self?.indexProgressManager.indexTasksWereScheduled(count: count)
           },