Merge pull request #2030 from ahoppen/plugin-logging

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/SKDRequestDictionaryReader.swift

@@ -13,14 +13,34 @@
 import Csourcekitd
 import SourceKitD
 
+#if canImport(Darwin)
+import Darwin
+#elseif canImport(Glibc)
+import Glibc
+#elseif canImport(Musl)
+import Musl
+#elseif canImport(CRT)
+import CRT
+#elseif canImport(Bionic)
+import Bionic
+#endif
+
 /// Provide getters to get values of a sourcekitd request dictionary.
 ///
 /// This is not part of the `SourceKitD` module because it uses `SourceKitD.servicePluginAPI` which must not be accessed
 /// outside of the service plugin.
-final class SKDRequestDictionaryReader: Sendable {
+final class SKDRequestDictionaryReader: Sendable, CustomStringConvertible {
   private nonisolated(unsafe) let dict: sourcekitd_api_object_t
   let sourcekitd: SourceKitD
 
+  var description: String {
+    guard let description = sourcekitd.api.request_description_copy(dict) else {
+      return "getting request description failed"
+    }
+    defer { free(description) }
+    return String(cString: description)
+  }
+
   /// Creates an `SKDRequestDictionary` that essentially provides a view into the given opaque
   /// `sourcekitd_api_object_t`.
   init?(_ request: sourcekitd_api_object_t, sourcekitd: SourceKitD) {

Sources/SwiftSourceKitPlugin/SKDResponse.swift

@@ -74,7 +74,7 @@ final class SKDResponse: CustomStringConvertible, Sendable {
   }
 
   public var description: String {
-    let cstr = sourcekitd.api.request_description_copy(value)!
+    let cstr = sourcekitd.api.response_description_copy(value)!
     defer { free(cstr) }
     return String(cString: cstr)
   }

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()