From aaa789d1421428d5217571dfdbc9efe137c2526f Mon Sep 17 00:00:00 2001 From: Joannis Orlandos Date: Mon, 25 Mar 2024 14:14:05 +0100 Subject: [PATCH 1/5] Add OTelLogHandler that sends OTelLogEntry to an OTelLogEntryProcessor --- .../OTel/Logging/OTLPLogEntryDataModel.swift | 22 +++++++ Sources/OTel/Logging/OTelLogHandler.swift | 62 +++++++++++++++++++ .../Processing/OTelLogEntryProcessor.swift | 31 ++++++++++ .../OTelNoOpLogEntryProcessor.swift | 40 ++++++++++++ 4 files changed, 155 insertions(+) create mode 100644 Sources/OTel/Logging/OTLPLogEntryDataModel.swift create mode 100644 Sources/OTel/Logging/OTelLogHandler.swift create mode 100644 Sources/OTel/Logging/Processing/OTelLogEntryProcessor.swift create mode 100644 Sources/OTel/Logging/Processing/OTelNoOpLogEntryProcessor.swift diff --git a/Sources/OTel/Logging/OTLPLogEntryDataModel.swift b/Sources/OTel/Logging/OTLPLogEntryDataModel.swift new file mode 100644 index 00000000..7e8fb6c1 --- /dev/null +++ b/Sources/OTel/Logging/OTLPLogEntryDataModel.swift @@ -0,0 +1,22 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift OTel open source project +// +// Copyright (c) 2024 Moritz Lang and the Swift OTel project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +import Logging + +@_spi(Logging) +public struct OTelLogEntry: Equatable, Sendable { + public let body: String + public let level: Logger.Level + public let metadata: Logger.Metadata? + public let timeNanosecondsSinceEpoch: UInt64 +} diff --git a/Sources/OTel/Logging/OTelLogHandler.swift b/Sources/OTel/Logging/OTelLogHandler.swift new file mode 100644 index 00000000..0d6c299d --- /dev/null +++ b/Sources/OTel/Logging/OTelLogHandler.swift @@ -0,0 +1,62 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift OTel open source project +// +// Copyright (c) 2024 Moritz Lang and the Swift OTel project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +import AsyncAlgorithms +import Logging +import NIOConcurrencyHelpers +import ServiceLifecycle +import Logging +import Tracing + +@_spi(Logging) +public struct OTelLogHandler: Sendable, LogHandler { + public var metadata: Logging.Logger.Metadata + public var logLevel: Logging.Logger.Level + private let processor: any OTelLogEntryProcessor + + public init( + processor: any OTelLogEntryProcessor, + logLevel: Logger.Level, + metadata: Logger.Metadata = [:] + ) { + self.processor = processor + self.logLevel = logLevel + self.metadata = metadata + } + + public subscript(metadataKey key: String) -> Logging.Logger.Metadata.Value? { + get { metadata[key] } + set { metadata[key] = newValue } + } + + public func log( + level: Logger.Level, + message: Logger.Message, + metadata: Logger.Metadata?, + source: String, + file: String, + function: String, + line: UInt + ) { + let instant = DefaultTracerClock().now + + let message = OTelLogEntry( + body: message.description, + level: level, + metadata: metadata, + timeNanosecondsSinceEpoch: instant.nanosecondsSinceEpoch + ) + + processor.onLog(message) + } +} diff --git a/Sources/OTel/Logging/Processing/OTelLogEntryProcessor.swift b/Sources/OTel/Logging/Processing/OTelLogEntryProcessor.swift new file mode 100644 index 00000000..e789899e --- /dev/null +++ b/Sources/OTel/Logging/Processing/OTelLogEntryProcessor.swift @@ -0,0 +1,31 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift OTel open source project +// +// Copyright (c) 2024 Moritz Lang and the Swift OTel project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +import ServiceLifecycle +import ServiceContextModule + +/// Log processors allow for processing logs throughout their lifetime via ``onStart(_:parentContext:)`` and ``onEnd(_:)`` calls. +/// Usually, log processors will forward logs to a configurable ``OTelLogEntryExporter``. +/// +/// [OpenTelemetry specification: LogRecord processor](https://github.com/open-telemetry/opentelemetry-specification/blob/v1.20.0/specification/logs/sdk.md#logrecordprocessor) +/// +/// ### Implementation Notes +/// +/// On shutdown, processors forwarding logs to an ``OTelLogEntryExporter`` MUST shutdown that exporter. +@_spi(Logging) +public protocol OTelLogEntryProcessor: Service & Sendable { + func onLog(_ log: OTelLogEntry) + + /// Force log processors that batch logs to flush immediately. + func forceFlush() async throws +} diff --git a/Sources/OTel/Logging/Processing/OTelNoOpLogEntryProcessor.swift b/Sources/OTel/Logging/Processing/OTelNoOpLogEntryProcessor.swift new file mode 100644 index 00000000..4610ede9 --- /dev/null +++ b/Sources/OTel/Logging/Processing/OTelNoOpLogEntryProcessor.swift @@ -0,0 +1,40 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift OTel open source project +// +// Copyright (c) 2024 Moritz Lang and the Swift OTel project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +import ServiceContextModule + +/// A log entry processor that ignores all operations, used when no logs should be processed. +@_spi(Logging) +public struct OTelNoOpLogEntryProcessor: OTelLogEntryProcessor, CustomStringConvertible { + public let description = "OTelNoOpLogEntryProcessor" + + private let stream: AsyncStream + private let continuation: AsyncStream.Continuation + + /// Initialize a no-op log entry processor. + public init() { + (stream, continuation) = AsyncStream.makeStream() + } + + public func run() async { + for await _ in stream.cancelOnGracefulShutdown() {} + } + + public func onLog(_ log: OTelLogEntry) { + // no-op + } + + public func forceFlush() async throws { + // no-op + } +} From c2d72a47fd2bfa5646c62efe605291b84f3eb71c Mon Sep 17 00:00:00 2001 From: Moritz Lang Date: Wed, 27 Mar 2024 21:58:18 +0100 Subject: [PATCH 2/5] Format Swift code --- Sources/OTel/Logging/OTelLogHandler.swift | 1 - Sources/OTel/Logging/Processing/OTelLogEntryProcessor.swift | 2 +- 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/Sources/OTel/Logging/OTelLogHandler.swift b/Sources/OTel/Logging/OTelLogHandler.swift index 0d6c299d..13808c83 100644 --- a/Sources/OTel/Logging/OTelLogHandler.swift +++ b/Sources/OTel/Logging/OTelLogHandler.swift @@ -15,7 +15,6 @@ import AsyncAlgorithms import Logging import NIOConcurrencyHelpers import ServiceLifecycle -import Logging import Tracing @_spi(Logging) diff --git a/Sources/OTel/Logging/Processing/OTelLogEntryProcessor.swift b/Sources/OTel/Logging/Processing/OTelLogEntryProcessor.swift index e789899e..2a9a5bf2 100644 --- a/Sources/OTel/Logging/Processing/OTelLogEntryProcessor.swift +++ b/Sources/OTel/Logging/Processing/OTelLogEntryProcessor.swift @@ -11,8 +11,8 @@ // //===----------------------------------------------------------------------===// -import ServiceLifecycle import ServiceContextModule +import ServiceLifecycle /// Log processors allow for processing logs throughout their lifetime via ``onStart(_:parentContext:)`` and ``onEnd(_:)`` calls. /// Usually, log processors will forward logs to a configurable ``OTelLogEntryExporter``. From 92a8b71f585972ae4870387e36be882ea566d312 Mon Sep 17 00:00:00 2001 From: Moritz Lang Date: Wed, 27 Mar 2024 23:14:28 +0100 Subject: [PATCH 3/5] Rename OTelLogEntry* to OTelLogRecord* Apparently it's called log records in the spec, not log entries as I originally thought: https://opentelemetry.io/docs/specs/otel/logs/data-model/#log-and-event-record-definition --- .../{OTLPLogEntryDataModel.swift => OTelLogRecord.swift} | 9 ++++++++- ...EntryProcessor.swift => OTelLogRecordProcessor.swift} | 4 ++-- ...yProcessor.swift => OTelNoOpLogRecordProcessor.swift} | 8 ++++---- 3 files changed, 14 insertions(+), 7 deletions(-) rename Sources/OTel/Logging/{OTLPLogEntryDataModel.swift => OTelLogRecord.swift} (65%) rename Sources/OTel/Logging/Processing/{OTelLogEntryProcessor.swift => OTelLogRecordProcessor.swift} (91%) rename Sources/OTel/Logging/Processing/{OTelNoOpLogEntryProcessor.swift => OTelNoOpLogRecordProcessor.swift} (75%) diff --git a/Sources/OTel/Logging/OTLPLogEntryDataModel.swift b/Sources/OTel/Logging/OTelLogRecord.swift similarity index 65% rename from Sources/OTel/Logging/OTLPLogEntryDataModel.swift rename to Sources/OTel/Logging/OTelLogRecord.swift index 7e8fb6c1..b460e327 100644 --- a/Sources/OTel/Logging/OTLPLogEntryDataModel.swift +++ b/Sources/OTel/Logging/OTelLogRecord.swift @@ -14,9 +14,16 @@ import Logging @_spi(Logging) -public struct OTelLogEntry: Equatable, Sendable { +public struct OTelLogRecord: Equatable, Sendable { public let body: String public let level: Logger.Level public let metadata: Logger.Metadata? public let timeNanosecondsSinceEpoch: UInt64 + + package init(body: String, level: Logger.Level, metadata: Logger.Metadata?, timeNanosecondsSinceEpoch: UInt64) { + self.body = body + self.level = level + self.metadata = metadata + self.timeNanosecondsSinceEpoch = timeNanosecondsSinceEpoch + } } diff --git a/Sources/OTel/Logging/Processing/OTelLogEntryProcessor.swift b/Sources/OTel/Logging/Processing/OTelLogRecordProcessor.swift similarity index 91% rename from Sources/OTel/Logging/Processing/OTelLogEntryProcessor.swift rename to Sources/OTel/Logging/Processing/OTelLogRecordProcessor.swift index 2a9a5bf2..d629989d 100644 --- a/Sources/OTel/Logging/Processing/OTelLogEntryProcessor.swift +++ b/Sources/OTel/Logging/Processing/OTelLogRecordProcessor.swift @@ -23,8 +23,8 @@ import ServiceLifecycle /// /// On shutdown, processors forwarding logs to an ``OTelLogEntryExporter`` MUST shutdown that exporter. @_spi(Logging) -public protocol OTelLogEntryProcessor: Service & Sendable { - func onLog(_ log: OTelLogEntry) +public protocol OTelLogRecordProcessor: Service & Sendable { + func onEmit(_ record: OTelLogRecord) /// Force log processors that batch logs to flush immediately. func forceFlush() async throws diff --git a/Sources/OTel/Logging/Processing/OTelNoOpLogEntryProcessor.swift b/Sources/OTel/Logging/Processing/OTelNoOpLogRecordProcessor.swift similarity index 75% rename from Sources/OTel/Logging/Processing/OTelNoOpLogEntryProcessor.swift rename to Sources/OTel/Logging/Processing/OTelNoOpLogRecordProcessor.swift index 4610ede9..71c89e60 100644 --- a/Sources/OTel/Logging/Processing/OTelNoOpLogEntryProcessor.swift +++ b/Sources/OTel/Logging/Processing/OTelNoOpLogRecordProcessor.swift @@ -13,10 +13,10 @@ import ServiceContextModule -/// A log entry processor that ignores all operations, used when no logs should be processed. +/// A log record processor that ignores all operations, used when no logs should be processed. @_spi(Logging) -public struct OTelNoOpLogEntryProcessor: OTelLogEntryProcessor, CustomStringConvertible { - public let description = "OTelNoOpLogEntryProcessor" +public struct OTelNoOpLogRecordProcessor: OTelLogRecordProcessor, CustomStringConvertible { + public let description = "OTelNoOpLogRecordProcessor" private let stream: AsyncStream private let continuation: AsyncStream.Continuation @@ -30,7 +30,7 @@ public struct OTelNoOpLogEntryProcessor: OTelLogEntryProcessor, CustomStringConv for await _ in stream.cancelOnGracefulShutdown() {} } - public func onLog(_ log: OTelLogEntry) { + public func onEmit(_ log: OTelLogRecord) { // no-op } From 74fe686f16d964514a32cd231b205c1bb8a20cee Mon Sep 17 00:00:00 2001 From: Moritz Lang Date: Wed, 27 Mar 2024 23:16:12 +0100 Subject: [PATCH 4/5] Add OTelInMemoryLogRecordProcessor for testing --- .../OTelInMemoryLogRecordProcessor.swift | 44 +++++++++++++++++++ 1 file changed, 44 insertions(+) create mode 100644 Sources/OTelTesting/OTelInMemoryLogRecordProcessor.swift diff --git a/Sources/OTelTesting/OTelInMemoryLogRecordProcessor.swift b/Sources/OTelTesting/OTelInMemoryLogRecordProcessor.swift new file mode 100644 index 00000000..65b7f558 --- /dev/null +++ b/Sources/OTelTesting/OTelInMemoryLogRecordProcessor.swift @@ -0,0 +1,44 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift OTel open source project +// +// Copyright (c) 2024 Moritz Lang and the Swift OTel project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +@_spi(Logging) import OTel +import NIOConcurrencyHelpers + +/// An in-memory log record processor, collecting emitted log records into ``onEmit(_:)``. +package final class OTelInMemoryLogRecordProcessor: OTelLogRecordProcessor { + package var records: [OTelLogRecord] { _records.withLockedValue { $0 } } + + private let _records = NIOLockedValueBox([OTelLogRecord]()) + private let _numberOfShutdowns = NIOLockedValueBox(0) + private let _numberOfForceFlushes = NIOLockedValueBox(0) + + private let stream: AsyncStream + private let continuation: AsyncStream.Continuation + + package init() { + (stream, continuation) = AsyncStream.makeStream() + } + + package func run() async throws { + for await _ in stream.cancelOnGracefulShutdown() {} + _numberOfShutdowns.withLockedValue { $0 += 1 } + } + + package func onEmit(_ record: OTelLogRecord) { + _records.withLockedValue { $0.append(record) } + } + + package func forceFlush() async throws { + _numberOfForceFlushes.withLockedValue { $0 += 1 } + } +} From f9886fe3ccd61c0c99247d537c3b570455bb301a Mon Sep 17 00:00:00 2001 From: Moritz Lang Date: Wed, 27 Mar 2024 23:16:23 +0100 Subject: [PATCH 5/5] Unit-test OTelLogHandler --- Sources/OTel/Logging/OTelLogHandler.swift | 41 +++++-- .../OTelInMemoryLogRecordProcessor.swift | 2 +- .../Logging/OTelLogHandlerTests.swift | 113 ++++++++++++++++++ 3 files changed, 145 insertions(+), 11 deletions(-) create mode 100644 Tests/OTelTests/Logging/OTelLogHandlerTests.swift diff --git a/Sources/OTel/Logging/OTelLogHandler.swift b/Sources/OTel/Logging/OTelLogHandler.swift index 13808c83..520df5b7 100644 --- a/Sources/OTel/Logging/OTelLogHandler.swift +++ b/Sources/OTel/Logging/OTelLogHandler.swift @@ -19,21 +19,37 @@ import Tracing @_spi(Logging) public struct OTelLogHandler: Sendable, LogHandler { - public var metadata: Logging.Logger.Metadata - public var logLevel: Logging.Logger.Level - private let processor: any OTelLogEntryProcessor + public var metadata: Logger.Metadata + public var logLevel: Logger.Level + private let processor: any OTelLogRecordProcessor + private let nanosecondsSinceEpoch: @Sendable () -> UInt64 public init( - processor: any OTelLogEntryProcessor, + processor: any OTelLogRecordProcessor, logLevel: Logger.Level, metadata: Logger.Metadata = [:] + ) { + self.init( + processor: processor, + logLevel: logLevel, + metadata: metadata, + nanosecondsSinceEpoch: { DefaultTracerClock.now.nanosecondsSinceEpoch } + ) + } + + package init( + processor: any OTelLogRecordProcessor, + logLevel: Logger.Level, + metadata: Logger.Metadata, + nanosecondsSinceEpoch: @escaping @Sendable () -> UInt64 ) { self.processor = processor self.logLevel = logLevel self.metadata = metadata + self.nanosecondsSinceEpoch = nanosecondsSinceEpoch } - public subscript(metadataKey key: String) -> Logging.Logger.Metadata.Value? { + public subscript(metadataKey key: String) -> Logger.Metadata.Value? { get { metadata[key] } set { metadata[key] = newValue } } @@ -47,15 +63,20 @@ public struct OTelLogHandler: Sendable, LogHandler { function: String, line: UInt ) { - let instant = DefaultTracerClock().now + let effectiveMetadata: Logger.Metadata? + if let metadata { + effectiveMetadata = self.metadata.merging(metadata, uniquingKeysWith: { $1 }) + } else { + effectiveMetadata = self.metadata.isEmpty ? nil : self.metadata + } - let message = OTelLogEntry( + let record = OTelLogRecord( body: message.description, level: level, - metadata: metadata, - timeNanosecondsSinceEpoch: instant.nanosecondsSinceEpoch + metadata: effectiveMetadata, + timeNanosecondsSinceEpoch: nanosecondsSinceEpoch() ) - processor.onLog(message) + processor.onEmit(record) } } diff --git a/Sources/OTelTesting/OTelInMemoryLogRecordProcessor.swift b/Sources/OTelTesting/OTelInMemoryLogRecordProcessor.swift index 65b7f558..5a25f0dd 100644 --- a/Sources/OTelTesting/OTelInMemoryLogRecordProcessor.swift +++ b/Sources/OTelTesting/OTelInMemoryLogRecordProcessor.swift @@ -11,8 +11,8 @@ // //===----------------------------------------------------------------------===// -@_spi(Logging) import OTel import NIOConcurrencyHelpers +@_spi(Logging) import OTel /// An in-memory log record processor, collecting emitted log records into ``onEmit(_:)``. package final class OTelInMemoryLogRecordProcessor: OTelLogRecordProcessor { diff --git a/Tests/OTelTests/Logging/OTelLogHandlerTests.swift b/Tests/OTelTests/Logging/OTelLogHandlerTests.swift new file mode 100644 index 00000000..362e041f --- /dev/null +++ b/Tests/OTelTests/Logging/OTelLogHandlerTests.swift @@ -0,0 +1,113 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift OTel open source project +// +// Copyright (c) 2024 Moritz Lang and the Swift OTel project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +@testable import Logging +@_spi(Logging) import OTel +import OTelTesting +import XCTest + +final class OTelLogHandlerTests: XCTestCase { + func test_log_withoutMetadata_forwardsLogEntryToProcessor() { + let processor = OTelInMemoryLogRecordProcessor() + let logger = Logger(label: #function) { _ in + OTelLogHandler(processor: processor, logLevel: .info, metadata: [:], nanosecondsSinceEpoch: { 42 }) + } + + logger.info("🏎️") + + XCTAssertEqual(processor.records, [ + OTelLogRecord(body: "🏎️", level: .info, metadata: nil, timeNanosecondsSinceEpoch: 42), + ]) + } + + func test_log_withLoggerMetadata_includesMetadataInLogRecord() { + let processor = OTelInMemoryLogRecordProcessor() + var logger = Logger(label: #function) { _ in + OTelLogHandler(processor: processor, logLevel: .info, metadata: [:], nanosecondsSinceEpoch: { 42 }) + } + logger[metadataKey: "logger"] = "42" + + logger.info("🏎️") + + XCTAssertEqual(processor.records, [ + OTelLogRecord(body: "🏎️", level: .info, metadata: ["logger": "42"], timeNanosecondsSinceEpoch: 42), + ]) + } + + func test_log_withHandlerMetadata_includesMetadataInLogRecord() { + let processor = OTelInMemoryLogRecordProcessor() + let logger = Logger(label: #function) { _ in + OTelLogHandler( + processor: processor, + logLevel: .info, + metadata: ["handler": "42"], + nanosecondsSinceEpoch: { 42 } + ) + } + + logger.info("🏎️") + + XCTAssertEqual(processor.records, [ + OTelLogRecord(body: "🏎️", level: .info, metadata: ["handler": "42"], timeNanosecondsSinceEpoch: 42), + ]) + } + + func test_log_withHandlerAndLoggerMetadata_overridesHandlerWithLoggerMetadata() { + let processor = OTelInMemoryLogRecordProcessor() + var logger = Logger(label: #function) { _ in + OTelLogHandler( + processor: processor, + logLevel: .info, + metadata: ["shared": "handler"], + nanosecondsSinceEpoch: { 42 } + ) + } + logger[metadataKey: "shared"] = "logger" + + logger.info("🏎️") + + XCTAssertEqual(processor.records, [ + OTelLogRecord(body: "🏎️", level: .info, metadata: ["shared": "logger"], timeNanosecondsSinceEpoch: 42), + ]) + } + + func test_log_withLoggerAndAdHocMetadata_overridesLoggerWithAdHocMetadata() { + let processor = OTelInMemoryLogRecordProcessor() + var logger = Logger(label: #function) { _ in + OTelLogHandler(processor: processor, logLevel: .info, metadata: [:], nanosecondsSinceEpoch: { 42 }) + } + logger[metadataKey: "shared"] = "logger" + + logger.info("🏎️", metadata: ["shared": "ad-hoc"]) + + XCTAssertEqual(processor.records, [ + OTelLogRecord(body: "🏎️", level: .info, metadata: ["shared": "ad-hoc"], timeNanosecondsSinceEpoch: 42), + ]) + } + + func test_loggerMetadataProxiesToHandlerMetadata() throws { + let processor = OTelInMemoryLogRecordProcessor() + var logger = Logger(label: #function) { _ in + OTelLogHandler(processor: processor, logLevel: .info, metadata: ["shared": "handler"]) + } + + logger[metadataKey: "shared"] = "logger" + let handler = try XCTUnwrap(logger.handler as? OTelLogHandler) + + XCTAssertEqual(handler[metadataKey: "shared"], "logger") + + logger.info("🏎️") + + XCTAssertEqual(try XCTUnwrap(processor.records.first).metadata, ["shared": "logger"]) + } +}