diff --git a/Sources/CmuxEventLogWriter.swift b/Sources/CmuxEventLogWriter.swift index 64dde29ec712..a32fb35857dd 100644 --- a/Sources/CmuxEventLogWriter.swift +++ b/Sources/CmuxEventLogWriter.swift @@ -3,7 +3,8 @@ import os nonisolated private let cmuxEventLogLogger = Logger(subsystem: "com.cmuxterm.app", category: "event-log") -// Sendable safety: pending state is protected by `lock`; file IO runs on `queue`. +// Sendable safety: pending state is protected by `lock`; file IO and +// `openLogHandle` are confined to `queue`. final class CmuxEventLogWriter: @unchecked Sendable { static let defaultMaxPendingLines = 1_024 @@ -17,6 +18,8 @@ final class CmuxEventLogWriter: @unchecked Sendable { private var pendingLines: [String] = [] private var flushScheduled = false private var droppedLineCount = 0 + /// The append-only log descriptor kept open across flushes. + private var openLogHandle: FileHandle? #if DEBUG private var flushSuspendedForTesting = false #endif @@ -136,15 +139,9 @@ final class CmuxEventLogWriter: @unchecked Sendable { private func append(_ lines: [String]) { guard !lines.isEmpty else { return } + let fileManager = FileManager.default do { - let fileManager = FileManager.default - // Every agent hook event flushes here, so the steady state is one - // open + seek + write. Directory and file creation run only when the - // open fails, and the end-of-file offset doubles as the current size - // instead of a separate attributesOfItem stat per flush. - var handle = try openForAppending(fileManager: fileManager) - defer { try? handle.close() } - var currentSize = try handle.seekToEnd() + var (handle, currentSize) = try logHandleForAppending(fileManager: fileManager) // One file segment at a time bounds the extra buffer to the rotation limit, // except for an indivisible oversized record (the existing write-whole policy). var batchData = Data() @@ -159,10 +156,9 @@ final class CmuxEventLogWriter: @unchecked Sendable { let lineBytes = UInt64(line.utf8.count) + 1 if currentSize + lineBytes > maxEventLogBytes { try writeBatch() - try handle.close() + closeOpenLog() try rotate(fileManager: fileManager) - handle = try FileHandle(forWritingTo: eventLogURL) - currentSize = 0 + (handle, currentSize) = try logHandleForAppending(fileManager: fileManager) } batchData.append(contentsOf: line.utf8) batchData.append(0x0a) @@ -170,22 +166,65 @@ final class CmuxEventLogWriter: @unchecked Sendable { } try writeBatch() } catch { + closeOpenLog() cmuxEventLogLogger.error("Failed to append cmux event log: \(String(describing: error), privacy: .private)") } } - private func openForAppending(fileManager: FileManager) throws -> FileHandle { - if let handle = try? FileHandle(forWritingTo: eventLogURL) { - return handle + /// Returns an append-only handle for the log and the log's current size. + /// + /// Events are flushed one burst at a time, often a single line. Reopening, + /// creating the directory, and stat'ing the file on every flush dominated the + /// event-log queue, so the handle stays open. Other cmux processes share this + /// log and may rotate, delete, or append to it: + /// - The open handle is reused only while the path still names the same file + /// (device and inode match). + /// - The descriptor is opened with `O_APPEND`, so every write lands at the + /// current end of file even when another process appended since our last + /// write. A seek-then-write handle could overwrite those lines. + /// - The size used for rotation comes from `fstat` on the open descriptor. + private func logHandleForAppending(fileManager: FileManager) throws -> (FileHandle, UInt64) { + let path = eventLogURL.path + var pathStatus = stat() + let pathExists = stat(path, &pathStatus) == 0 + if let handle = openLogHandle { + var handleStatus = stat() + if pathExists, + fstat(handle.fileDescriptor, &handleStatus) == 0, + handleStatus.st_dev == pathStatus.st_dev, + handleStatus.st_ino == pathStatus.st_ino { + return (handle, UInt64(max(0, handleStatus.st_size))) + } + closeOpenLog() } - try fileManager.createDirectory( - at: eventLogURL.deletingLastPathComponent(), - withIntermediateDirectories: true - ) - if !fileManager.fileExists(atPath: eventLogURL.path) { - _ = fileManager.createFile(atPath: eventLogURL.path, contents: nil) + + // Directory creation runs only when the open reports a missing parent. + var descriptor = open(path, O_WRONLY | O_APPEND | O_CREAT | O_CLOEXEC, 0o644) + if descriptor < 0, errno == ENOENT { + try fileManager.createDirectory( + at: eventLogURL.deletingLastPathComponent(), + withIntermediateDirectories: true + ) + descriptor = open(path, O_WRONLY | O_APPEND | O_CREAT | O_CLOEXEC, 0o644) + } + guard descriptor >= 0 else { + throw POSIXError(POSIXErrorCode(rawValue: errno) ?? .EIO) } - return try FileHandle(forWritingTo: eventLogURL) + let handle = FileHandle(fileDescriptor: descriptor, closeOnDealloc: true) + var handleStatus = stat() + guard fstat(descriptor, &handleStatus) == 0 else { + let code = POSIXErrorCode(rawValue: errno) ?? .EIO + try? handle.close() + throw POSIXError(code) + } + openLogHandle = handle + return (handle, UInt64(max(0, handleStatus.st_size))) + } + + private func closeOpenLog() { + guard let handle = openLogHandle else { return } + try? handle.close() + openLogHandle = nil } private func rotate(fileManager: FileManager) throws { diff --git a/cmuxTests/CmuxEventLogWriteSpy.swift b/cmuxTests/CmuxEventLogWriteSpy.swift index 25cd53fabea9..a5acd7d09e8f 100644 --- a/cmuxTests/CmuxEventLogWriteSpy.swift +++ b/cmuxTests/CmuxEventLogWriteSpy.swift @@ -5,10 +5,14 @@ final class CmuxEventLogWriteSpy: @unchecked Sendable { private let lock = NSLock() private var sizes: [Int] = [] private var onMainThread = false + // Retained so a closed handle's address cannot be reused by a later one. + private var handles: [FileHandle] = [] private let failedCall: Int? + private let beforeWrite: (@Sendable () throws -> Void)? - init(failedCall: Int? = nil) { + init(failedCall: Int? = nil, beforeWrite: (@Sendable () throws -> Void)? = nil) { self.failedCall = failedCall + self.beforeWrite = beforeWrite } var writeSizes: [Int] { @@ -17,6 +21,13 @@ final class CmuxEventLogWriteSpy: @unchecked Sendable { return sizes } + /// Identity of the handle passed to each write, in call order. + var handleIdentities: [ObjectIdentifier] { + lock.lock() + defer { lock.unlock() } + return handles.map(ObjectIdentifier.init) + } + var wroteOnMainThread: Bool { lock.lock() defer { lock.unlock() } @@ -26,10 +37,12 @@ final class CmuxEventLogWriteSpy: @unchecked Sendable { func write(_ handle: FileHandle, data: Data) throws { lock.lock() sizes.append(data.count) + handles.append(handle) onMainThread = onMainThread || Thread.isMainThread let shouldFail = sizes.count == failedCall lock.unlock() if shouldFail { throw CocoaError(.fileWriteUnknown) } + try beforeWrite?() try handle.write(contentsOf: data) } } diff --git a/cmuxTests/CmuxEventLogWriterTests.swift b/cmuxTests/CmuxEventLogWriterTests.swift index f04934777b36..fa9ed5648e5d 100644 --- a/cmuxTests/CmuxEventLogWriterTests.swift +++ b/cmuxTests/CmuxEventLogWriterTests.swift @@ -180,6 +180,86 @@ struct CmuxEventLogWriterTests { #expect(try Data(contentsOf: url) == jsonl([#"{"seq":9}"#])) } + /// Every hook, feed, and sidebar event is flushed on its own. Reopening, + /// seeking, and stat'ing the log per flush made the event-log queue one of + /// the busiest background queues in an idle app sample. + @Test + func consecutiveFlushesReuseOneOpenHandle() throws { + let (writer, url, spy) = makeWriter() + defer { try? FileManager.default.removeItem(at: url.deletingLastPathComponent()) } + + flush([#"{"seq":1}"#], with: writer) + flush([#"{"seq":2}"#], with: writer) + flush([#"{"seq":3}"#], with: writer) + + #expect(spy.writeSizes.count == 3) + #expect(Set(spy.handleIdentities).count == 1) + #expect(try Data(contentsOf: url) == jsonl([#"{"seq":1}"#, #"{"seq":2}"#, #"{"seq":3}"#])) + } + + /// Another cmux process (a tagged dev build shares `~/.cmuxterm/events.jsonl`) + /// can rotate or delete the log between flushes. The next flush must land in + /// the file now at the path, not the renamed or unlinked inode. + @Test(arguments: [false, true]) + func externalRotationOrDeletionBetweenFlushesWritesToCurrentPath(deleteInsteadOfRotate: Bool) throws { + let (writer, url, _) = makeWriter() + defer { try? FileManager.default.removeItem(at: url.deletingLastPathComponent()) } + let rotatedURL = url.appendingPathExtension("external") + + flush([#"{"seq":1}"#], with: writer) + if deleteInsteadOfRotate { + try FileManager.default.removeItem(at: url) + } else { + try FileManager.default.moveItem(at: url, to: rotatedURL) + } + flush([#"{"seq":2}"#], with: writer) + + #expect(try Data(contentsOf: url) == jsonl([#"{"seq":2}"#])) + if !deleteInsteadOfRotate { + #expect(try Data(contentsOf: rotatedURL) == jsonl([#"{"seq":1}"#])) + } + } + + /// When another process rotates and has already created the next log, the + /// path exists but names a different inode. The writer must switch to it. + @Test + func externalRotationWithReplacementFileWritesToReplacement() throws { + let (writer, url, _) = makeWriter() + defer { try? FileManager.default.removeItem(at: url.deletingLastPathComponent()) } + let rotatedURL = url.appendingPathExtension("external") + + flush([#"{"seq":1}"#], with: writer) + try FileManager.default.moveItem(at: url, to: rotatedURL) + #expect(FileManager.default.createFile(atPath: url.path, contents: nil)) + flush([#"{"seq":2}"#], with: writer) + + #expect(try Data(contentsOf: url) == jsonl([#"{"seq":2}"#])) + #expect(try Data(contentsOf: rotatedURL) == jsonl([#"{"seq":1}"#])) + } + + /// Another cmux process can append to the shared log after this writer has + /// positioned its handle but before its write lands. The append-only + /// descriptor must keep both lines instead of overwriting the other writer's. + @Test + func concurrentExternalAppendIsNotOverwritten() throws { + let urlBox = CmuxEventLogURLBox() + let spy = CmuxEventLogWriteSpy(beforeWrite: { + guard let url = urlBox.url else { return } + let external = try FileHandle(forWritingTo: url) + defer { try? external.close() } + try external.seekToEnd() + try external.write(contentsOf: Data("{\"external\":true}\n".utf8)) + }) + let (writer, url, _) = makeWriter(spy: spy) + defer { try? FileManager.default.removeItem(at: url.deletingLastPathComponent()) } + + flush([#"{"seq":1}"#], with: writer) + urlBox.url = url + flush([#"{"seq":2}"#], with: writer) + + #expect(try Data(contentsOf: url) == jsonl([#"{"seq":1}"#, #"{"external":true}"#, #"{"seq":2}"#])) + } + private func makeWriter( maxBytes: UInt64 = 16 * 1024 * 1024, spy: CmuxEventLogWriteSpy = CmuxEventLogWriteSpy() @@ -229,3 +309,22 @@ struct CmuxEventLogWriterTests { } } } + +/// Lets a `@Sendable` write hook see the log URL once the writer exists. +private final class CmuxEventLogURLBox: @unchecked Sendable { + private let lock = NSLock() + private var storedURL: URL? + + var url: URL? { + get { + lock.lock() + defer { lock.unlock() } + return storedURL + } + set { + lock.lock() + storedURL = newValue + lock.unlock() + } + } +}