From 7d3b44079ac6cc89e065ddb8b21190d15f0e354d Mon Sep 17 00:00:00 2001 From: Alex Hoppen Date: Mon, 3 Jun 2024 12:56:44 -0700 Subject: [PATCH] Write log messages to files on non-Darwin platforms Instead of logging to `stderr`, write log messages to files in `.sourcekit-lsp/logs/sourcekit-lsp-..log`. This allows us to retrieve the log messages from `sourcekit-lsp diagnose`. Fixes #1286 rdar://127138318 --- Package.swift | 3 +- Sources/Diagnose/DiagnoseCommand.swift | 28 ++- Sources/LSPLogging/CMakeLists.txt | 2 + Sources/LSPLogging/NonDarwinLogging.swift | 29 ++- .../LSPLogging/SetGlobalLogFileHandler.swift | 202 ++++++++++++++++++ Sources/sourcekit-lsp/SourceKitLSP.swift | 9 + Tests/LSPLoggingTests/LoggingTests.swift | 46 ++-- 7 files changed, 286 insertions(+), 33 deletions(-) create mode 100644 Sources/LSPLogging/SetGlobalLogFileHandler.swift diff --git a/Package.swift b/Package.swift index c9f932632..e9bcd1d88 100644 --- a/Package.swift +++ b/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")] diff --git a/Sources/Diagnose/DiagnoseCommand.swift b/Sources/Diagnose/DiagnoseCommand.swift index d58f3b289..0cb71757e 100644 --- a/Sources/Diagnose/DiagnoseCommand.swift +++ b/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) } diff --git a/Sources/LSPLogging/CMakeLists.txt b/Sources/LSPLogging/CMakeLists.txt index 615754910..c2313dd91 100644 --- a/Sources/LSPLogging/CMakeLists.txt +++ b/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 $<$>:Foundation>) target_link_libraries(LSPLogging PUBLIC Crypto) diff --git a/Sources/LSPLogging/NonDarwinLogging.swift b/Sources/LSPLogging/NonDarwinLogging.swift index 045fc5b22..2f1301dea 100644 --- a/Sources/LSPLogging/NonDarwinLogging.swift +++ b/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() /// 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 { diff --git a/Sources/LSPLogging/SetGlobalLogFileHandler.swift b/Sources/LSPLogging/SetGlobalLogFileHandler.swift new file mode 100644 index 000000000..659365df7 --- /dev/null +++ b/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 +} diff --git a/Sources/sourcekit-lsp/SourceKitLSP.swift b/Sources/sourcekit-lsp/SourceKitLSP.swift index 3b89b55b8..22f2291ae 100644 --- a/Sources/sourcekit-lsp/SourceKitLSP.swift +++ b/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, diff --git a/Tests/LSPLoggingTests/LoggingTests.swift b/Tests/LSPLoggingTests/LoggingTests.swift index 8e596704c..5ce3cc663 100644 --- a/Tests/LSPLoggingTests/LoggingTests.swift +++ b/Tests/LSPLoggingTests/LoggingTests.swift @@ -21,7 +21,7 @@ fileprivate func assertLogging( _ body: (NonDarwinLogger) -> Void, file: StaticString = #filePath, line: UInt = #line -) { +) async { // nonisolated(unsafe) because calls of `assertLogging` do not log to `logHandler` concurrently. nonisolated(unsafe) var messages: [String] = [] let logger = NonDarwinLogger( @@ -29,10 +29,10 @@ fileprivate func assertLogging( category: "test", logLevel: logLevel, privacyLevel: privacyLevel, - logHandler: { messages.append($0) } + overrideLogHandler: { messages.append($0) } ) body(logger) - NonDarwinLogger.flush() + await NonDarwinLogger.flush() guard messages.count == expected.count else { XCTFail( """ @@ -77,7 +77,7 @@ final class LoggingTests: XCTestCase { let logger = NonDarwinLogger( subsystem: LoggingScope.subsystem, category: "test", - logHandler: { + overrideLogHandler: { message = $0 expectation.fulfill() } @@ -91,27 +91,27 @@ final class LoggingTests: XCTestCase { XCTAssert(message.hasSuffix("\nmy message\n---"), "Message did not have expected body. Received \n\(message)") } - func testLoggingBasic() { - assertLogging( + func testLoggingBasic() async { + await assertLogging( expected: ["a"], { $0.log("a") } ) - assertLogging( + await assertLogging( expected: [], { _ in } ) - assertLogging(expected: ["b\n\nc"]) { + await assertLogging(expected: ["b\n\nc"]) { $0.log("b\n\nc") } } - func testLogLevels() { - assertLogging( + func testLogLevels() async { + await assertLogging( logLevel: .default, expected: ["d", "e", "f"] ) { @@ -122,7 +122,7 @@ final class LoggingTests: XCTestCase { $0.debug("h") } - assertLogging( + await assertLogging( logLevel: .error, expected: ["d", "e"] ) { @@ -133,7 +133,7 @@ final class LoggingTests: XCTestCase { $0.debug("h") } - assertLogging( + await assertLogging( logLevel: .fault, expected: ["d"] ) { @@ -145,23 +145,23 @@ final class LoggingTests: XCTestCase { } } - func testPrivacyMaskingLevels() { - assertLogging(expected: ["password is "]) { + func testPrivacyMaskingLevels() async { + await assertLogging(expected: ["password is "]) { let password: String = "1234" $0.log("password is \(password, privacy: .sensitive)") } - assertLogging(expected: ["username is root"]) { + await assertLogging(expected: ["username is root"]) { let username: String = "root" $0.log("username is \(username, privacy: .private)") } - assertLogging(expected: ["username is root"]) { + await assertLogging(expected: ["username is root"]) { let username: String = "root" $0.log("username is \(username)") } - assertLogging( + await assertLogging( privacyLevel: .public, expected: ["username is "] ) { @@ -169,7 +169,7 @@ final class LoggingTests: XCTestCase { $0.log("username is \(username, privacy: .private)") } - assertLogging( + await assertLogging( privacyLevel: .public, expected: ["username is "] ) { @@ -178,15 +178,15 @@ final class LoggingTests: XCTestCase { } } - func testPrivacyMaskingTypes() { - assertLogging( + func testPrivacyMaskingTypes() async { + await assertLogging( privacyLevel: .public, expected: ["logging a static string"] ) { $0.log("logging a \("static string")") } - assertLogging( + await assertLogging( privacyLevel: .public, expected: ["logging from LSPLoggingTests.LoggingTests"] ) { @@ -198,14 +198,14 @@ final class LoggingTests: XCTestCase { var redactedDescription: String = "redacted description" } - assertLogging( + await assertLogging( privacyLevel: .public, expected: ["got redacted description"] ) { $0.log("got \(LogStringConvertible().forLogging)") } - assertLogging( + await assertLogging( privacyLevel: .private, expected: ["got full description"] ) {