Skip to content

Commit 0ba3840

Browse files
committed
Write log messages to files on Linux
Instead of logging to `stderr`, write log messages to files in `.sourcekit-lsp/logs/sourcekit-lsp-<pid>.<log index>.log`. This allows us to retrieve the log messages from `sourcekit-lsp diagnose`. We should be able to expand this to also write to log files on Windows but I still need to figure out what an appropriate log directory might be. That will be a follow-up PR. Fixes #1286 rdar://127138318
1 parent 9c13dbb commit 0ba3840

File tree

7 files changed

+272
-33
lines changed

7 files changed

+272
-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
@@ -232,6 +232,32 @@ public struct DiagnoseCommand: AsyncParsableCommand {
232232
#endif
233233
}
234234

235+
@MainActor
236+
private func addNonDarwinLogs(toBundle bundlePath: URL) async throws {
237+
reportProgress(.collectingLogMessages(progress: 0), message: "Collecting log files")
238+
239+
let destinationDir = bundlePath.appendingPathComponent("logs")
240+
try FileManager.default.createDirectory(at: destinationDir, withIntermediateDirectories: true)
241+
242+
let logFileDirectoryURL = URL(fileURLWithPath: ("~/.sourcekit-lsp/logs" as NSString).expandingTildeInPath)
243+
let enumerator = FileManager.default.enumerator(at: logFileDirectoryURL, includingPropertiesForKeys: nil)
244+
while let fileUrl = enumerator?.nextObject() as? URL {
245+
guard fileUrl.lastPathComponent.hasPrefix("sourcekit-lsp") else {
246+
continue
247+
}
248+
try? FileManager.default.copyItem(
249+
at: fileUrl,
250+
to: destinationDir.appendingPathComponent(fileUrl.lastPathComponent)
251+
)
252+
}
253+
}
254+
255+
@MainActor
256+
private func addLogs(toBundle bundlePath: URL) async throws {
257+
try await addNonDarwinLogs(toBundle: bundlePath)
258+
try await addOsLog(toBundle: bundlePath)
259+
}
260+
235261
@MainActor
236262
private func addCrashLogs(toBundle bundlePath: URL) throws {
237263
#if os(macOS)
@@ -328,7 +354,7 @@ public struct DiagnoseCommand: AsyncParsableCommand {
328354
await orPrintError { try addCrashLogs(toBundle: bundlePath) }
329355
}
330356
if components.isEmpty || components.contains(.logs) {
331-
await orPrintError { try await addOsLog(toBundle: bundlePath) }
357+
await orPrintError { try await addLogs(toBundle: bundlePath) }
332358
}
333359
if components.isEmpty || components.contains(.swiftVersions) {
334360
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: 188 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,188 @@
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 !canImport(os) || SOURCEKITLSP_FORCE_NON_DARWIN_LOGGER
17+
fileprivate struct FailedToCreateFileError: Error, CustomStringConvertible {
18+
let logFile: URL
19+
20+
var description: String {
21+
return "Failed to create log file at \(logFile)"
22+
}
23+
}
24+
25+
/// The number of log file handles that have been created by this process.
26+
///
27+
/// See comment on `logFileHandle`.
28+
@LogHandlerActor
29+
fileprivate var logRotateIndex = 0
30+
31+
/// The file handle to the current log file. When the file managed by this handle reaches its maximum size, we increment
32+
/// the `logRotateIndex` by 1 and set the `logFileHandle` to `nil`. This causes a new log file handle with index
33+
/// `logRotateIndex % logRotateCount` to be created on the next log call.
34+
@LogHandlerActor
35+
fileprivate var logFileHandle: FileHandle?
36+
37+
@LogHandlerActor
38+
func getOrCreateLogFileHandle(logDirectory: URL, logRotateCount: Int) -> FileHandle {
39+
if let logFileHandle {
40+
return logFileHandle
41+
}
42+
43+
// Name must match the regex in `cleanOldLogFiles` and the prefix in `DiagnoseCommand.addNonDarwinLogs`.
44+
let logFileUrl = logDirectory.appendingPathComponent(
45+
"sourcekit-lsp-\(ProcessInfo.processInfo.processIdentifier).\(logRotateIndex % logRotateCount).log"
46+
)
47+
48+
do {
49+
try FileManager.default.createDirectory(at: logDirectory, withIntermediateDirectories: true)
50+
if !FileManager.default.fileExists(atPath: logFileUrl.path) {
51+
guard FileManager.default.createFile(atPath: logFileUrl.path, contents: nil) else {
52+
throw FailedToCreateFileError(logFile: logFileUrl)
53+
}
54+
}
55+
let newFileHandle = try FileHandle(
56+
forWritingTo: logDirectory.appendingPathComponent(
57+
"sourcekit-lsp-\(ProcessInfo.processInfo.processIdentifier).\(logRotateIndex % logRotateCount).log"
58+
)
59+
)
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 the given log file handle.
75+
///
76+
/// Occasionally check if the log file exceeds the target log size. If this is the case, truncate the beginning of the
77+
/// log to reduce the log size.
78+
@LogHandlerActor
79+
private func logToFile(message: String, logDirectory: URL, logFileMaxBytes: Int, logRotateCount: Int) throws {
80+
81+
guard let data = message.data(using: .utf8) else {
82+
fputs(
83+
"""
84+
Failed to convert log message to UTF-8 data
85+
\(message)
86+
87+
""",
88+
stderr
89+
)
90+
return
91+
}
92+
let logFileHandleUnwrapped = getOrCreateLogFileHandle(logDirectory: logDirectory, logRotateCount: logRotateCount)
93+
try logFileHandleUnwrapped.write(contentsOf: data)
94+
95+
// If this log file has exceeded the maximum size, start writing to a new log file.
96+
if try logFileHandleUnwrapped.offset() > logFileMaxBytes {
97+
logRotateIndex += 1
98+
// Resetting `logFileHandle` will cause a new logFileHandle to be created on the next log call.
99+
logFileHandle = nil
100+
}
101+
}
102+
103+
/// If the file at the given path is writable, redirect log messages handled by `NonDarwinLogHandler` to the given file.
104+
///
105+
/// Occasionally checks that the log does not exceed `targetLogSize` (in bytes) and truncates the beginning of the log
106+
/// when it does.
107+
@LogHandlerActor
108+
private func setUpGlobalLogFileHandlerImpl(logFileDirectory: URL, logFileMaxBytes: Int, logRotateCount: Int) {
109+
logHandler = { @LogHandlerActor message in
110+
do {
111+
try logToFile(
112+
message: message,
113+
logDirectory: logFileDirectory,
114+
logFileMaxBytes: logFileMaxBytes,
115+
logRotateCount: logRotateCount
116+
)
117+
} catch {
118+
fputs(
119+
"""
120+
Failed to write message to log file: \(error)
121+
\(message)
122+
123+
""",
124+
stderr
125+
)
126+
}
127+
}
128+
}
129+
130+
private func cleanOldLogFilesImpl(logFileDirectory: URL, maxAge: TimeInterval) {
131+
let enumerator = FileManager.default.enumerator(at: logFileDirectory, includingPropertiesForKeys: nil)
132+
while let url = enumerator?.nextObject() as? URL {
133+
let name = url.lastPathComponent
134+
let regex = Regex {
135+
"sourcekit-lsp-"
136+
Capture(ZeroOrMore(.digit))
137+
"."
138+
ZeroOrMore(.digit)
139+
".log"
140+
}
141+
guard let match = name.matches(of: regex).only, let pid = Int32(match.1) else {
142+
continue
143+
}
144+
if kill(pid, 0) == 0 {
145+
// Process that owns this log file is still alive. Don't delete it.
146+
continue
147+
}
148+
guard
149+
let modificationDate = orLog(
150+
"Getting mtime of old log file",
151+
{ try FileManager.default.attributesOfItem(atPath: url.path)[.modificationDate] }
152+
) as? Date,
153+
Date().timeIntervalSince(modificationDate) > maxAge
154+
else {
155+
// File has been modified in the last hour. Don't delete it because it's useful to diagnose issues after
156+
// sourcekit-lsp has exited.
157+
continue
158+
}
159+
orLog("Deleting old log file") { try FileManager.default.removeItem(at: url) }
160+
}
161+
}
162+
#endif
163+
164+
/// If the file at the given path is writable, redirect log messages handled by `NonDarwinLogHandler` to the given file.
165+
///
166+
/// Occasionally checks that the log does not exceed `targetLogSize` (in bytes) and truncates the beginning of the log
167+
/// when it does.
168+
///
169+
/// No-op when using OSLog.
170+
public func setUpGlobalLogFileHandler(logFileDirectory: URL, logFileMaxBytes: Int, logRotateCount: Int) async {
171+
#if !canImport(os) || SOURCEKITLSP_FORCE_NON_DARWIN_LOGGER
172+
await setUpGlobalLogFileHandlerImpl(
173+
logFileDirectory: logFileDirectory,
174+
logFileMaxBytes: logFileMaxBytes,
175+
logRotateCount: logRotateCount
176+
)
177+
#endif
178+
}
179+
180+
/// Deletes all sourcekit-lsp log files in `logFilesDirectory` that are not associated with a running process and that
181+
/// haven't been modified within the last hour.
182+
///
183+
/// No-op when using OSLog.
184+
public func cleanOldLogFiles(logFileDirectory: URL, maxAge: TimeInterval) {
185+
#if !canImport(os) || SOURCEKITLSP_FORCE_NON_DARWIN_LOGGER
186+
cleanOldLogFilesImpl(logFileDirectory: logFileDirectory, maxAge: maxAge)
187+
#endif
188+
}

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)