Add logging for requests handled by the SourceKit plugin

Author: ahoppen

Package.swift

@@ -334,6 +334,7 @@ var targets: [Target] = [
     swiftSettings: globalSwiftSettings + lspLoggingSwiftSettings + [
       // We can't depend on swift-crypto in the plugin because we can't module-alias it due to https://github.com/swiftlang/swift-package-manager/issues/8119
       .define("NO_CRYPTO_DEPENDENCY"),
+      .define("SKLOGGING_FOR_PLUGIN"),
       .unsafeFlags([
         "-module-alias", "SwiftExtensions=SwiftExtensionsForPlugin",
       ]),

Sources/SKLogging/LoggingScope.swift

@@ -21,7 +21,11 @@ package final class LoggingScope {
 
   /// The name of the current logging subsystem.
   package static var subsystem: String {
+    #if SKLOGGING_FOR_PLUGIN
+    return _subsystem ?? "org.swift.sourcekit-lsp.plugin"
+    #else
     return _subsystem ?? "org.swift.sourcekit-lsp"
+    #endif
   }
 
   /// The name of the current logging scope.

Sources/SwiftSourceKitPlugin/Plugin.swift

@@ -11,6 +11,7 @@
 //===----------------------------------------------------------------------===//
 
 import Foundation
+import SKLogging
 import SourceKitD
 import SwiftExtensions
 import SwiftSourceKitPluginCommon
@@ -62,14 +63,31 @@ final class RequestHandler: Sendable {
     func produceResult(
       body: @escaping @Sendable () async throws -> SKDResponseDictionaryBuilder
     ) -> HandleRequestResult {
-      requestHandlingQueue.async {
-        do {
-          receiver(try await body().response)
-        } catch {
-          receiver(SKDResponse.from(error: error, sourcekitd: self.sourcekitd))
+      withLoggingScope("request-\(handle?.numericValue ?? 0 % 100)") {
+        let start = Date()
+        logger.debug(
+          """
+          Plugin received sourcekitd request (handle: \(handle?.numericValue ?? -1))
+          \(dict.description)
+          """
+        )
+        requestHandlingQueue.async {
+          let response: SKDResponse
+          do {
+            response = try await body().response
+          } catch {
+            response = SKDResponse.from(error: error, sourcekitd: self.sourcekitd)
+          }
+          logger.debug(
+            """
+            Finished (took \(Date().timeIntervalSince(start))s)
+            \(response.description)
+            """
+          )
+          receiver(response)
         }
+        return .requestHandled
       }
-      return .requestHandled
     }
 
     func sourcekitdProducesResult(body: @escaping @Sendable () async -> ()) -> HandleRequestResult {
@@ -139,6 +157,7 @@ final class RequestHandler: Sendable {
   }
 
   func cancel(_ handle: RequestHandle) {
+    logger.debug("Cancelling request with handle \(handle.numericValue)")
     self.completionProvider.cancel(handle: handle)
   }
 }

Sources/SwiftSourceKitPlugin/SourceKitDWrappers.swift

@@ -31,4 +31,8 @@ struct RequestHandle: Sendable {
     }
     self.handle = handle
   }
+
+  var numericValue: Int {
+    Int(bitPattern: handle)
+  }
 }

Tests/SwiftSourceKitPluginTests/SwiftSourceKitPluginTests.swift

@@ -272,7 +272,6 @@ final class SwiftSourceKitPluginTests: XCTestCase {
   }
 
   func testCancellation() async throws {
-    try XCTSkipIf(true, "rdar://145905708")
     try await SkipUnless.sourcekitdSupportsPlugin()
     let sourcekitd = try await getSourceKitD()
     let path = scratchFilePath()