Skip to content

Commit 6f7bffa

Browse files
authored
Merge pull request #1411 from ahoppen/log-to-file
Write log messages to files on non-Darwin platforms
2 parents e9d0ceb + 7d3b440 commit 6f7bffa

File tree

7 files changed

+286
-33
lines changed

7 files changed

+286
-33
lines changed

Package.swift

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -161,7 +161,8 @@ let package = Package(
161161
.target(
162162
name: "LSPLogging",
163163
dependencies: [
164-
.product(name: "Crypto", package: "swift-crypto")
164+
"SwiftExtensions",
165+
.product(name: "Crypto", package: "swift-crypto"),
165166
],
166167
exclude: ["CMakeLists.txt"],
167168
swiftSettings: lspLoggingSwiftSettings + [.enableExperimentalFeature("StrictConcurrency")]

Sources/Diagnose/DiagnoseCommand.swift

Lines changed: 27 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -240,6 +240,32 @@ public struct DiagnoseCommand: AsyncParsableCommand {
240240
#endif
241241
}
242242

243+
@MainActor
244+
private func addNonDarwinLogs(toBundle bundlePath: URL) async throws {
245+
reportProgress(.collectingLogMessages(progress: 0), message: "Collecting log files")
246+
247+
let destinationDir = bundlePath.appendingPathComponent("logs")
248+
try FileManager.default.createDirectory(at: destinationDir, withIntermediateDirectories: true)
249+
250+
let logFileDirectoryURL = URL(fileURLWithPath: ("~/.sourcekit-lsp/logs" as NSString).expandingTildeInPath)
251+
let enumerator = FileManager.default.enumerator(at: logFileDirectoryURL, includingPropertiesForKeys: nil)
252+
while let fileUrl = enumerator?.nextObject() as? URL {
253+
guard fileUrl.lastPathComponent.hasPrefix("sourcekit-lsp") else {
254+
continue
255+
}
256+
try? FileManager.default.copyItem(
257+
at: fileUrl,
258+
to: destinationDir.appendingPathComponent(fileUrl.lastPathComponent)
259+
)
260+
}
261+
}
262+
263+
@MainActor
264+
private func addLogs(toBundle bundlePath: URL) async throws {
265+
try await addNonDarwinLogs(toBundle: bundlePath)
266+
try await addOsLog(toBundle: bundlePath)
267+
}
268+
243269
@MainActor
244270
private func addCrashLogs(toBundle bundlePath: URL) throws {
245271
#if os(macOS)
@@ -340,7 +366,7 @@ public struct DiagnoseCommand: AsyncParsableCommand {
340366
await orPrintError { try addCrashLogs(toBundle: bundlePath) }
341367
}
342368
if components.isEmpty || components.contains(.logs) {
343-
await orPrintError { try await addOsLog(toBundle: bundlePath) }
369+
await orPrintError { try await addLogs(toBundle: bundlePath) }
344370
}
345371
if components.isEmpty || components.contains(.swiftVersions) {
346372
await orPrintError { try await addSwiftVersion(toBundle: bundlePath) }

Sources/LSPLogging/CMakeLists.txt

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,10 +5,12 @@ add_library(LSPLogging STATIC
55
LoggingScope.swift
66
NonDarwinLogging.swift
77
OrLog.swift
8+
SetGlobalLogFileHandler.swift
89
SplitLogMessage.swift)
910
set_target_properties(LSPLogging PROPERTIES
1011
INTERFACE_INCLUDE_DIRECTORIES ${CMAKE_Swift_MODULE_DIRECTORY})
1112
target_link_libraries(LSPLogging PRIVATE
13+
SwiftExtensions
1214
$<$<NOT:$<PLATFORM_ID:Darwin>>:Foundation>)
1315
target_link_libraries(LSPLogging PUBLIC
1416
Crypto)

Sources/LSPLogging/NonDarwinLogging.swift

Lines changed: 21 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@
1111
//===----------------------------------------------------------------------===//
1212

1313
import Foundation
14+
import SwiftExtensions
1415

1516
// MARK: - Log settings
1617

@@ -261,22 +262,34 @@ private let dateFormatter = {
261262
return dateFormatter
262263
}()
263264

265+
/// Actor that protects `logHandler`
266+
@globalActor
267+
actor LogHandlerActor {
268+
static var shared: LogHandlerActor = LogHandlerActor()
269+
}
270+
271+
/// The handler that is called to log a message from `NonDarwinLogger` unless `overrideLogHandler` is set on the logger.
272+
@LogHandlerActor
273+
var logHandler: @Sendable (String) async -> Void = { fputs($0 + "\n", stderr) }
274+
264275
/// The queue on which we log messages.
265276
///
266277
/// A global queue since we create and discard loggers all the time.
267-
private let loggingQueue: DispatchQueue = DispatchQueue(label: "loggingQueue", qos: .utility)
278+
private let loggingQueue = AsyncQueue<Serial>()
268279

269280
/// A logger that is designed to be API-compatible with `os.Logger` for all uses
270281
/// in sourcekit-lsp.
271282
///
272283
/// This logger is used to log messages to stderr on platforms where OSLog is
273284
/// not available.
285+
///
286+
/// `overrideLogHandler` allows capturing of the logged messages for testing purposes.
274287
public struct NonDarwinLogger: Sendable {
275288
private let subsystem: String
276289
private let category: String
277290
private let logLevel: NonDarwinLogLevel
278291
private let privacyLevel: NonDarwinLogPrivacy
279-
private let logHandler: @Sendable (String) -> Void
292+
private let overrideLogHandler: (@Sendable (String) -> Void)?
280293

281294
/// - Parameters:
282295
/// - subsystem: See os.Logger
@@ -291,13 +304,13 @@ public struct NonDarwinLogger: Sendable {
291304
category: String,
292305
logLevel: NonDarwinLogLevel? = nil,
293306
privacyLevel: NonDarwinLogPrivacy? = nil,
294-
logHandler: @escaping @Sendable (String) -> Void = { fputs($0 + "\n", stderr) }
307+
overrideLogHandler: (@Sendable (String) -> Void)? = nil
295308
) {
296309
self.subsystem = subsystem
297310
self.category = category
298311
self.logLevel = logLevel ?? LogConfig.logLevel
299312
self.privacyLevel = privacyLevel ?? LogConfig.privacyLevel
300-
self.logHandler = logHandler
313+
self.overrideLogHandler = overrideLogHandler
301314
}
302315

303316
/// Logs the given message at the given level.
@@ -310,7 +323,7 @@ public struct NonDarwinLogger: Sendable {
310323
) {
311324
guard level >= self.logLevel else { return }
312325
let date = Date()
313-
loggingQueue.async {
326+
loggingQueue.async(priority: .utility) { @LogHandlerActor in
314327
// Truncate log message after 10.000 characters to avoid flooding the log with huge log messages (eg. from a
315328
// sourcekitd response). 10.000 characters was chosen because it seems to fit the result of most sourcekitd
316329
// responses that are not generated interface or global completion results (which are a lot bigger).
@@ -321,7 +334,7 @@ public struct NonDarwinLogger: Sendable {
321334
message = message.prefix(10_000) + "..."
322335
}
323336
// Start each log message with `[org.swift.sourcekit-lsp` so that it’s easy to split the log to the different messages
324-
logHandler(
337+
await (overrideLogHandler ?? logHandler)(
325338
"""
326339
[\(subsystem):\(category)] \(level) \(dateFormatter.string(from: date))
327340
\(message)
@@ -361,8 +374,8 @@ public struct NonDarwinLogger: Sendable {
361374
/// Useful for testing to make sure all asynchronous log calls have actually
362375
/// written their data.
363376
@_spi(Testing)
364-
public static func flush() {
365-
loggingQueue.sync {}
377+
public static func flush() async {
378+
await loggingQueue.async {}.value
366379
}
367380

368381
public func makeSignposter() -> NonDarwinSignposter {
Lines changed: 202 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,202 @@
1+
//===----------------------------------------------------------------------===//
2+
//
3+
// This source file is part of the Swift.org open source project
4+
//
5+
// Copyright (c) 2014 - 2023 Apple Inc. and the Swift project authors
6+
// Licensed under Apache License v2.0 with Runtime Library Exception
7+
//
8+
// See https://swift.org/LICENSE.txt for license information
9+
// See https://swift.org/CONTRIBUTORS.txt for the list of Swift project authors
10+
//
11+
//===----------------------------------------------------------------------===//
12+
13+
import Foundation
14+
import RegexBuilder
15+
16+
#if os(Windows)
17+
import WinSDK
18+
#endif
19+
20+
#if !canImport(os) || SOURCEKITLSP_FORCE_NON_DARWIN_LOGGER
21+
fileprivate struct FailedToCreateFileError: Error, CustomStringConvertible {
22+
let logFile: URL
23+
24+
var description: String {
25+
return "Failed to create log file at \(logFile)"
26+
}
27+
}
28+
29+
/// The number of log file handles that have been created by this process.
30+
///
31+
/// See comment on `logFileHandle`.
32+
@LogHandlerActor
33+
fileprivate var logRotateIndex = 0
34+
35+
/// The file handle to the current log file. When the file managed by this handle reaches its maximum size, we increment
36+
/// the `logRotateIndex` by 1 and set the `logFileHandle` to `nil`. This causes a new log file handle with index
37+
/// `logRotateIndex % logRotateCount` to be created on the next log call.
38+
@LogHandlerActor
39+
fileprivate var logFileHandle: FileHandle?
40+
41+
@LogHandlerActor
42+
func getOrCreateLogFileHandle(logDirectory: URL, logRotateCount: Int) -> FileHandle {
43+
if let logFileHandle {
44+
return logFileHandle
45+
}
46+
47+
// Name must match the regex in `cleanOldLogFiles` and the prefix in `DiagnoseCommand.addNonDarwinLogs`.
48+
let logFileUrl = logDirectory.appendingPathComponent(
49+
"sourcekit-lsp-\(ProcessInfo.processInfo.processIdentifier).\(logRotateIndex % logRotateCount).log"
50+
)
51+
52+
do {
53+
try FileManager.default.createDirectory(at: logDirectory, withIntermediateDirectories: true)
54+
if !FileManager.default.fileExists(atPath: logFileUrl.path) {
55+
guard FileManager.default.createFile(atPath: logFileUrl.path, contents: nil) else {
56+
throw FailedToCreateFileError(logFile: logFileUrl)
57+
}
58+
}
59+
let newFileHandle = try FileHandle(forWritingTo: logFileUrl)
60+
logFileHandle = newFileHandle
61+
try newFileHandle.truncate(atOffset: 0)
62+
return newFileHandle
63+
} catch {
64+
// If we fail to create a file handle for the log file, log one message about it to stderr and then log to stderr.
65+
// We will try creating a log file again once this section of the log reaches `maxLogFileSize` but that means that
66+
// we'll only log this error every `maxLogFileSize` bytes, which is a lot less spammy than logging it on every log
67+
// call.
68+
fputs("Failed to open file handle for log file at \(logFileUrl.path): \(error)", stderr)
69+
logFileHandle = FileHandle.standardError
70+
return FileHandle.standardError
71+
}
72+
}
73+
74+
/// Log the given message to a log file in the given log directory.
75+
///
76+
/// The name of the log file includes the PID of the current process to make sure it is exclusively writing to the file.
77+
/// When a log file reaches `logFileMaxBytes`, it will be rotated, with at most `logRotateCount` different log files
78+
/// being created.
79+
@LogHandlerActor
80+
private func logToFile(message: String, logDirectory: URL, logFileMaxBytes: Int, logRotateCount: Int) throws {
81+
82+
guard let data = message.data(using: .utf8) else {
83+
fputs(
84+
"""
85+
Failed to convert log message to UTF-8 data
86+
\(message)
87+
88+
""",
89+
stderr
90+
)
91+
return
92+
}
93+
let logFileHandleUnwrapped = getOrCreateLogFileHandle(logDirectory: logDirectory, logRotateCount: logRotateCount)
94+
try logFileHandleUnwrapped.write(contentsOf: data)
95+
96+
// If this log file has exceeded the maximum size, start writing to a new log file.
97+
if try logFileHandleUnwrapped.offset() > logFileMaxBytes {
98+
logRotateIndex += 1
99+
// Resetting `logFileHandle` will cause a new logFileHandle to be created on the next log call.
100+
logFileHandle = nil
101+
}
102+
}
103+
104+
/// If the file at the given path is writable, redirect log messages handled by `NonDarwinLogHandler` to the given file.
105+
///
106+
/// Occasionally checks that the log does not exceed `targetLogSize` (in bytes) and truncates the beginning of the log
107+
/// when it does.
108+
@LogHandlerActor
109+
private func setUpGlobalLogFileHandlerImpl(logFileDirectory: URL, logFileMaxBytes: Int, logRotateCount: Int) {
110+
logHandler = { @LogHandlerActor message in
111+
do {
112+
try logToFile(
113+
message: message,
114+
logDirectory: logFileDirectory,
115+
logFileMaxBytes: logFileMaxBytes,
116+
logRotateCount: logRotateCount
117+
)
118+
} catch {
119+
fputs(
120+
"""
121+
Failed to write message to log file: \(error)
122+
\(message)
123+
124+
""",
125+
stderr
126+
)
127+
}
128+
}
129+
}
130+
131+
/// Returns `true` if a process with the given PID still exists and is alive.
132+
private func isProcessAlive(pid: Int32) -> Bool {
133+
#if os(Windows)
134+
if let handle = OpenProcess(UInt32(PROCESS_QUERY_INFORMATION), /*bInheritHandle=*/ false, UInt32(pid)) {
135+
CloseHandle(handle)
136+
return true
137+
}
138+
return false
139+
#else
140+
return kill(pid, 0) == 0
141+
#endif
142+
}
143+
144+
private func cleanOldLogFilesImpl(logFileDirectory: URL, maxAge: TimeInterval) {
145+
let enumerator = FileManager.default.enumerator(at: logFileDirectory, includingPropertiesForKeys: nil)
146+
while let url = enumerator?.nextObject() as? URL {
147+
let name = url.lastPathComponent
148+
let regex = Regex {
149+
"sourcekit-lsp-"
150+
Capture(ZeroOrMore(.digit))
151+
"."
152+
ZeroOrMore(.digit)
153+
".log"
154+
}
155+
guard let match = name.matches(of: regex).only, let pid = Int32(match.1) else {
156+
continue
157+
}
158+
if isProcessAlive(pid: pid) {
159+
// Process that owns this log file is still alive. Don't delete it.
160+
continue
161+
}
162+
guard
163+
let modificationDate = orLog(
164+
"Getting mtime of old log file",
165+
{ try FileManager.default.attributesOfItem(atPath: url.path)[.modificationDate] }
166+
) as? Date,
167+
Date().timeIntervalSince(modificationDate) > maxAge
168+
else {
169+
// File has been modified in the last hour. Don't delete it because it's useful to diagnose issues after
170+
// sourcekit-lsp has exited.
171+
continue
172+
}
173+
orLog("Deleting old log file") { try FileManager.default.removeItem(at: url) }
174+
}
175+
}
176+
#endif
177+
178+
/// If the file at the given path is writable, redirect log messages handled by `NonDarwinLogHandler` to the given file.
179+
///
180+
/// Occasionally checks that the log does not exceed `targetLogSize` (in bytes) and truncates the beginning of the log
181+
/// when it does.
182+
///
183+
/// No-op when using OSLog.
184+
public func setUpGlobalLogFileHandler(logFileDirectory: URL, logFileMaxBytes: Int, logRotateCount: Int) async {
185+
#if !canImport(os) || SOURCEKITLSP_FORCE_NON_DARWIN_LOGGER
186+
await setUpGlobalLogFileHandlerImpl(
187+
logFileDirectory: logFileDirectory,
188+
logFileMaxBytes: logFileMaxBytes,
189+
logRotateCount: logRotateCount
190+
)
191+
#endif
192+
}
193+
194+
/// Deletes all sourcekit-lsp log files in `logFilesDirectory` that are not associated with a running process and that
195+
/// haven't been modified within the last hour.
196+
///
197+
/// No-op when using OSLog.
198+
public func cleanOldLogFiles(logFileDirectory: URL, maxAge: TimeInterval) {
199+
#if !canImport(os) || SOURCEKITLSP_FORCE_NON_DARWIN_LOGGER
200+
cleanOldLogFilesImpl(logFileDirectory: logFileDirectory, maxAge: maxAge)
201+
#endif
202+
}

Sources/sourcekit-lsp/SourceKitLSP.swift

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -242,6 +242,15 @@ struct SourceKitLSP: AsyncParsableCommand {
242242

243243
let realStdoutHandle = FileHandle(fileDescriptor: realStdout, closeOnDealloc: false)
244244

245+
// Directory should match the directory we are searching for logs in `DiagnoseCommand.addNonDarwinLogs`.
246+
let logFileDirectoryURL = URL(fileURLWithPath: ("~/.sourcekit-lsp/logs" as NSString).expandingTildeInPath)
247+
await setUpGlobalLogFileHandler(
248+
logFileDirectory: logFileDirectoryURL,
249+
logFileMaxBytes: 5_000_000,
250+
logRotateCount: 10
251+
)
252+
cleanOldLogFiles(logFileDirectory: logFileDirectoryURL, maxAge: 60 * 60 /* 1h */)
253+
245254
let clientConnection = JSONRPCConnection(
246255
name: "client",
247256
protocol: MessageRegistry.lspProtocol,

0 commit comments

Comments
 (0)