Merge pull request #933 from ahoppen/ahoppen/log-sourcekitd-crash-info

When sourcekitd crashes, log the file contents with which it crashed and the request

Author: ahoppen

Sources/LSPLogging/CMakeLists.txt

@@ -5,6 +5,7 @@ add_library(LSPLogging STATIC
   LoggingScope.swift
   NonDarwinLogging.swift
   OrLog.swift
+  SplitLogMessage.swift
 )
 set_target_properties(LSPLogging PROPERTIES
   INTERFACE_INCLUDE_DIRECTORIES ${CMAKE_Swift_MODULE_DIRECTORY})

Sources/LSPLogging/SplitLogMessage.swift

@@ -0,0 +1,30 @@
+//===----------------------------------------------------------------------===//
+//
+// This source file is part of the Swift.org open source project
+//
+// Copyright (c) 2014 - 2023 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
+//
+//===----------------------------------------------------------------------===//
+
+/// Splits `message` on newline characters such that each chunk is at most `maxChunkSize` bytes long.
+///
+/// The intended use case for this is to split compiler arguments into multiple chunks so that each chunk doesn't exceed
+/// the maximum message length of `os_log` and thus won't get truncated.
+///
+///  - Note: This will only split along newline boundary. If a single line is longer than `maxChunkSize`, it won't be
+///    split. This is fine for compiler argument splitting since a single argument is rarely longer than 800 characters.
+public func splitLongMultilineMessage(message: String, maxChunkSize: Int = 800) -> [String] {
+  var chunks: [String] = []
+  for line in message.split(separator: "\n", omittingEmptySubsequences: false) {
+    if let lastChunk = chunks.last, lastChunk.utf8.count + line.utf8.count < maxChunkSize {
+      chunks[chunks.count - 1] += "\n" + line
+    } else {
+      chunks.append(String(line))
+    }
+  }
+  return chunks
+}

Sources/SKCore/BuildSystemManager.swift

@@ -325,7 +325,7 @@ fileprivate actor BuildSettingsLogger {
       \(settings.workingDirectory ?? "<nil>")
       """
 
-    let chunks = splitLongMultilineMessage(message: log, maxChunkSize: 800)
+    let chunks = splitLongMultilineMessage(message: log)
     for (index, chunk) in chunks.enumerated() {
       logger.log(
         """
@@ -335,23 +335,4 @@ fileprivate actor BuildSettingsLogger {
       )
     }
   }
-
-  /// Splits `message` on newline characters such that each chunk is at most `maxChunkSize` bytes long.
-  ///
-  /// The intended use case for this is to split compiler arguments into multiple chunks so that each chunk doesn't exceed
-  /// the maximum message length of `os_log` and thus won't get truncated.
-  ///
-  ///  - Note: This will only split along newline boundary. If a single line is longer than `maxChunkSize`, it won't be
-  ///    split. This is fine for compiler argument splitting since a single argument is rarely longer than 800 characters.
-  private func splitLongMultilineMessage(message: String, maxChunkSize: Int) -> [String] {
-    var chunks: [String] = []
-    for line in message.split(separator: "\n", omittingEmptySubsequences: false) {
-      if let lastChunk = chunks.last, lastChunk.utf8.count + line.utf8.count < maxChunkSize {
-        chunks[chunks.count - 1] += "\n" + line
-      } else {
-        chunks.append(String(line))
-      }
-    }
-    return chunks
-  }
 }

Sources/SourceKitD/SourceKitD.swift

@@ -65,7 +65,11 @@ extension SourceKitD {
 
   // MARK: - Convenience API for requests.
 
-  public func send(_ req: SKDRequestDictionary) async throws -> SKDResponseDictionary {
+  /// - Parameters:
+  ///   - req: The request to send to sourcekitd.
+  ///   - fileContents: The contents of the file that the request operates on. If sourcekitd crashes, the file contents
+  ///     will be logged.
+  public func send(_ req: SKDRequestDictionary, fileContents: String?) async throws -> SKDResponseDictionary {
     logRequest(req)
 
     let signposter = logger.makeSignposter()
@@ -86,6 +90,24 @@ extension SourceKitD {
 
     guard let dict = sourcekitdResponse.value else {
       signposter.endInterval("sourcekitd-request", signposterState, "Error")
+      if sourcekitdResponse.error == .connectionInterrupted {
+        let log = """
+          Request:
+          \(req.description)
+
+          File contents:
+          \(fileContents ?? "<nil>")
+          """
+        let chunks = splitLongMultilineMessage(message: log)
+        for (index, chunk) in chunks.enumerated() {
+          logger.fault(
+            """
+            sourcekitd crashed (\(index + 1)/\(chunks.count))
+            \(chunk)
+            """
+          )
+        }
+      }
       throw sourcekitdResponse.error!
     }
 
@@ -95,9 +117,7 @@ extension SourceKitD {
 }
 
 private func logRequest(_ request: SKDRequestDictionary) {
-  // FIXME: Ideally we could log the request key here at the info level but the dictionary is
-  // readonly.
-  logger.log(
+  logger.info(
     """
     Sending sourcekitd request:
     \(request.forLogging)

Sources/SourceKitLSP/SourceKitServer.swift

@@ -666,12 +666,7 @@ extension SourceKitServer: MessageHandler {
   }
 
   private func handleImpl(_ notification: some NotificationType, from clientID: ObjectIdentifier) async {
-    logger.log(
-      """
-      Received notification
-      \(notification.forLogging)
-      """
-    )
+    logger.log("Received notification: \(notification.forLogging)")
 
     switch notification {
     case let notification as InitializedNotification:

Sources/SourceKitLSP/Swift/CodeCompletionSession.swift

@@ -197,7 +197,7 @@ class CodeCompletionSession {
       req[keys.compilerargs] = compileCommand.compilerArgs
     }
 
-    let dict = try await sourcekitd.send(req)
+    let dict = try await sourcekitd.send(req, fileContents: snapshot.text)
     self.state = .open
 
     guard let completions: SKDResponseArray = dict[keys.results] else {
@@ -230,7 +230,7 @@ class CodeCompletionSession {
     req[keys.name] = uri.pseudoPath
     req[keys.codecomplete_options] = optionsDictionary(filterText: filterText, options: options)
 
-    let dict = try await sourcekitd.send(req)
+    let dict = try await sourcekitd.send(req, fileContents: snapshot.text)
     guard let completions: SKDResponseArray = dict[keys.results] else {
       return CompletionList(isIncomplete: false, items: [])
     }
@@ -275,7 +275,7 @@ class CodeCompletionSession {
       req[keys.offset] = self.utf8StartOffset
       req[keys.name] = self.snapshot.uri.pseudoPath
       logger.info("Closing code completion session: \(self, privacy: .private)")
-      _ = try? await sourcekitd.send(req)
+      _ = try? await sourcekitd.send(req, fileContents: nil)
       self.state = .closed
     }
   }

Sources/SourceKitLSP/Swift/CursorInfo.swift

@@ -107,7 +107,7 @@ extension SwiftLanguageServer {
 
     appendAdditionalParameters?(skreq)
 
-    let dict = try await self.sourcekitd.send(skreq)
+    let dict = try await self.sourcekitd.send(skreq, fileContents: snapshot.text)
 
     guard let kind: sourcekitd_uid_t = dict[keys.kind] else {
       // Nothing to report.

Sources/SourceKitLSP/Swift/OpenInterface.swift

@@ -82,7 +82,7 @@ extension SwiftLanguageServer {
       skreq[keys.compilerargs] = compileCommand.compilerArgs
     }
 
-    let dict = try await self.sourcekitd.send(skreq)
+    let dict = try await self.sourcekitd.send(skreq, fileContents: nil)
     return InterfaceInfo(contents: dict[keys.sourcetext] ?? "")
   }
 
@@ -103,7 +103,7 @@ extension SwiftLanguageServer {
       skreq[keys.sourcefile] = uri.pseudoPath
       skreq[keys.usr] = symbol
 
-      let dict = try await self.sourcekitd.send(skreq)
+      let dict = try await self.sourcekitd.send(skreq, fileContents: snapshot.text)
       if let offset: Int = dict[keys.offset],
         let position = snapshot.positionOf(utf8Offset: offset)
       {

Sources/SourceKitLSP/Swift/SemanticRefactoring.swift

@@ -155,7 +155,7 @@ extension SwiftLanguageServer {
       skreq[keys.compilerargs] = compileCommand.compilerArgs
     }
 
-    let dict = try await self.sourcekitd.send(skreq)
+    let dict = try await self.sourcekitd.send(skreq, fileContents: snapshot.text)
     guard let refactor = SemanticRefactoring(refactorCommand.title, dict, snapshot, self.keys) else {
       throw SemanticRefactoringError.noEditsNeeded(uri)
     }

Sources/SourceKitLSP/Swift/SemanticTokens.swift

@@ -31,7 +31,7 @@ extension SwiftLanguageServer {
     // FIXME: SourceKit should probably cache this for us.
     skreq[keys.compilerargs] = buildSettings.compilerArgs
 
-    let dict = try await sourcekitd.send(skreq)
+    let dict = try await sourcekitd.send(skreq, fileContents: snapshot.text)
 
     guard let skTokens: SKDResponseArray = dict[keys.semantic_tokens] else {
       return nil

Sources/SourceKitLSP/Swift/SwiftLanguageServer.swift

@@ -262,7 +262,7 @@ extension SwiftLanguageServer {
   public func _crash() async {
     let req = SKDRequestDictionary(sourcekitd: sourcekitd)
     req[sourcekitd.keys.request] = sourcekitd.requests.crash_exit
-    _ = try? await sourcekitd.send(req)
+    _ = try? await sourcekitd.send(req, fileContents: nil)
   }
 
   // MARK: - Build System Integration
@@ -276,7 +276,7 @@ extension SwiftLanguageServer {
     let closeReq = SKDRequestDictionary(sourcekitd: self.sourcekitd)
     closeReq[keys.request] = self.requests.editor_close
     closeReq[keys.name] = path
-    _ = try? await self.sourcekitd.send(closeReq)
+    _ = try? await self.sourcekitd.send(closeReq, fileContents: nil)
 
     let openReq = SKDRequestDictionary(sourcekitd: self.sourcekitd)
     openReq[keys.request] = self.requests.editor_open
@@ -286,7 +286,7 @@ extension SwiftLanguageServer {
       openReq[keys.compilerargs] = compileCmd.compilerArgs
     }
 
-    _ = try? await self.sourcekitd.send(openReq)
+    _ = try? await self.sourcekitd.send(openReq, fileContents: snapshot.text)
 
     publishDiagnosticsIfNeeded(for: snapshot.uri)
   }
@@ -336,7 +336,7 @@ extension SwiftLanguageServer {
       req[keys.compilerargs] = compilerArgs
     }
 
-    _ = try? await self.sourcekitd.send(req)
+    _ = try? await self.sourcekitd.send(req, fileContents: snapshot.text)
     publishDiagnosticsIfNeeded(for: note.textDocument.uri)
   }
 
@@ -354,7 +354,7 @@ extension SwiftLanguageServer {
     req[keys.request] = self.requests.editor_close
     req[keys.name] = uri.pseudoPath
 
-    _ = try? await self.sourcekitd.send(req)
+    _ = try? await self.sourcekitd.send(req, fileContents: nil)
   }
 
   /// Cancels any in-flight tasks to send a `PublishedDiagnosticsNotification` after edits.
@@ -464,7 +464,7 @@ extension SwiftLanguageServer {
       req[keys.length] = edit.length
       req[keys.sourcetext] = edit.replacement
       do {
-        _ = try await self.sourcekitd.send(req)
+        _ = try await self.sourcekitd.send(req, fileContents: nil)
       } catch {
         fatalError("failed to apply edit")
       }
@@ -639,7 +639,7 @@ extension SwiftLanguageServer {
       skreq[keys.compilerargs] = compileCommand.compilerArgs
     }
 
-    let dict = try await self.sourcekitd.send(skreq)
+    let dict = try await self.sourcekitd.send(skreq, fileContents: snapshot.text)
 
     guard let results: SKDResponseArray = dict[self.keys.results] else {
       return []
@@ -1090,7 +1090,7 @@ extension SwiftLanguageServer {
     // FIXME: SourceKit should probably cache this for us.
     skreq[keys.compilerargs] = buildSettings.compilerArgs
 
-    let dict = try await self.sourcekitd.send(skreq)
+    let dict = try await self.sourcekitd.send(skreq, fileContents: snapshot.text)
 
     try Task.checkCancellation()
     guard (try? documentManager.latestSnapshot(req.textDocument.uri).id) == snapshot.id else {

Sources/SourceKitLSP/Swift/VariableTypeInfo.swift

@@ -104,7 +104,7 @@ extension SwiftLanguageServer {
       skreq[keys.compilerargs] = compileCommand.compilerArgs
     }
 
-    let dict = try await self.sourcekitd.send(skreq)
+    let dict = try await self.sourcekitd.send(skreq, fileContents: snapshot.text)
     guard let skVariableTypeInfos: SKDResponseArray = dict[keys.variable_type_list] else {
       return []
     }

Tests/SourceKitDTests/SourceKitDTests.swift

@@ -88,14 +88,14 @@ final class SourceKitDTests: XCTestCase {
     args.append(path)
     req[keys.compilerargs] = args
 
-    _ = try await sourcekitd.send(req)
+    _ = try await sourcekitd.send(req, fileContents: nil)
 
     try await fulfillmentOfOrThrow([expectation1, expectation2])
 
     let close = SKDRequestDictionary(sourcekitd: sourcekitd)
     close[keys.request] = sourcekitd.requests.editor_close
     close[keys.name] = path
-    _ = try await sourcekitd.send(close)
+    _ = try await sourcekitd.send(close, fileContents: nil)
   }
 }