Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Introduce task local logger #315

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 9 additions & 0 deletions Benchmarks/.gitignore
Original file line number Diff line number Diff line change
@@ -0,0 +1,9 @@
.DS_Store
/.build
/Packages
xcuserdata/
DerivedData/
.swiftpm/configuration/registries.json
.swiftpm/xcode/package.xcworkspace/contents.xcworkspacedata
.netrc
.benchmarkBaselines/
58 changes: 58 additions & 0 deletions Benchmarks/Benchmarks/LoggingBenchmarks/Benchmarks.swift
Original file line number Diff line number Diff line change
@@ -0,0 +1,58 @@
//===----------------------------------------------------------------------===//
//
// 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 Benchmark
import Logging

let benchmarks = {
let defaultMetrics: [BenchmarkMetric] = [
.mallocCountTotal,
.instructions,
.wallClock,
]

Benchmark(
"NoOpLogger",
configuration: Benchmark.Configuration(
metrics: defaultMetrics,
scalingFactor: .mega,
maxDuration: .seconds(10_000_000),
maxIterations: 100
)
) { benchmark in
let logger = Logger(label: "Logger", SwiftLogNoOpLogHandler())

for _ in 0..<benchmark.scaledIterations.upperBound {
logger.info("Log message")
}
}

Benchmark(
"NoOpLogger task local",
configuration: Benchmark.Configuration(
metrics: defaultMetrics,
scalingFactor: .mega,
maxDuration: .seconds(10_000_000),
maxIterations: 100
)
) { benchmark in
let logger = Logger(label: "Logger", SwiftLogNoOpLogHandler())

Logger.$logger.withValue(logger) {
for _ in 0..<benchmark.scaledIterations.upperBound {
Logger.logger.info("Log message")
}
}
}
}
27 changes: 27 additions & 0 deletions Benchmarks/Package.swift
Original file line number Diff line number Diff line change
@@ -0,0 +1,27 @@
// swift-tools-version: 5.8

import PackageDescription

let package = Package(
name: "benchmarks",
platforms: [
.macOS("14")
],
dependencies: [
.package(path: "../"),
.package(url: "https://github.com/ordo-one/package-benchmark.git", from: "1.22.0"),
],
targets: [
.executableTarget(
name: "LoggingBenchmarks",
dependencies: [
.product(name: "Benchmark", package: "package-benchmark"),
.product(name: "Logging", package: "swift-log"),
],
path: "Benchmarks/LoggingBenchmarks",
plugins: [
.plugin(name: "BenchmarkPlugin", package: "package-benchmark")
]
),
]
)
8 changes: 6 additions & 2 deletions Sources/Logging/Logging.swift
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,9 @@ import WASILibc
/// logger.info("Hello World!")
/// ```
public struct Logger {
@available(macOS 10.15, *)
@TaskLocal
public static var logger: Logger = Logger(label: "NoOp")
/// Storage class to hold the label and log handler
@usableFromInline
internal final class Storage: @unchecked /* and not actually */ Sendable /* but safe if only used with CoW */ {
Expand Down Expand Up @@ -90,8 +93,9 @@ public struct Logger {
return self.handler.metadataProvider
}

@usableFromInline
internal init(label: String, _ handler: any LogHandler) {
/// Creates a logger with a specific label and handler.
@inlinable
public init(label: String, _ handler: any LogHandler) {
self._storage = Storage(label: label, handler: handler)
}
}
Expand Down
32 changes: 32 additions & 0 deletions Tests/LoggingTests/TaskLocalLoggerTests.swift
Original file line number Diff line number Diff line change
@@ -0,0 +1,32 @@
//===----------------------------------------------------------------------===//
//
// 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 XCTest
import Logging

final class TaskLocalLoggerTests: XCTestCase {
func test() async {
let logger = Logger(label: "TestLogger") { StreamLogHandler.standardOutput(label: $0) }

Logger.$logger.withValue(logger) {
Logger.logger.info("Start log")
var logger = Logger.logger
logger[metadataKey: "MetadataKey1"] = "Value1"
logger.logLevel = .trace
Logger.$logger.withValue(logger) {
Logger.logger.info("Log2")
}
Logger.logger.info("End log")
}
}
}
114 changes: 114 additions & 0 deletions proposals/0002-task-local-logger.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,114 @@
# Task local logger

Authors: [Franz Busch](https://github.com/FranzBusch)

## Introduction

Swift Structured Concurrency provides first class capabilities to propagate data
down the task tree via task locals. This provides an amazing opportunity for
structured logging.

## Motivation

Structured logging is a powerful tool to build logging message that contain
contextual metadata. This metadata is often build up over time by adding more to
it the more context is available. A common example for this are request ids.
Once a request id is extracted it is added to the loggers metadata and from that
point onwards all log messages contain the request id. This improves
observability and debuggability. The current pattern to do this in `swift-log`
looks like this:

```swift
func handleRequest(_ request: Request, logger: Logger) async throws {
// Extract the request id to the metadata of the logger
var logger = logger
logger[metadataKey: "request.id"] = "\(request.id)"

// Importantly we have to pass the new logger forward since it contains the request id
try await sendResponse(logger: logger)
}
```

This works but it causes significant overhead due to passing of the logger
through all methods in the call stack. Furthermore, sometimes it is impossible to pass
a logger to some methods if those are protocol requirements like `init(from: Decoder)`.

Swift Structured Concurrency introduced the concept of task locals which
propagate down the structured task tree. This fits perfectly with how we expect
logging metadata to accumulate and provide more information the further down the
task tree we get.

## Proposed solution

I propose to add a new task local definition to `Logger`. Adding this task local
inside the `Logging` module provides the one canonical task local that all other
packages in the ecosystem can use.

```swift
extension Logger {
/// The task local logger.
///
/// It is recommended to use this logger in applications and libraries that use Swift Concurrency
/// instead of passing around loggers manually.
@TaskLocal
public static var logger: Logger
}
```

The default value for this logger is going to be a `SwiftLogNoOpLogHandler()`.

Applications can then set the task local logger similar to how they currently bootstrap
the logging backend. If no library in the proccess is creating its own logger it is even possible
to not use the normal bootstrapping methods at all and fully rely on structured concurrency for
propagating the logger and its metadata.

```swift
static func main() async throws {
let logger = Logger(label: "Logger") { StreamLogHandler.standardOutput(label: $0)}

Logger.$logger.withValue(logger) {
// Run your application code
try await application.run()
}
}
```

Places that want to log can then just access the task local and produce a log message.

```swift
Logger.logger.info("My log message")
```

Adding additional metadata to the task local logger is as easy as updating the logger
and binding the task local value again.

```swift
Logger.$logger.withValue(logger) {
Logger.logger.info("First log")

var logger = Logger.logger
logger[metadataKey: "MetadataKey1"] = "Value1"
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should Logger.label also become publicly settable? If we have a single Logger in the task local, and there's no way to create a copy of the Logger (with the same log handler, level, and metadata, but different label), is the label even meaningful at that point, if ~all log events from the same task hierarchy will have the same label?

Copy link
Member

@weissi weissi Mar 12, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

label was never really meaningful. It's only there because it was easy to add and it enables one feature: If you have one process that runs two (or more) services, then you can use the label to distinguish. Example problem that we thought of: Let's say you use gRPC in both your services (let's call them "main service" and "admin endpoint") and now you get a log from gRPC, you probably care more about it if it's the main service (and much less if it's the admin endpoint).

For example you could query label=com.me.my-service source=GRPC level>=WARNING and you wouldn't get admin endpoint GRPC warnings.

Said all that, you can of course do that with metadata too:

var loggerBase = Logger(label: "everything")

var adminEnpointLogger = loggerBase
adminEndpointLogger[metadataKey: "service"] = "admin"

var mainServiceLogger = loggerBase
mainServiceLogger[metadataKey: "service" = "main"

and then query service=main source=GRPC level>=WARNING.

Copy link
Member

@weissi weissi Mar 12, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So it's a non-overridable "base label" or whatever. Conveniently, it also allowed a transition from Logger-per-class setups that older logging frameworks (and some other ecosystems) use...

I'd consider label a legacy.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's fair, but it's still part of the non-deprecated API. This proposal creates/worsens the problem, so I think it should address it, or at the very least acknowledge it and recommend a workaround.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@czechboy0 Oh I see, are you saying that with this proposal it's impossible for the user to wholesale switch from one Logger to another? If so then I think this needs addressing indeed.

More importantly than label, we also have the logging backend. And I do sometimes hand a logger with a different backend.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's exactly like it is today and yes: It is helpful, your log aggregation system likely aggregates stuff from all of your services. So the label is essentially your service name.

And as I said before, the pod name isn't a good substitute for that because you may run two mostly separate services in one process.

So essentially label == service name, regardless if the service has its own pod or if it's in the same process as a few others. I legitimately use it every day.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the label is essentially your service name

Yeah I could get behind that. Many libraries don't do that, and create loggers and put their subcomponent names there, but maybe with the task-local logger, we can start moving in the direction where the label is not something libraries even think about (only apps).

The log events already get fileID, line number, and function name - that is hopefully enough, with user-provided metadata, to track where a log event is coming from. I wonder if we should also propose a #module macro and include that in log events, possibly replacing what some people use labels for today.

Copy link
Member

@weissi weissi Mar 13, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah I could get behind that. Many libraries don't do that, and create loggers and put their subcomponent names there, but maybe with the task-local logger, we can start moving in the direction where the label is not something libraries even think about (only apps).

  1. Yes. And part of swift-log's design was squaring the circle such that it's not incompatible with existing logging modes (which means that label is used in various different ways -- but it was primarily meant for what we're discussing here: The service name/some root identifier).
  2. You phrased my thinking really well: The task-local logger should hopefully be enough of a carrot that we can all reap the benefits of structured logging without necessarily having to pass down a logger manually which feels alien to some devs and breaks APIs in some cases. Hence: win/win IMHO :)

The log events already get fileID, line number, and function name

Yes, and also crucially source which is your module name which is currently derived from #fileID which guarantees that it starts with ModuleName/. But of course, it should just be source: String = #module.

And yes please to #module, I had pitched it before over here: https://forums.swift.org/t/pitch-introduce-module-to-get-the-current-module-name/45806

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, and also crucially source which is your module name.

Completely missed that. So yeah I agree we can just update docs on label and steer people in this direction, once the task-local logger lands.

Copy link
Member

@weissi weissi Mar 13, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, and also crucially source which is your module name.
Completely missed that. So yeah I agree we can just update docs on label and steer people in this direction, once the task-local logger lands.

Sounds like a plan to me. And yes, the docs have always been spotty which we should fix.

Logger.$logger.withValue(logger) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this syntax required for passing metadata through to child tasks? I thought that was automatic. E.g.:

logger[metadataKey: "MetadataKey1"] = "Value1"
try await someFunction()


func someFunction() async throws {
  // `MetadataKey1` is available here
}

Definitely agree with renaming logger here - the API doesn't come across great with the double logger in this example

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Logger is a value type, so the modified copy needs to be written back into the task local to be propagated to child tasks.

Logger.logger.info("Second log")
}

Logger.logger.info("Third log")
}
```

Running the above code will produce the following output:

```
First log
MetadataKey1=Value1 Second log
Third log
```

## Alternatives considered

### Provide static log methods

Instead of going through the task local `Logger.logger` to emit log messages we
could add new static log methods like `Logger.log()` or `Logger.info()` that
access the task local internally. This is soemthing that we can do in the future
as an enhancement but isn't required initially.