diff --git a/Sources/Logging/LogHandler.swift b/Sources/Logging/LogHandler.swift index 11a8a47a..d62ab227 100644 --- a/Sources/Logging/LogHandler.swift +++ b/Sources/Logging/LogHandler.swift @@ -114,6 +114,12 @@ /// level has not been overridden. And most importantly it passes the requirement listed above: A change to the log /// level on one `Logger` should not affect the log level of another `Logger` variable. public protocol LogHandler: _SwiftLogSendableLogHandler { + /// The metadata provider this `LogHandler` will use when a log statement is about to be emitted. + /// + /// A ``Logger/MetadataProvider`` may add a constant set of metadata, + /// or use task-local values to pick up contextual metadata and add it to emitted logs. + var metadataProvider: Logger.MetadataProvider? { get set } + /// This method is called when a `LogHandler` must emit a log message. There is no need for the `LogHandler` to /// check if the `level` is above or below the configured `logLevel` as `Logger` already performed this check and /// determined that a message should be logged. @@ -163,6 +169,19 @@ public protocol LogHandler: _SwiftLogSendableLogHandler { var logLevel: Logger.Level { get set } } +extension LogHandler { + /// Default implementation for `metadataProvider` which defaults to `nil`. + /// This default exists in order to facilitate source-compatible introduction of the `metadataProvider` protocol requirement. + public var metadataProvider: Logger.MetadataProvider? { + get { + nil + } + set { + self.log(level: .warning, message: "Attempted to set metadataProvider on \(Self.self) that did not implement support for them. Please contact the log handler maintainer to implement metadata provider support.", metadata: nil, source: "Logging", file: #file, function: #function, line: #line) + } + } +} + extension LogHandler { @available(*, deprecated, message: "You should implement this method instead of using the default implementation") public func log(level: Logger.Level, diff --git a/Sources/Logging/Logging.swift b/Sources/Logging/Logging.swift index acc1b9a7..879ba17c 100644 --- a/Sources/Logging/Logging.swift +++ b/Sources/Logging/Logging.swift @@ -43,6 +43,11 @@ public struct Logger { /// An identifier of the creator of this `Logger`. public let label: String + /// The metadata provider this logger was created with. + public var metadataProvider: Logger.MetadataProvider? { + return self.handler.metadataProvider + } + internal init(label: String, _ handler: LogHandler) { self.label = label self.handler = handler @@ -264,6 +269,7 @@ extension Logger { } #else + @inlinable public func debug(_ message: @autoclosure () -> Logger.Message, metadata: @autoclosure () -> Logger.Metadata? = nil, source: @autoclosure () -> String? = nil, @@ -435,6 +441,7 @@ extension Logger { } #else + @inlinable public func notice(_ message: @autoclosure () -> Logger.Message, metadata: @autoclosure () -> Logger.Metadata? = nil, file: String = #file, function: String = #function, line: UInt = #line) { @@ -653,7 +660,8 @@ extension Logger { /// configured. `LoggingSystem` is set up just once in a given program to set up the desired logging backend /// implementation. public enum LoggingSystem { - private static let _factory = FactoryBox(StreamLogHandler.standardOutput) + private static let _factory = FactoryBox { label, _ in StreamLogHandler.standardOutput(label: label) } + private static let _metadataProviderFactory = MetadataProviderBox(nil) /// `bootstrap` is a one-time configuration function which globally selects the desired logging backend /// implementation. `bootstrap` can be called at maximum once in any given program, calling it more than once will @@ -662,28 +670,73 @@ public enum LoggingSystem { /// - parameters: /// - factory: A closure that given a `Logger` identifier, produces an instance of the `LogHandler`. public static func bootstrap(_ factory: @escaping (String) -> LogHandler) { + self._factory.replaceFactory({ label, _ in + factory(label) + }, validate: true) + } + + /// `bootstrap` is a one-time configuration function which globally selects the desired logging backend + /// implementation. + /// + /// - Warning: + /// `bootstrap` can be called at maximum once in any given program, calling it more than once will + /// lead to undefined behavior, most likely a crash. + /// + /// - parameters: + /// - metadataProvider: The `MetadataProvider` used to inject runtime-generated metadata from the execution context. + /// - factory: A closure that given a `Logger` identifier, produces an instance of the `LogHandler`. + public static func bootstrap(_ factory: @escaping (String, Logger.MetadataProvider?) -> LogHandler, + metadataProvider: Logger.MetadataProvider?) { + self._metadataProviderFactory.replaceMetadataProvider(metadataProvider, validate: true) self._factory.replaceFactory(factory, validate: true) } - // for our testing we want to allow multiple bootstraping + // for our testing we want to allow multiple bootstrapping internal static func bootstrapInternal(_ factory: @escaping (String) -> LogHandler) { + self._metadataProviderFactory.replaceMetadataProvider(nil, validate: false) + self._factory.replaceFactory({ label, _ in + factory(label) + }, validate: false) + } + + // for our testing we want to allow multiple bootstrapping + internal static func bootstrapInternal(_ factory: @escaping (String, Logger.MetadataProvider?) -> LogHandler, + metadataProvider: Logger.MetadataProvider?) { + self._metadataProviderFactory.replaceMetadataProvider(metadataProvider, validate: false) self._factory.replaceFactory(factory, validate: false) } - fileprivate static var factory: (String) -> LogHandler { - return self._factory.underlying + fileprivate static var factory: (String, Logger.MetadataProvider?) -> LogHandler { + return { label, metadataProvider in + var handler = self._factory.underlying(label, metadataProvider) + handler.metadataProvider = metadataProvider + return handler + } + } + + /// System wide ``Logger/MetadataProvider`` that was configured during the logging system's `bootstrap`. + /// + /// When creating a ``Logger`` using the plain ``Logger/init(label:)`` initializer, this metadata provider + /// will be provided to it. + /// + /// When using custom log handler factories, make sure to provide the bootstrapped metadata provider to them, + /// or the metadata will not be filled in automatically using the provider on log-sites. While using a custom + /// factory to avoid using the bootstrapped metadata provider may sometimes be useful, usually it will lead to + /// un-expected behavior, so make sure to always propagate it to your handlers. + public static var metadataProvider: Logger.MetadataProvider? { + return self._metadataProviderFactory.metadataProvider } private final class FactoryBox { private let lock = ReadWriteLock() - fileprivate var _underlying: (String) -> LogHandler + fileprivate var _underlying: (_ label: String, _ provider: Logger.MetadataProvider?) -> LogHandler private var initialized = false - init(_ underlying: @escaping (String) -> LogHandler) { + init(_ underlying: @escaping (String, Logger.MetadataProvider?) -> LogHandler) { self._underlying = underlying } - func replaceFactory(_ factory: @escaping (String) -> LogHandler, validate: Bool) { + func replaceFactory(_ factory: @escaping (String, Logger.MetadataProvider?) -> LogHandler, validate: Bool) { self.lock.withWriterLock { precondition(!validate || !self.initialized, "logging system can only be initialized once per process.") self._underlying = factory @@ -691,7 +744,32 @@ public enum LoggingSystem { } } - var underlying: (String) -> LogHandler { + var underlying: (String, Logger.MetadataProvider?) -> LogHandler { + return self.lock.withReaderLock { + return self._underlying + } + } + } + + private final class MetadataProviderBox { + private let lock = ReadWriteLock() + + internal var _underlying: Logger.MetadataProvider? + private var initialized = false + + init(_ underlying: Logger.MetadataProvider?) { + self._underlying = underlying + } + + func replaceMetadataProvider(_ metadataProvider: Logger.MetadataProvider?, validate: Bool) { + self.lock.withWriterLock { + precondition(!validate || !self.initialized, "logging system can only be initialized once per process.") + self._underlying = metadataProvider + self.initialized = true + } + } + + var metadataProvider: Logger.MetadataProvider? { return self.lock.withReaderLock { return self._underlying } @@ -786,7 +864,7 @@ extension Logger { /// - parameters: /// - label: An identifier for the creator of a `Logger`. public init(label: String) { - self.init(label: label, LoggingSystem.factory(label)) + self.init(label: label, LoggingSystem.factory(label, LoggingSystem.metadataProvider)) } /// Construct a `Logger` given a `label` identifying the creator of the `Logger` or a non-standard `LogHandler`. @@ -803,6 +881,39 @@ extension Logger { public init(label: String, factory: (String) -> LogHandler) { self = Logger(label: label, factory(label)) } + + /// Construct a `Logger` given a `label` identifying the creator of the `Logger` or a non-standard `LogHandler`. + /// + /// The `label` should identify the creator of the `Logger`. This can be an application, a sub-system, or even + /// a datatype. + /// + /// This initializer provides an escape hatch in case the global default logging backend implementation (set up + /// using `LoggingSystem.bootstrap` is not appropriate for this particular logger. + /// + /// - parameters: + /// - label: An identifier for the creator of a `Logger`. + /// - factory: A closure creating non-standard `LogHandler`s. + public init(label: String, factory: (String, Logger.MetadataProvider?) -> LogHandler) { + self = Logger(label: label, factory(label, LoggingSystem.metadataProvider)) + } + + /// Construct a `Logger` given a `label` identifying the creator of the `Logger` and a non-standard ``Logger/MetadataProvider``. + /// + /// The `label` should identify the creator of the `Logger`. This can be an application, a sub-system, or even + /// a datatype. + /// + /// This initializer provides an escape hatch in case the global default logging backend implementation (set up + /// using `LoggingSystem.bootstrap` is not appropriate for this particular logger. + /// + /// - parameters: + /// - label: An identifier for the creator of a `Logger`. + /// - metadataProvider: The custom metadata provider this logger should invoke, + /// instead of the system wide bootstrapped one, when a log statement is about to be emitted. + public init(label: String, metadataProvider: MetadataProvider) { + self = Logger(label: label, factory: { label in + LoggingSystem.factory(label, metadataProvider) + }) + } } extension Logger.Level { @@ -1081,6 +1192,11 @@ let systemStdout = WASILibc.stdout! /// `StreamLogHandler` is a simple implementation of `LogHandler` for directing /// `Logger` output to either `stderr` or `stdout` via the factory methods. +/// +/// Metadata is merged in the following order: +/// 1. Metadata set on the log handler itself is used as the base metadata. +/// 2. The handler's ``metadataProvider`` is invoked, overriding any existing keys. +/// 3. The per-log-statement metadata is merged, overriding any previously set keys. public struct StreamLogHandler: LogHandler { #if compiler(>=5.6) internal typealias _SendableTextOutputStream = TextOutputStream & Sendable @@ -1090,12 +1206,12 @@ public struct StreamLogHandler: LogHandler { /// Factory that makes a `StreamLogHandler` to directs its output to `stdout` public static func standardOutput(label: String) -> StreamLogHandler { - return StreamLogHandler(label: label, stream: StdioOutputStream.stdout) + return StreamLogHandler(label: label, stream: StdioOutputStream.stdout, metadataProvider: LoggingSystem.metadataProvider) } /// Factory that makes a `StreamLogHandler` to directs its output to `stderr` public static func standardError(label: String) -> StreamLogHandler { - return StreamLogHandler(label: label, stream: StdioOutputStream.stderr) + return StreamLogHandler(label: label, stream: StdioOutputStream.stderr, metadataProvider: LoggingSystem.metadataProvider) } private let stream: _SendableTextOutputStream @@ -1103,6 +1219,8 @@ public struct StreamLogHandler: LogHandler { public var logLevel: Logger.Level = .info + public var metadataProvider: Logger.MetadataProvider? + private var prettyMetadata: String? public var metadata = Logger.Metadata() { didSet { @@ -1121,38 +1239,72 @@ public struct StreamLogHandler: LogHandler { // internal for testing only internal init(label: String, stream: _SendableTextOutputStream) { + self.init(label: label, stream: stream, metadataProvider: LoggingSystem.metadataProvider) + } + + // internal for testing only + internal init(label: String, stream: _SendableTextOutputStream, metadataProvider: Logger.MetadataProvider?) { self.label = label self.stream = stream + self.metadataProvider = metadataProvider } public func log(level: Logger.Level, message: Logger.Message, - metadata: Logger.Metadata?, + metadata explicitMetadata: Logger.Metadata?, source: String, file: String, function: String, line: UInt) { - let prettyMetadata = metadata?.isEmpty ?? true - ? self.prettyMetadata - : self.prettify(self.metadata.merging(metadata!, uniquingKeysWith: { _, new in new })) + let effectiveMetadata = StreamLogHandler.prepareMetadata(base: self.metadata, provider: self.metadataProvider, explicit: explicitMetadata) + + let prettyMetadata: String? + if let effectiveMetadata = effectiveMetadata { + prettyMetadata = self.prettify(effectiveMetadata) + } else { + prettyMetadata = self.prettyMetadata + } var stream = self.stream stream.write("\(self.timestamp()) \(level) \(self.label) :\(prettyMetadata.map { " \($0)" } ?? "") [\(source)] \(message)\n") } + internal static func prepareMetadata(base: Logger.Metadata, provider: Logger.MetadataProvider?, explicit: Logger.Metadata?) -> Logger.Metadata? { + var metadata = base + + let provided = provider?.get() ?? [:] + + guard !provided.isEmpty || !((explicit ?? [:]).isEmpty) else { + // all per-log-statement values are empty + return nil + } + + if !provided.isEmpty { + metadata.merge(provided, uniquingKeysWith: { _, provided in provided }) + } + + if let explicit = explicit, !explicit.isEmpty { + metadata.merge(explicit, uniquingKeysWith: { _, explicit in explicit }) + } + + return explicit + } + private func prettify(_ metadata: Logger.Metadata) -> String? { - return !metadata.isEmpty - ? metadata.lazy.sorted(by: { $0.key < $1.key }).map { "\($0)=\($1)" }.joined(separator: " ") - : nil + if metadata.isEmpty { + return nil + } else { + return metadata.lazy.sorted(by: { $0.key < $1.key }).map { "\($0)=\($1)" }.joined(separator: " ") + } } private func timestamp() -> String { var buffer = [Int8](repeating: 0, count: 255) #if os(Windows) - var timestamp: __time64_t = __time64_t() + var timestamp = __time64_t() _ = _time64(×tamp) - var localTime: tm = tm() + var localTime = tm() _ = _localtime64_s(&localTime, ×tamp) _ = strftime(&buffer, buffer.count, "%Y-%m-%dT%H:%M:%S%z", &localTime) diff --git a/Sources/Logging/MetadataProvider.swift b/Sources/Logging/MetadataProvider.swift new file mode 100644 index 00000000..a3d4d63f --- /dev/null +++ b/Sources/Logging/MetadataProvider.swift @@ -0,0 +1,113 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift Logging API open source project +// +// Copyright (c) 2018-2022 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 +// +//===----------------------------------------------------------------------===// + +#if os(macOS) || os(iOS) || os(tvOS) || os(watchOS) +import Darwin +#elseif os(Windows) +import CRT +#elseif canImport(Glibc) +import Glibc +#elseif canImport(WASILibc) +import WASILibc +#else +#error("Unsupported runtime") +#endif + +#if compiler(>=5.6) +@preconcurrency protocol _SwiftLogSendable: Sendable {} +#else +protocol _SwiftLogSendable {} +#endif + +extension Logger { + /// A `MetadataProvider` is used to automatically inject runtime-generated metadata + /// to all logs emitted by a logger. + /// + /// ### Example + /// A metadata provider may be used to automatically inject metadata such as + /// trace IDs: + /// + /// ```swift + /// import Tracing // https://github.com/apple/swift-distributed-tracing + /// + /// let metadataProvider = MetadataProvider { + /// guard let traceID = Baggage.current?.traceID else { return nil } + /// return ["traceID": "\(traceID)"] + /// } + /// let logger = Logger(label: "example", metadataProvider: metadataProvider) + /// var baggage = Baggage.topLevel + /// baggage.traceID = 42 + /// Baggage.withValue(baggage) { + /// logger.info("hello") // automatically includes ["traceID": "42"] metadata + /// } + /// ``` + /// + /// We recommend referring to [swift-distributed-tracing](https://github.com/apple/swift-distributed-tracing) + /// for metadata providers which make use of its tracing and metadata propagation infrastructure. It is however + /// possible to make use of metadata providers independently of tracing and instruments provided by that library, + /// if necessary. + public struct MetadataProvider: _SwiftLogSendable { + /// Provide ``Logger.Metadata`` from current context. + #if swift(>=5.5) && canImport(_Concurrency) // we could instead typealias the function type, but it was requested that we avoid this for better developer experience + @usableFromInline + internal let _provideMetadata: @Sendable() -> Metadata + #else + @usableFromInline + internal let _provideMetadata: () -> Metadata + #endif + + /// Create a new `MetadataProvider`. + /// + /// - Parameter provideMetadata: A closure extracting metadata from the current execution context. + #if swift(>=5.5) && canImport(_Concurrency) + public init(_ provideMetadata: @escaping @Sendable() -> Metadata) { + self._provideMetadata = provideMetadata + } + + #else + public init(_ provideMetadata: @escaping () -> Metadata) { + self._provideMetadata = provideMetadata + } + #endif + + /// Invoke the metadata provider and return the generated contextual ``Logger/Metadata``. + public func get() -> Metadata { + return self._provideMetadata() + } + } +} + +extension Logger.MetadataProvider { + /// A pseudo-`MetadataProvider` that can be used to merge metadata from multiple other `MetadataProvider`s. + /// + /// ### Merging conflicting keys + /// + /// `MetadataProvider`s are invoked left to right in the order specified in the `providers` argument. + /// In case multiple providers try to add a value for the same key, the last provider "wins" and its value is being used. + /// + /// - Parameter providers: An array of `MetadataProvider`s to delegate to. The array must not be empty. + /// - Returns: A pseudo-`MetadataProvider` merging metadata from the given `MetadataProvider`s. + public static func multiplex(_ providers: [Logger.MetadataProvider]) -> Logger.MetadataProvider? { + assert(!providers.isEmpty, "providers MUST NOT be empty") + return Logger.MetadataProvider { + providers.reduce(into: [:]) { metadata, provider in + let providedMetadata = provider.get() + guard !providedMetadata.isEmpty else { + return + } + metadata.merge(providedMetadata, uniquingKeysWith: { _, rhs in rhs }) + } + } + } +} diff --git a/Tests/LinuxMain.swift b/Tests/LinuxMain.swift index 3cfdbccc..aa73eac8 100644 --- a/Tests/LinuxMain.swift +++ b/Tests/LinuxMain.swift @@ -31,5 +31,6 @@ XCTMain([ testCase(LocalLoggerTest.allTests), testCase(LoggingTest.allTests), testCase(MDCTest.allTests), + testCase(MetadataProviderTest.allTests), ]) #endif diff --git a/Tests/LoggingTests/LoggingTest+XCTest.swift b/Tests/LoggingTests/LoggingTest+XCTest.swift index d83c0f9b..6cf50fb0 100644 --- a/Tests/LoggingTests/LoggingTest+XCTest.swift +++ b/Tests/LoggingTests/LoggingTest+XCTest.swift @@ -44,6 +44,10 @@ extension LoggingTest { ("testLogsEmittedFromSubdirectoryGetCorrectModuleInNewerSwifts", testLogsEmittedFromSubdirectoryGetCorrectModuleInNewerSwifts), ("testLogMessageWithStringInterpolation", testLogMessageWithStringInterpolation), ("testLoggingAString", testLoggingAString), + ("testMultiplexMetadataProviderMergesInSpecifiedOrder", testMultiplexMetadataProviderMergesInSpecifiedOrder), + ("testLoggerWithoutFactoryOverrideDefaultsToUsingLoggingSystemMetadataProvider", testLoggerWithoutFactoryOverrideDefaultsToUsingLoggingSystemMetadataProvider), + ("testLoggerWithPredefinedLibraryMetadataProvider", testLoggerWithPredefinedLibraryMetadataProvider), + ("testLoggerWithFactoryOverrideDefaultsToUsingLoggingSystemMetadataProvider", testLoggerWithFactoryOverrideDefaultsToUsingLoggingSystemMetadataProvider), ("testMultiplexerIsValue", testMultiplexerIsValue), ("testLoggerWithGlobalOverride", testLoggerWithGlobalOverride), ("testLogLevelCases", testLogLevelCases), diff --git a/Tests/LoggingTests/LoggingTest.swift b/Tests/LoggingTests/LoggingTest.swift index 441b6f94..254e6e51 100644 --- a/Tests/LoggingTests/LoggingTest.swift +++ b/Tests/LoggingTests/LoggingTest.swift @@ -537,6 +537,69 @@ class LoggingTest: XCTestCase { testLogging.history.assertExist(level: .debug, message: "hello world!") } + func testMultiplexMetadataProviderMergesInSpecifiedOrder() { + let logging = TestLogging() + + let providerA = Logger.MetadataProvider { ["provider": "a", "a": "foo"] } + let providerB = Logger.MetadataProvider { ["provider": "b", "b": "bar"] } + let logger = Logger(label: #function, + factory: { label in + logging.makeWithMetadataProvider(label: label, metadataProvider: .multiplex([providerA, providerB])) + }) + + logger.log(level: .info, "test", metadata: ["one-off": "42"]) + + logging.history.assertExist(level: .info, + message: "test", + metadata: ["provider": "b", "a": "foo", "b": "bar", "one-off": "42"]) + } + + func testLoggerWithoutFactoryOverrideDefaultsToUsingLoggingSystemMetadataProvider() { + let logging = TestLogging() + LoggingSystem.bootstrapInternal({ label, metadataProvider in + logging.makeWithMetadataProvider(label: label, metadataProvider: metadataProvider) + }, metadataProvider: .init { ["provider": "42"] }) + + let logger = Logger(label: #function) + + logger.log(level: .info, "test", metadata: ["one-off": "42"]) + + logging.history.assertExist(level: .info, + message: "test", + metadata: ["provider": "42", "one-off": "42"]) + } + + func testLoggerWithPredefinedLibraryMetadataProvider() { + let logging = TestLogging() + LoggingSystem.bootstrapInternal( + logging.makeWithMetadataProvider, + metadataProvider: .exampleMetadataProvider + ) + + let logger = Logger(label: #function) + + logger.log(level: .info, "test", metadata: ["one-off": "42"]) + + logging.history.assertExist(level: .info, + message: "test", + metadata: ["example": "example-value", "one-off": "42"]) + } + + func testLoggerWithFactoryOverrideDefaultsToUsingLoggingSystemMetadataProvider() { + let logging = TestLogging() + LoggingSystem.bootstrapInternal(logging.makeWithMetadataProvider, metadataProvider: .init { ["provider": "42"] }) + + let logger = Logger(label: #function, factory: { label in + logging.makeWithMetadataProvider(label: label, metadataProvider: LoggingSystem.metadataProvider) + }) + + logger.log(level: .info, "test", metadata: ["one-off": "42"]) + + logging.history.assertExist(level: .info, + message: "test", + metadata: ["provider": "42", "one-off": "42"]) + } + func testMultiplexerIsValue() { let multi = MultiplexLogHandler([StreamLogHandler.standardOutput(label: "x"), StreamLogHandler.standardOutput(label: "y")]) LoggingSystem.bootstrapInternal { _ in @@ -702,7 +765,7 @@ class LoggingTest: XCTestCase { func testStreamLogHandlerOutputFormat() { let interceptStream = InterceptStream() let label = "testLabel" - LoggingSystem.bootstrapInternal { _ in + LoggingSystem.bootstrapInternal { label in StreamLogHandler(label: label, stream: interceptStream) } let source = "testSource" @@ -722,7 +785,7 @@ class LoggingTest: XCTestCase { func testStreamLogHandlerOutputFormatWithMetaData() { let interceptStream = InterceptStream() let label = "testLabel" - LoggingSystem.bootstrapInternal { _ in + LoggingSystem.bootstrapInternal { label in StreamLogHandler(label: label, stream: interceptStream) } let source = "testSource" @@ -742,7 +805,7 @@ class LoggingTest: XCTestCase { func testStreamLogHandlerOutputFormatWithOrderedMetadata() { let interceptStream = InterceptStream() let label = "testLabel" - LoggingSystem.bootstrapInternal { _ in + LoggingSystem.bootstrapInternal { label in StreamLogHandler(label: label, stream: interceptStream) } let log = Logger(label: label) @@ -757,8 +820,8 @@ class LoggingTest: XCTestCase { return } - XCTAssert(interceptStream.strings[0].contains("a=a0 b=b0")) - XCTAssert(interceptStream.strings[1].contains("a=a1 b=b1")) + XCTAssert(interceptStream.strings[0].contains("a=a0 b=b0"), "LINES: \(interceptStream.strings[0])") + XCTAssert(interceptStream.strings[1].contains("a=a1 b=b1"), "LINES: \(interceptStream.strings[1])") } func testStdioOutputStreamWrite() { @@ -890,6 +953,12 @@ extension Logger { #endif } +extension Logger.MetadataProvider { + static var exampleMetadataProvider: Self { + .init { ["example": .string("example-value")] } + } +} + // Sendable #if compiler(>=5.6) diff --git a/Tests/LoggingTests/MetadataProviderTest+XCTest.swift b/Tests/LoggingTests/MetadataProviderTest+XCTest.swift new file mode 100644 index 00000000..67a2a0f8 --- /dev/null +++ b/Tests/LoggingTests/MetadataProviderTest+XCTest.swift @@ -0,0 +1,33 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift Logging API open source project +// +// Copyright (c) 2018-2019 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 +// +//===----------------------------------------------------------------------===// +// +// MetadataProviderTest+XCTest.swift +// +import XCTest + +/// +/// NOTE: This file was generated by generate_linux_tests.rb +/// +/// Do NOT edit this file directly as it will be regenerated automatically when needed. +/// + +extension MetadataProviderTest { + static var allTests: [(String, (MetadataProviderTest) -> () throws -> Void)] { + return [ + ("testLoggingMergesOneOffMetadataWithProvidedMetadataFromExplicitlyPassed", testLoggingMergesOneOffMetadataWithProvidedMetadataFromExplicitlyPassed), + ("testLogHandlerThatDidNotImplementProvidersButSomeoneAttemptsToSetOneOnIt", testLogHandlerThatDidNotImplementProvidersButSomeoneAttemptsToSetOneOnIt), + ("testLogHandlerThatDidImplementProvidersButSomeoneAttemptsToSetOneOnIt", testLogHandlerThatDidImplementProvidersButSomeoneAttemptsToSetOneOnIt), + ] + } +} diff --git a/Tests/LoggingTests/MetadataProviderTest.swift b/Tests/LoggingTests/MetadataProviderTest.swift new file mode 100644 index 00000000..3d2dfda2 --- /dev/null +++ b/Tests/LoggingTests/MetadataProviderTest.swift @@ -0,0 +1,131 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift Logging API open source project +// +// Copyright (c) 2018-2019 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 +// +//===----------------------------------------------------------------------===// +@testable import Logging +import XCTest + +#if os(macOS) || os(iOS) || os(tvOS) || os(watchOS) +import Darwin +#elseif os(Windows) +import WinSDK +#else +import Glibc +#endif + +final class MetadataProviderTest: XCTestCase { + func testLoggingMergesOneOffMetadataWithProvidedMetadataFromExplicitlyPassed() throws { + let logging = TestLogging() + LoggingSystem.bootstrapInternal(logging.make) + + let logger = Logger(label: #function, metadataProvider: .init { + [ + "common": "provider", + "provider": "42", + ] + }) + + logger.log(level: .info, "test", metadata: ["one-off": "42", "common": "one-off"]) + + logging.history.assertExist(level: .info, + message: "test", + metadata: ["common": "one-off", "one-off": "42", "provider": "42"]) + } + + func testLogHandlerThatDidNotImplementProvidersButSomeoneAttemptsToSetOneOnIt() { + let logging = TestLogging() + var handler = LogHandlerThatDidNotImplementMetadataProviders(testLogging: logging) + + handler.metadataProvider = .simpleTestProvider + + logging.history.assertExist(level: .warning, message: "Attempted to set metadataProvider on LogHandlerThatDidNotImplementMetadataProviders that did not implement support for them. Please contact the log handler maintainer to implement metadata provider support.", source: "Logging") + } + + func testLogHandlerThatDidImplementProvidersButSomeoneAttemptsToSetOneOnIt() { + let logging = TestLogging() + var handler = LogHandlerThatDidImplementMetadataProviders(testLogging: logging) + + handler.metadataProvider = .simpleTestProvider + + logging.history.assertNotExist(level: .warning, message: "Attempted to set metadataProvider on LogHandlerThatDidImplementMetadataProviders that did not implement support for them. Please contact the log handler maintainer to implement metadata provider support.", source: "Logging") + } +} + +extension Logger.MetadataProvider { + static var simpleTestProvider: Logger.MetadataProvider { + return Logger.MetadataProvider { + return ["test": "provided"] + } + } +} + +public struct LogHandlerThatDidNotImplementMetadataProviders: LogHandler { + let testLogging: TestLogging + init(testLogging: TestLogging) { + self.testLogging = testLogging + } + + public subscript(metadataKey _: String) -> Logging.Logger.Metadata.Value? { + get { + return nil + } + set(newValue) { + // ignore + } + } + + public var metadata: Logging.Logger.Metadata = [:] + + public var logLevel: Logging.Logger.Level = .trace + + public func log(level: Logger.Level, + message: Logger.Message, + metadata: Logger.Metadata?, + source: String, + file: String, + function: String, + line: UInt) { + self.testLogging.make(label: "fake").log(level: level, message: message, metadata: metadata, source: source, file: file, function: function, line: line) + } +} + +public struct LogHandlerThatDidImplementMetadataProviders: LogHandler { + let testLogging: TestLogging + init(testLogging: TestLogging) { + self.testLogging = testLogging + } + + public subscript(metadataKey _: String) -> Logging.Logger.Metadata.Value? { + get { + return nil + } + set(newValue) { + // ignore + } + } + + public var metadata: Logging.Logger.Metadata = [:] + + public var logLevel: Logging.Logger.Level = .trace + + public var metadataProvider: Logger.MetadataProvider? + + public func log(level: Logger.Level, + message: Logger.Message, + metadata: Logger.Metadata?, + source: String, + file: String, + function: String, + line: UInt) { + self.testLogging.make(label: "fake").log(level: level, message: message, metadata: metadata, source: source, file: file, function: function, line: line) + } +} diff --git a/Tests/LoggingTests/TestLogger.swift b/Tests/LoggingTests/TestLogger.swift index 2e880ac9..8a1e8028 100644 --- a/Tests/LoggingTests/TestLogger.swift +++ b/Tests/LoggingTests/TestLogger.swift @@ -23,7 +23,21 @@ internal struct TestLogging { private let recorder = Recorder() // shared among loggers func make(label: String) -> LogHandler { - return TestLogHandler(label: label, config: self.config, recorder: self.recorder) + return TestLogHandler( + label: label, + config: self.config, + recorder: self.recorder, + metadataProvider: LoggingSystem.metadataProvider + ) + } + + func makeWithMetadataProvider(label: String, metadataProvider: Logger.MetadataProvider?) -> LogHandler { + return TestLogHandler( + label: label, + config: self.config, + recorder: self.recorder, + metadataProvider: metadataProvider + ) } var config: Config { return self._config } @@ -36,16 +50,43 @@ internal struct TestLogHandler: LogHandler { private var logger: Logger // the actual logger let label: String - init(label: String, config: Config, recorder: Recorder) { + public var metadataProvider: Logger.MetadataProvider? + + init(label: String, config: Config, recorder: Recorder, metadataProvider: Logger.MetadataProvider?) { self.label = label self.config = config self.recorder = recorder self.logger = Logger(label: "test", StreamLogHandler.standardOutput(label: label)) self.logger.logLevel = .debug + self.metadataProvider = metadataProvider } - func log(level: Logger.Level, message: Logger.Message, metadata: Logger.Metadata?, source: String, file: String, function: String, line: UInt) { - let metadata = (self._metadataSet ? self.metadata : MDC.global.metadata).merging(metadata ?? [:], uniquingKeysWith: { _, new in new }) + init(label: String, config: Config, recorder: Recorder) { + self.label = label + self.config = config + self.recorder = recorder + self.logger = Logger(label: "test", StreamLogHandler.standardOutput(label: label)) + self.logger.logLevel = .debug + self.metadataProvider = LoggingSystem.metadataProvider + } + + func log(level: Logger.Level, + message: Logger.Message, + metadata explicitMetadata: Logger.Metadata?, + source: String, + file: String, function: String, line: UInt) { + // baseline metadata, that was set on handler: + var metadata = self._metadataSet ? self.metadata : MDC.global.metadata + // contextual metadata, e.g. from task-locals: + let contextualMetadata = self.metadataProvider?.get() ?? [:] + if !contextualMetadata.isEmpty { + metadata.merge(contextualMetadata, uniquingKeysWith: { _, contextual in contextual }) + } + // override using any explicit metadata passed for this log statement: + if let explicitMetadata = explicitMetadata { + metadata.merge(explicitMetadata, uniquingKeysWith: { _, explicit in explicit }) + } + self.logger.log(level: level, message, metadata: metadata, source: source, file: file, function: function, line: line) self.recorder.record(level: level, metadata: metadata, message: message, source: source) } @@ -224,10 +265,36 @@ extension History { func find(level: Logger.Level, message: String, metadata: Logger.Metadata? = nil, source: String) -> LogEntry? { return self.entries.first { entry in - entry.level == level && - entry.message == message && - entry.metadata ?? [:] == metadata ?? [:] && - entry.source == source + if entry.level != level { + return false + } + if entry.message != message { + return false + } + if let lhs = entry.metadata, let rhs = metadata { + if lhs.count != rhs.count { + return false + } + + for lk in lhs.keys { + if lhs[lk] != rhs[lk] { + return false + } + } + + for rk in rhs.keys { + if lhs[rk] != rhs[rk] { + return false + } + } + + return true + } + if entry.source != source { + return false + } + + return true } } } diff --git a/proposals/0001-metadata-providers.md b/proposals/0001-metadata-providers.md new file mode 100644 index 00000000..a0480d9d --- /dev/null +++ b/proposals/0001-metadata-providers.md @@ -0,0 +1,328 @@ +# Metadata Providers + +Authors: [Moritz Lang](https://github.com/slashmo), [Konrad 'ktoso' Malawski](https://github.com/ktoso) + +## Introduction + +While global metadata attributes may be manually set on a `LogHandler` level, there's currently no way of reliably providing contextual, automatically propagated, metadata when logging with swift-log. + +## Motivation + +To benefit from tools such as [Distributed Tracing](https://github.com/apple/swift-distributed-tracing) it is necessary for libraries to make use of the trace information. + +Most notably, loggers should participate in tracing by including some trace metadata (such as e.g. a `trace-id`) when logging, as it transparently enables developers to benefit from log correlation using those IDs. + +Today, the only supported way of providing such metadata is to pass them along to each log call explicitly: + +```swift +logger.info("first this ...", metadata: ["trace-id": MyTracingLibrary.currentTraceID]) +logger.info("... now this", metadata: ["trace-id": MyTracingLibrary.currentTraceID]) +``` + +This comes with a couple of downsides: + +### Error-prone and repetitive + +It's easy to forget passing this metadata to _all_ log statements, resulting in an inconsistent debugging experience as these log statements cannot be found using correlation IDs. + +The repetitiveness and verboseness of logging multiple metadata in-line quickly becomes annoying and vastly decreases the signal-to-noise ratio of Swift code trying to be a good citizen and making use of log correlation techniques such as distributed tracing. + +### Impossible to implement for libraries + +A large portion of logs are not generated by the end-user but by libraries such as AsyncHTTPClient, Vapor etc. +These libraries, by design, don't know about the specific metadata keys that should be included in the logs. +Those keys are after all runtime dependent, and may change depending on what tracing system is configured by the end user. + +For example, a specific `Tracer` implementation would use a type representing a trace ID, and has a way of extracting +that trace ID from a [Swift Distributed Tracing Baggage](https://github.com/apple/swift-distributed-tracing-baggage). But other libraries can't know about this _specific_ trace ID and therefore would not be +able to pass such values along to their log statements. + +## Proposed solution + +To support this kind of runtime-generated metadata in `swift-log`, we need to extend the logging APIs in an open-ended way, to allow any kinds of metadata to be provided from the asynchronous context (i.e. task local values). + +We also have a desire to keep `swift-log` a "zero dependencies" library, as it intends only to focus on describing a logging API, and not incur any additional dependencies, so it can be used in the most minimal of projects. + +To solve this, we propose the extension of swift-log APIs with a new concept: _metadata providers_. + +`MetadataProvider` is a struct nested in the `Logger` type, sitting alongside `MetadataValue` and the `Metadata`. +Its purpose is to _provide_ `Logger.Metadata` from the asynchronous context, by e.g. looking up various task-local values, +and converting them into `Logger.Metadata`. This is performed by calling the `get()` function, like so: + +```swift +extension Logger { + public struct MetadataProvider: Sendable { + // ... + public init(_ provideMetadata: @escaping @Sendable () -> Metadata) + + public get() -> Metadata + } +} +``` + +### Defining a `MetadataProvider` + +While `MetadataProvider`s can be created in an ad-hoc fashion, the struct may be used as a namespace +to define providers in. + +For example, a `MyTracer` implementation of swift-distributed-tracing would be expected to provide a metadata provider +that is aware of its own `Baggage` and specific keys it uses to carry the trace and span identifiers, like this: + +```swift +import Tracing // swift-distributed-tracing + +extension Logger.MetadataProvider { + static let myTracer = Logger.MetadataProvider { + guard let baggage = Baggage.current else { + return [:] + } + guard let spanContext = baggage.spanContext else { + return [:] + } + + return [ + "traceID": "\(spanContext.traceID)", + "spanID": "\(spanContext.spanID)", + ] + } +} +``` + +### Using a `MetadataProvider` + +A `MetadataProvider` can be set up either globally, on a boot-strapped logging system: + +```swift +LoggingSystem.bootstrap( + metadataProvider: .myTracer, + StreamLogHandler.standardOutput +) +``` + +or, using the metadata provider specific bootstrap method: + +```swift +LoggingSystem.bootstrapMetadataProvider(.myTracer) +``` + +It is also possible to configure a metadata provider on a per-logger basis, like this: + +```swift +let logger = Logger(label: "example", metadataProvider: Logger.MetadataProvider { + guard let baggage = Baggage.current else { + return [:] + } + guard let operationID = baggage.operationID else { + return nil + } + return ["extra/opID": "\(opID)"] +}) +``` + +which _overrides_ the default bootstrapped metadata provider. + +> NOTE: Setting the metadata provider on the logger directly means the `LoggingSystem` metadata provider +> is skipped (if defined), following how an explicitly passed handler `factory` +> overrides the `LoggingSystem`s `factory`. + +Once a metadata provider was set up, when a log statement is about to be emitted, the log handler implementation shall +invoke it whenever it is about to emit a log statement. This must be done from the same asynchronous context as the log statement +was made; I.e. if a log handler were to asynchronously–in a _detached_ task–create the actual log message, the invocation of +the metadata provider still _must_ be performed before passing the data over to the other detached task. + +Usually, metadata providers will reach for the task's Swift Distributed Tracing [`Baggage`](https://github.com/apple/swift-distributed-tracing-baggage) which is the mechanism that swift-distributed-tracing +and instrumentation libraries use to propagate metadata across asynchronous, as well as process, boundaries. Handlers +may also inspect other task-local values, however they should not expect other libraries to be able to propagage those +as well as they will propagate `Baggage` values. + +Those metadata will then be included in the log statement, e.g. like this: + +```swift +var baggage = Baggage.topLevel +baggage.spanContext = SpanContext() +Baggage.withValue(baggage) { + test() +} + +func test() { + log.info("Test", metadata: ["oneOff": "42"]) + // info [traceID: abc, spanID: 123, onOff: 42] Test +} +``` + +### Multiple `MetadataProvider`s using `MetadataProvider.multiplex(_:)` + +Borrowing the concept from log handlers, metadata providers also have a multiplexing implementation. +It is defined as an extension on `MetadataProvider` and is useful in cases where users want to utilize +more than one metadata provider at the same time: + +```swift +extension Logger.MetadataProvider { + public static func multiplex(_ providers: [Logger.MetadataProvider]) -> Logger.MetadataProvider { + precondition(!providers.isEmpty, "providers MUST NOT be empty") + return Logger.MetadataProvider { baggage in + providers.reduce(into: nil) { metadata, provider in + if let providedMetadata = provider.metadata(baggage) { + if metadata != nil { + metadata!.merge(providedMetadata, uniquingKeysWith: { _, rhs in rhs }) + } else { + metadata = providedMetadata + } + } + } + } + } +} +``` + +Metadata keys are unique, so in case multiple metadata providers return the same key, +the last provider in the array _wins_ and provides the value. + +Note that it is possible to query the `LoggingSystem` for the configured, system-wide, metadata provider, +and combine it using a `multiplex` provider if the system-wide provider should not be replaced, but augmented +by additional providers. + +### Understanding Swift Distributed Tracing `Baggage` + +The `Baggage` type is more than just a fancy type-safe container for your values which are meant to be carried across +using a single, well-known, [task-local value](https://developer.apple.com/documentation/swift/tasklocal). + +Values stored in `Baggage` are intended to be carried _across process boundaries_, and e.g. libraries such as HTTP clients, +or other RPC mechanisms, or even messaging systems implement distributed tracing [instruments](https://github.com/apple/swift-distributed-tracing/blob/main/Sources/Instrumentation/Instrument.swift) +which `inject` and `extract` baggage values into their respective carrier objects, e.g. an `HTTPRequest` in the case of an HTTP client. + +In other words, whenever intending to propagate information _across processes_ utilize the `Baggage` type to carry it, +and ensure to provide an `Instrument` that is able to inject/extract the values of interest into the carrier types you are interested in. +To learn more about baggage and instrumentation, refer to the [Swift Distributed Tracing](https://github.com/apple/swift-distributed-tracing/) library documentation. + +#### When to use `Baggage` vs. `Logger[metadataKey:]` + +While `Baggage` is context-dependent and changes depending on where the log methods are being called from, the metadata set on a `Logger` is static and not context-dependent. E.g, if you wanted to add things like an instance ID or a subsystem name to a `Logger`, that could be seen as static information and set via `Logger[metadataKey:]`. + +```swift +var logger = Logger(label: "org.swift.my-service") +logger[metadataKey: "instanceId"] = "123" + +logger.info("Service started.") +// [instanceId: 123] Service started. +``` + +On the other hand, things like a trace ID are dynamic and context-dependent, therefore would be obtained via `Baggage`: + +```swift +logger.info("Product fetched.") +// [traceId: 42] Product fetched. +``` + +Inline-metadata is suitable for one-offs such as a `productId` or a `paymentMethod` in an online store service, but are not enough to corralate the following log statements, i.e. tying them both to the same request: + +```swift +logger.info("Product fetched.", metadata: ["productId": "42"]) +logger.info("Product purchased.", metadata: ["paymentMethod": "apple-pay"]) + +// [productId: 42] Product fetched. +// [paymentMethod: apple-pay] Product fetched. +``` + +If there was a `Baggage` value with a trace ID surrounding these log statements, they would be automatically correlatable: + +```swift +var baggage = Baggage.topLevel +baggage.traceID = 42 +Baggage.$current.withValue(baggage) { + logger.info("Product fetched.", metadata: ["productId": "42"]) + logger.info("Product purchased.", metadata: ["paymentMethod": "apple-pay"]) +} + +// [trace-id: 42, productId: 42] Product fetched. +// [trace-id: 42, paymentMethod: apple-pay] Product fetched. +``` + +## Alternatives considered + +### MetadataProviders as a function of `Baggage -> Metadata` + +This was considered and fully developed, however it would cause swift-log to have a dependency on the instrumentation type `Baggage`, +which was seen as in-conflict-with the interest of swift-log remaining a zero-dependency library. + +`Baggage` _is_ the well known type that is intended to be used for any kind of distributed systems instrumentation and tracing, +however it adds additional complexity and confusion for users who are not interested in this domain. For example, developers +may be confused about why `Baggage` and `Logger.Metadata` look somewhat similar, but behave very differently. This complexity +is inherent to the two types actually being _very_ different, however we do not want to overwhelm newcomers or developers +who are only intending to use swift-log within process. Such developers do not need to care about the added complexities +of distributed systems. + +The tradeoff we take here is that every metadata provider will have to perform its own task-local (and therefore also thread-local), +access in order to obtain the `Baggage` value, rather than the lookup being able to be performed _once_ and shared between +multiple providers when a multiplex provider was configured in the system. We view this tradeoff as worth taking, as the cost +of actually formatting the metadata usually strongly dominates the cost of the task-local lookup. + +### Removing `LogHandler.Metadata` in favor of `Baggage` + +Removing logger metadata is not a good option because it serves a slightly different style of metadata than the baggage. + +Baggage is intended for contextual, task-local, metadata which is _carried across multiple libraries_. The values stored in baggage are well-typed, and must declare keys for accessing values in a baggage, this works well for multiple pieces of an application needing to reach for specific baggage items: everyone aware of the `traceID` key, is able to query the baggage for this key (`baggage.traceID`) and obtain a well-typed value. This comes with a higher cost on declaring keys though, as well as a global namespace for those - which is desirable for such kinds of metadata. + +This is not the same usage pattern as emitting a plain structured log where we'd like to include the name of an item we just queried: + +```swift +log.info("Obtained item! Hooray!", metadata: ["item": "\(item)"]) +``` + +In this example, the key/value pair for `"item"` is pretty ad-hoc, and we never need to refer to it elsewhere in the program. It never is queried by other pieces of the application, nor would it be useful to set it in baggage metadata, as the only purpose of the `item` key here is to log, and forget about it. + +### Explicitly passing `Baggage` always + +Baggage is designed for use cases like distributed tracing, or similar instrumentation patterns where "all" participating code may need to reach for it. + +Specifically in logging, this means that _every_ call site for _every_ log statement would have to pass it explicitly resulting in annoying noisy code: + +```swift +class StoresRepository { + func store(byID id: String, eventLoop: EventLoop, logger: Logger, baggage: Baggage) async throws -> Store { + InstrumentationSystem.tracer.withSpan("Fetch Store") { span in + logger.info("Fetched store.", baggage: span.baggage) + } + } +} + +try await storesRepository.store( + byID: storeID, + eventLoop: eventLoop, + logger: logger, + baggage: baggage +) +``` + +### Explicitly passing `Logger` always + +Imagine we don't have metadata providers, we'd have to manually set trace IDs on loggers which doesn't really work as all libraries involved would need to know about the same specific trace ID. Even if we inverted the dependency to have `Tracing` depend on `Logging` so that we'd be able to define something like "Tracing, please populate this logger with metadata", we'd have to make sure this thing is called in all places to avoid dropping contextual metadata. + +```swift +import Tracing +import Logging + +let contextualLogger = InstrumentationSystem.tracer.populateTraceMetadata(logger) +contextualLogger.info("Request received.") +``` + +### Tracing providing extensions on Logger + +Instead of having `swift-log` depend on `swift-distributed-tracing-baggage` we could also create extensions for `Logger` inside `swift-distributed-tracing` and have users call these new overloaded methods instead: + +```swift +extension Logger { + func tinfo(_ message: ..., baggage: Baggage?) { + // ... + } +} +``` + +Such extensions could work like the currently-proposed APIs, but the risk of users calling the wrong methods is incredibly high and we cannot overload the existing methods' signatures because of ambiguity of call-sides without explicit Baggage being passed: + +```swift +logger.info("Hello") +// we want this to pick up Baggage, but the signature would be ambiguous +``` + +Also, this extension-based contextual metadata would require basically everyone in Server-side Swift to adapt their usage of `Logging` to use these extensions instead. With the proposed APIs, we'd only need to modify `Logging` and any NIO-based libraries such as `AsyncHTTPClient`, `Vapor`, etc. and not every single log statement in every application.