diff --git a/Package.swift b/Package.swift index 728b0342..4fefb70e 100644 --- a/Package.swift +++ b/Package.swift @@ -19,15 +19,20 @@ let package = Package( name: "swift-log", products: [ .library(name: "Logging", targets: ["Logging"]), + .library(name: "LoggingTestKit", targets: ["LoggingTestKit"]), ], targets: [ .target( name: "Logging", dependencies: [] ), + .target( + name: "LoggingTestKit", + dependencies: ["Logging"] + ), .testTarget( name: "LoggingTests", - dependencies: ["Logging"] + dependencies: ["Logging", "LoggingTestKit"] ), ] ) diff --git a/Sources/LoggingTestKit/TestLogHandler.swift b/Sources/LoggingTestKit/TestLogHandler.swift new file mode 100644 index 00000000..74e7c0ca --- /dev/null +++ b/Sources/LoggingTestKit/TestLogHandler.swift @@ -0,0 +1,320 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift Logging API open source project +// +// Copyright (c) 2024 Apple Inc. and the Swift Logging API project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// See CONTRIBUTORS.txt for the list of Swift Logging API project authors +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +import Foundation +import Logging + +#if os(Linux) + import Glibc +#else + import Darwin.C +#endif + +public struct CapturedLogMessage: CustomStringConvertible { + private static let timestampFormat = createTimestampFormat() + + private static func createTimestampFormat() -> DateFormatter { + let dateFormatter = DateFormatter() + dateFormatter.dateFormat = "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'" + return dateFormatter + } + + public var timestamp: Date + public var label: String + + public var level: Logger.Level + public var message: Logger.Message + public var metadata: Logger.Metadata + public var source: String + + public var file: String + public var function: String + public var line: UInt + + public var prettyMetadata: String { + metadata.sorted(by: { + $0.key < $1.key + }).map { + "\($0)=\($1)" + }.joined(separator: " ") + } + + public var description: String { + "\(Self.timestampFormat.string(from: timestamp)) \(level) \(label) :\(prettyMetadata) [\(source)] \(message)" + } + + public init( + timestamp: Date = Date(), + label: String = "nil", + level: Logger.Level = .info, + message: Logger.Message = .init(stringLiteral: ""), + metadata: Logger.Metadata = [:], + source: String = "nil", + file: String = "nil", + function: String = "nil", + line: UInt = 0 + ) { + self.timestamp = timestamp + self.label = label + self.level = level + self.message = message + self.metadata = metadata + self.source = source + self.file = file + self.function = function + self.line = line + } + + // Easily check if log message matches certain characteristics: + @available(macOS 13.0, *) + public func match( + label: String? = nil, + level: Logger.Level? = nil, + message: Regex? = nil, + metadata: [(Logger.Metadata.Element) -> Bool] = [], + source: Regex? = nil, + file: Regex? = nil, + function: String? = nil, + line: UInt? = nil + ) -> Bool { + if let label, + self.label != label + { + return false + } + if let level, + self.level != level + { + return false + } + if let message, + !self.message.description.contains(message) + { + return false + } + for predicate in metadata { + if !self.metadata.contains(where: predicate) { + return false + } + } + if let source, + !self.source.contains(source) + { + return false + } + if let file, + !self.file.contains(file) + { + return false + } + if let function, + self.function != function + { + return false + } + if let line, + self.line != line + { + return false + } + + return true + } +} + +public struct TestLogHandler: LogHandler, Sendable { + public typealias Filter = (CapturedLogMessage) -> Bool + + public final class Container: @unchecked Sendable { + // Guarded by queue: + private var _messages: [CapturedLogMessage] = [] + + private let queue: DispatchQueue + + private let filter: Filter + + init(_ filter: @escaping Filter) { + self.filter = filter + queue = DispatchQueue(label: "TestLogHandler.Container:\(type(of: filter))") + } + + public var messages: [CapturedLogMessage] { + var result: [CapturedLogMessage] = [] + queue.sync { + result = self._messages + } + return result + } + + public func append(_ message: CapturedLogMessage) -> Bool { + if filter(message) { + queue.sync { + _messages.append(message) + } + return true + } + return false + } + + public func reset() { + queue.sync { + self._messages = [] + } + } + + public var factory: (String) -> TestLogHandler { + { label in + TestLogHandler(label: label, container: self) + } + } + } + + private static let queue = DispatchQueue(label: "TestLogHandler") + + // Guarded by queue: + private static var isInitialized = false + // Guarded by queue: + private static var logLevel: Logger.Level = .info + // Guarded by queue: + private static var _containers: [Weak] = [] + + public static func bootstrap() { + queue.sync { + if !isInitialized { + isInitialized = true + LoggingSystem.bootstrap(Self.init) + } + } + } + + // Call in order to create a container of log messages which will only + // contain messages that match the filter. + public static func container(_ filter: @escaping Filter) -> Container { + let container = Container(filter) + queue.sync { + Self._containers.append(Weak(container)) + } + return container + } + + // Override the default global log level (defaults to .info) + public static func setLevel(_ level: Logger.Level) { + queue.sync { + logLevel = level + } + } + + // Introspect containers + public static var containers: [Container] { + var copy: [Weak]! + queue.sync { + copy = Self._containers + } + return copy.compactMap(\.value) + } + + private let label: String + private var _logLevel: Logger.Level? = nil + private let container: Container? + + // Defined in LogHandler protocol: + public var metadata: Logger.Metadata = [:] + public var logLevel: Logger.Level { + // ALWAYS return .trace to ensure our log() method will be called. The + // effectiveLogLevel is then used for if we should print to stderr: + get { .trace } + set { + _logLevel = newValue + } + } + + public var effectiveLogLevel: Logger.Level { + if let level = _logLevel { + return level + } else { + var level: Logger.Level! + Self.queue.sync { + level = Self.logLevel + } + return level + } + } + + public init(label: String) { + self.label = label + self.container = nil + } + + private init(label: String, container: Container) { + self.label = label + self.container = container + } + + public func log( + level: Logger.Level, + message: Logger.Message, + metadata: Logger.Metadata?, + source: String, + file: String, + function: String, + line: UInt + ) { + var metadata = metadata ?? [:] + metadata.merge(self.metadata, uniquingKeysWith: { left, _ in left }) + + let message = CapturedLogMessage( + label: label, + level: level, + message: message, + metadata: metadata, + source: source, + file: file, + function: function, + line: line + ) + var inContainer = false + if let container = self.container { + if container.append(message) { + inContainer = true + } + } else { + for container in Self.containers { + if container.append(message) { + inContainer = true + } + } + } + if !inContainer, effectiveLogLevel <= level { + FileHandle.standardError.write(Data(message.description.utf8)) + FileHandle.standardError.write(Data("\n".utf8)) + fflush(stderr) + } + } + + public subscript(metadataKey metadataKey: String) -> Logger.Metadata.Value? { + get { + metadata[metadataKey] + } + set { + metadata[metadataKey] = newValue + } + } +} + +private class Weak { + weak var value: T? + init(_ value: T) { + self.value = value + } +} diff --git a/Tests/LoggingTests/LoggingTest.swift b/Tests/LoggingTests/LoggingTest.swift index f77b9dfe..8150deb4 100644 --- a/Tests/LoggingTests/LoggingTest.swift +++ b/Tests/LoggingTests/LoggingTest.swift @@ -40,9 +40,8 @@ class LoggingTest: XCTestCase { func testAutoclosure() throws { // bootstrap with our test logging impl let logging = TestLogging() - LoggingSystem.bootstrapInternal { logging.make(label: $0) } - var logger = Logger(label: "test") + var logger = Logger(label: "test", factory: logging.make) logger.logLevel = .info logger.log(level: .debug, { XCTFail("debug should not be called") @@ -77,9 +76,10 @@ class LoggingTest: XCTestCase { // bootstrap with our test logging impl let logging1 = TestLogging() let logging2 = TestLogging() - LoggingSystem.bootstrapInternal { MultiplexLogHandler([logging1.make(label: $0), logging2.make(label: $0)]) } - var logger = Logger(label: "test") + var logger = Logger(label: "test") { + MultiplexLogHandler([logging1.make(label: $0), logging2.make(label: $0)]) + } logger.logLevel = .warning logger.info("hello world?") logger[metadataKey: "foo"] = "bar" @@ -97,11 +97,9 @@ class LoggingTest: XCTestCase { let logger1 = logging1.make(label: "1").with(logLevel: .info) let logger2 = logging2.make(label: "2").with(logLevel: .debug) - LoggingSystem.bootstrapInternal { _ in + let multiplexLogger = Logger(label: "test") { _ in MultiplexLogHandler([logger1, logger2]) } - - let multiplexLogger = Logger(label: "test") multiplexLogger.trace("trace") multiplexLogger.debug("debug") multiplexLogger.info("info") @@ -125,14 +123,12 @@ class LoggingTest: XCTestCase { let logger1 = logging1.make(label: "1").with(logLevel: .info) let logger2 = logging2.make(label: "2").with(logLevel: .info) - LoggingSystem.bootstrapInternal { _ in - MultiplexLogHandler([logger1, logger2]) - } - var messageMaterializations: Int = 0 var metadataMaterializations: Int = 0 - let multiplexLogger = Logger(label: "test") + let multiplexLogger = Logger(label: "test") { _ in + MultiplexLogHandler([logger1, logger2]) + } multiplexLogger.info( { () -> Logger.Message in messageMaterializations += 1 @@ -162,12 +158,10 @@ class LoggingTest: XCTestCase { .withMetadata("two", "222") .withMetadata("in", "in-2") - LoggingSystem.bootstrapInternal { _ in + var multiplexLogger = Logger(label: "test") { _ in MultiplexLogHandler([logger1, logger2]) } - var multiplexLogger = Logger(label: "test") - // each logs its own metadata multiplexLogger.info("info") logging1.history.assertExist(level: .info, message: "info", metadata: [ @@ -219,12 +213,10 @@ class LoggingTest: XCTestCase { .withMetadata("two", "222") .withMetadata("in", "in-2") - LoggingSystem.bootstrapInternal { _ in + let multiplexLogger = Logger(label: "test") { _ in MultiplexLogHandler([logger1, logger2]) } - let multiplexLogger = Logger(label: "test") - XCTAssertEqual(multiplexLogger.handler.metadata, [ "one": "111", "two": "222", @@ -257,12 +249,10 @@ class LoggingTest: XCTestCase { return handler2 }() - LoggingSystem.bootstrapInternal { _ in + let multiplexLogger = Logger(label: "test") { _ in MultiplexLogHandler([handler1, handler2]) } - let multiplexLogger = Logger(label: "test") - XCTAssertEqual(multiplexLogger.handler.metadata, [ "one": "111", "two": "222", @@ -301,16 +291,14 @@ class LoggingTest: XCTestCase { return handler2 }() - LoggingSystem.bootstrapInternal({ _, metadataProvider in + let multiplexLogger = Logger(label: "test") { _, metadataProvider in MultiplexLogHandler( [handler1, handler2], - metadataProvider: metadataProvider + metadataProvider: .constant([ + "provider-overlap": "provided-outer", + ]) ) - }, metadataProvider: .constant([ - "provider-overlap": "provided-outer", - ])) - - let multiplexLogger = Logger(label: "test") + } let provider = multiplexLogger.metadataProvider! @@ -327,9 +315,8 @@ class LoggingTest: XCTestCase { func testDictionaryMetadata() { let testLogging = TestLogging() - LoggingSystem.bootstrapInternal { testLogging.make(label: $0) } - var logger = Logger(label: "\(#function)") + var logger = Logger(label: "\(#function)", factory: testLogging.make) logger[metadataKey: "foo"] = ["bar": "buz"] logger[metadataKey: "empty-dict"] = [:] logger[metadataKey: "nested-dict"] = ["l1key": ["l2key": ["l3key": "l3value"]]] @@ -343,9 +330,8 @@ class LoggingTest: XCTestCase { func testListMetadata() { let testLogging = TestLogging() - LoggingSystem.bootstrapInternal { testLogging.make(label: $0) } - var logger = Logger(label: "\(#function)") + var logger = Logger(label: "\(#function)", factory: testLogging.make) logger[metadataKey: "foo"] = ["bar", "buz"] logger[metadataKey: "empty-list"] = [] logger[metadataKey: "nested-list"] = ["l1str", ["l2str1", "l2str2"]] @@ -386,8 +372,7 @@ class LoggingTest: XCTestCase { func testStringConvertibleMetadata() { let testLogging = TestLogging() - LoggingSystem.bootstrapInternal { testLogging.make(label: $0) } - var logger = Logger(label: "\(#function)") + var logger = Logger(label: "\(#function)", factory: testLogging.make) logger[metadataKey: "foo"] = .stringConvertible("raw-string") let lazyBox = LazyMetadataBox { "rendered-at-first-use" } @@ -406,9 +391,8 @@ class LoggingTest: XCTestCase { func testAutoClosuresAreNotForcedUnlessNeeded() { let testLogging = TestLogging() - LoggingSystem.bootstrapInternal { testLogging.make(label: $0) } - var logger = Logger(label: "\(#function)") + var logger = Logger(label: "\(#function)", factory: testLogging.make) logger.logLevel = .error logger.debug(self.dontEvaluateThisString(), metadata: ["foo": "\(self.dontEvaluateThisString())"]) @@ -420,9 +404,8 @@ class LoggingTest: XCTestCase { func testLocalMetadata() { let testLogging = TestLogging() - LoggingSystem.bootstrapInternal { testLogging.make(label: $0) } - var logger = Logger(label: "\(#function)") + var logger = Logger(label: "\(#function)", factory: testLogging.make) logger.info("hello world!", metadata: ["foo": "bar"]) logger[metadataKey: "bar"] = "baz" logger[metadataKey: "baz"] = "qux" @@ -461,9 +444,8 @@ class LoggingTest: XCTestCase { func testAllLogLevelsExceptCriticalCanBeBlocked() { let testLogging = TestLogging() - LoggingSystem.bootstrapInternal { testLogging.make(label: $0) } - var logger = Logger(label: "\(#function)") + var logger = Logger(label: "\(#function)", factory: testLogging.make) logger.logLevel = .critical logger.trace("no") @@ -485,9 +467,8 @@ class LoggingTest: XCTestCase { func testAllLogLevelsWork() { let testLogging = TestLogging() - LoggingSystem.bootstrapInternal { testLogging.make(label: $0) } - var logger = Logger(label: "\(#function)") + var logger = Logger(label: "\(#function)", factory: testLogging.make) logger.logLevel = .trace logger.trace("yes: trace") @@ -509,9 +490,8 @@ class LoggingTest: XCTestCase { func testAllLogLevelByFunctionRefWithSource() { let testLogging = TestLogging() - LoggingSystem.bootstrapInternal { testLogging.make(label: $0) } - var logger = Logger(label: "\(#function)") + var logger = Logger(label: "\(#function)", factory: testLogging.make) logger.logLevel = .trace let trace = logger.trace(_:metadata:source:file:function:line:) @@ -541,9 +521,8 @@ class LoggingTest: XCTestCase { func testAllLogLevelByFunctionRefWithoutSource() { let testLogging = TestLogging() - LoggingSystem.bootstrapInternal { testLogging.make(label: $0) } - var logger = Logger(label: "\(#function)") + var logger = Logger(label: "\(#function)", factory: testLogging.make) logger.logLevel = .trace let trace = logger.trace(_:metadata:file:function:line:) @@ -573,9 +552,8 @@ class LoggingTest: XCTestCase { func testLogsEmittedFromSubdirectoryGetCorrectModuleInNewerSwifts() { let testLogging = TestLogging() - LoggingSystem.bootstrapInternal { testLogging.make(label: $0) } - var logger = Logger(label: "\(#function)") + var logger = Logger(label: "\(#function)", factory: testLogging.make) logger.logLevel = .trace emitLogMessage("hello", to: logger) @@ -593,9 +571,8 @@ class LoggingTest: XCTestCase { func testLogMessageWithStringInterpolation() { let testLogging = TestLogging() - LoggingSystem.bootstrapInternal { testLogging.make(label: $0) } - var logger = Logger(label: "\(#function)") + var logger = Logger(label: "\(#function)", factory: testLogging.make) logger.logLevel = .debug let someInt = Int.random(in: 23 ..< 42) @@ -606,9 +583,8 @@ class LoggingTest: XCTestCase { func testLoggingAString() { let testLogging = TestLogging() - LoggingSystem.bootstrapInternal { testLogging.make(label: $0) } - var logger = Logger(label: "\(#function)") + var logger = Logger(label: "\(#function)", factory: testLogging.make) logger.logLevel = .debug let anActualString: String = "hello world!" @@ -639,10 +615,10 @@ class LoggingTest: XCTestCase { func testLoggerWithoutFactoryOverrideDefaultsToUsingLoggingSystemMetadataProvider() { let logging = TestLogging() - LoggingSystem.bootstrapInternal({ logging.makeWithMetadataProvider(label: $0, metadataProvider: $1) }, - metadataProvider: .init { ["provider": "42"] }) - let logger = Logger(label: #function) + let logger = Logger(label: #function) { + logging.makeWithMetadataProvider(label: $0, metadataProvider: .init { ["provider": "42"] }) + } logger.log(level: .info, "test", metadata: ["one-off": "42"]) @@ -653,12 +629,10 @@ class LoggingTest: XCTestCase { func testLoggerWithPredefinedLibraryMetadataProvider() { let logging = TestLogging() - LoggingSystem.bootstrapInternal( - { logging.makeWithMetadataProvider(label: $0, metadataProvider: $1) }, - metadataProvider: .exampleMetadataProvider - ) - let logger = Logger(label: #function) + let logger = Logger(label: #function) { + logging.makeWithMetadataProvider(label: $0, metadataProvider: .exampleMetadataProvider) + } logger.log(level: .info, "test", metadata: ["one-off": "42"]) @@ -681,16 +655,16 @@ class LoggingTest: XCTestCase { logging.history.assertExist(level: .info, message: "test", metadata: ["provider": "42", "one-off": "42"]) + LoggingSystem.bootstrapInternal({ StreamLogHandler.standardError(label: $0) }) } func testMultiplexerIsValue() { let multi = MultiplexLogHandler([StreamLogHandler.standardOutput(label: "x"), StreamLogHandler.standardOutput(label: "y")]) - LoggingSystem.bootstrapInternal { _ in - print("new multi") - return multi - } let logger1: Logger = { - var logger = Logger(label: "foo") + var logger = Logger(label: "foo") { _ in + print("new multi") + return multi + } logger.logLevel = .debug logger[metadataKey: "only-on"] = "first" return logger @@ -782,11 +756,10 @@ class LoggingTest: XCTestCase { } let logRecorder = Recorder() - LoggingSystem.bootstrapInternal { _ in + + var logger1 = Logger(label: "logger-\(#file):\(#line)") { _ in LogHandlerWithGlobalLogLevelOverride(recorder: logRecorder) } - - var logger1 = Logger(label: "logger-\(#file):\(#line)") var logger2 = logger1 logger1.logLevel = .warning logger1[metadataKey: "only-on"] = "first" @@ -853,10 +826,10 @@ class LoggingTest: XCTestCase { func testStreamLogHandlerWritesToAStream() { let interceptStream = InterceptStream() - LoggingSystem.bootstrapInternal { _ in + + let log = Logger(label: "test") { _ in StreamLogHandler(label: "test", stream: interceptStream) } - let log = Logger(label: "test") let testString = "my message is better than yours" log.critical("\(testString)") @@ -870,11 +843,11 @@ class LoggingTest: XCTestCase { func testStreamLogHandlerOutputFormat() { let interceptStream = InterceptStream() let label = "testLabel" - LoggingSystem.bootstrapInternal { label in + + let source = "testSource" + let log = Logger(label: label) { label in StreamLogHandler(label: label, stream: interceptStream) } - let source = "testSource" - let log = Logger(label: label) let testString = "my message is better than yours" log.critical("\(testString)", source: source) @@ -890,11 +863,11 @@ class LoggingTest: XCTestCase { func testStreamLogHandlerOutputFormatWithMetaData() { let interceptStream = InterceptStream() let label = "testLabel" - LoggingSystem.bootstrapInternal { label in + + let source = "testSource" + let log = Logger(label: label) { label in StreamLogHandler(label: label, stream: interceptStream) } - let source = "testSource" - let log = Logger(label: label) let testString = "my message is better than yours" log.critical("\(testString)", metadata: ["test": "test"], source: source) @@ -910,10 +883,10 @@ class LoggingTest: XCTestCase { func testStreamLogHandlerOutputFormatWithOrderedMetadata() { let interceptStream = InterceptStream() let label = "testLabel" - LoggingSystem.bootstrapInternal { label in + + let log = Logger(label: label) { label in StreamLogHandler(label: label, stream: interceptStream) } - let log = Logger(label: label) let testString = "my message is better than yours" log.critical("\(testString)", metadata: ["a": "a0", "b": "b0"]) @@ -931,10 +904,10 @@ class LoggingTest: XCTestCase { func testStreamLogHandlerWritesIncludeMetadataProviderMetadata() { let interceptStream = InterceptStream() - LoggingSystem.bootstrapInternal({ _, metadataProvider in - StreamLogHandler(label: "test", stream: interceptStream, metadataProvider: metadataProvider) - }, metadataProvider: .exampleMetadataProvider) - let log = Logger(label: "test") + + let log = Logger(label: "test") { _ in + StreamLogHandler(label: "test", stream: interceptStream, metadataProvider: .exampleMetadataProvider) + } let testString = "my message is better than yours" log.critical("\(testString)") @@ -950,8 +923,10 @@ class LoggingTest: XCTestCase { func testStdioOutputStreamWrite() { self.withWriteReadFDsAndReadBuffer { writeFD, readFD, readBuffer in let logStream = StdioOutputStream(file: writeFD, flushMode: .always) - LoggingSystem.bootstrapInternal { StreamLogHandler(label: $0, stream: logStream) } - let log = Logger(label: "test") + + let log = Logger(label: "test") { + StreamLogHandler(label: $0, stream: logStream) + } let testString = "hello\u{0} world" log.critical("\(testString)") @@ -967,8 +942,10 @@ class LoggingTest: XCTestCase { // flush on every statement self.withWriteReadFDsAndReadBuffer { writeFD, readFD, readBuffer in let logStream = StdioOutputStream(file: writeFD, flushMode: .always) - LoggingSystem.bootstrapInternal { StreamLogHandler(label: $0, stream: logStream) } - Logger(label: "test").critical("test") + + Logger(label: "test") { + StreamLogHandler(label: $0, stream: logStream) + }.critical("test") let size = read(readFD, readBuffer, 256) XCTAssertGreaterThan(size, -1, "expected flush") @@ -980,8 +957,10 @@ class LoggingTest: XCTestCase { // default flushing self.withWriteReadFDsAndReadBuffer { writeFD, readFD, readBuffer in let logStream = StdioOutputStream(file: writeFD, flushMode: .undefined) - LoggingSystem.bootstrapInternal { StreamLogHandler(label: $0, stream: logStream) } - Logger(label: "test").critical("test") + + Logger(label: "test") { + StreamLogHandler(label: $0, stream: logStream) + }.critical("test") let size = read(readFD, readBuffer, 256) XCTAssertEqual(size, -1, "expected no flush") @@ -1049,9 +1028,8 @@ class LoggingTest: XCTestCase { } // bootstrap with our test logging impl let logging = TestLogging() - LoggingSystem.bootstrapInternal { logging.make(label: $0) } - var logger = Logger(label: "test") + var logger = Logger(label: "test", factory: logging.make) logger.logLevel = .error logger.error(error: Dummy()) diff --git a/Tests/LoggingTests/MDCTest.swift b/Tests/LoggingTests/MDCTest.swift index 029cd6aa..518aed04 100644 --- a/Tests/LoggingTests/MDCTest.swift +++ b/Tests/LoggingTests/MDCTest.swift @@ -17,9 +17,6 @@ import XCTest class MDCTest: XCTestCase { func test1() throws { - // bootstrap with our test logger - let logging = TestLogging() - LoggingSystem.bootstrapInternal { logging.make(label: $0) } // run the program MDC.global["foo"] = "bar" diff --git a/Tests/LoggingTests/TestTestingLogHandler.swift b/Tests/LoggingTests/TestTestingLogHandler.swift new file mode 100644 index 00000000..2b18d626 --- /dev/null +++ b/Tests/LoggingTests/TestTestingLogHandler.swift @@ -0,0 +1,41 @@ +@testable import Logging +import LoggingTestKit +import XCTest + +typealias TestingLogHandler = LoggingTestKit.TestLogHandler + +final class TestTestingLogHandler: XCTestCase { + + public func testExample() { + do { + let container = TestingLogHandler.container { + $0.match(label: "Example", level: .debug) + } + XCTAssertEqual(TestingLogHandler.containers.count, 1) + + var example = Logger(label: "Example", factory: container.factory) + example.logLevel = .critical + example.info("Not matched, since info level is different") + example.debug("Matched") + + var example1 = Logger(label: "Example1", factory: container.factory) + example1.logLevel = .debug + example1.debug("This message should be printed to stderr") + + XCTAssertFalse(container.messages.isEmpty) + if let first = container.messages.first { + XCTAssertEqual(first.message.description, "Matched") + XCTAssertTrue( + try first.description.contains(Regex( + "^\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}.\\d+Z debug Example : \\[LoggingTests\\] Matched$" + )), + "message format, not as expected: \(first.description)" + ) + } + } + + // Ensure weak ref works correctly: + XCTAssertEqual(TestingLogHandler.containers.count, 0) + LoggingSystem.bootstrapInternal({ StreamLogHandler.standardError(label: $0) }) + } +} \ No newline at end of file diff --git a/proposals/0002-testing-log-handler.md b/proposals/0002-testing-log-handler.md new file mode 100644 index 00000000..e76ec2ff --- /dev/null +++ b/proposals/0002-testing-log-handler.md @@ -0,0 +1,187 @@ +# Test Log Handler + +Authors: [Brian Maher](https://github.com/brimworks), [Konrad 'ktoso' Malawski](https://github.com/ktoso) + +## Introduction + +Software operators rely on logging to provide insight into what is being done, +therefore, testing log output is an important facet. + +## Motivation + +A variety of implementations have cropped up organically, but having a single +test log handler to build off of will reduce the re-write churn. + +### Existing Implementations + +* [swift-log-testing](https://github.com/neallester/swift-log-testing) +* [swift-distributed-actors/LogCapture](https://github.com/apple/swift-distributed-actors/blob/main/Sources/DistributedActorsTestKit/LogCapture.swift) +* [swift-cluster-membership/LogCapture](https://github.com/apple/swift-cluster-membership/blob/main/Tests/SWIMTestKit/LogCapture.swift) +* [RediStack/RedisLoggingTests](https://github.com/swift-server/RediStack/blob/master/Tests/RediStackIntegrationTests/RedisLoggingTests.swift) +* [swift-log/TestLogger](https://github.com/apple/swift-log/blob/main/Tests/LoggingTests/TestLogger.swift#L52) + + +## Features + +A testing log handler needs the following features: +* The ability to capture log entries at the start of a unit test. +* The ability to assert the captured log entries contain a matching message. +* Work correctly in the face of parallel test execution. +* Print log messages to the console if the log entry does not match a log entry + that is being asserted. +* Bootstrap the test log handler as early as possible so we don't miss any + `Logger()` creations which may happen during setup. + +## Ideal World vs Real World + +In an ideal world, all `Logger()` instances could be manually "injected" in +which case, one could use the `Logger`s `init(handler:)` constructor to inject +in the testing log handler. + +The unfortunate reality of the "real world" is that many `Logger` instances have +no way to be injected, or performing that injection would be very tedious. + +Therefore, the solution needs some way to work without requiring the usage of +a manually injected log handler. + +## Proposed Solution + +Users of the library will create assertions about future log messages. These +assertions simply last for a well defined scope. At the end of the scope, if +no log message matches the assertion, then the assertion will be deemed a +failure. + +Ideally, the users of this test log handler would manually construct their +`Logger` instances to use the log handler as such: + +```swift +let assertion = TestLogHandler.assertion(label: "Example", level: .debug) +let logger = Logger(label: "Example", factory: assertion.factory) +... +XCTAssertTrue(assertion.test, assertion.description) +``` + +However, to support situations where the person performing the log tests is +**not** in control of the creation of `Logger` instances, you can choose to +bootstrap with the `TestLogHandler` using the test frameworks `setUp` method: + +```swift +class TestMyLogs: XCTestCase { + override func setUp() { + TestLogHandler.bootstrap() + } + func testExample() { + let logger = Logger(label: "Example") + let assertion = TestLogHandler.assertion(label: "Example", level: .debug) + ... + XCTAssertTrue(assertion.test, assertion.description) + } +} +``` + +The disadvantage here, is that **every** `Logger` instance is eligible for +matching the assertion verses a very specific instance of `Logger` being the only +instance which is eligible for assertion. In practice though, this shouldn't be +a problem, since it is easy to target specific `Logger` instances via the +`label`. + +Note that we bootstrapped `TestLogHandler` using the `TestLogHandler.bootstrap()` +method over manually calling `LoggingSystem.bootstrap(TestLogHandler.init)` so +that we can ensure this setup happens exactly once, and any future attempt to +bootstrap will not cause a fatal error. This way multiple test suites can all +have a `setUp()` which bootstraps the `TestLogHandler` without the `logging +system can only be initialized once per process` error. + +### Why Declare Assertion And Later Perform Assertion? + +In the examples so far, the assertion is created first, then "stuff" happens +which is expected to cause the assertion to pass, and finally the assertion is +tested to ensure that expectation was met. + +By setting the expectation about what assertion we are searching for up front, +we can "ignore" all other log messages which do not match that assertion. These +"ignored" log messages can then be (potentially) printed to stderr, which aids +immensely in the understanding of potential failures which are being handled by +logging. For example, it isn't to uncommon to catch all exceptions and then +log them at an "error" level. If these "error" level exceptions are not printed +to stderr, then it becomes very difficult to understand various failure modes. +This is especially painful in any CI (Continuous Integration) system, where your +only hope of understanding what took place is to introspect the stderr log +messages. + +### Other Use Cases + +Another use-case for the `TestLogHandler` is to simply discard "noisy" log +messages. For example, when fuzz testing, it isn't to uncommon for the various +fuzzes to trigger spurious log messages that you want to just discard. + +To support this use-case, you can create a "container" of log messages that +match a filter. These will not be considered "ignored" log messages and thus +will not be printed to stderr by default. + +To create a new "container" we can have a function that takes a filter parameter +and returns the new log container: + +```swift +let container = TestLogHandler.container { logMessage in + // Ideally, you would be as specific as possible in your filtering! + return logMessage.level == Logger.Level.debug && + logMessage.label == "Test" && + logMessage.message.description == "Matched" +} +// Emit a log that matches the filter: +Logger(label: "Test").debug("Matched") + +// Emit a log that does NOT match the filter: +Logger(label: "Test").debug("Printed to console") + +// Assert that the log message was found: +XCTAssertFalse(container.messages.isEmpty) +``` + +It is recommended to create a separate container for each log assertion so that +you can simply check that the messages in a container are non-empty. If you use +this pattern you also protect yourself from accidental log message matches that +occur due to a test ran in parallel. An accidental match could cause a failing +test to spuriously succeed, but it would never cause a successful test to +spuriously fail. + +If a log message is emitted that does **not** match any container's filter, it +will be printed to the console in the same way as the default built-in log +handler. + +In order to make filtering easier, the `CapturedLogMessage` struct contains a `match` +function that takes the following optional parameters: +* label: `String?` +* level: `Logger.Level?` +* message: `Regex?` +* metadata: `[(Logger.Metadata.Element) -> Bool]` +* source: `Regex?` +* file: `Regex?` +* function: `String?` +* line: `UInt?` + +Only if all specified parameters match will this function return true. + +In order to make debugging easier, the `CapturedLogMessage` struct will implement +`CustomStringConvertible` which causes the log message to be formatted in the +default built-in log handler format. + +Additionally, each field of the log message is public and can be used for +custom filtering: +* timestamp: `Date` +* label: `String` +* level: `Logger.Level` +* message: `Logger.Message` (note that this is also `CustomStringConvertible`) +* metadata: `Logger.Metadata` +* source: `String` +* file: `String` +* function: `String` +* line: `UInt` + +Note that the log handler implementation must maintain "weak" pointers to all +the containers so as to avoid memory leaks. + +Also note that the `LogHandler.logLevel` is **always** `.trace`, otherwise log +messages that are at to low of a level will not have a chance to be captured +due to the `if self.logLevel <= level` guard on the `Logging.log()` method.