Write log messages to files on non-Darwin platforms

Package.swift

@@ -161,7 +161,8 @@ let package = Package(
     .target(
       name: "LSPLogging",
       dependencies: [
-        .product(name: "Crypto", package: "swift-crypto")
+        "SwiftExtensions",
+        .product(name: "Crypto", package: "swift-crypto"),
       ],
       exclude: ["CMakeLists.txt"],
       swiftSettings: lspLoggingSwiftSettings + [.enableExperimentalFeature("StrictConcurrency")]

Sources/Diagnose/DiagnoseCommand.swift

@@ -232,6 +232,32 @@ public struct DiagnoseCommand: AsyncParsableCommand {
     #endif
   }
 
+  @MainActor
+  private func addNonDarwinLogs(toBundle bundlePath: URL) async throws {
+    reportProgress(.collectingLogMessages(progress: 0), message: "Collecting log files")
+
+    let destinationDir = bundlePath.appendingPathComponent("logs")
+    try FileManager.default.createDirectory(at: destinationDir, withIntermediateDirectories: true)
+
+    let logFileDirectoryURL = URL(fileURLWithPath: ("~/.sourcekit-lsp/logs" as NSString).expandingTildeInPath)
+    let enumerator = FileManager.default.enumerator(at: logFileDirectoryURL, includingPropertiesForKeys: nil)
+    while let fileUrl = enumerator?.nextObject() as? URL {
+      guard fileUrl.lastPathComponent.hasPrefix("sourcekit-lsp") else {
+        continue
+      }
+      try? FileManager.default.copyItem(
+        at: fileUrl,
+        to: destinationDir.appendingPathComponent(fileUrl.lastPathComponent)
+      )
+    }
+  }
+
+  @MainActor
+  private func addLogs(toBundle bundlePath: URL) async throws {
+    try await addNonDarwinLogs(toBundle: bundlePath)
+    try await addOsLog(toBundle: bundlePath)
+  }
+
   @MainActor
   private func addCrashLogs(toBundle bundlePath: URL) throws {
     #if os(macOS)
@@ -328,7 +354,7 @@ public struct DiagnoseCommand: AsyncParsableCommand {
       await orPrintError { try addCrashLogs(toBundle: bundlePath) }
     }
     if components.isEmpty || components.contains(.logs) {
-      await orPrintError { try await addOsLog(toBundle: bundlePath) }
+      await orPrintError { try await addLogs(toBundle: bundlePath) }
     }
     if components.isEmpty || components.contains(.swiftVersions) {
       await orPrintError { try await addSwiftVersion(toBundle: bundlePath) }

Sources/LSPLogging/CMakeLists.txt

@@ -5,10 +5,12 @@ add_library(LSPLogging STATIC
   LoggingScope.swift
   NonDarwinLogging.swift
   OrLog.swift
+  SetGlobalLogFileHandler.swift
   SplitLogMessage.swift)
 set_target_properties(LSPLogging PROPERTIES
   INTERFACE_INCLUDE_DIRECTORIES ${CMAKE_Swift_MODULE_DIRECTORY})
 target_link_libraries(LSPLogging PRIVATE
+  SwiftExtensions
   $<$<NOT:$<PLATFORM_ID:Darwin>>:Foundation>)
 target_link_libraries(LSPLogging PUBLIC
   Crypto)

Sources/LSPLogging/NonDarwinLogging.swift

@@ -11,6 +11,7 @@
 //===----------------------------------------------------------------------===//
 
 import Foundation
+import SwiftExtensions
 
 // MARK: - Log settings
 
@@ -261,22 +262,34 @@ private let dateFormatter = {
   return dateFormatter
 }()
 
+/// Actor that protects `logHandler`
+@globalActor
+actor LogHandlerActor {
+  static var shared: LogHandlerActor = LogHandlerActor()
+}
+
+/// The handler that is called to log a message from `NonDarwinLogger` unless `overrideLogHandler` is set on the logger.
+@LogHandlerActor
+var logHandler: @Sendable (String) async -> Void = { fputs($0 + "\n", stderr) }
+
 /// The queue on which we log messages.
 ///
 /// A global queue since we create and discard loggers all the time.
-private let loggingQueue: DispatchQueue = DispatchQueue(label: "loggingQueue", qos: .utility)
+private let loggingQueue = AsyncQueue<Serial>()
 
 /// A logger that is designed to be API-compatible with `os.Logger` for all uses
 /// in sourcekit-lsp.
 ///
 /// This logger is used to log messages to stderr on platforms where OSLog is
 /// not available.
+///
+/// `overrideLogHandler` allows capturing of the logged messages for testing purposes.
 public struct NonDarwinLogger: Sendable {
   private let subsystem: String
   private let category: String
   private let logLevel: NonDarwinLogLevel
   private let privacyLevel: NonDarwinLogPrivacy
-  private let logHandler: @Sendable (String) -> Void
+  private let overrideLogHandler: (@Sendable (String) -> Void)?
 
   /// - Parameters:
   ///   - subsystem: See os.Logger
@@ -291,13 +304,13 @@ public struct NonDarwinLogger: Sendable {
     category: String,
     logLevel: NonDarwinLogLevel? = nil,
     privacyLevel: NonDarwinLogPrivacy? = nil,
-    logHandler: @escaping @Sendable (String) -> Void = { fputs($0 + "\n", stderr) }
+    overrideLogHandler: (@Sendable (String) -> Void)? = nil
   ) {
     self.subsystem = subsystem
     self.category = category
     self.logLevel = logLevel ?? LogConfig.logLevel
     self.privacyLevel = privacyLevel ?? LogConfig.privacyLevel
-    self.logHandler = logHandler
+    self.overrideLogHandler = overrideLogHandler
   }
 
   /// Logs the given message at the given level.
@@ -310,7 +323,7 @@ public struct NonDarwinLogger: Sendable {
   ) {
     guard level >= self.logLevel else { return }
     let date = Date()
-    loggingQueue.async {
+    loggingQueue.async(priority: .utility) { @LogHandlerActor in
       // Truncate log message after 10.000 characters to avoid flooding the log with huge log messages (eg. from a
       // sourcekitd response). 10.000 characters was chosen because it seems to fit the result of most sourcekitd
       // responses that are not generated interface or global completion results (which are a lot bigger).
@@ -321,7 +334,7 @@ public struct NonDarwinLogger: Sendable {
         message = message.prefix(10_000) + "..."
       }
       // Start each log message with `[org.swift.sourcekit-lsp` so that it’s easy to split the log to the different messages
-      logHandler(
+      await (overrideLogHandler ?? logHandler)(
         """
         [\(subsystem):\(category)] \(level) \(dateFormatter.string(from: date))
         \(message)
@@ -361,8 +374,8 @@ public struct NonDarwinLogger: Sendable {
   /// Useful for testing to make sure all asynchronous log calls have actually
   /// written their data.
   @_spi(Testing)
-  public static func flush() {
-    loggingQueue.sync {}
+  public static func flush() async {
+    await loggingQueue.async {}.value
   }
 
   public func makeSignposter() -> NonDarwinSignposter {

Sources/LSPLogging/SetGlobalLogFileHandler.swift

@@ -0,0 +1,202 @@
+//===----------------------------------------------------------------------===//
+//
+// 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
+//
+//===----------------------------------------------------------------------===//
+
+import Foundation
+import RegexBuilder
+
+#if os(Windows)
+import WinSDK
+#endif
+
+#if !canImport(os) || SOURCEKITLSP_FORCE_NON_DARWIN_LOGGER
+fileprivate struct FailedToCreateFileError: Error, CustomStringConvertible {
+  let logFile: URL
+
+  var description: String {
+    return "Failed to create log file at \(logFile)"
+  }
+}
+
+/// The number of log file handles that have been created by this process.
+///
+/// See comment on `logFileHandle`.
+@LogHandlerActor
+fileprivate var logRotateIndex = 0
+
+/// The file handle to the current log file. When the file managed by this handle reaches its maximum size, we increment
+/// the `logRotateIndex` by 1 and set the `logFileHandle` to `nil`. This causes a new log file handle with index
+/// `logRotateIndex % logRotateCount` to be created on the next log call.
+@LogHandlerActor
+fileprivate var logFileHandle: FileHandle?
+
+@LogHandlerActor
+func getOrCreateLogFileHandle(logDirectory: URL, logRotateCount: Int) -> FileHandle {
+  if let logFileHandle {
+    return logFileHandle
+  }
+
+  // Name must match the regex in `cleanOldLogFiles` and the prefix in `DiagnoseCommand.addNonDarwinLogs`.
+  let logFileUrl = logDirectory.appendingPathComponent(
+    "sourcekit-lsp-\(ProcessInfo.processInfo.processIdentifier).\(logRotateIndex % logRotateCount).log"
+  )
+
+  do {
+    try FileManager.default.createDirectory(at: logDirectory, withIntermediateDirectories: true)
+    if !FileManager.default.fileExists(atPath: logFileUrl.path) {
+      guard FileManager.default.createFile(atPath: logFileUrl.path, contents: nil) else {
+        throw FailedToCreateFileError(logFile: logFileUrl)
+      }
+    }
+    let newFileHandle = try FileHandle(forWritingTo: logFileUrl)
+    logFileHandle = newFileHandle
+    try newFileHandle.truncate(atOffset: 0)
+    return newFileHandle
+  } catch {
+    // If we fail to create a file handle for the log file, log one message about it to stderr and then log to stderr.
+    // We will try creating a log file again once this section of the log reaches `maxLogFileSize` but that means that
+    // we'll only log this error every `maxLogFileSize` bytes, which is a lot less spammy than logging it on every log
+    // call.
+    fputs("Failed to open file handle for log file at \(logFileUrl.path): \(error)", stderr)
+    logFileHandle = FileHandle.standardError
+    return FileHandle.standardError
+  }
+}
+
+/// Log the given message to a log file in the given log directory.
+///
+/// The name of the log file includes the PID of the current process to make sure it is exclusively writing to the file.
+/// When a log file reaches `logFileMaxBytes`, it will be rotated, with at most `logRotateCount` different log files
+/// being created.
+@LogHandlerActor
+private func logToFile(message: String, logDirectory: URL, logFileMaxBytes: Int, logRotateCount: Int) throws {
+
+  guard let data = message.data(using: .utf8) else {
+    fputs(
+      """
+      Failed to convert log message to UTF-8 data
+      \(message)
+
+      """,
+      stderr
+    )
+    return
+  }
+  let logFileHandleUnwrapped = getOrCreateLogFileHandle(logDirectory: logDirectory, logRotateCount: logRotateCount)
+  try logFileHandleUnwrapped.write(contentsOf: data)
+
+  // If this log file has exceeded the maximum size, start writing to a new log file.
+  if try logFileHandleUnwrapped.offset() > logFileMaxBytes {
+    logRotateIndex += 1
+    // Resetting `logFileHandle` will cause a new logFileHandle to be created on the next log call.
+    logFileHandle = nil
+  }
+}
+
+/// If the file at the given path is writable, redirect log messages handled by `NonDarwinLogHandler` to the given file.
+///
+/// Occasionally checks that the log does not exceed `targetLogSize` (in bytes) and truncates the beginning of the log
+/// when it does.
+@LogHandlerActor
+private func setUpGlobalLogFileHandlerImpl(logFileDirectory: URL, logFileMaxBytes: Int, logRotateCount: Int) {
+  logHandler = { @LogHandlerActor message in
+    do {
+      try logToFile(
+        message: message,
+        logDirectory: logFileDirectory,
+        logFileMaxBytes: logFileMaxBytes,
+        logRotateCount: logRotateCount
+      )
+    } catch {
+      fputs(
+        """
+        Failed to write message to log file: \(error)
+        \(message)
+
+        """,
+        stderr
+      )
+    }
+  }
+}
+
+/// Returns `true` if a process with the given PID still exists and is alive.
+private func isProcessAlive(pid: Int32) -> Bool {
+  #if os(Windows)
+  if let handle = OpenProcess(UInt32(PROCESS_QUERY_INFORMATION), /*bInheritHandle=*/ false, UInt32(pid)) {
+    CloseHandle(handle)
+    return true
+  }
+  return false
+  #else
+  return kill(pid, 0) == 0
+  #endif
+}
+
+private func cleanOldLogFilesImpl(logFileDirectory: URL, maxAge: TimeInterval) {
+  let enumerator = FileManager.default.enumerator(at: logFileDirectory, includingPropertiesForKeys: nil)
+  while let url = enumerator?.nextObject() as? URL {
+    let name = url.lastPathComponent
+    let regex = Regex {
+      "sourcekit-lsp-"
+      Capture(ZeroOrMore(.digit))
+      "."
+      ZeroOrMore(.digit)
+      ".log"
+    }
+    guard let match = name.matches(of: regex).only, let pid = Int32(match.1) else {
+      continue
+    }
+    if isProcessAlive(pid: pid) {
+      // Process that owns this log file is still alive. Don't delete it.
+      continue
+    }
+    guard
+      let modificationDate = orLog(
+        "Getting mtime of old log file",
+        { try FileManager.default.attributesOfItem(atPath: url.path)[.modificationDate] }
+      ) as? Date,
+      Date().timeIntervalSince(modificationDate) > maxAge
+    else {
+      // File has been modified in the last hour. Don't delete it because it's useful to diagnose issues after
+      // sourcekit-lsp has exited.
+      continue
+    }
+    orLog("Deleting old log file") { try FileManager.default.removeItem(at: url) }
+  }
+}
+#endif
+
+/// If the file at the given path is writable, redirect log messages handled by `NonDarwinLogHandler` to the given file.
+///
+/// Occasionally checks that the log does not exceed `targetLogSize` (in bytes) and truncates the beginning of the log
+/// when it does.
+///
+/// No-op when using OSLog.
+public func setUpGlobalLogFileHandler(logFileDirectory: URL, logFileMaxBytes: Int, logRotateCount: Int) async {
+  #if !canImport(os) || SOURCEKITLSP_FORCE_NON_DARWIN_LOGGER
+  await setUpGlobalLogFileHandlerImpl(
+    logFileDirectory: logFileDirectory,
+    logFileMaxBytes: logFileMaxBytes,
+    logRotateCount: logRotateCount
+  )
+  #endif
+}
+
+/// Deletes all sourcekit-lsp log files in `logFilesDirectory` that are not associated with a running process and that
+/// haven't been modified within the last hour.
+///
+/// No-op when using OSLog.
+public func cleanOldLogFiles(logFileDirectory: URL, maxAge: TimeInterval) {
+  #if !canImport(os) || SOURCEKITLSP_FORCE_NON_DARWIN_LOGGER
+  cleanOldLogFilesImpl(logFileDirectory: logFileDirectory, maxAge: maxAge)
+  #endif
+}

Sources/sourcekit-lsp/SourceKitLSP.swift

@@ -242,6 +242,15 @@ struct SourceKitLSP: AsyncParsableCommand {
 
     let realStdoutHandle = FileHandle(fileDescriptor: realStdout, closeOnDealloc: false)
 
+    // Directory should match the directory we are searching for logs in `DiagnoseCommand.addNonDarwinLogs`.
+    let logFileDirectoryURL = URL(fileURLWithPath: ("~/.sourcekit-lsp/logs" as NSString).expandingTildeInPath)
+    await setUpGlobalLogFileHandler(
+      logFileDirectory: logFileDirectoryURL,
+      logFileMaxBytes: 5_000_000,
+      logRotateCount: 10
+    )
+    cleanOldLogFiles(logFileDirectory: logFileDirectoryURL, maxAge: 60 * 60 /* 1h */)
+
     let clientConnection = JSONRPCConnection(
       name: "client",
       protocol: MessageRegistry.lspProtocol,