diff --git a/.gitignore b/.gitignore index e613a74..b6e80cb 100644 --- a/.gitignore +++ b/.gitignore @@ -6,3 +6,5 @@ xcuserdata/ .swiftpm /Package.resolved +.history +.vscode diff --git a/Docs/README.md b/Docs/README.md new file mode 100644 index 0000000..fdeb5cb --- /dev/null +++ b/Docs/README.md @@ -0,0 +1,3 @@ +# Documentation landing page + +This documentation target exists only to serve as a landing page for self hosted documentation. \ No newline at end of file diff --git a/Docs/SwiftDistributedTracing/Docs.docc/index.md b/Docs/SwiftDistributedTracing/Docs.docc/index.md new file mode 100644 index 0000000..b6e4147 --- /dev/null +++ b/Docs/SwiftDistributedTracing/Docs.docc/index.md @@ -0,0 +1,29 @@ +# ``SwiftDistributedTracing`` + +A Distributed Tracing API for Swift. + +## Overview + +This is a collection of Swift libraries enabling the instrumentation of server side applications using tools such as tracers. Our goal is to provide a common foundation that allows to freely choose how to instrument systems with minimal changes to your actual code. + +While Swift Distributed Tracing allows building all kinds of _instruments_, which can co-exist in applications transparently, its primary use is instrumenting multi-threaded and distributed systems with Distributed Traces. + +### Quickstart Guides + +We provide a number of guides aimed at getting your started with tracing your systems and have prepared them from three "angles": + +1. **Application developers** who create server-side applications + * please refer to the guide. +2. **Library/Framework developers** who provide building blocks to create these applications + * please refer to the guide. +3. **Instrument developers** who provide tools to collect distributed metadata about your application + * please refer to the guide. + + +## Topics + +### Guides + +- +- +- diff --git a/Docs/SwiftDistributedTracing/empty.swift b/Docs/SwiftDistributedTracing/empty.swift new file mode 100644 index 0000000..2f2036f --- /dev/null +++ b/Docs/SwiftDistributedTracing/empty.swift @@ -0,0 +1,19 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift Distributed Tracing open source project +// +// Copyright (c) 2020-2021 Apple Inc. and the Swift Distributed Tracing project +// authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +// !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! // +// This module is left purposefully empty of any source files, as it serves +// only as a "landing page" for the documentation. This is in-place until docc +// gains the ability to support package-wide documentation. +// !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! // \ No newline at end of file diff --git a/Package.swift b/Package.swift index 2366ce3..1df9a8c 100644 --- a/Package.swift +++ b/Package.swift @@ -8,7 +8,9 @@ let package = Package( .library(name: "Tracing", targets: ["Tracing"]), ], dependencies: [ - .package(url: "https://github.com/apple/swift-distributed-tracing-baggage.git", .upToNextMinor(from: "0.4.1")), + .package(url: "https://github.com/apple/swift-distributed-tracing-baggage", .upToNextMinor(from: "0.4.1")), + // .package(url: "https://github.com/apple/swift-log.git", from: "1.4.4"), + .package(url: "https://github.com/ktoso/swift-log", .branch("wip-baggage-in-handlers-but-not-api")), .package(url: "https://github.com/apple/swift-docc-plugin", from: "1.0.0"), ], targets: [ @@ -19,6 +21,7 @@ let package = Package( name: "Instrumentation", dependencies: [ .product(name: "InstrumentationBaggage", package: "swift-distributed-tracing-baggage"), + .product(name: "Logging", package: "swift-log"), ] ), .testTarget( diff --git a/Package@swift-5.2.swift b/Package@swift-5.2.swift index 111d4ff..7081256 100644 --- a/Package@swift-5.2.swift +++ b/Package@swift-5.2.swift @@ -9,6 +9,7 @@ let package = Package( ], dependencies: [ .package(url: "https://github.com/apple/swift-distributed-tracing-baggage.git", .upToNextMinor(from: "0.4.1")), + .package(url: "https://github.com/apple/swift-log.git", from: "1.4.4"), ], targets: [ // ==== -------------------------------------------------------------------------------------------------------- @@ -18,6 +19,7 @@ let package = Package( name: "Instrumentation", dependencies: [ .product(name: "InstrumentationBaggage", package: "swift-distributed-tracing-baggage"), + .product(name: "Logging", package: "swift-log"), ] ), .testTarget( diff --git a/Package@swift-5.3.swift b/Package@swift-5.3.swift index 111d4ff..7081256 100644 --- a/Package@swift-5.3.swift +++ b/Package@swift-5.3.swift @@ -9,6 +9,7 @@ let package = Package( ], dependencies: [ .package(url: "https://github.com/apple/swift-distributed-tracing-baggage.git", .upToNextMinor(from: "0.4.1")), + .package(url: "https://github.com/apple/swift-log.git", from: "1.4.4"), ], targets: [ // ==== -------------------------------------------------------------------------------------------------------- @@ -18,6 +19,7 @@ let package = Package( name: "Instrumentation", dependencies: [ .product(name: "InstrumentationBaggage", package: "swift-distributed-tracing-baggage"), + .product(name: "Logging", package: "swift-log"), ] ), .testTarget( diff --git a/Package@swift-5.4.swift b/Package@swift-5.4.swift index 111d4ff..7081256 100644 --- a/Package@swift-5.4.swift +++ b/Package@swift-5.4.swift @@ -9,6 +9,7 @@ let package = Package( ], dependencies: [ .package(url: "https://github.com/apple/swift-distributed-tracing-baggage.git", .upToNextMinor(from: "0.4.1")), + .package(url: "https://github.com/apple/swift-log.git", from: "1.4.4"), ], targets: [ // ==== -------------------------------------------------------------------------------------------------------- @@ -18,6 +19,7 @@ let package = Package( name: "Instrumentation", dependencies: [ .product(name: "InstrumentationBaggage", package: "swift-distributed-tracing-baggage"), + .product(name: "Logging", package: "swift-log"), ] ), .testTarget( diff --git a/Package@swift-5.5.swift b/Package@swift-5.5.swift index 111d4ff..7081256 100644 --- a/Package@swift-5.5.swift +++ b/Package@swift-5.5.swift @@ -9,6 +9,7 @@ let package = Package( ], dependencies: [ .package(url: "https://github.com/apple/swift-distributed-tracing-baggage.git", .upToNextMinor(from: "0.4.1")), + .package(url: "https://github.com/apple/swift-log.git", from: "1.4.4"), ], targets: [ // ==== -------------------------------------------------------------------------------------------------------- @@ -18,6 +19,7 @@ let package = Package( name: "Instrumentation", dependencies: [ .product(name: "InstrumentationBaggage", package: "swift-distributed-tracing-baggage"), + .product(name: "Logging", package: "swift-log"), ] ), .testTarget( diff --git a/README.md b/README.md index 8e67175..5ae8978 100644 --- a/README.md +++ b/README.md @@ -4,57 +4,25 @@ A Distributed Tracing API for Swift. This is a collection of Swift libraries enabling the instrumentation of server side applications using tools such as tracers. Our goal is to provide a common foundation that allows to freely choose how to instrument systems with minimal changes to your actual code. -While Swift Distributed Tracing allows building all kinds of _instruments_, which can co-exist in applications transparently, its primary use is instrumenting multi-threaded and distributed systems with Distributed Traces. +While Swift Distributed Tracing allows building all kinds of _instruments_, which can co-exist in applications transparently, its primary use is instrumenting multi-threaded and distributed systems with "traces". + +## Documentation > Warning: The docs below, showcasing the 0.3.x series of the logging integration are **deprecated** thanks to the latest inclusion of [metadata providers in swift-log](https://github.com/apple/swift-log/pull/238). With the introduction of [task local values in Swift](https://developer.apple.com/documentation/swift/tasklocal), and metadata providers in swift-log, the `LoggingContext` pattern showcased below has become an _anti-pattern_. Please give us a moment to finish the [new documentation PR #69](https://github.com/apple/swift-distributed-tracing/pull/69), which will explain the new integration style in detail. > > Tracer APIs will not change substantially, as we're closing up on announcing version 1.0. Please look forward to beta releases very soon! ---- - -This project uses the context progagation type defined independently in: - -- 🧳 [swift-distributed-tracing-baggage](https://github.com/apple/swift-distributed-tracing-baggage) -- [`Baggage`](https://apple.github.io/swift-distributed-tracing-baggage/docs/current/InstrumentationBaggage/Structs/Baggage.html) (zero dependencies) - ---- - -## Table of Contents +Please refer to the docc generated [Reference Guide and API Documentation](TODO). -* [Compatibility](#compatibility) - + [Tracing Backends](#tracing-backends) - + [Libraries & Frameworks](#libraries--frameworks) -* [Getting Started](#getting-started) - + [Dependencies & Tracer backend](#dependencies--tracer-backend) - + [Benefiting from instrumented libraries/frameworks](#benefiting-from-instrumented-libraries-frameworks) - + [Instrumenting your code](#instrumenting-your-code) - + [More examples](#more-examples) -* [In-Depth Guide](#in-depth-guide) -* In-Depth Guide for **Application Developers** - + [Setting up instruments & tracers](#setting-up-instruments--tracers) - + [Bootstrapping the InstrumentationSystem](#bootstrapping-the-instrumentationsystem) - + [Context propagation](#passing-context-objects) - + [Creating context objects](#creating-context-objects--and-when-not-to-do-so-) - + [Working with `Span`s](#spans) -* In-Depth Guide for: **Library/Framework developers** - + [Instrumenting your software](#library-framework-developers--instrumenting-your-software) - + [Extracting & injecting Baggage](#extracting--injecting-baggage) - + [Tracing your library](#tracing-your-library) -* In-Depth Guide for: **Instrument developers** - + [Creating an `Instrument`](#instrument-developers--creating-an-instrument) - + [Creating a `Tracer`](#creating-a--tracer-) -* [Contributing](#contributing) +## Dependencies ---- +This project uses the context propagation type defined independently in: -## Compatibility - -This project is designed in a very open and extensible manner, such that various instrumentation and tracing systems can be built on top of it. - -The purpose of the tracing package is to serve as common API for all tracer and instrumentation implementations. Thanks to this, libraries may only need to be instrumented once, and then be used with any tracer which conforms to this API. +- 🧳 [swift-distributed-tracing-baggage](https://github.com/apple/swift-distributed-tracing-baggage) -- [`Baggage`](https://apple.github.io/swift-distributed-tracing-baggage/docs/current/InstrumentationBaggage/Structs/Baggage.html) (zero dependencies) -### Tracing Backends - +## Implementations + Compatible `Tracer` implementations: | Library | Status | Description | @@ -65,9 +33,22 @@ Compatible `Tracer` implementations: If you know of any other library please send in a [pull request](https://github.com/apple/swift-distributed-tracing/compare) to add it to the list, thank you! -### Libraries & Frameworks +## Libraries & Frameworks + +For distributed tracing to be most useful, it needs to be integrated in libraries, especially those serving to inter-connect different processes such as HTTP, or other RPC clients/servers. This then enables end users to reap the benefits of automatic trace propagation across nodes in a system, as well as restoring baggage when incoming messages are received by such library/framework. + +The table below illustrates the -As this API package was just released, no projects have yet fully adopted it, the following table for not serves as reference to prior work in adopting tracing work. As projects move to adopt tracing completely, the table will be used to track adoption phases of the various libraries. +| Library | Status | Baggage propagation | Automatic spans (e.g. "request" span) | +|--------------------------------------------------|-------------------------------------------------------------|-------------------|-----------------------------------------------------------| +| [gRPC Swift](https://github.com/grpc/grpc-swift) | [PR - in progress](https://github.com/grpc/grpc-swift/pull/1510) | WIP | Pending | | +| _Your library?_ | ... | ... |[Get in touch!](https://forums.swift.org/c/server/43) | + + +### Legacy PoC integrations + +Previously, before Swift shipped Task Local Values, a number of proof of concept integrations was implemented. +You can refer to them below, and potentially orchestrate efforts to mature those integrations to use the 1.0 version of distributed tracing, at which point those projects **may** adopt it in their primary releases: | Library | Integrates | Status | | ------- | ---------- | ------ | @@ -85,507 +66,6 @@ As this API package was just released, no projects have yet fully adopted it, th If you know of any other library please send in a [pull request](https://github.com/apple/swift-distributed-tracing/compare) to add it to the list, thank you! ---- - -## Getting Started - -In this short getting started example, we'll go through bootstrapping, immediately benefiting from tracing, and instrumenting our own synchronous and asynchronous APIs. The following sections will explain all the pieces of the API in more depth. When in doubt, you may want to refer to the [OpenTelemetry](https://opentelemetry.io), [Zipkin](https://zipkin.io), or [Jaeger](https://www.jaegertracing.io) documentations because all the concepts for different tracers are quite similar. - -### Dependencies & Tracer backend - -In order to use tracing you will need to bootstrap a tracing backend ([available backends](#backends)). - -When developing an *application* locate the specific tracer library you would like to use and add it as an dependency directly: - -```swift -.package(url: "", // the specific tracer - ] -), -``` - -Then (in an application, libraries should _never_ invoke `bootstrap`), you will want to bootstrap the specific tracer you want to use in your application. A `Tracer` is a type of `Instrument` and can be offered used to globally bootstrap the tracing system, like this: - - -```swift -import Tracing // the tracing API -import AwesomeTracing // the specific tracer - -InstrumentationSystem.bootstrap(AwesomeTracing()) -``` - -If you don't bootstrap (or other instrument) the default no-op tracer is used, which will result in no trace data being collected. - -### Benefiting from instrumented libraries/frameworks - -**Automatically reported spans**: When using an already instrumented library, e.g. an HTTP Server which automatically emits spans internally, this is all you have to do to enable tracing. It should now automatically record and emit spans using your configured backend. - -**Using baggage and logging context**: The primary transport type for tracing metadata is called `Baggage`, and the primary type used to pass around baggage context and loggers is `LoggingContext`. Logging context combines baggage context values with a smart `Logger` that automatically includes any baggage values ("trace metadata") when it is used for logging. For example, when using an instrumented HTTP server, the API could look like this: - -```swift -SomeHTTPLibrary.handle { (request, context) in - context.logger.info("Wow, tracing!") // automatically includes tracing metadata such as "trace-id" - return try doSomething(request context: context) -} -``` - -In this snippet, we use the context logger to log a very useful message. However it is even more useful than it seems at first sight: if a tracer was installed and extracted tracing information from the incoming request, it would automatically log our message _with_ the trace information, allowing us to co-relate all log statements made during handling of this specific request: - -``` -05:46:38 example-trace-id=1111-23-1234556 info: Wow tracing! -05:46:38 example-trace-id=9999-22-9879797 info: Wow tracing! -05:46:38 example-trace-id=9999-22-9879797 user=Alice info: doSomething() for user Alice -05:46:38 example-trace-id=1111-23-1234556 user=Charlie info: doSomething() for user Charlie -05:46:38 example-trace-id=1111-23-1234556 user=Charlie error: doSomething() could not complete request! -05:46:38 example-trace-id=9999-22-9879797 user=alice info: doSomething() completed -``` - -Thanks to tracing, and trace identifiers, even if not using tracing visualization libraries, we can immediately co-relate log statements and know that the request `1111-23-1234556` has failed. Since our application can also _add_ values to the context, we can quickly notice that the error seems to occur for the user `Charlie` and not for user `Alice`. Perhaps the user Charlie has exceeded some quotas, does not have permissions or we have a bug in parsing names that include the letter `h`? We don't know _yet_, but thanks to tracing we can much quicker begin our investigation. - -**Passing context to client libraries**: When using client libraries that support distributed tracing, they will accept a `Baggage.LoggingContext` type as their _last_ parameter in many calls. - -When using client libraries that support distributed tracing, they will accept a `Baggage.LoggingContext` type as their _last_ parameter in many calls. Please refer to [Context argument naming/positioning](#context-propagation-by-explicit-loggingcontext-passing) in the [Context propagation](#context-propagation-by-explicit-loggingcontext-passing) section of this readme to learn more about how to properly pass context values around. - -### Instrumenting your code - -Adding a span to synchronous functions can be achieved like this: - -```swift -func handleRequest(_ op: String, context: LoggingContext) -> String { - let tracer = InstrumentationSystem.tracer - let span = tracer.startSpan(operationName: "handleRequest(\(name))", context: context) - defer { span.end() } - - return "done:\(op)" -} -``` - -Throwing can be handled by either recording errors manually into a span by calling `span.recordError(error:)`, or by wrapping a potentially throwing operation using the `withSpan(operation:context:body:)` function, which automatically records any thrown error and ends the span at the end of the body closure scope: - -```swift -func handleRequest(_ op: String, context: LoggingContext) -> String { - return try InstrumentationSystem.tracer - .withSpan(operationName: "handleRequest(\(name))", context: context) { - return try dangerousOperation() - } -} -``` - -If this function were asynchronous, and returning a [Swift NIO](https://github.com/apple/swift-nio) `EventLoopFuture`, -we need to end the span when the future completes. We can do so in its `onComplete`: - -```swift -func handleRequest(_ op: String, context: LoggingContext) -> EventLoopFuture { - let tracer = InstrumentationSystem.tracer - let span = tracer.startSpan(operationName: "handleRequest(\(name))", context: context) - - let future: EventLoopFuture = someOperation(op) - future.whenComplete { _ in - span.end() // oh no, ignored errors! - } - - return future -} -``` - -This is better, however we ignored the possibility that the future perhaps has failed. If this happens, we would like to report the span as _errored_ because then it will show up as such in tracing backends and we can then easily search for failed operations etc. - -To do this within the future we could manually invoke the `span.recordError` API before ending the span like this: - -```swift -func handleRequest(_ op: String, context: LoggingContext) -> EventLoopFuture { - let tracer = InstrumentationSystem.tracer - let span = tracer.startSpan(operationName: "handleRequest(\(name))", context: context) - - let future: EventLoopFuture = someOperation(op) - future.whenComplete { result in - switch result { - case .failure(let error): span.recordError(error) - case .success(let value): // ... record additional *attributes* into the span - } - span.end() - } - - return future -} -``` - -While this is verbose, this is only the low-level building blocks that this library provides, higher level helper utilities can be - -> Eventually convenience wrappers will be provided, automatically wrapping future types etc. We welcome such contributions, but likely they should live in `swift-distributed-tracing-extras`. - -Once a system, or multiple systems have been instrumented, a Tracer has been selected and your application runs and emits some trace information, you will be able to inspect how your application is behaving by looking at one of the various trace UIs, such as e.g. Zipkin: - -![Simple example trace in Zipkin Web UI](Sources/Tracing/Docs.docc/Resources/zipkin_trace.png) - -### More examples - -It sometimes is easier to grasp the usage of tracing by looking at a "real" application - which is why we have implemented an example application, spanning multiple nodes and using various databases - tracing through all of them. You can view the example application here: [slashmo/swift-tracing-examples](https://github.com/slashmo/swift-tracing-examples/tree/main/hotrod). - -### Future work: Tracing asynchronous functions - -> ⚠️ This section refers to in-development upcoming Swift Concurrency features and can be tried out using nightly snapshots of the Swift toolchain. - -With Swift's ongoing work towards asynchronous functions, actors, and tasks, tracing in Swift will become more pleasant than it is today. - -Firstly, a lot of the callback heavy code will be folded into normal control flow, which is easy and correct to integrate with tracing like this: - -```swift -func perform(context: LoggingContext) async -> String { - let span = InstrumentationSystem.tracer.startSpan(operationName: #function, context: context) - defer { span.end() } - - return await someWork() -} -``` - - -## In-Depth Guide - -When instrumenting server applications there are typically three parties involved: - -1. [Application developers](#application-developers-setting-up-instruments) creating server-side applications -2. [Library/Framework developers](#libraryframework-developers-instrumenting-your-software) providing building blocks to create these applications -3. [Instrument developers](#instrument-developers-creating-an-instrument) providing tools to collect distributed metadata about your application - -For applications to be instrumented correctly these three parts have to play along nicely. - -## Application Developers - -### Setting up instruments & tracers - -As an end-user building server applications you get to choose what instruments to use to instrument your system. Here's -all the steps you need to take to get up and running: - -Add a package dependency for this repository in your `Package.swift` file, and one for the specific instrument you want -to use, in this case `FancyInstrument`: - -```swift -.package(url: "https://github.com/apple/swift-distributed-tracing.git", .branch("main")), -.package(url: "", from: "<4.2.0>"), -``` - -To your main target, add a dependency on the `Instrumentation library` and the instrument you want to use: - -```swift -.target( - name: "MyApplication", - dependencies: [ - "FancyInstrument" - ] -), -``` - -### Bootstrapping the `InstrumentationSystem` - -Instead of providing each instrumented library with a specific instrument explicitly, you *bootstrap* the -`InstrumentationSystem` which acts as a singleton that libraries/frameworks access when calling out to the configured -`Instrument`: - -```swift -InstrumentationSystem.bootstrap(FancyInstrument()) -``` - -#### Recommended bootstrap order - -Swift offers developers a suite of observability libraries: logging, metrics and tracing. Each of those systems offers a `bootstrap` function. It is useful to stick to a recommended boot order in order to achieve predictable initialization of applications and sub-systems. - -Specifically, it is recommended to bootstrap systems in the following order: - -1. [Swift Log](https://github.com/apple/swift-log#default-logger-behavior)'s `LoggingSystem` -2. [Swift Metrics](https://github.com/apple/swift-metrics#selecting-a-metrics-backend-implementation-applications-only)' `MetricsSystem` -3. Swift Tracing's `InstrumentationSystem` -4. Finally, any other parts of your application - -This is because tracing systems may attempt to emit metrics about their status etc. - -#### Bootstrapping multiple instruments using MultiplexInstrument - -It is important to note that `InstrumentationSystem.bootstrap(_: Instrument)` must only be called once. In case you -want to bootstrap the system to use multiple instruments, you group them in a `MultiplexInstrument` first, which you -then pass along to the `bootstrap` method like this: - -```swift -InstrumentationSystem.bootstrap(MultiplexInstrument([FancyInstrument(), OtherFancyInstrument()])) -``` - -`MultiplexInstrument` will then call out to each instrument it has been initialized with. - - - -### Context propagation, by explicit `LoggingContext` passing - -> `LoggingContext` naming has been carefully selected and it reflects the type's purpose and utility: It binds a [Swift Log `Logger`](https://github.com/apple/swift-log) with an associated distributed tracing [Baggage](https://github.com/apple/swift-distributed-tracing-baggage). -> -> It _also_ is used for tracing, by tracers reaching in to read or modify the carried baggage. - -For instrumentation and tracing to work, certain pieces of metadata (usually in the form of identifiers), must be -carried throughout the entire system–including across process and service boundaries. Because of that, it's essential -for a context object to be passed around your application and the libraries/frameworks you depend on, but also carried -over asynchronous boundaries like an HTTP call to another service of your app. - -`LoggingContext` should always be passed around explicitly. - -Libraries which support tracing are expected to accept a `LoggingContext` parameter, which can be passed through the entire application. Make sure to always pass along the context that's previously handed to you. E.g., when making an HTTP request using `AsyncHTTPClient` in a `NIO` handler, you can use the `ChannelHandlerContext`s `baggage` property to access the `LoggingContext`. - -#### Context argument naming/positioning - -> 💡 This general style recommendation has been ironed out together with the Swift standard library, core team, the SSWG as well as members of the community. Please respect these recommendations when designing APIs such that all APIs are able to "feel the same" yielding a great user experience for our end users ❤️ -> -> It is possible that the ongoing Swift Concurrency efforts, and "Task Local" values will resolve this explicit context passing problem, however until these arrive in the language, please adopt the "context is the last parameter" style as outlined here. - -Propagating baggage context through your system is to be done explicitly, meaning as a parameter in function calls, following the "flow" of execution. - -When passing baggage context explicitly we strongly suggest sticking to the following style guideline: - -- Assuming the general parameter ordering of Swift function is as follows (except DSL exceptions): - 1. Required non-function parameters (e.g. `(url: String)`), - 2. Defaulted non-function parameters (e.g. `(mode: Mode = .default)`), - 3. Required function parameters, including required trailing closures (e.g. `(onNext elementHandler: (Value) -> ())`), - 4. Defaulted function parameters, including optional trailing closures (e.g. `(onComplete completionHandler: (Reason) -> ()) = { _ in }`). -- Logging Context should be passed as **the last parameter in the required non-function parameters group in a function declaration**. - -This way when reading the call side, users of these APIs can learn to "ignore" or "skim over" the context parameter and the method signature remains human-readable and “Swifty”. - -Examples: - -- `func request(_ url: URL,` **`context: LoggingContext`** `)`, which may be called as `httpClient.request(url, context: context)` -- `func handle(_ request: RequestObject,` **`context: LoggingContext`** `)` - - if a "framework context" exists and _carries_ the baggage context already, it is permitted to pass that context - together with the baggage; - - it is _strongly recommended_ to store the baggage context as `baggage` property of `FrameworkContext`, and conform `FrameworkContext` to `LoggingContext` in such cases, in order to avoid the confusing spelling of `context.context`, and favoring the self-explanatory `context.baggage` spelling when the baggage is contained in a framework context object. -- `func receiveMessage(_ message: Message, context: FrameworkContext)` -- `func handle(element: Element,` **`context: LoggingContext`** `, settings: Settings? = nil)` - - before any defaulted non-function parameters -- `func handle(element: Element,` **`context: LoggingContext`** `, settings: Settings? = nil, onComplete: () -> ())` - - before defaulted parameters, which themselfes are before required function parameters -- `func handle(element: Element,` **`context: LoggingContext`** `, onError: (Error) -> (), onComplete: (() -> ())? = nil)` - -In case there are _multiple_ "framework-ish" parameters, such as passing a NIO `EventLoop` or similar, we suggest: - -- `func perform(_ work: Work, for user: User,` _`frameworkThing: Thing, eventLoop: NIO.EventLoop,`_ **`context: LoggingContext`** `)` - - pass the baggage as **last** of such non-domain specific parameters as it will be _by far more_ omnipresent than any - specific framework parameter - as it is expected that any framework should be accepting a context if it can do so. - While not all libraries are necessarily going to be implemented using the same frameworks. - -We feel it is important to preserve Swift's human-readable nature of function definitions. In other words, we intend to -keep the read-out-loud phrasing of methods to remain _"request that URL (ignore reading out loud the context parameter)"_ -rather than _"request (ignore this context parameter when reading) that URL"_. - -#### When to use what context type? - -Generally libraries should favor accepting the general `LoggingContext` type, and **not** attempt to wrap it, as it will result in difficult to compose APIs between multiple libraries. Because end users are likely going to be combining various libraries in a single application, it is important that they can "just pass along" the same context object through all APIs, regardless which other library they are calling into. - -Frameworks may need to be more opinionated here, and e.g. already have some form of "per request context" contextual object which they will conform to `LoggingContext`. _Within_ such framework it is fine and expected to accept and pass the explicit `SomeFrameworkContext`, however when designing APIs which may be called _by_ other libraries, such framework should be able to accept a generic `LoggingContext` rather than its own specific type. - -#### Existing context argument - -When adapting an existing library/framework to support `LoggingContext` and it already has a "framework context" which is expected to be passed through "everywhere", we suggest to follow these guidelines for adopting LoggingContext: - -1. Add a `Baggage` as a property called `baggage` to your own `context` type, so that the call side for your - users becomes `context.baggage` (rather than the confusing `context.context`) -2. If you cannot or it would not make sense to carry baggage inside your framework's context object, pass (and accept (!)) the `LoggingContext` in your framework functions like follows: -- if they take no framework context, accept a `context: LoggingContext` which is the same guideline as for all other cases -- if they already _must_ take a context object and you are out of words (or your API already accepts your framework context as "context"), pass the baggage as **last** parameter (see above) yet call the parameter `baggage` to disambiguate your `context` object from the `baggage` context object. - -Examples: - -- `Lambda.Context` may contain `baggage` and a `logger` and should be able to conform to `LoggingContext` - - passing context to a `Lambda.Context` unaware library becomes: `http.request(url: "...", context: context)`. -- `ChannelHandlerContext` offers a way to set/get baggage on the underlying channel via `context.baggage = ...` - - this context is not passed outside a handler, but within it may be passed as is, and the baggage may be accessed on it directly through it. - - Example: https://github.com/apple/swift-nio/pull/1574 - -### Creating context objects (and when not to do so) - -Generally application developers _should not_ create new context objects, but rather keep passing on a context value that they were given by e.g. the web framework invoking the their code. - -If really necessary, or for the purposes of testing, one can create a baggage or context using one of the two factory functions: - -- [`DefaultLoggingContext.topLevel(logger:)`](https://github.com/apple/swift-distributed-tracing-baggage/blob/main/Sources/Baggage/LoggingContext.swift) or [`Baggage.topLevel`](https://github.com/apple/swift-distributed-tracing-baggage-core/blob/main/Sources/CoreBaggage/Baggage.swift) - which creates an empty context/baggage, without any values. It should _not_ be used too frequently, and as the name implies in applications it only should be used on the "top level" of the application, or at the beginning of a contextless (e.g. timer triggered) event processing. -- [`DefaultLoggingContext.TODO(logger:reason:)`](https://github.com/apple/swift-distributed-tracing-baggage/blob/main/Sources/Baggage/LoggingContext.swift) or [`Baggage.TODO`](https://github.com/apple/swift-distributed-tracing-baggage-core/blob/main/Sources/CoreBaggage/Baggage.swift) - which should be used to mark a parameter where "before this code goes into production, a real context should be passed instead." An application can be run with `-DBAGGAGE_CRASH_TODOS` to cause the application to crash whenever a TODO context is still in use somewhere, making it easy to diagnose and avoid breaking context propagation by accidentally leaving in a `TODO` context in production. - -Please refer to the respective functions documentation for details. - -If using a framework which itself has a "`...Context`" object you may want to inspect it for similar factory functions, as `LoggingContext` is a protocol, that may be conformed to by frameworks to provide a smoother user experience. - - -### Working with `Span`s - -The primary purpose of this API is to start and end so-called `Span` types. - -Spans form hierarchies with their parent spans, and end up being visualized using various tools, usually in a format similar to gant charts. So for example, if we had multiple operations that compose making dinner, they would be modelled as child spans of a main `makeDinner` span. Any sub tasks are again modelled as child spans of any given operation, and so on, resulting in a trace view similar to: - -``` ->-o-o-o----- makeDinner ----------------o---------------x [15s] - \-|-|- chopVegetables--------x | [2s] - | | \- chop -x | | [1s] - | | \--- chop -x | [1s] - \-|- marinateMeat -----------x | [3s] - \- preheatOven -----------------x | [10s] - \--cook---------x [5s] -``` - -The above trace is achieved by starting and ending spans in all the mentioned functions, for example, like this: - -```swift -let tracer: Tracer - -func makeDinner(context: LoggingContext) async throws -> Meal { - tracer.withSpan(operationName: "makeDinner", context) { - let veggiesFuture = try chopVegetables(context: span.context) - let meatFuture = marinateMeat(context: span.context) - let ovenFuture = try preheatOven(temperature: 350, context: span.context) - ... - return cook(veggies, meat, oven) - } -} -``` - -> ❗️ It is tremendously important to **always `end()` a started `Span`**! make sure to end any started span on _every_ code path, including error paths -> -> Failing to do so is an error, and a tracer *may* decide to either crash the application or log warnings when an not-ended span is deinitialized. - - -## Library/Framework developers: Instrumenting your software - -### Extracting & injecting Baggage - -When hitting boundaries like an outgoing HTTP request you call out to the [configured instrument(s)](#Bootstrapping-the-Instrumentation-System): - -An HTTP client e.g. should inject the given `LoggingContext` into the HTTP headers of its outbound request: - -```swift -func get(url: String, context: LoggingContext) { - var request = HTTPRequest(url: url) - InstrumentationSystem.instrument.inject( - context.baggage, - into: &request.headers, - using: HTTPHeadersInjector() - ) -} -``` - -On the receiving side, an HTTP server should use the following `Instrument` API to extract the HTTP headers of the given -`HTTPRequest` into: - -```swift -func handler(request: HTTPRequest, context: LoggingContext) { - InstrumentationSystem.instrument.extract( - request.headers, - into: &context.baggage, - using: HTTPHeadersExtractor() - ) - // ... -} -``` - -> In case your library makes use of the `NIOHTTP1.HTTPHeaders` type we already have an `HTTPHeadersInjector` & -`HTTPHeadersExtractor` available as part of the `NIOInstrumentation` library. - -For your library/framework to be able to carry `LoggingContext` across asynchronous boundaries, it's crucial that you carry the context throughout your entire call chain in order to avoid dropping metadata. - -### Tracing your library - -When your library/framework can benefit from tracing, you should make use of it by integrating the `Tracing` library. - -In order to work with the tracer [configured by the end-user](#Bootstrapping-the-Instrumentation-System), it adds a property to `InstrumentationSystem` that gives you back a `Tracer`. You can then use that tracer to start `Span`s. In an HTTP client you e.g. -should start a `Span` when sending the outgoing HTTP request: - -```swift -func get(url: String, context: LoggingContext) { - var request = HTTPRequest(url: url) - - // inject the request headers into the baggage as explained above - - // start a span for the outgoing request - let tracer = InstrumentationSystem.tracer - var span = tracer.startSpan(named: "HTTP GET", context: context, ofKind: .client) - - // set attributes on the span - span.attributes.http.method = "GET" - // ... - - self.execute(request).always { _ in - // set some more attributes & potentially record an error - - // end the span - span.end() - } -} -``` - -> ⚠️ Make sure to ALWAYS end spans. Ensure that all paths taken by the code will result in ending the span. -> Make sure that error cases also set the error attribute and end the span. - -> In the above example we used the semantic `http.method` attribute that gets exposed via the -`TracingOpenTelemetrySupport` library. - -## Instrument developers: Creating an instrument - -Creating an instrument means adopting the `Instrument` protocol (or `Tracer` in case you develop a tracer). -`Instrument` is part of the `Instrumentation` library & `Tracing` contains the `Tracer` protocol. - -`Instrument` has two requirements: - -1. A method to inject values inside a `LoggingContext` into a generic carrier (e.g. HTTP headers) -2. A method to extract values from a generic carrier (e.g. HTTP headers) and store them in a `LoggingContext` - -The two methods will be called by instrumented libraries/frameworks at asynchronous boundaries, giving you a chance to -act on the provided information or to add additional information to be carried across these boundaries. - -> Check out the [`Baggage` documentation](https://github.com/apple/swift-distributed-tracing-baggage) for more information on -how to retrieve values from the `LoggingContext` and how to set values on it. - -### Creating a `Tracer` - -When creating a tracer you need to create two types: - -1. Your tracer conforming to `Tracer` -2. A span class conforming to `Span` - -> The `Span` conforms to the standard rules defined in [OpenTelemetry](https://github.com/open-telemetry/opentelemetry-specification/blob/v0.7.0/specification/trace/api.md#span), so if unsure about usage patterns, you can refer to this specification and examples referring to it. - -### Defining, injecting and extracting Baggage - -```swift -import Tracing - -private enum TraceIDKey: BaggageKey { - typealias Value = String -} - -extension Baggage { - var traceID: String? { - get { - return self[TraceIDKey.self] - } - set { - self[TraceIDKey.self] = newValue - } - } -} - -var context = DefaultLoggingContext.topLevel(logger: ...) -context.baggage.traceID = "4bf92f3577b34da6a3ce929d0e0e4736" -print(context.baggage.traceID ?? "new trace id") -``` - ## Contributing Please make sure to run the `./scripts/soundness.sh` script when contributing, it checks formatting and similar things. @@ -601,3 +81,7 @@ echo './scripts/soundness.sh' > .git/hooks/pre-push We use a specific version of [`nicklockwood/swiftformat`](https://github.com/nicklockwood/swiftformat). Please take a look at our [`Dockerfile`](docker/Dockerfile) to see which version is currently being used and install it on your machine before running the script. + +### License + +Apache 2.0 \ No newline at end of file diff --git a/Samples/Dinner/.gitignore b/Samples/Dinner/.gitignore new file mode 100644 index 0000000..0a4509a --- /dev/null +++ b/Samples/Dinner/.gitignore @@ -0,0 +1,2 @@ +.build +Package.resolved diff --git a/Samples/Dinner/Package.swift b/Samples/Dinner/Package.swift new file mode 100644 index 0000000..37f565c --- /dev/null +++ b/Samples/Dinner/Package.swift @@ -0,0 +1,23 @@ +// swift-tools-version:5.3 +import PackageDescription + +let package = Package( + name: "onboarding", + platforms: [ + .macOS("14.0.0"), + ], + products: [ + .executable(name: "onboarding", targets: ["Onboarding"]), + ], + dependencies: [ + // This example uses the following tracer implementation: + .package(url: "https://github.com/slashmo/opentelemetry-swift", .branch("main")), + .package(url: "https://github.com/apple/swift-log.git", from: "1.0.0"), + ], + targets: [ + .target(name: "Onboarding", dependencies: [ + .product(name: "OpenTelemetry", package: "opentelemetry-swift"), + .product(name: "OtlpGRPCSpanExporting", package: "opentelemetry-swift"), + ]), + ] +) diff --git a/Samples/Dinner/README.md b/Samples/Dinner/README.md new file mode 100644 index 0000000..ac0cae5 --- /dev/null +++ b/Samples/Dinner/README.md @@ -0,0 +1,18 @@ +## Tracing Dinner Sample App + +In order to try this sample app, and visualize traces it produces, you should first run docker-compose in order +to launch a docker containers which host a Zipkin UI and collector: + +``` +# cd Samples/Dinner + +docker-compose -f docker/docker-compose.yaml up --build +``` + +and then run the sample app which will produce a number of traces: + +``` +swift run -c release +``` + +Refer to the "Trace Your Application" guide in the documentation to learn more about how to interpret this sample. \ No newline at end of file diff --git a/Samples/Dinner/Sources/Onboarding/Clock+Extensions.swift b/Samples/Dinner/Sources/Onboarding/Clock+Extensions.swift new file mode 100644 index 0000000..3d00f64 --- /dev/null +++ b/Samples/Dinner/Sources/Onboarding/Clock+Extensions.swift @@ -0,0 +1,16 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift OpenTelemetry open source project +// +// Copyright (c) 2021 Moritz Lang and the Swift OpenTelemetry project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +func sleep(for duration: ContinuousClock.Duration) async { + try? await Task.sleep(until: ContinuousClock.now + duration, clock: .continuous) +} \ No newline at end of file diff --git a/Samples/Dinner/Sources/Onboarding/Dinner.swift b/Samples/Dinner/Sources/Onboarding/Dinner.swift new file mode 100644 index 0000000..b88293e --- /dev/null +++ b/Samples/Dinner/Sources/Onboarding/Dinner.swift @@ -0,0 +1,76 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift OpenTelemetry open source project +// +// Copyright (c) 2021 Moritz Lang and the Swift OpenTelemetry project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +import Tracing + +func makeDinner() async throws -> Meal { + try await InstrumentationSystem.tracer.withSpan("makeDinner") { _ in + await sleep(for: .milliseconds(200)) + + async let veggies = try chopVegetables() + async let meat = marinateMeat() + async let oven = preheatOven(temperature: 350) + // ... + return try await cook(veggies, meat, oven) + } +} + +func chopVegetables() async throws -> [Vegetable] { + try await otelChopping1.tracer().withSpan("chopVegetables") { _ in + // Chop the vegetables...! + // + // However, since chopping is a very difficult operation, + // one chopping task can be performed at the same time on a single service! + // (Imagine that... we cannot parallelize these two tasks, and need to involve another service). + async let carrot = try chop(.carrot, tracer: otelChopping1.tracer()) + async let potato = try chop(.potato, tracer: otelChopping2.tracer()) + return try await [carrot, potato] + } +} + +func chop(_ vegetable: Vegetable, tracer: any Tracer) async throws -> Vegetable { + await tracer.withSpan("chop-\(vegetable)") { _ in + await sleep(for: .seconds(5)) + // ... + return vegetable // "chopped" + } +} + +func marinateMeat() async -> Meat { + await sleep(for: .milliseconds(620)) + + return await InstrumentationSystem.tracer.withSpan("marinateMeat") { _ in + await sleep(for: .seconds(3)) + // ... + return Meat() + } +} + +func preheatOven(temperature: Int) async -> Oven { + await InstrumentationSystem.tracer.withSpan("preheatOven") { _ in + // ... + await sleep(for: .seconds(6)) + return Oven() + } +} + +func cook(_: Any, _: Any, _: Any) async -> Meal { + await InstrumentationSystem.tracer.withSpan("cook") { span in + span.addEvent("children-asking-if-done-already") + await sleep(for: .seconds(3)) + span.addEvent("children-asking-if-done-already-again") + await sleep(for: .seconds(2)) + // ... + return Meal() + } +} diff --git a/Samples/Dinner/Sources/Onboarding/Model.swift b/Samples/Dinner/Sources/Onboarding/Model.swift new file mode 100644 index 0000000..d1005de --- /dev/null +++ b/Samples/Dinner/Sources/Onboarding/Model.swift @@ -0,0 +1,21 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift OpenTelemetry open source project +// +// Copyright (c) 2021 Moritz Lang and the Swift OpenTelemetry project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +struct Meal: Sendable {} +struct Meat: Sendable {} +struct Oven: Sendable {} +enum Vegetable: Sendable { + case potato + case carrot +} + diff --git a/Samples/Dinner/Sources/Onboarding/main.swift b/Samples/Dinner/Sources/Onboarding/main.swift new file mode 100644 index 0000000..c5c74ca --- /dev/null +++ b/Samples/Dinner/Sources/Onboarding/main.swift @@ -0,0 +1,63 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift OpenTelemetry open source project +// +// Copyright (c) 2021 Moritz Lang and the Swift OpenTelemetry project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +import Logging +import NIO +import OpenTelemetry +import OtlpGRPCSpanExporting +import Tracing + +// ==== ---------------------------------------------------------------------------------------------------------------- + +let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + +LoggingSystem.bootstrap { label in + var handler = StreamLogHandler.standardOutput(label: label) + handler.logLevel = .trace + return handler +} + +// ==== ---------------------------------------------------------------------------------------------------------------- +// MARK: - Configure OTel + +let exporter = OtlpGRPCSpanExporter(config: OtlpGRPCSpanExporter.Config(eventLoopGroup: group)) +let processor = OTel.SimpleSpanProcessor(exportingTo: exporter) +let otel = OTel(serviceName: "DinnerService", eventLoopGroup: group, processor: processor) + +let otelChopping1 = OTel(serviceName: "ChoppingService-1", eventLoopGroup: group, processor: processor) +let otelChopping2 = OTel(serviceName: "ChoppingService-2", eventLoopGroup: group, processor: processor) + +// First start `OTel`, then bootstrap the instrumentation system. +// This makes sure that all components are ready to begin handling spans. +try otel.start().wait() +try otelChopping1.start().wait() +try otelChopping2.start().wait() + +// By bootstrapping the instrumentation system, our dependencies +// compatible with "Swift Distributed Tracing" will also automatically +// use the "OpenTelemetry Swift" Tracer 🚀. +InstrumentationSystem.bootstrap(otel.tracer()) + +// ==== ---------------------------------------------------------------------------------------------------------------- +// MARK: - Run the sample app + +let dinner = try await makeDinner() + +// ==== ---------------------------------------------------------------------------------------------------------------- +// MARK: - Shutdown + +// Wait a second to let the exporter finish before shutting down. +sleep(2) + +try otel.shutdown().wait() +try group.syncShutdownGracefully() diff --git a/Samples/Dinner/docker/collector-config.yaml b/Samples/Dinner/docker/collector-config.yaml new file mode 100644 index 0000000..1a9f4b8 --- /dev/null +++ b/Samples/Dinner/docker/collector-config.yaml @@ -0,0 +1,24 @@ +receivers: + otlp: + protocols: + grpc: + endpoint: otel-collector:4317 + +exporters: + logging: + logLevel: debug + + jaeger: + endpoint: "jaeger:14250" + tls: + insecure: true + + zipkin: + endpoint: "http://zipkin:9411/api/v2/spans" + + +service: + pipelines: + traces: + receivers: otlp + exporters: [logging, jaeger, zipkin] diff --git a/Samples/Dinner/docker/docker-compose.yaml b/Samples/Dinner/docker/docker-compose.yaml new file mode 100644 index 0000000..b4522b4 --- /dev/null +++ b/Samples/Dinner/docker/docker-compose.yaml @@ -0,0 +1,26 @@ +version: '3' +services: + otel-collector: + image: otel/opentelemetry-collector-contrib:latest + command: ["--config=/etc/config.yaml"] + volumes: + - ./collector-config.yaml:/etc/config.yaml + ports: + - "4317:4317" + networks: [exporter] + depends_on: [zipkin, jaeger] + + zipkin: + image: openzipkin/zipkin:latest + ports: + - "9411:9411" + networks: [exporter] + + jaeger: + image: jaegertracing/all-in-one + ports: + - "16686:16686" + networks: [exporter] + +networks: + exporter: diff --git a/Sources/Instrumentation/Instrument.swift b/Sources/Instrumentation/Instrument.swift index 924f004..4796abc 100644 --- a/Sources/Instrumentation/Instrument.swift +++ b/Sources/Instrumentation/Instrument.swift @@ -14,36 +14,46 @@ import InstrumentationBaggage -/// Conforming types are used to extract values from a specific `Carrier`. -public protocol Extractor { - /// The carrier to extract values from. - associatedtype Carrier +public enum Instrument { - /// Extract the value for the given key from the `Carrier`. + /// Convenience to access the globally bootstrapped instrument on ``InstrumentationSystem``. /// - /// - Parameters: - /// - key: The key to be extracted. - /// - carrier: The `Carrier` to extract from. - func extract(key: String, from carrier: Carrier) -> String? -} + /// Equivalent to ``InstrumentationSystem/instrument``. + static var current: InstrumentProtocol { + InstrumentationSystem.instrument + } -/// Conforming types are used to inject values into a specific `Carrier`. -public protocol Injector { - /// The carrier to inject values into. - associatedtype Carrier + /// Obtain the ``current`` instrument which was bootstrapped on the global ``InstrumentationSystem``, + /// and invoke ``InstrumentProtocol/extract(_:into:using:)`` on it. + /// + /// Extract values from a `Carrier` by using the given extractor and inject them into the given `Baggage`. + /// It's quite common for `Instrument`s to come up with new values if they weren't passed along in the given `Carrier`. + /// + /// - Parameters: + /// - carrier: The `Carrier` that was used to propagate values across boundaries. + /// - baggage: The `Baggage` into which these values should be injected. + /// - extractor: The ``Extractor`` that extracts values from the given `Carrier`. + public static func extract(_ carrier: Carrier, into baggage: inout Baggage, using extractor: Extract) where Extract: Extractor, Extract.Carrier == Carrier { + Instrument.current.extract(carrier, into: &baggage, using: extractor) + } - /// Inject the given value for the given key into the given `Carrier`. + /// Obtain the ``current`` instrument which was bootstrapped on the global ``InstrumentationSystem``, + /// and invoke ``InstrumentProtocol/extract(_:into:using:)`` on it. + /// + /// Take values from a `Baggage` and inject them into the given `Carrier` using the given ``Injector``. /// /// - Parameters: - /// - value: The value to be injected. - /// - key: The key for which to inject the value. - /// - carrier: The `Carrier` to inject into. - func inject(_ value: String, forKey key: String, into carrier: inout Carrier) + /// - baggage: The `Baggage` from which relevant information will be extracted. + /// - carrier: The `Carrier` into which this information will be injected. + /// - injector: The ``Injector`` used to inject extracted `Baggage` into the given `Carrier`. + public static func inject(_ baggage: Baggage, into carrier: inout Carrier, using injector: Inject) where Inject: Injector, Inject.Carrier == Carrier { + Instrument.current.inject(baggage, into: &carrier, using: injector) + } } /// Conforming types are usually cross-cutting tools like tracers. They are agnostic of what specific `Carrier` is used /// to propagate metadata across boundaries, but instead just specify what values to use for which keys. -public protocol Instrument { +public protocol InstrumentProtocol { /// Extract values from a `Carrier` by using the given extractor and inject them into the given `Baggage`. /// It's quite common for `Instrument`s to come up with new values if they weren't passed along in the given `Carrier`. /// @@ -54,7 +64,7 @@ public protocol Instrument { func extract(_ carrier: Carrier, into baggage: inout Baggage, using extractor: Extract) where Extract: Extractor, Extract.Carrier == Carrier - /// Extract values from a `Baggage` and inject them into the given `Carrier` using the given ``Injector``. + /// Take values from a `Baggage` and inject them into the given `Carrier` using the given ``Injector``. /// /// - Parameters: /// - baggage: The `Baggage` from which relevant information will be extracted. @@ -63,3 +73,30 @@ public protocol Instrument { func inject(_ baggage: Baggage, into carrier: inout Carrier, using injector: Inject) where Inject: Injector, Inject.Carrier == Carrier } + +/// Conforming types are used to extract values from a specific `Carrier`. +public protocol Extractor { + /// The carrier to extract values from. + associatedtype Carrier + + /// Extract the value for the given key from the `Carrier`. + /// + /// - Parameters: + /// - key: The key to be extracted. + /// - carrier: The `Carrier` to extract from. + func extract(key: String, from carrier: Carrier) -> String? +} + +/// Conforming types are used to inject values into a specific `Carrier`. +public protocol Injector { + /// The carrier to inject values into. + associatedtype Carrier + + /// Inject the given value for the given key into the given `Carrier`. + /// + /// - Parameters: + /// - value: The value to be injected. + /// - key: The key for which to inject the value. + /// - carrier: The `Carrier` to inject into. + func inject(_ value: String, forKey key: String, into carrier: inout Carrier) +} diff --git a/Sources/Instrumentation/InstrumentationSystem.swift b/Sources/Instrumentation/InstrumentationSystem.swift index 9c512a8..7d3b6a4 100644 --- a/Sources/Instrumentation/InstrumentationSystem.swift +++ b/Sources/Instrumentation/InstrumentationSystem.swift @@ -24,14 +24,14 @@ import InstrumentationBaggage /// ``instrument``: Returns whatever you passed to ``bootstrap(_:)`` as an ``Instrument``. public enum InstrumentationSystem { private static let lock = ReadWriteLock() - private static var _instrument: Instrument = NoOpInstrument() + private static var _instrument: InstrumentProtocol = NoOpInstrument() private static var isInitialized = false /// Globally select the desired ``Instrument`` implementation. /// /// - Parameter instrument: The ``Instrument`` you want to share globally within your system. /// - Warning: Do not call this method more than once. This will lead to a crash. - public static func bootstrap(_ instrument: Instrument) { + public static func bootstrap(_ instrument: InstrumentProtocol) { self.lock.withWriterLock { precondition( !self.isInitialized, """ @@ -47,7 +47,7 @@ public enum InstrumentationSystem { /// For testing scenarios one may want to set instruments multiple times, rather than the set-once semantics enforced by ``bootstrap(_:)``. /// /// - Parameter instrument: the instrument to boostrap the system with, if `nil` the ``NoOpInstrument`` is bootstrapped. - internal static func bootstrapInternal(_ instrument: Instrument?) { + internal static func bootstrapInternal(_ instrument: InstrumentProtocol?) { self.lock.withWriterLock { self._instrument = instrument ?? NoOpInstrument() } @@ -56,14 +56,14 @@ public enum InstrumentationSystem { /// Returns the globally configured ``Instrument``. /// /// Defaults to a no-op ``Instrument`` if ``bootstrap(_:)`` wasn't called before. - public static var instrument: Instrument { + public static var instrument: InstrumentProtocol { self.lock.withReaderLock { self._instrument } } } extension InstrumentationSystem { /// :nodoc: INTERNAL API: Do Not Use - public static func _findInstrument(where predicate: (Instrument) -> Bool) -> Instrument? { + public static func _findInstrument(where predicate: (InstrumentProtocol) -> Bool) -> InstrumentProtocol? { self.lock.withReaderLock { if let multiplex = self._instrument as? MultiplexInstrument { return multiplex.firstInstrument(where: predicate) diff --git a/Sources/Instrumentation/Logger+Baggage.swift b/Sources/Instrumentation/Logger+Baggage.swift new file mode 100644 index 0000000..a97d0da --- /dev/null +++ b/Sources/Instrumentation/Logger+Baggage.swift @@ -0,0 +1,43 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift Distributed Tracing open source project +// +// Copyright (c) 2020-2022 Apple Inc. and the Swift Distributed Tracing project +// authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +import Logging +@_exported import InstrumentationBaggage + +#if swift(>=5.5.0) && canImport(_Concurrency) +@available(macOS 10.15, iOS 13.0, watchOS 6.0, tvOS 13.0, *) +extension Logger { + + /// Extract any potential ``Logger/Metadata`` that might be obtained by extracting the + /// passed ``InstrumentationBaggage/Baggage`` to this logger's configured ``Logger/MetadataProvider``. + /// + /// Use this when it is necessary to "materialize" contextual baggage metadata into the logger, for future use, + /// and you cannot rely on using the task-local way of passing Baggage around, e.g. when the logger will be + /// used from multiple callbacks, and it would be troublesome to have to restore the task-local baggage in every callback. + /// + /// Generally prefer to set the task-local baggage using `Baggage.current` or `Tracer.withSpan`. + public mutating func provideMetadata(from baggage: Baggage?) { + guard let baggage = baggage else { + return + } + + Baggage.withValue(baggage) { + let metadata = self.metadataProvider.provideMetadata() + for (k, v) in metadata { + self[metadataKey: k] = v + } + } + } +} +#endif diff --git a/Sources/Instrumentation/MultiplexInstrument.swift b/Sources/Instrumentation/MultiplexInstrument.swift index 6679357..e550650 100644 --- a/Sources/Instrumentation/MultiplexInstrument.swift +++ b/Sources/Instrumentation/MultiplexInstrument.swift @@ -17,24 +17,24 @@ import InstrumentationBaggage /// A pseudo-``Instrument`` that may be used to instrument using multiple other ``Instrument``s across a /// common `Baggage`. public struct MultiplexInstrument { - private var instruments: [Instrument] + private var instruments: [InstrumentProtocol] /// Create a ``MultiplexInstrument``. /// /// - Parameter instruments: An array of ``Instrument``s, each of which will be used to ``Instrument/inject(_:into:using:)`` or ``Instrument/extract(_:into:using:)`` /// through the same `Baggage`. - public init(_ instruments: [Instrument]) { + public init(_ instruments: [InstrumentProtocol]) { self.instruments = instruments } } extension MultiplexInstrument { - func firstInstrument(where predicate: (Instrument) -> Bool) -> Instrument? { + func firstInstrument(where predicate: (InstrumentProtocol) -> Bool) -> InstrumentProtocol? { self.instruments.first(where: predicate) } } -extension MultiplexInstrument: Instrument { +extension MultiplexInstrument: InstrumentProtocol { public func inject(_ baggage: Baggage, into carrier: inout Carrier, using injector: Inject) where Inject: Injector, Carrier == Inject.Carrier { diff --git a/Sources/Instrumentation/NoOpInstrument.swift b/Sources/Instrumentation/NoOpInstrument.swift index 437b31b..d8f096d 100644 --- a/Sources/Instrumentation/NoOpInstrument.swift +++ b/Sources/Instrumentation/NoOpInstrument.swift @@ -15,7 +15,7 @@ import InstrumentationBaggage /// A "no op" implementation of an ``Instrument``. -public struct NoOpInstrument: Instrument { +public struct NoOpInstrument: InstrumentProtocol { public init() {} public func inject(_ baggage: Baggage, into carrier: inout Carrier, using injector: Inject) diff --git a/Sources/Tracing/Docs.docc/Guides/ImplementATracer.md b/Sources/Tracing/Docs.docc/Guides/ImplementATracer.md new file mode 100644 index 0000000..dc8d40f --- /dev/null +++ b/Sources/Tracing/Docs.docc/Guides/ImplementATracer.md @@ -0,0 +1,186 @@ +# Implement a Tracer + +## Overview + +This guide is aimed at ``TracerProtocol`` and ``InstrumentProtocol`` implementation authors. + +This guide is for you if you find yourself in need of implementing your own tracing client such as Zipkin, Jaeger, X-Trace, OpenTelemetry or something similar that is custom to your company or distributed system. + +## Do you need an Instrument or a Tracer? + +Distributed tracing offers two types of instrumentation protocols: an instrument, and a tracer. + +A tracer is-an instrument as well, and further refines it with the ability to start a trace ``Span``. + +## Creating an instrument + +Creating an instrument means adopting the ``InstrumentProtocol`` protocol (or ``TracerProtocol`` in case you develop a tracer). +``InstrumentProtocol`` is part of the `Instrumentation` library and `Tracing` contains the ``TracerProtocol`` protocol. + +`Instrument` has two requirements: + +1. A method to inject values into a `FIXME!!!` a generic carrier (e.g. HTTP headers) +2. A method to extract values from a generic carrier (e.g. HTTP headers) and store them in a `FIXME!!!` + +The two methods will be called by instrumented libraries/frameworks at asynchronous boundaries, giving you a chance to +act on the provided information or to add additional information to be carried across these boundaries. + +> Check out the [`Baggage` documentation](https://github.com/apple/swift-distributed-tracing-baggage) for more information on +how to retrieve values from the `FIXME!!!` and how to set values on it. + +### Creating a `Tracer` + +When creating a tracer you need to create two types: + +1. Your tracer conforming to ``Tracer`` +2. A span class conforming to ``Span`` + +> ``Span`` conforms to the standard rules defined in [OpenTelemetry](https://github.com/open-telemetry/opentelemetry-specification/blob/v0.7.0/specification/trace/api.md#span), so if unsure about usage patterns, you can refer to this specification and examples referring to it. + +### Defining, injecting and extracting Baggage + +```swift +import Tracing + +private enum TraceIDKey: BaggageKey { + typealias Value = String +} + +extension Baggage { + var traceID: String? { + get { + return self[TraceIDKey.self] + } + set { + self[TraceIDKey.self] = newValue + } + } +} + +var context = DefaultFIXME!!!.topLevel(logger: ...) +context.baggage.traceID = "4bf92f3577b34da6a3ce929d0e0e4736" +print(context.baggage.traceID ?? "new trace id") +``` + + +### Extracting & injecting Baggage + +When hitting boundaries like an outgoing HTTP request you call out to the [configured instrument(s)](#Bootstrapping-the-Instrumentation-System): + +An HTTP client e.g. should inject the given `FIXME!!!` into the HTTP headers of its outbound request: + +```swift +func get(url: String, context: FIXME!!!) { + var request = HTTPRequest(url: url) + InstrumentationSystem.instrument.inject( + context.baggage, + into: &request.headers, + using: HTTPHeadersInjector() + ) +} +``` + +On the receiving side, an HTTP server should use the following `Instrument` API to extract the HTTP headers of the given +`HTTPRequest`: + +```swift +func handler(request: HTTPRequest, context: FIXME!!!) { + InstrumentationSystem.instrument.extract( + request.headers, + into: &context.baggage, + using: HTTPHeadersExtractor() + ) + // ... +} +``` + +> In case your library makes use of the `NIOHTTP1.HTTPHeaders` type we already have an `HTTPHeadersInjector` and +`HTTPHeadersExtractor` available as part of the `NIOInstrumentation` library. + +For your library/framework to be able to carry `FIXME!!!` across asynchronous boundaries, it's crucial that you carry the context throughout your entire call chain in order to avoid dropping metadata. + +### Tracing your library + +When your library/framework can benefit from tracing, you should make use of it by integrating the `Tracing` library. + +In order to work with the tracer [configured by the end-user](#Bootstrapping-the-Instrumentation-System), it adds a property to `InstrumentationSystem` that gives you back a `Tracer`. You can then use that tracer to start `Span`s. In an HTTP client you e.g. +should start a `Span` when sending the outgoing HTTP request: + +```swift +func get(url: String, context: FIXME!!!) { + var request = HTTPRequest(url: url) + + // inject the request headers into the baggage as explained above + + // start a span for the outgoing request + let tracer = InstrumentationSystem.tracer + var span = tracer.startSpan(named: "HTTP GET", context: context, ofKind: .client) + + // set attributes on the span + span.attributes.http.method = "GET" + // ... + + self.execute(request).always { _ in + // set some more attributes & potentially record an error + + // end the span + span.end() + } +} +``` + +> ⚠️ Make sure to ALWAYS end spans to ensure that all paths taken by the code will result in ending the span. +> Make sure that error cases also set the error attribute and end the span. + +> In the above example we used the semantic `http.method` attribute that gets exposed via the +`TracingOpenTelemetrySupport` library. + +## Instrument developers: Creating an instrument + +Creating an instrument means adopting the `Instrument` protocol (or `Tracer` in case you develop a tracer). +`Instrument` is part of the `Instrumentation` library & `Tracing` contains the `Tracer` protocol. + +`Instrument` has two requirements: + +1. A method to inject values inside a `FIXME!!!` into a generic carrier (e.g. HTTP headers) +2. A method to extract values from a generic carrier (e.g. HTTP headers) and store them in a `FIXME!!!` + +The two methods will be called by instrumented libraries/frameworks at asynchronous boundaries, giving you a chance to +act on the provided information or to add additional information to be carried across these boundaries. + +> Check out the [`Baggage` documentation](https://github.com/apple/swift-distributed-tracing-baggage) for more information on +how to retrieve values from the `FIXME!!!` and how to set values on it. + +### Creating a `Tracer` + +When creating a tracer you need to create two types: + +1. Your tracer conforming to `Tracer` +2. A span class conforming to `Span` + +> The `Span` conforms to the standard rules defined in [OpenTelemetry](https://github.com/open-telemetry/opentelemetry-specification/blob/v0.7.0/specification/trace/api.md#span), so if unsure about usage patterns, you can refer to this specification and examples referring to it. + +### Defining, injecting and extracting Baggage + +```swift +import Tracing + +private enum TraceIDKey: BaggageKey { + typealias Value = String +} + +extension Baggage { + var traceID: String? { + get { + return self[TraceIDKey.self] + } + set { + self[TraceIDKey.self] = newValue + } + } +} + +var context = DefaultFIXME!!!.topLevel(logger: ...) +context.baggage.traceID = "4bf92f3577b34da6a3ce929d0e0e4736" +print(context.baggage.traceID ?? "new trace id") +``` \ No newline at end of file diff --git a/Sources/Tracing/Docs.docc/Guides/InstrumentYourLibrary.md b/Sources/Tracing/Docs.docc/Guides/InstrumentYourLibrary.md new file mode 100644 index 0000000..54c9f37 --- /dev/null +++ b/Sources/Tracing/Docs.docc/Guides/InstrumentYourLibrary.md @@ -0,0 +1,331 @@ +# Instrument Your Library or Framework + +## Overview + +This guide is aimed at library and framework developers who wish to instrument their code using distributed tracing. + +Doing so within a library may enable automatic trace propagation and is key to propagating trace information across +distributed nodes, e.g. by instrumenting the HTTP client used by such system. + +Other examples of libraries which would benefit _the most_ from being instrumented using distributed tracing include: + +- HTTP Clients (e.g. AsyncHTTPClient), +- HTTP Servers (e.g. Vapor or Smoke), +- RPC systems (Swift gRPC or Swift's `DistributedActorSystem` implementations), +- database drivers (e.g. SQL or MongoDB clients), +- any other library which can emit meaningful span information about tasks it is performing. + +The most important libraries to instrument are "edge" libraries, which serve to connect between systems, because +it is them who must inject and extract contextual baggage metadata to enable distributed trace ``Span`` propagation. + +Following those, any database or other complex library which may be able to emit useful information about its internals are +also good candidates to being instrumented. Note that libraries may do so optionally, or hide the "verboseness" of such traces +behind options, or only attach information if a ``Span`` is already active etc. Please review your library's documentation to learn +more about it has integrated tracing support. + +### Propagating baggage metadata + +When crossing boundaries between processes, such as making or receiving an HTTP request, the library responsible for doing so should invoke instrumentation in order to inject or extract the contextual baggage metadata into/from the "carrier" type (such as the `HTTPResponse`) type. + +#### Handling outbound requests + +When a library makes an "outgoing" request or message interaction, it should invoke the method of a configured instrument. This will invoke whichever instrument the end-user has configured and allow them to customize what metadata gets to be propagated. This can be depicted by the following diagram: + +``` + ┌──────────────────────────────────┐ + │ Specific Tracer / Instrument │ + └──────────────────────────────────┘ + │ + instrument.inject(baggage: baggage, into: request, using: httpInjector) + │ + ┌────────▼──────┐ + ┌───────────────┤ Tracing API ├────────────┐ ┌────┐ + │HTTPClient └────────▲──────┘ │ │ N │ + │ │ │ │ e │ + │ ┌───────────────┐ ┌──▼──────────────┐ │ │ t │ +┌───────────┐ │ | make │ │ add metadata to │ │ │ w │ +│ User code |────▶│ │ HTTPRequest │──▶│ HTTPRequest │────┼─────▶│ o │ +└───────────┘ │ └───────────────┘ └─────────────────┘ │ │ r │ + │ │ │ k │ + └────────────────────────────────────────────┘ └────┘ +``` + +> Note: A library _itself_ cannot really know what information to propagate, since that depends on the used tracing or instrumentation system. The library does however understand its carrier type, and thus can implement the ``Injector`` protocol. + +For example, an HTTP client e.g. should inject the current baggage (which could be carrying trace ``Span`` information) into the HTTP headers as follows: + +```swift +func get(url: String) -> HTTPResponse { + var request = HTTPRequest(url: url) + + if let baggage = Baggage.current { + InstrumentationSystem.instrument.inject( + baggage, + into: &request, + using: HTTPRequestInjector() + ) + } + + try await _send(request) +} +``` + +As you can see, the library does not know anything about what tracing system or instrumentation is installed, because it cannot know that ahead of time. + +All it has to do is query for the current [task-local](https://developer.apple.com/documentation/swift/tasklocal) `Baggage` value, and if one is present, call on the instrumentation system to inject it into the request. + +Since neither the tracing API, nor the specific tracer backend are aware of this library's specific `HTTPRequest` type, we also need to implement an ``Injector`` which takes on the responsibility of adding the metadata into the carrier type (which in our case is the `HTTPRequest`). An injector could for example be implemented like this: + +```swift +struct HTTPRequestInjector: Injector { + func inject(_ value: String, forKey key: String, into request: inout HTTPRequest) { + request.headers.append((key, value)) + } +} +``` + +Once the metadata has been injected, the request–including all the additional metadata–is sent over the network. + +> Note: The actual logic of deciding what baggage values to inject depend on the tracer implementation, and thus we are not covering it in this _end-user_ focused guide. Refer to if you'd like to learn about implementing a ``TracerProtocol``. + +#### Handling inbound requests + +On the receiving side, an HTTP server needs to perform the inverse operation, as it receives the request from the network and forms an `HTTPRequest` object. Before it is passed it to user-code, it must extract any trace metadata from the request headers into the `Baggage`. + +``` + ┌──────────────────────────────────┐ + │ Specific Tracer / Instrument │ + └──────────────────────────────────┘ + ▲ + │ + instrument.extract(request, into: &baggage, using: httpExtractor) + │ + ┌──────▼──────┐ +┌────┐ ┌──────────────┤ Tracing API ├────────────┐ +│ N │ │HTTPServerLib └──────▲──────┘ │ +│ e │ │ │ │ +│ t │ │┌───────────────┐ ┌─▼───────────────┐ │ +│ w │ ││ parse │ │extract metadata │ │ ┌───────────┐ +│ o │─────────▶││ HTTPRequest ├──▶from HTTPRequest │───┼────▶│ User code │ +│ r │ │└───────────────┘ └─────────────────┘ │ └───────────┘ +│ k │ │ │ +│ │ └─────────────────────────────────────────┘ +└──── +``` + +This is very similar to what we were doing on the outbound side, but the roles of baggage and request are somewhat reversed: we're extracting values from the carrier into the baggage. The code performing this task could look something like this: + +```swift +func handler(request: HTTPRequest) async { + // we are beginning a new "top level" context - the beginning of a request - + // and thus start from a fresh, empty, top-level baggage: + var baggage = Baggage.topLevel + + // populate the baggage by extracting interesting metadata from the incoming request: + InstrumentationSystem.instrument.extract( + request, + into: &baggage, + using: HTTPRequestExtractor() + ) + + // ... invoke user code ... +} +``` + +Similarly to the outbound side, we need to implement an ``Extractor`` because the tracing libraries don't know about our specific HTTP types, yet we need to have them decide for which values to extract keys. + +```swift +struct HTTPRequestExtract: Instrumentation.Extractor { + func extract(key: String, from request: HTTPRequest) -> String? { + request.headers.first(where: { $0.0 == key })?.1 + } +} +``` + +Which exact keys will be asked for depends on the tracer implementation, thus we don't present this part of the implementation in part of the guide. For example, a tracer most likely would look for, and extract, values for keys such as `trace-id` and `span-id`. Note though that the exact semantics and keys used by various tracers differ, which is why we have to leave the decision of what to extract up to tracer implementations. + +Next, your library should "*restore*" the contextual baggage, this is performed by setting the baggage task-local value around calling into user code, like this: + +```swift +func handler(request: HTTPRequest) async { + // ... + InstrumentationSystem.instrument.extract(..., into: &baggage, ...) + // ... + + await Baggage.withValue(baggage) { + await userCode(request) + } +} +``` + +This sets the task-local value `Baggage.current` which is used by [swift-log](https://github.com/apple/swift-log), as well as ``TracerProtocol`` APIs in order to later "*pick up*" the baggage and e.g. include it in log statements, or start new trace spans using the information stored in the baggage. + +> Note: The end goal here being that when end-users of your library write `log.info("Hello")` the logger is able to pick up the contextual baggage information and include the e.g. the `trace-id` in such log statement automatically! This way, every log made during the handling of this request would include the `trace-id` automatically, e.g. like this: +> +> `12:43:32 info [trace-id=463a...13ad] Logging during handling of a request!` + +If your library makes multiple calls to user-code as part of handling the same request, you may consider if restoring the baggage around all of these callbacks is beneficial. For example, if a library had callbacks such as: + +```swift +/// Example library protocol, offering multiple callbacks, all semantically part of the same request handling. +protocol SampleHTTPHandler { + // called immediately when an incoming HTTPRequests headers are available, + // even before the request body has been processed. + func requestHeaders(headers: HTTPHeaders) async + + // Called multiple (or zero) times, for each "part" of the incoming HTTPRequest body. + func requestBodyPart(ByteBuffer) async +} +``` + +You may want to restore the baggage once around both those calls, or if that is not possible, restore it every time when calling back into user code, e.g. like this: + +```swift +actor MySampleServer { + + var baggage: Baggage = .topLevel + var userCode: SampleHTTPHandler + + func onHeaders(headers: HTTPHeaders) async { + await Baggage.withValue(self.baggage) { + await userHandler.requestHeaders(headers) + } + } + + func onBodyPart(part: ByteBuffer) async { + await Baggage.withValue(self.baggage) { + await userHandler.requestHeaders(headers) + } + } +} +``` + +While this code is very simple for illustration purposes, and it may seem surprising why there are two separate places where we need to call into user-code separately, in practice such situations can happen when using asynchronous network or database libraries which offer their API in terms of callbacks. Always consider if and when to restore baggage such that it makes sense for the end user. + +### Starting Trace Spans in Your Library + +The above steps are enough if you wanted to provide contextual baggage propagation. It already enables techniques such as **correlation ids** which can be set once, in one system, and then carried through to any downstream services the code makes calls from while the baggage is set. + +Many libraries also have the opportunity to start trace spans themselfes, on behalf of users, in pieces of the library that can provide useful insight in the behavior or the library in production. For example, the `HTTPServer` can start spans as soon as it begins handling HTTP requests, and this way provide a parent span to any spans the user-code would be creating itself. + +Let us revisit the previous sample `HTTPServer` which restored baggage around invoking the user-code, and further extend it to start a span including basic information about the `HTTPRequest` being handled: + +```swift +// SUB-OPTIMAL EXAMPLE: +func handler(request: HTTPRequest) async { + // 1) extract trace information into baggage... + InstrumentationSystem.instrument.extract(..., into: &baggage, ...) + // ... + + // 2) restore baggage, using a task-local: + await Baggage.withValue(baggage) { + // 3) start span, using contextual baggage (which may contain trace-ids already): + await InstrumentationSystem.tracer.withSpan("\(request.path)") { span in + // 3.1) Set useful attributes:on the span: + span.attributes["http.method"] = request.method + // ... + // See also: Open Telemetry typed attributes in swift-distributed-tracing-extras + + // 4) user code will have the apropriate Span baggage restored: + await userCode(request) + } + } +} +``` + +This is introducing multiple layers of nesting, and we have un-necessarily restored, picked-up, and restored the baggage again. In order to avoid this duplicate work, it is beneficial to use the ``TracerProtocol/withSpan(_:baggage:ofKind:_:)-1w7i6`` overload, which also accepts a `Baggage` as parameter, rather than picking it up from the task-local value: + +```swift +// BETTER +func handler(request: HTTPRequest) async { + // 1) extract trace information into baggage: + InstrumentationSystem.instrument.extract(..., into: &baggage, ...) + + // 2) start span, passing the freshly extracted baggage explicitly: + await InstrumentationSystem.tracer.withSpan("\(request.path)", baggage: baggage) { span in + // ... + } +} +``` + +This method will only restore the baggage once, after the tracer has had a chance to decide if this execution will be traced, and if so, setting its own trace and span identifiers. This way only one task-local access (set) is performed in this version of the code, which is preferable to the set/read/set that was performed previously. + +#### Manual Span Lifetime Management + +While the ``TracerProtocol/withSpan(_:ofKind:_:)-11n3y`` API is preferable in most situations, it may not be possible to use when the lifetime of a span only terminates in yet another callback API. In such situations, it may be impossible to "wrap" the entire piece of code that would logically represent "the span" using a `withSpan(...) { ... }` call. + +In such situations you can resort to using the ``TracerProtocol/startSpan(_:baggage:ofKind:)`` and ``Span/end()`` APIs explicitly. Those APIs can then be used like this: + +```swift +// Callback heavy APIs may need to store and manage spans manually: +var span: Span? + +func startHandling(request: HTTPRequest) { + self.span = InstrumentationSystem.tracer.startSpan("\(request.path)") + + userCode.handle(request) +} + +func finishHandling(request: HTTPRequest, response: HTTPResponse) { + // always end spans (!) + span?.end() // ends and flushes the span +} +``` + +It is very important to _always_ end spans that are started, as attached resources may keep accumulating and lead to memory leaks or worse issues in tracing backends depending on their implementation. + +The manual way of managing spans also means that error paths need to be treated with increased attention. This is something that `withSpan` APIs handle automatically, but we cannot rely on `withSpan` detecting an error thrown out of its body closure anymore when using the `startSpan`/`end` APIs. + +When an error is thrown, or if the span should be considered errored for some reason, you should invoke the ``Span/recordError(_:)`` method and pass an ``Error`` that should be recorded on the span. Since failed spans usually show up in very visually distinct ways, and are most often the first thing a developer inspecting an application using tracing is looking for, it is important to get error reporting right in your library. Here is a simple example how this might look like: + +```swift +var span: Span + +func onError(error: Error) { + span.recordError(error) // record the error + span.end() // and end the span +} +``` + +It is worth noting that double-ending a span should be considered a programmer error, and tracer implementations are free to crash or otherwise report such problem. + +> Note: The problem with finding a span that was ended in two places is that its lifecycle seems to be incorrectly managed, and therefore the span timing information is at risk of being incorrect. +> +> Please also take care to never `end()` a span that was created using `withSpan()` APIs, because `withSpan` will automatically end the span when the closure returns. + +#### Storing and restoring baggage across callbacks + +Note also since a `Span` contains an instrumentation `Baggage`, you can also pass the span's baggage to any APIs which may need it, or even restore the baggage e.g. for loggers to pick it up while emitting log statements: + +```swift +class StatefulHandler { + var span: Span + + func startHandling(request: HTTPRequest) { + self.span = InstrumentationSystem.tracer.startSpan("\(request.path)") + } + + // callback, form other task, so we don't have the task-local information here anymore + func onSomethingHappening(event: SomeEvent) { + Baggage.withValue(span.baggage) { // restore task-local baggage + // which allows the baggage to be used by loggers and tracers as usual again: + log.info("Event happened: \(event)") + + // since the baggage was restored here, the startSpan will pick it up, + // and the "event-id" span will be a child of the "request.path" span we started before. + InstrumentationSystem.tracer.startSpan("event-\(event.id)") { + // ... handle the event ... + } + } + } +} + +``` + +### Global vs. "Stored" Tracers and Instruments + +Tracing functions similarily to swift-log and swift-metrics, in the sense that there is a global "backend" configured at application start, by end-users (developers) of an application. And this is how using ``InstrumentationSystem/tracer`` gets the "right" tracer at runtime. + +You may be tempted to allow users _configuring_ a tracer as part of your applications intialization. Generally we advice against that pattern, because it makes it confusing which library needs to be configured, how, and where -- and if libraries are composed, perhaps the setting is not available to the actual "end-user" anymore. + +On the other hand, it may be valuable for testing scenarios to be able to set a tracer on a specific instance of your library. Therefore, if you really want to offer a configurable `Instrument` or `Tracer` then we suggest defaulting this setting to `nil`, and if it is `nil`, reaching to the global `InstrumentationSystem/instrument` or `InstrumentationSystem/tracer` - this way it is possible to override a tracer for testing on a per-instance basis, but the default mode of operation that end-users expect from libraries remains working. diff --git a/Sources/Tracing/Docs.docc/Guides/TraceYourApplication.md b/Sources/Tracing/Docs.docc/Guides/TraceYourApplication.md new file mode 100644 index 0000000..1dcd53a --- /dev/null +++ b/Sources/Tracing/Docs.docc/Guides/TraceYourApplication.md @@ -0,0 +1,442 @@ +# Trace Your Application + +## Overview + +This guide is aimed at **application developers** who have some server-side system and want to make use of distributed tracing +in order to improve their understanding and facilitate performance tuning and debugging their services in production or development. + +Distributed tracing offers a way to gain additional insight into how your application is performing in production, without having to reconstruct the "big picture" from manually piecing together log lines and figuring out what happened +after what else and _why_. Distributed traces, as the name implies, also span multiple nodes in a microservice architecture +or clustered system, and provide a profiler-like experience to debugging the handling of a "request" or otherwise defined span. + +### Setting up + +The first step to get metadata propagation and tracing working in your application is picking an instrumentation or tracer +implementation. A complete [list of swift-distributed-tracing implementations](http://github.com/apple/swift-distributed-tracing) +is available in this project's README. Select an implementation you'd like to use and follow its bootstrap steps. + +> Note: Since instrumenting an **application** in practice will always need to pull in an existing tracer implementation, +> in this guide we'll use the community maintained [`opentelemetry-swift`](https://github.com/slashmo/opentelemetry-swift) +> tracer, as an example of how you'd start using tracing in your real applications. +> +> If you'd rather implement your own tracer, refer to . + +Once you have selected an implementation, add it as a dependency to your `Package.swift` file. + +```swift +// Depend on the instrumentation library, e.g. opentelemetry-swift: +.package(url: "https://github.com/slashmo/opentelemetry-swift.git", from: ""), + +// This will automatically include a dependency on the swift-distributed-tracing API: +// .package(url: "https://github.com/apple/swift-distributed-tracing.git", from: "1.0.0"), +``` + +Next, add the dependency to your application target: + +```swift +.target( + name: "MyApplication", + dependencies: [ + .product(name: "OpenTelemetry", package: "opentelemetry-swift"), + ] +), +``` + +### Bootstrapping the Tracer + +Similar to [swift-log](https://github.com/apple/swift-log) and [swift-metrics](https://github.com/apple/swift-metrics), +the first thing you'll need to do in your application to use tracing, is to bootstrap the global instance of the tracing system. + +This will allow not only your code, that we're about to write, to use tracing, but also all other libraries which +have been implemented against the distributed tracing API to use it as well. For example, by configuring the global +tracing system, an HTTP server or client will automatically handle trace propagation for you, so make sure to always +bootstrap your tracer globally, otherwise you might miss out on its crucial context propagation features. + +How the tracer library is initialized will differ from library to library, so refer to the respective implementation's +documentation. Once you're ready, pass the tracer or instrument to the ``InstrumentationSystem/bootstrap(_:)`` method, +e.g. like this: + +```swift +import Tracing // this library + +// Import and prepare whatever the specific tracer implementation needs. +// In our example case, we'll prepare the OpenTelemetry tracing system: +import NIO +import OpenTelemetry + +let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) +let otel = OTel(serviceName: "onboarding", eventLoopGroup: group) +try otel.start().wait() + +// Bootstrap the tracing system: +InstrumentationSystem.bootstrap(otel.tracer()) +``` + +You'll notice that the API specifically talks about Instrumentation rather than just Tracing. +This is because it is also possible to use various instrumentation systems, e.g. which only take care +of propagating certain `Baggage` values across process boundaries, without using tracing itself. + +In other words, all tracers are instruments, and the `InstrumentationSystem` works equally for ``InstrumentProtocol``, +as well as ``TracerProtocol`` implementations. + +Our guide focuses on tracing through, so let's continue with that in mind. + +#### Recommended bootstrap order + +Swift offers developers a suite of observability libraries: logging, metrics and tracing. Each of those systems offers a `bootstrap` function. It is useful to stick to a recommended boot order in order to achieve predictable initialization of applications and sub-systems. + +Specifically, it is recommended to bootstrap systems in the following order: + +1. [Swift Log](https://github.com/apple/swift-log#default-logger-behavior)'s `LoggingSystem` +2. [Swift Metrics](https://github.com/apple/swift-metrics#selecting-a-metrics-backend-implementation-applications-only)' `MetricsSystem` +3. [Swift Distributed Tracing](https://github.com/apple/swift-distributed-tracing)'s `InstrumentationSystem` +4. Finally, any other parts of your application + +This is because tracing systems may attempt to emit logs or metrics about their status etc. + +If you intend to use trace identifiers for log correlation (i.e. logging a `trace-id` in every log statement that is part of a trace), +then don't forget to also configure a swift-lot `MetadataProvider`. + +A typical bootstrap could look something like this: + +```swift +import OpenTelemetry +import StatsdMetrics + +extension Logger.MetadataProvider { + + // Include the following OpenTelemetry tracer specific metadata in log statements: + static let otel = Logger.MetadataProvider { baggage in + guard let spanContext = baggage?.spanContext else { return nil } + return [ + "trace-id": "\(spanContext.traceID)", + "span-id": "\(spanContext.spanID)", + ] + } +} + +// 1) bootstrap swift-log: stdout-logger +LoggingSystem.bootstrap( + StreamLogHandler.standardOutput, + metadataProvider: .otel +) + +// 2) bootstrap metrics: statsd +let statsdClient = try StatsdClient(host: host, port: port) +MetricsSystem.bootstrap(statsdClient) + +// 3) bootstrap swift-distributed-tracing: open-telemetry +let group: MultiThreadedEventLoopGroup = ... +let otel = OTel(serviceName: "onboarding", eventLoopGroup: group) + +try otel.start().wait() +InstrumentationSystem.bootstrap(otel.tracer()) + +// 4) Continue starting your application ... +``` + +#### Bootstrapping multiple instruments using MultiplexInstrument + +If you'd find yourself in need of using multiple instrumentation or tracer implementations you can group them in a `MultiplexInstrument` first, which you then pass along to the `bootstrap` method like this: + +```swift +InstrumentationSystem.bootstrap(MultiplexInstrument([FancyInstrument(), OtherFancyInstrument()])) +``` + +`MultiplexInstrument` will then call out to each instrument it has been initialized with. + +### Introducing Trace Spans + +The primary way you interact with distributed tracing is by starting ``Span``s. + +Spans form hierarchies with their parent spans, and end up being visualized using various tools, usually in a format similar to gant charts. So for example, if we had multiple operations that compose making dinner, they would be modelled as child spans of a main `makeDinner` span. Any sub tasks are again modelled as child spans of any given operation, and so on. + +In order to discuss how tracing works, let us first look at a sample trace, before we even take a look at the any source code. This reflects how you may find yourself using tracing once it has been adopted in your microservice or distributed system architecture: there are many services involved, and often times only from a trace you can know where to start looking at a performance or logical regression in the system. + +> Experiment: **Follow along!** You can follow along and explore the generated traces, and the code producing them by opening the sample project located in `Samples/Dinner`! +> +> The sample includes a docker-compose file which starts an [OpenTelemetry](https://opentelemetry.io) [collector](https://opentelemetry.io/docs/collector/), as well as two UIs which can be used to explore the generated traces: +> +> - [Zipkin](http://zipkin.io) - available at [http://127.0.0.1:9411](http://127.0.0.1:9411) +> - [Jaeger](https://www.jaegertracing.io) - available at [http://127.0.0.1:16686](http://127.0.0.1:16686) +> +> In order to start these containers, navigate to the `Samples/Dinner` project and run `docker-compose`, like this: +> +> ```bash +> $ cd Samples/Dinner +> $ docker-compose -f docker/docker-compose.yaml up --build +> # Starting docker_zipkin_1 ... done +> # Starting docker_jaeger_1 ... done +> # Recreating docker_otel-collector_1 ... done +> # Attaching to docker_jaeger_1, docker_zipkin_1, docker_otel-collector_1 +> ``` +> +> This will run docker containers with the services described above, and expose their ports via localhost, including the collector to which we now can export our traces from our development machine. +> +> Keep these containers running, and then, in another terminal window run the sample app that will generate some traces: +> +> ```bash +> $ swift run -c release +> ``` + +Once you have run the sample app, you need to hit "search" in either trace visualization UI, and navigate through to expand the trace view. You'll be greeted with a trace looking somwhat like this (in Zipkin): + +![Make dinner trace diagram](makeDinner-zipkin-01) + +Or, if you prefer Jaeger, it'd look something like this: + +![Make dinner trace diagram](makeDinner-jaeger-01) + +Take a moment to look at the trace spans featured in these diagrams. + +By looking at them, you should be able to get a rough idea what the code is doing. That's right, it is a top-level `makeDinner` method, that seems to be performing a bunch of tasks in order to prepare a nice meal. + +You may also notice that all those traces are executing in the same _service_: the `DinnerService`. This means that we only had one process involved in this trace. Further, by investigating this trace, we can spot that the `chopVegetables` parent span starts two child spans: `chop-carrot` and `chop-potato`, but does so **sequentially**! If we were looking to optimize the time it takes for `makeDinner` to complete, parallelizing these vegetable chopping tasks could be a good idea. + +Now, let us take a brief look at the code creating all these spans. + +> Tip: You can refer to the full code by viewing the `main.swift` file in the Dinner sample app. + +```swift +func makeDinner() async throws -> Meal { + try await InstrumentationSystem.tracer.withSpan("makeDinner") { _ in + async let veggies = try chopVegetables() + async let meat = marinateMeat() + async let oven = preheatOven(temperature: 350) + // ... + return try await cook(veggies, meat, oven) + } +} + +func chopVegetables() async throws -> [Vegetable] { + await Tracer.withSpan("chopVegetables") { + // Chop the vegetables...! + // + // However, since chopping is a very difficult operation, + // one chopping task can be performed at the same time on a single service! + // (Imagine that... we cannot parallelize these two tasks, and need to involve another service). + let carrot = try await chop(.carrot) + let potato = try await chop(.potato) + return [carrot, potato] + } +} + +// ... +``` + +It seems that the sequential work on the vegetable chopping is not accidental... we cannot do two of those at the same time on a single service. Therfore, let's introduce new services that will handle the vegetable chopping for us! + +For example, we could split out the vegetable chopping into a service on its own, and request it (via an HTTP, gRPC, or `distributed actor` call), to chop some vegetables for us. The resulting trace will have the same information, even though a part of it now has been executing on a different host! To further illustrate that, let us re-draw the previous diagram, while adding node designations to each span: + +A trace of such system would then look like this: + +![A new service handling "chopping" tasks is introduced, it has 3 spans about chopping](makeDinner-zipkin-02) + +The `DinnerService` reached out to `ChoppingService-1` that it discovered, and then to parallelize the work, it submitted the secondary chopping task to another service (`ChoppingService-2`). Those two tasks are now performed in parallel, leading to a an improved response time of `makeDinner` service call. + +Let us have another look at these spans in Jaeger. The search UI will show us both the previous, and latest execution traces, so we can compare how the execution changed over time: + +![Search view in Jaeger, showing the different versions of traces](makeDinner-jaeger-02) + +The different services are color coded, and we can see them execute in parallel here as well: + +![Trace view in Jaeger, spans are parallel now](makeDinner-jaeger-03) + +One additional view we can explore in Jaeger is a **flamegraph** based off the traces. Here we can compare the "before" and "after" flamegraphs: + +**Before:** + +![](makeDinner-jaeger-040-before) + +**After:** + +![](makeDinner-jaeger-041-after) + +By investigating flamegraphs, you are able to figure out the percentage of time spent and dominating certain functions. Our example was a fairly typical change, where we sped up the `chopVegetables` from taking 65% of the `makeDinner` execution, to just 43%. The flamegraph view can be useful in complex applications, in order to quickly locate which methods or services are taking the most time, and would be worth optimizing, as the span overview sometime can get pretty "busy" in a larger system, performing many calls. + +This was just a quick introduction to tracing, but hopefully you are now excited to learn more about tracing and using it to monitor and improve your server side Swift applications! In the following sections we'll discuss how to actually instrument your code, and how to make spans effective by including as much relevant information in them as possible. + +### Efficiently working with Spans + +We already saw the basic API to spawn a trace span, the ``TracerProtocol/withSpan(_:ofKind:_:)-28ctq`` method, but we didn't discuss it in depth yet. In this section we'll discuss how to efficiently work with spans and some common patterns and practices. + +Firstly, spans are created using a `withSpan` call and performing the operation contained within the span in the trailing operation closure body. This is important because it automatically, and correctly, delimits the lifetime of the span: from it's creation, until the operation closure returns: + +```swift +Tracer.withSpan("Working on my novel") { span in + write(.novel) +} +``` + +This API is available both in synchronous and asynchronous contexts. The closure also is passed a `span` object which is a mutable, but `Sendable ` object that tracer implementations must provide. A `Span` is an in memory representation of the trace span that can be enriched with various information about this execution. For example, if the span represents an HTTP request, one would typically add **span attributes** for `http.method`, `http.path` etc. + +Throwing out of the operation closure automatically records an error in the `span` + +#### Span Attributes + +Span ``Span/attributes`` are additional information you can record in a ``Span`` which are then associated with the span and accessible in tracing visualization systems. + +While you are free to record any information you want in attributes, it usually is best to to stick to "well known" and standardized values, in order to make querying for them _across_ services more consistent. We will discuss pre-defined attributes below. + +Recording extra attributes in a Span is simple. You can record any information you want into the ``Span/attributes`` object using the subscript syntax, like this: + +```swift +Tracer.withSpan("showAttributes") { span in + span.attributes["http.method"] = "POST" + span.attributes["http.status_code"] = 200 +} +``` + +Once the span is ``Span/end()``-ed the attributes are flushed along with it to the backend tracing system. + +However it may be beneficial to use type-safe span attributes instead, so both the String keys and values can be set in a more discoverable, as well as type-safe way. + +Attributes show up when you click on a specific `Span` in a trave visualization system. For example, like this in Jaeger: + +![Attributes show up under the Span in Jaeger](jaeger-attribute) + +Note that some attributes, like for example the information about the process emitting the trace are included in the span automatically. Refer to your tracer's documentation to learn more about how to configure what attributes it should include by default. Common things to include are hostnames, region information or other things which can identify the node in a cluster. + +#### Predefined Type-safe Span Attributes + +The tracing API provides a way to declare and re-use well known span attributes in a type-safe way. Many of those are defined in `swift-distributed-tracing-extras`, and allow e.g. for setting HTTP values like this: + +For example, you can include the `TracingOpenTelemetrySemanticConventions` into your project like this: + +```swift +import PackageDescription + +let package = Package( + // ... + dependencies: [ + .package(url: "https://github.com/apple/swift-distributed-tracing.git", from: "..."), + .package(url: "https://github.com/apple/swift-distributed-tracing-extras.git", from: "..."), + ], + targets: [ + .target( + name: "MyTarget", + dependencies: [ + .product(name: "Tracing", package: "swift-distributed-tracing"), + .product(name: "TracingOpenTelemetrySemanticConventions", package: "swift-distributed-tracing-extras"), + ] + ), + // ... + ] +) + +``` + +In order to gain a whole set of well-typed attributes which are pre-defined by the [OpenTelemetry](http://opentelemetry.io) initiatve. + +For example, like these for HTTP: + +```swift +attributes.http.method = "GET" +attributes.http.url = "https://www.swift.org/download" +attributes.http.target = "/download" +attributes.http.host = "www.swift.org" +attributes.http.scheme = "https" +attributes.http.statusCode = 418 +attributes.http.flavor = "1.1" +attributes.http.userAgent = "test" +attributes.http.retryCount = 42 +``` + +or these, for database operations–which can be very useful to detect slow queries in your system: + +```swift +attributes.db.system = "postgresql" +attributes.db.connectionString = "test" +attributes.db.user = "swift" +attributes.db.statement = "SELECT name, display_lang FROM Users WHERE id={};" +``` + +Using such standardized attributes allows you, and other developers of other services you interact with, have a consistent and simple to search by attribute namespace. + +#### Declaring your own type-safe Span Attributes + +You can define your own type-safe span attributes, which is useful if your team or company has a certain set of attributes you like to set in all services; This way it is easier to remember what attributes one should be setting, and what their types should be, because the attributes pop up in your favorite IDE's autocompletion. + +Doing so requires some boilerplate, but you only have to do this once, and later on the use-sites of those attributes look quite neat (as you've seen above). Here is how you would declare a custom `http.method` nested attribute: + +```swift +extension SpanAttributes { + /// Semantic conventions for HTTP spans. + /// + /// OpenTelemetry Spec: [Semantic conventions for HTTP spans](https://github.com/open-telemetry/opentelemetry-specification/blob/v1.11.0/specification/trace/semantic_conventions/http.md#semantic-conventions-for-http-spans) + public var http: HTTPAttributes { + get { + .init(attributes: self) + } + set { + self = newValue.attributes + } + } +} +``` + +```swift +/// Semantic conventions for HTTP spans. +/// +/// OpenTelemetry Spec: [Semantic conventions for HTTP spans](https://github.com/open-telemetry/opentelemetry-specification/blob/v1.11.0/specification/trace/semantic_conventions/http.md#semantic-conventions-for-http-spans) +@dynamicMemberLookup +public struct HTTPAttributes: SpanAttributeNamespace { + public var attributes: SpanAttributes + + public init(attributes: SpanAttributes) { + self.attributes = attributes + } + + public struct NestedSpanAttributes: NestedSpanAttributesProtocol { + public init() {} + + /// HTTP request method. E.g. "GET". + public var method: Key { "http.method" } + } +} +``` + +### Span Events + +Events are similar to logs in the sense that they signal "something happened" during the execution of the ``Span``. + +> Note: There is a general tension between logs and trace events, as they can be used to achieve very similar outcomes. Consult the documentation of your tracing solution and how you'll be reading and investigating logs correlated to traces, and vice versa, and stick to a pattern that works best for your project. + +Events are recorded into a span like this: + +```swift +Tracer.withSpan("showEvents") { span in + if cacheHit { + span.addEvent("cache-hit") + return cachedValue + } + + return computeValue() +} +``` + +An event is actually a value of the ``SpanEvent`` type, and carries along with it a ``SpanEvent/time`` as well as additional ``SpanEvent/attributes`` related to this specific event. In other words, if a ``Span`` represents an interval–something with a beginning and an end–a ``SpanEvent`` represents something that happened at a specific point-in-time during that span's execution. + +Events usually show up in a in a trace view as points on the timeline (note that some tracing systems are able to do exactly the same when a log statement includes a correlation trace and span ID in its metadata): + +**Jaeger:** + +![An event during the cook span](makeDinner-jaeger-event) + +**Zipkin:** + +![An event during the cook span](makeDinner-zipkin-event) + +Events cannot be "failed" or "successful", that is a property of a ``Span``, and they do not have anything that would be equivalent to a log level. When a trace span is recorded and collected, so will all events related to it. In that sense, events are different from log statements, because one can easily change a logger to include the "debug level" log statements, but technically no such concept exists for Events (although you could simmulate it with attributes). + +### Where (and how) do Baggage and Spans propagate? + + + +### Integrations + +#### Swift-log integration + +> Warning: This integration is currently proposed, but merged in swift-log. Please participate in the proposal review over here: [https://github.com/apple/swift-log/pull/235](https://github.com/apple/swift-log/pull/235) + +The swift-log integration diff --git a/Sources/Tracing/Docs.docc/Images/jaeger-attribute.png b/Sources/Tracing/Docs.docc/Images/jaeger-attribute.png new file mode 100644 index 0000000..48dac7a Binary files /dev/null and b/Sources/Tracing/Docs.docc/Images/jaeger-attribute.png differ diff --git a/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-01.png b/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-01.png new file mode 100644 index 0000000..b5eed13 Binary files /dev/null and b/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-01.png differ diff --git a/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-02.png b/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-02.png new file mode 100644 index 0000000..ae9d430 Binary files /dev/null and b/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-02.png differ diff --git a/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-03.png b/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-03.png new file mode 100644 index 0000000..b3ad7f5 Binary files /dev/null and b/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-03.png differ diff --git a/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-040-before.png b/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-040-before.png new file mode 100644 index 0000000..554c908 Binary files /dev/null and b/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-040-before.png differ diff --git a/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-041-after.png b/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-041-after.png new file mode 100644 index 0000000..005682e Binary files /dev/null and b/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-041-after.png differ diff --git a/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-event.png b/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-event.png new file mode 100644 index 0000000..e3f2920 Binary files /dev/null and b/Sources/Tracing/Docs.docc/Images/makeDinner-jaeger-event.png differ diff --git a/Sources/Tracing/Docs.docc/Images/makeDinner-zipkin-01.png b/Sources/Tracing/Docs.docc/Images/makeDinner-zipkin-01.png new file mode 100644 index 0000000..fbfaad0 Binary files /dev/null and b/Sources/Tracing/Docs.docc/Images/makeDinner-zipkin-01.png differ diff --git a/Sources/Tracing/Docs.docc/Images/makeDinner-zipkin-02.png b/Sources/Tracing/Docs.docc/Images/makeDinner-zipkin-02.png new file mode 100644 index 0000000..16ebb2f Binary files /dev/null and b/Sources/Tracing/Docs.docc/Images/makeDinner-zipkin-02.png differ diff --git a/Sources/Tracing/Docs.docc/Images/makeDinner-zipkin-event.png b/Sources/Tracing/Docs.docc/Images/makeDinner-zipkin-event.png new file mode 100644 index 0000000..f6e1d5e Binary files /dev/null and b/Sources/Tracing/Docs.docc/Images/makeDinner-zipkin-event.png differ diff --git a/Sources/Tracing/Docs.docc/InDepthGuide.md b/Sources/Tracing/Docs.docc/InDepthGuide.md deleted file mode 100644 index 052f9f2..0000000 --- a/Sources/Tracing/Docs.docc/InDepthGuide.md +++ /dev/null @@ -1,332 +0,0 @@ -# In-Depth Guide - -An in-depth guide on using the Distributed Tracing API. - -## Overview - -When instrumenting server applications there are typically three parties involved: - -1. **Application developers** create server-side applications -2. **Library/Framework developers** provide building blocks to create these applications -3. **Instrument developers** provide tools to collect distributed metadata about your application - -For applications to be instrumented correctly these three parts have to play along nicely. - -## Application Developers - -### Setting up instruments & tracers - -As an end-user building server applications you get to choose what instruments to use to instrument your system. Here are -all the steps you need to take to get up and running: - -Add a package dependency for this repository in your `Package.swift` file, and one for the specific instrument you want -to use, in this case `FancyInstrument`: - -```swift -.package(url: "https://github.com/apple/swift-distributed-tracing.git", .branch("main")), -.package(url: "", from: "<4.2.0>"), -``` - -To your main target, add a dependency on the `Instrumentation library` and the instrument you want to use: - -```swift -.target( - name: "MyApplication", - dependencies: [ - "FancyInstrument" - ] -), -``` - -### Bootstrapping the `InstrumentationSystem` - -Instead of providing each instrumented library with a specific instrument explicitly, you *bootstrap* the -`InstrumentationSystem` which acts as a singleton that libraries/frameworks access when calling out to the configured -`Instrument`: - -```swift -InstrumentationSystem.bootstrap(FancyInstrument()) -``` - -#### Recommended bootstrap order - -Swift offers developers a suite of observability libraries: logging, metrics and tracing. Each of those systems offers a `bootstrap` function. It is useful to stick to a recommended boot order in order to achieve predictable initialization of applications and sub-systems. - -Specifically, it is recommended to bootstrap systems in the following order: - -1. [Swift Log](https://github.com/apple/swift-log#default-logger-behavior)'s `LoggingSystem` -2. [Swift Metrics](https://github.com/apple/swift-metrics#selecting-a-metrics-backend-implementation-applications-only)' `MetricsSystem` -3. Swift Tracing's `InstrumentationSystem` -4. Finally, any other parts of your application - -This is because tracing systems may attempt to emit metrics about their status etc. - -#### Bootstrapping multiple instruments using MultiplexInstrument - -It is important to note that `InstrumentationSystem.bootstrap(_: Instrument)` must only be called once. In case you -want to bootstrap the system to use multiple instruments, you group them in a `MultiplexInstrument` first, which you -then pass along to the `bootstrap` method like this: - -```swift -InstrumentationSystem.bootstrap(MultiplexInstrument([FancyInstrument(), OtherFancyInstrument()])) -``` - -`MultiplexInstrument` will then call out to each instrument it has been initialized with. - -### Context propagation, by explicit `LoggingContext` passing - -> `LoggingContext` naming has been carefully selected and it reflects the type's purpose and utility: It binds a [Swift Log `Logger`](https://github.com/apple/swift-log) with an associated distributed tracing [Baggage](https://github.com/apple/swift-distributed-tracing-baggage). -> -> It _also_ is used for tracing, by tracers reaching in to read or modify the carried baggage. - -For instrumentation and tracing to work, certain pieces of metadata (usually in the form of identifiers), must be -carried throughout the entire system–including across process and service boundaries. Because of that, it's essential -for a context object to be passed around your application and the libraries/frameworks you depend on, but also carried -over asynchronous boundaries like an HTTP call to another service of your app. - -`LoggingContext` should always be passed around explicitly. - -Libraries which support tracing are expected to accept a `LoggingContext` parameter, which can be passed through the entire application. Make sure to always pass along the context that's previously handed to you. E.g., when making an HTTP request using `AsyncHTTPClient` in a `NIO` handler, you can use the `ChannelHandlerContext`s `baggage` property to access the `LoggingContext`. - -#### Context argument naming/positioning - -> 💡 This general style recommendation has been ironed out together with the Swift standard library, core team, the SSWG as well as members of the community. Please respect these recommendations when designing APIs such that all APIs are able to "feel the same" yielding a great user experience for our end users ❤️ -> -> It is possible that the ongoing Swift Concurrency efforts, and "Task Local" values will resolve this explicit context passing problem, however until these arrive in the language, please adopt the "context is the last parameter" style as outlined here. - -Propagating baggage context through your system is to be done explicitly, meaning as a parameter in function calls, following the "flow" of execution. - -When passing baggage context explicitly we strongly suggest sticking to the following style guideline: - -- Assuming the general parameter ordering of Swift function is as follows (except DSL exceptions): - 1. Required non-function parameters (e.g. `(url: String)`), - 2. Defaulted non-function parameters (e.g. `(mode: Mode = .default)`), - 3. Required function parameters, including required trailing closures (e.g. `(onNext elementHandler: (Value) -> ())`), - 4. Defaulted function parameters, including optional trailing closures (e.g. `(onComplete completionHandler: (Reason) -> ()) = { _ in }`). -- Logging Context should be passed as **the last parameter in the required non-function parameters group in a function declaration**. - -This way when reading the call side, users of these APIs can learn to "ignore" or "skim over" the context parameter and the method signature remains human-readable and “Swifty”. - -Examples: - -- `func request(_ url: URL,` **`context: LoggingContext`** `)`, which may be called as `httpClient.request(url, context: context)` -- `func handle(_ request: RequestObject,` **`context: LoggingContext`**`)` - - if a "framework context" exists and _carries_ the baggage context already, it is permitted to pass that context - together with the baggage; - - it is _strongly recommended_ to store the baggage context as `baggage` property of `FrameworkContext`, and conform `FrameworkContext` to `LoggingContext` in such cases, in order to avoid the confusing spelling of `context.context`, and favoring the self-explanatory `context.baggage` spelling when the baggage is contained in a framework context object. -- `func receiveMessage(_ message: Message, context: FrameworkContext)` -- `func handle(element: Element,` **`context: LoggingContext`** `, settings: Settings? = nil)` - - before any defaulted non-function parameters -- `func handle(element: Element,` **`context: LoggingContext`** `, settings: Settings? = nil, onComplete: () -> ())` - - before defaulted parameters, which themselfes are before required function parameters -- `func handle(element: Element,` **`context: LoggingContext`** `, onError: (Error) -> (), onComplete: (() -> ())? = nil)` - -In case there are _multiple_ "framework-ish" parameters, such as passing a NIO `EventLoop` or similar, we suggest: - -- `func perform(_ work: Work, for user: User,` _`frameworkThing: Thing, eventLoop: NIO.EventLoop,`_ **`context: LoggingContext`**`)` - - pass the baggage as **last** of such non-domain specific parameters as it will be _by far more_ omnipresent than any - specific framework parameter - as it is expected that any framework should be accepting a context if it can do so. - While not all libraries are necessarily going to be implemented using the same frameworks. - -We feel it is important to preserve Swift's human-readable nature of function definitions. In other words, we intend to -keep the read-out-loud phrasing of methods to remain _"request that URL (ignore reading out loud the context parameter)"_ -rather than _"request (ignore this context parameter when reading) that URL"_. - -#### When to use what context type? - -Generally libraries should favor accepting the general `LoggingContext` type, and **not** attempt to wrap it, as it will result in difficult to compose APIs between multiple libraries. Because end users are likely going to be combining various libraries in a single application, it is important that they can "just pass along" the same context object through all APIs, regardless which other library they are calling into. - -Frameworks may need to be more opinionated here, and e.g. already have some form of "per request context" contextual object which they will conform to `LoggingContext`. _Within_ such framework it is fine and expected to accept and pass the explicit `SomeFrameworkContext`, however when designing APIs which may be called _by_ other libraries, such framework should be able to accept a generic `LoggingContext` rather than its own specific type. - -#### Existing context argument - -When adapting an existing library/framework to support `LoggingContext` and it already has a "framework context" which is expected to be passed through "everywhere", we suggest to follow these guidelines for adopting LoggingContext: - -1. Add a `Baggage` as a property called `baggage` to your own `context` type, so that the call side for your - users becomes `context.baggage` (rather than the confusing `context.context`) -2. If you cannot or it would not make sense to carry baggage inside your framework's context object, pass (and accept (!)) the `LoggingContext` in your framework functions like follows: -- if they take no framework context, accept a `context: LoggingContext` which is the same guideline as for all other cases -- if they already _must_ take a context object and you are out of words (or your API already accepts your framework context as "context"), pass the baggage as **last** parameter (see above) yet call the parameter `baggage` to disambiguate your `context` object from the `baggage` context object. - -Examples: - -- `Lambda.Context` may contain `baggage` and a `logger` and should be able to conform to `LoggingContext` - - passing context to a `Lambda.Context` unaware library becomes: `http.request(url: "...", context: context)`. -- `ChannelHandlerContext` offers a way to set/get baggage on the underlying channel via `context.baggage = ...` - - this context is not passed outside a handler, but within it may be passed as is, and the baggage may be accessed on it directly through it. - - Example: [https://github.com/apple/swift-nio/pull/1574](https://github.com/apple/swift-nio/pull/1574) - -### Creating context objects (and when not to do so) - -Generally application developers _should not_ create new context objects, but rather keep passing on a context value that they were given by e.g. the web framework invoking the their code. - -If really necessary, or for the purposes of testing, one can create a baggage or context using one of the two factory functions: - -- [`DefaultLoggingContext.topLevel(logger:)`](https://github.com/apple/swift-distributed-tracing-baggage/blob/main/Sources/Baggage/LoggingContext.swift) or [`Baggage.topLevel`](https://github.com/apple/swift-distributed-tracing-baggage-core/blob/main/Sources/CoreBaggage/Baggage.swift) - which creates an empty context/baggage, without any values. It should _not_ be used too frequently, and as the name implies in applications it only should be used on the "top level" of the application, or at the beginning of a contextless (e.g. timer triggered) event processing. -- [`DefaultLoggingContext.TODO(logger:reason:)`](https://github.com/apple/swift-distributed-tracing-baggage/blob/main/Sources/Baggage/LoggingContext.swift) or [`Baggage.TODO`](https://github.com/apple/swift-distributed-tracing-baggage-core/blob/main/Sources/CoreBaggage/Baggage.swift) - which should be used to mark a parameter where "before this code goes into production, a real context should be passed instead." An application can be run with `-DBAGGAGE_CRASH_TODOS` to cause the application to crash whenever a TODO context is still in use somewhere, making it easy to diagnose and avoid breaking context propagation by accidentally leaving in a `TODO` context in production. - -Please refer to the respective functions documentation for details. - -If using a framework which itself has a "`...Context`" object you may want to inspect it for similar factory functions, as `LoggingContext` is a protocol, that may be conformed to by frameworks to provide a smoother user experience. - -### Working with `Span`s - -The primary purpose of this API is to start and end so-called ``Span`` types. - -Spans form hierarchies with their parent spans, and end up being visualized using various tools, usually in a format similar to gant charts. So for example, if we had multiple operations that compose making dinner, they would be modelled as child spans of a main `makeDinner` span. Any sub tasks are again modelled as child spans of any given operation, and so on, resulting in a trace view similar to: - -``` ->-o-o-o----- makeDinner ----------------o---------------x [15s] - \-|-|- chopVegetables--------x | [2s] - | | \- chop -x | | [1s] - | | \--- chop -x | [1s] - \-|- marinateMeat -----------x | [3s] - \- preheatOven -----------------x | [10s] - \--cook---------x [5s] -``` - -The above trace is achieved by starting and ending spans in all the mentioned functions, for example, like this: - -```swift -let tracer: Tracer - -func makeDinner(context: LoggingContext) async throws -> Meal { - tracer.withSpan(operationName: "makeDinner", context) { - let veggiesFuture = try chopVegetables(context: span.context) - let meatFuture = marinateMeat(context: span.context) - let ovenFuture = try preheatOven(temperature: 350, context: span.context) - ... - return cook(veggies, meat, oven) - } -} -``` - -> ❗️ It is tremendously important to **always `end()` a started ``Span``**! make sure to end any started span on _every_ code path, including error paths -> -> Failing to do so is an error, and a tracer *may* decide to either crash the application or log warnings when an not-ended span is deinitialized. - - -## Library/Framework developers: Instrumenting your software - -### Extracting & injecting Baggage - -When hitting boundaries like an outgoing HTTP request you call out to the configured instrument(s) (see ): - -An HTTP client e.g. should inject the given `LoggingContext` into the HTTP headers of its outbound request: - -```swift -func get(url: String, context: LoggingContext) { - var request = HTTPRequest(url: url) - InstrumentationSystem.instrument.inject( - context.baggage, - into: &request.headers, - using: HTTPHeadersInjector() - ) -} -``` - -On the receiving side, an HTTP server should use the following `Instrument` API to extract the HTTP headers of the given -`HTTPRequest` into: - -```swift -func handler(request: HTTPRequest, context: LoggingContext) { - InstrumentationSystem.instrument.extract( - request.headers, - into: &context.baggage, - using: HTTPHeadersExtractor() - ) - // ... -} -``` - -> In case your library makes use of the `NIOHTTP1.HTTPHeaders` type we already have an `HTTPHeadersInjector` & -`HTTPHeadersExtractor` available as part of the `NIOInstrumentation` library. - -For your library/framework to be able to carry `LoggingContext` across asynchronous boundaries, it's crucial that you carry the context throughout your entire call chain in order to avoid dropping metadata. - -### Tracing your library - -When your library/framework can benefit from tracing, you should make use of it by integrating the `Tracing` library. - -In order to work with the tracer configured by the end-user (see ), it adds a property to `InstrumentationSystem` that gives you back a ``Tracer``. You can then use that tracer to start ``Span``s. In an HTTP client you e.g. -should start a ``Span`` when sending the outgoing HTTP request: - -```swift -func get(url: String, context: LoggingContext) { - var request = HTTPRequest(url: url) - - // inject the request headers into the baggage as explained above - - // start a span for the outgoing request - let tracer = InstrumentationSystem.tracer - var span = tracer.startSpan(named: "HTTP GET", context: context, ofKind: .client) - - // set attributes on the span - span.attributes.http.method = "GET" - // ... - - self.execute(request).always { _ in - // set some more attributes & potentially record an error - - // end the span - span.end() - } -} -``` - -> ⚠️ Make sure to ALWAYS end spans. Ensure that all paths taken by the code will result in ending the span. -> Make sure that error cases also set the error attribute and end the span. - -> In the above example we used the semantic `http.method` attribute that gets exposed via the -`TracingOpenTelemetrySupport` library. - -## Instrument developers: Creating an instrument - -Creating an instrument means adopting the `Instrument` protocol (or ``Tracer`` in case you develop a tracer). -`Instrument` is part of the `Instrumentation` library & `Tracing` contains the ``Tracer`` protocol. - -`Instrument` has two requirements: - -1. A method to inject values inside a `LoggingContext` into a generic carrier (e.g. HTTP headers) -2. A method to extract values from a generic carrier (e.g. HTTP headers) and store them in a `LoggingContext` - -The two methods will be called by instrumented libraries/frameworks at asynchronous boundaries, giving you a chance to -act on the provided information or to add additional information to be carried across these boundaries. - -> Check out the [`Baggage` documentation](https://github.com/apple/swift-distributed-tracing-baggage) for more information on -how to retrieve values from the `LoggingContext` and how to set values on it. - -### Creating a `Tracer` - -When creating a tracer you need to create two types: - -1. Your tracer conforming to ``Tracer`` -2. A span class conforming to ``Span`` - -> ``Span`` conforms to the standard rules defined in [OpenTelemetry](https://github.com/open-telemetry/opentelemetry-specification/blob/v0.7.0/specification/trace/api.md#span), so if unsure about usage patterns, you can refer to this specification and examples referring to it. - -### Defining, injecting and extracting Baggage - -```swift -import Tracing - -private enum TraceIDKey: BaggageKey { - typealias Value = String -} - -extension Baggage { - var traceID: String? { - get { - return self[TraceIDKey.self] - } - set { - self[TraceIDKey.self] = newValue - } - } -} - -var context = DefaultLoggingContext.topLevel(logger: ...) -context.baggage.traceID = "4bf92f3577b34da6a3ce929d0e0e4736" -print(context.baggage.traceID ?? "new trace id") -``` - diff --git a/Sources/Tracing/Docs.docc/TracerProtocol.md b/Sources/Tracing/Docs.docc/TracerProtocol.md new file mode 100644 index 0000000..2b36f53 --- /dev/null +++ b/Sources/Tracing/Docs.docc/TracerProtocol.md @@ -0,0 +1,13 @@ +# ``Tracing/TracerProtocol`` + +## Topics + +### Working with Spans + +- ``withSpan(_:ofKind:_:)-11n3y`` +- ``withSpan(_:baggage:ofKind:_:)-1w7i6`` + +### Manual Span management + +- ``startSpan(_:baggage:ofKind:)`` +- ``Span/end()`` diff --git a/Sources/Tracing/Docs.docc/index.md b/Sources/Tracing/Docs.docc/index.md index f541c06..b7a8a06 100644 --- a/Sources/Tracing/Docs.docc/index.md +++ b/Sources/Tracing/Docs.docc/index.md @@ -8,197 +8,22 @@ This is a collection of Swift libraries enabling the instrumentation of server s While Swift Distributed Tracing allows building all kinds of _instruments_, which can co-exist in applications transparently, its primary use is instrumenting multi-threaded and distributed systems with Distributed Traces. +### Quickstart Guides ---- +We provide a number of guides aimed at getting your started with tracing your systems and have prepared them from three "angles": -This project uses the context progagation type defined independently in: +1. **Application developers** who create server-side applications + * please refer to the guide. +2. **Library/Framework developers** who provide building blocks to create these applications + * please refer to the guide. +3. **Instrument developers** who provide tools to collect distributed metadata about your application + * please refer to the guide. -- 🧳 [swift-distributed-tracing-baggage](https://github.com/apple/swift-distributed-tracing-baggage) -- [`Baggage`](https://apple.github.io/swift-distributed-tracing-baggage/docs/current/InstrumentationBaggage/Structs/Baggage.html) (zero dependencies) - -## Compatibility - -This project is designed in a very open and extensible manner, such that various instrumentation and tracing systems can be built on top of it. - -The purpose of the tracing package is to serve as common API for all tracer and instrumentation implementations. Thanks to this, libraries may only need to be instrumented once, and then be used with any tracer which conforms to this API. - -### Tracing Backends - -Compatible `Tracer` implementations: - -| Library | Status | Description | -| ------- | ------ | ----------- | -| [@slashmo](https://github.com/slashmo) / [**OpenTelemetry** Swift](https://github.com/slashmo/opentelemetry-swift) | Complete | Exports spans to OpenTelemetry Collector; **X-Ray** & **Jaeger** propagation available via extensions. | -| [@pokrywka](https://github.com/pokryfka) / [AWS **xRay** SDK Swift](https://github.com/pokryfka/aws-xray-sdk-swift) | Complete (?) | ... | - -## Getting Started - -In this short getting started example, we'll go through bootstrapping, immediately benefiting from tracing, and instrumenting our own synchronous and asynchronous APIs. The explain all the pieces of the API in more depth. When in doubt, you may want to refer to the [OpenTelemetry](https://opentelemetry.io), [Zipkin](https://zipkin.io), or [Jaeger](https://www.jaegertracing.io) documentations because all the concepts for different tracers are quite similar. - -### Dependencies & Tracer backend - -In order to use tracing you will need to bootstrap a tracing backend (). - -When developing an *application* locate the specific tracer library you would like to use and add it as an dependency directly: - -```swift -.package(url: "", // the specific tracer - ] -), -``` - -Then (in an application, libraries should _never_ invoke `bootstrap`), you will want to bootstrap the specific tracer you want to use in your application. A ``Tracer`` is a type of `Instrument` and can be offered used to globally bootstrap the tracing system, like this: - - -```swift -import Tracing // the tracing API -import AwesomeTracing // the specific tracer - -InstrumentationSystem.bootstrap(AwesomeTracing()) -``` - -If you don't bootstrap (or other instrument) the default no-op tracer is used, which will result in no trace data being collected. - -### Benefiting from instrumented libraries/frameworks - -**Automatically reported spans**: When using an already instrumented library, e.g. an HTTP Server which automatically emits spans internally, this is all you have to do to enable tracing. It should now automatically record and emit spans using your configured backend. - -**Using baggage and logging context**: The primary transport type for tracing metadata is called `Baggage`, and the primary type used to pass around baggage context and loggers is `LoggingContext`. Logging context combines baggage context values with a smart `Logger` that automatically includes any baggage values ("trace metadata") when it is used for logging. For example, when using an instrumented HTTP server, the API could look like this: - -```swift -SomeHTTPLibrary.handle { (request, context) in - context.logger.info("Wow, tracing!") // automatically includes tracing metadata such as "trace-id" - return try doSomething(request context: context) -} -``` - -In this snippet, we use the context logger to log a very useful message. However it is even more useful than it seems at first sight: if a tracer was installed and extracted tracing information from the incoming request, it would automatically log our message _with_ the trace information, allowing us to co-relate all log statements made during handling of this specific request: - -``` -05:46:38 example-trace-id=1111-23-1234556 info: Wow tracing! -05:46:38 example-trace-id=9999-22-9879797 info: Wow tracing! -05:46:38 example-trace-id=9999-22-9879797 user=Alice info: doSomething() for user Alice -05:46:38 example-trace-id=1111-23-1234556 user=Charlie info: doSomething() for user Charlie -05:46:38 example-trace-id=1111-23-1234556 user=Charlie error: doSomething() could not complete request! -05:46:38 example-trace-id=9999-22-9879797 user=alice info: doSomething() completed -``` - -Thanks to tracing, and trace identifiers, even if not using tracing visualization libraries, we can immediately co-relate log statements and know that the request `1111-23-1234556` has failed. Since our application can also _add_ values to the context, we can quickly notice that the error seems to occur for the user `Charlie` and not for user `Alice`. Perhaps the user Charlie has exceeded some quotas, does not have permissions or we have a bug in parsing names that include the letter `h`? We don't know _yet_, but thanks to tracing we can much quicker begin our investigation. - -**Passing context to client libraries**: When using client libraries that support distributed tracing, they will accept a `Baggage.LoggingContext` type as their _last_ parameter in many calls. - -When using client libraries that support distributed tracing, they will accept a `Baggage.LoggingContext` type as their _last_ parameter in many calls. Please refer to the section of the to learn more about how to properly pass context values around. - -### Instrumenting your code - -Adding a span to synchronous functions can be achieved like this: - -```swift -func handleRequest(_ op: String, context: LoggingContext) -> String { - let tracer = InstrumentationSystem.tracer - let span = tracer.startSpan(operationName: "handleRequest(\(name))", context: context) - defer { span.end() } - - return "done:\(op)" -} -``` - -Throwing can be handled by either recording errors manually into a span by calling ``Span/recordError(_:)``, or by wrapping a potentially throwing operation using the `withSpan(operation:context:body:)` function, which automatically records any thrown error and ends the span at the end of the body closure scope: - -```swift -func handleRequest(_ op: String, context: LoggingContext) -> String { - return try InstrumentationSystem.tracer - .withSpan(operationName: "handleRequest(\(name))", context: context) { - return try dangerousOperation() - } -} -``` - -If this function were asynchronous, and returning a [Swift NIO](https://github.com/apple/swift-nio) `EventLoopFuture`, -we need to end the span when the future completes. We can do so in its `onComplete`: - -```swift -func handleRequest(_ op: String, context: LoggingContext) -> EventLoopFuture { - let tracer = InstrumentationSystem.tracer - let span = tracer.startSpan(operationName: "handleRequest(\(name))", context: context) - - let future: EventLoopFuture = someOperation(op) - future.whenComplete { _ in - span.end() // oh no, ignored errors! - } - - return future -} -``` - -This is better, however we ignored the possibility that the future perhaps has failed. If this happens, we would like to report the span as _errored_ because then it will show up as such in tracing backends and we can then easily search for failed operations etc. - -To do this within the future we could manually invoke the ``Span/recordError(_:)`` API before ending the span like this: - -```swift -func handleRequest(_ op: String, context: LoggingContext) -> EventLoopFuture { - let tracer = InstrumentationSystem.tracer - let span = tracer.startSpan(operationName: "handleRequest(\(name))", context: context) - - let future: EventLoopFuture = someOperation(op) - future.whenComplete { result in - switch result { - case .failure(let error): span.recordError(error) - case .success(let value): // ... record additional *attributes* into the span - } - span.end() - } - - return future -} -``` - -While this is verbose, this is only the low-level building blocks that this library provides, higher level helper utilities can be - -> Eventually convenience wrappers will be provided, automatically wrapping future types etc. We welcome such contributions, but likely they should live in `swift-distributed-tracing-extras`. - -Once a system, or multiple systems have been instrumented, a ``Tracer`` has been selected and your application runs and emits some trace information, you will be able to inspect how your application is behaving by looking at one of the various trace UIs, such as e.g. Zipkin: - -![Simple example trace in Zipkin Web UI](zipkin_trace.png) - -### More examples - -It sometimes is easier to grasp the usage of tracing by looking at a "real" application - which is why we have implemented an example application, spanning multiple nodes and using various databases - tracing through all of them. You can view the example application here: [slashmo/swift-tracing-examples](https://github.com/slashmo/swift-tracing-examples/tree/main/hotrod). - -### Future work: Tracing asynchronous functions - -> ⚠️ This section refers to in-development upcoming Swift Concurrency features and can be tried out using nightly snapshots of the Swift toolchain. - -With Swift's ongoing work towards asynchronous functions, actors, and tasks, tracing in Swift will become more pleasant than it is today. - -Firstly, a lot of the callback heavy code will be folded into normal control flow, which is easy and correct to integrate with tracing like this: - -```swift -func perform(context: LoggingContext) async -> String { - let span = InstrumentationSystem.tracer.startSpan(operationName: #function, context: context) - defer { span.end() } - - return await someWork() -} -``` ## Topics -### Articles +### Guides -- +- +- +- diff --git a/Sources/Tracing/InstrumentationSystem+Tracing.swift b/Sources/Tracing/InstrumentationSystem+Tracing.swift index 1be4949..5866f0c 100644 --- a/Sources/Tracing/InstrumentationSystem+Tracing.swift +++ b/Sources/Tracing/InstrumentationSystem+Tracing.swift @@ -21,7 +21,7 @@ extension InstrumentationSystem { /// tracing instrument as passed to the multiplex instrument. If none is found, a ``NoOpTracer`` is returned. /// /// - Returns: A ``Tracer`` if the system was bootstrapped with one, and ``NoOpTracer`` otherwise. - public static var tracer: Tracer { - (self._findInstrument(where: { $0 is Tracer }) as? Tracer) ?? NoOpTracer() + public static var tracer: TracerProtocol { + (self._findInstrument(where: { $0 is TracerProtocol }) as? TracerProtocol) ?? NoOpTracer() } } diff --git a/Sources/Tracing/NoOpTracer.swift b/Sources/Tracing/NoOpTracer.swift index 97bfc35..0e7deac 100644 --- a/Sources/Tracing/NoOpTracer.swift +++ b/Sources/Tracing/NoOpTracer.swift @@ -17,7 +17,7 @@ import Dispatch @_exported import InstrumentationBaggage /// No operation ``Tracer``, used when no tracing is required. -public struct NoOpTracer: Tracer { +public struct NoOpTracer: TracerProtocol { public init() {} public func startSpan( diff --git a/Sources/Tracing/Span.swift b/Sources/Tracing/Span.swift index 5316b22..85a9e65 100644 --- a/Sources/Tracing/Span.swift +++ b/Sources/Tracing/Span.swift @@ -16,10 +16,31 @@ import Dispatch @_exported import InstrumentationBaggage /// A `Span` represents an interval from the start of an operation to its end, along with additional metadata included -/// with it. A `Span` can be created from a `Baggage` or `LoggingContext` which MAY contain existing span identifiers, -/// in which case this span should be considered as "child" of the previous span. +/// with it. A `Span` can be created from a `Baggage` which contains span information, in which case this span should +/// be considered as "child" of the previous span. /// -/// Creating a `Span` is delegated to a ``Tracer`` and end users should never create them directly. +/// Creating a `Span` is delegated to an implementation of ``TracerProtocol`` and end-users should never instantiate spans directly. +/// Most commonly, a span is started using the `withSpan` API of a tracer, like this: +/// +/// ``` +/// tracer.withSpan("working-on-\(thing)") { span in +/// // ... +/// } +/// ``` +/// +/// Once started, a span contains its start time and additional metadata necessary for the tracing backend to handle e.g. +/// further child spans. +/// +/// ### Child Spans +/// +/// +/// ## Manual lifetime management +/// In some situations it may not be possible +/// +/// > Warning: Generally spans should be started using the ``TracerProtocol/withSpan(_:ofKind:_:)-11n3y`` method, +/// > however it may sometimes be necessary to use the alternate ``TracerProtocol/startSpan(_:baggage:ofKind:)`` API. +/// > If the `startSpan` API is used to create a span, it must be explicitly ended using ``end()`` on *every* code-path +/// > leading to the logical end of the span. Omitting to end a span or ending it twice is a programmer error. /// /// - SeeAlso: For more details refer to the [OpenTelemetry Specification: Span](https://github.com/open-telemetry/opentelemetry-specification/blob/v0.7.0/specification/trace/api.md#span) which this type is compatible with. public protocol Span: AnyObject { @@ -77,8 +98,6 @@ extension Span { /// Implementations SHOULD prevent double-emitting by marking a span as ended internally, however it still is a /// programming mistake to rely on this behavior. /// - /// - Parameter time: The `DispatchWallTime` at which the span ended. - /// /// - SeeAlso: ``end(at:)`` which allows passing in a specific time, e.g. if the operation was ended and recorded somewhere and we need to post-factum record it. /// Generally though prefer using the ``end()`` version of this API in user code and structure your system such that it can be called in the right place and time. public func end() { @@ -86,6 +105,7 @@ extension Span { } /// Adds a ``SpanLink`` between this `Span` and the given `Span`. + /// /// - Parameter other: The `Span` to link to. /// - Parameter attributes: The ``SpanAttributes`` describing this link. Defaults to no attributes. public func addLink(_ other: Span, attributes: SpanAttributes = [:]) { diff --git a/Sources/Tracing/Tracer.swift b/Sources/Tracing/Tracer.swift index f0b3cb4..9931a48 100644 --- a/Sources/Tracing/Tracer.swift +++ b/Sources/Tracing/Tracer.swift @@ -16,9 +16,19 @@ import Dispatch @_exported import Instrumentation @_exported import InstrumentationBaggage -/// An `Instrument` with added functionality for distributed tracing. It uses the span-based tracing model and is -/// based on the OpenTracing/OpenTelemetry spec. -public protocol Tracer: Instrument { +/// Convenience entry point to operations on the tracer configured +/// on the global ``InstrumentationSystem`` using the `InstrumentationSystem/bootstrap(_:)` method. +/// +/// If no tracer was bootstrapped, these operations will default to a no-op tracer (creating no spans). +/// +/// For implementing a new tracer, see ``TracerProtocol``. +enum Tracer: TracerStartSpanOps { + func startSpan(_ operationName: String, baggage: Baggage, ofKind kind: SpanKind, at time: DispatchWallTime) -> Span { + InstrumentationSystem.tracer.startSpan(operationName, baggage: baggage, ofKind: kind, at: time) + } +} + +public protocol TracerStartSpanOps { /// Start a new ``Span`` with the given `Baggage` at a given time. /// /// - Note: Prefer to use `withSpan` to start a span as it automatically takes care of ending the span, @@ -42,14 +52,6 @@ public protocol Tracer: Instrument { file fileID: String, line: UInt ) -> Span - - /// Export all ended spans to the configured backend that have not yet been exported. - /// - /// This function should only be called in cases where it is absolutely necessary, - /// such as when using some FaaS providers that may suspend the process after an invocation, but before the backend exports the completed spans. - /// - /// This function should not block indefinitely, implementations should offer a configurable timeout for flush operations. - func forceFlush() } extension Tracer { @@ -115,7 +117,7 @@ extension Tracer { // ==== ---------------------------------------------------------------------------------------------------------------- // MARK: Starting spans: `withSpan` -extension Tracer { +extension TracerStartSpanOps { #if swift(>=5.3.0) /// Execute a specific task within a newly created ``Span``. /// @@ -206,7 +208,7 @@ extension Tracer { #if swift(>=5.5) && canImport(_Concurrency) @available(macOS 10.15, iOS 13.0, tvOS 13.0, watchOS 6.0, *) -extension Tracer { +extension TracerStartSpanOps { /// Execute the given operation within a newly created ``Span``, /// started as a child of the currently stored task local `Baggage.current` or as a root span if `nil`. /// @@ -243,6 +245,32 @@ extension Tracer { } } + /// Execute the given operation within a newly created ``Span``, + /// started as a child of the currently stored task local `Baggage.current` or as a root span if `nil`. + /// + /// DO NOT `end()` the passed in span manually. It will be ended automatically when the `operation` returns. + /// + /// - Parameters: + /// - operationName: The name of the operation being traced. This may be a handler function, database call, ... + /// - kind: The ``SpanKind`` of the ``Span`` to be created. Defaults to ``SpanKind/internal``. + /// - operation: operation to wrap in a span start/end and execute immediately + /// - Returns: the value returned by `operation` + /// - Throws: the error the `operation` has thrown (if any) + public func withSpan( + _ operationName: String, + ofKind kind: SpanKind = .internal, + _ operation: () throws -> T + ) rethrows -> T { + try self.withSpan(operationName, baggage: .current ?? .topLevel, ofKind: kind) { span in + try Baggage.$current.withValue(span.baggage) { + try operation() + } + } + } +} + +@available(macOS 10.15, iOS 13.0, tvOS 13.0, watchOS 6.0, *) +extension TracerStartSpanOps { /// Execute the given async operation within a newly created ``Span``, /// started as a child of the currently stored task local `Baggage.current` or as a root span if `nil`. /// @@ -322,3 +350,18 @@ extension Tracer { } } #endif + +// ==== ---------------------------------------------------------------------------------------------------------------- +// MARK: TracerProtocol + +/// An `Instrument` with added functionality for distributed tracing. It uses the span-based tracing model and is +/// based on the OpenTracing/OpenTelemetry spec. +public protocol TracerProtocol: TracerStartSpanOps, InstrumentProtocol { + /// Export all ended spans to the configured backend that have not yet been exported. + /// + /// This function should only be called in cases where it is absolutely necessary, + /// such as when using some FaaS providers that may suspend the process after an invocation, but before the backend exports the completed spans. + /// + /// This function should not block indefinitely, implementations should offer a configurable timeout for flush operations. + func forceFlush() +} \ No newline at end of file diff --git a/Tests/InstrumentationTests/BaggageLoggingTest+XCTest.swift b/Tests/InstrumentationTests/BaggageLoggingTest+XCTest.swift new file mode 100644 index 0000000..a747c00 --- /dev/null +++ b/Tests/InstrumentationTests/BaggageLoggingTest+XCTest.swift @@ -0,0 +1,37 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift Distributed Tracing open source project +// +// Copyright (c) 2020-2021 Apple Inc. and the Swift Distributed Tracing project +// authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// +// +// BaggageLoggingTest+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 BaggageLoggingTest { + + @available(*, deprecated, message: "not actually deprecated. Just deprecated to allow deprecated tests (which test deprecated functionality) without warnings") + static var allTests : [(String, (BaggageLoggingTest) -> () throws -> Void)] { + return [ + ("testLoggingCallsMetadataProviderWithTaskLocalBaggage", testLoggingCallsMetadataProviderWithTaskLocalBaggage), + ("testLoggingMergesOneOffMetadataWithProvidedMetadataFromTaskLocalBaggage", testLoggingMergesOneOffMetadataWithProvidedMetadataFromTaskLocalBaggage), + ("testLoggingMergesOneOffMetadataWithProvidedMetadataFromExplicitlyPassedBaggage", testLoggingMergesOneOffMetadataWithProvidedMetadataFromExplicitlyPassedBaggage), + ("testLoggingIncludesExplicitBaggageOverTaskLocal", testLoggingIncludesExplicitBaggageOverTaskLocal), + ("testLogHandlerThatDidNotImplementProvidersButSomeoneAttemptsToSetOneOnIt", testLogHandlerThatDidNotImplementProvidersButSomeoneAttemptsToSetOneOnIt), + ] + } +} + diff --git a/Tests/InstrumentationTests/BaggageLoggingTest.swift b/Tests/InstrumentationTests/BaggageLoggingTest.swift new file mode 100644 index 0000000..f01100a --- /dev/null +++ b/Tests/InstrumentationTests/BaggageLoggingTest.swift @@ -0,0 +1,228 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the Swift Distributed Tracing open source project +// +// Copyright (c) 2020-2021 Apple Inc. and the Swift Distributed Tracing project +// authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +@testable import Instrumentation +import InstrumentationBaggage +import Tracing +@testable import Logging +import XCTest + +final class BaggageLoggingTest: XCTestCase { + @available(macOS 10.15, iOS 13, tvOS 13, watchOS 6, *) + func testLoggingCallsMetadataProviderWithTaskLocalBaggage() throws { + #if swift(>=5.5) && canImport(_Concurrency) + let logging = TestLogging() + LoggingSystem.bootstrapInternal(logging.makeWithMetadataProvider) + + var logger = Logger(label: #function, metadataProvider: .init { + guard let baggage = Baggage.current, let testID = baggage[TestIDKey.self] else { + XCTFail("Expected Baggage to be passed along to the metadata provider.") + return [:] + } + return ["provider": .string(testID)] + }) + logger.logLevel = .trace + + var baggage = Baggage.topLevel + baggage[TestIDKey.self] = "42" + + Baggage.$current.withValue(baggage) { + logger.trace("test") + logger.debug("test") + logger.info("test") + logger.notice("test") + logger.warning("test") + logger.error("test") + logger.critical("test") + } + + logging.history.assertExist(level: .trace, message: "test", metadata: ["provider": "42"]) + logging.history.assertExist(level: .debug, message: "test", metadata: ["provider": "42"]) + logging.history.assertExist(level: .info, message: "test", metadata: ["provider": "42"]) + logging.history.assertExist(level: .notice, message: "test", metadata: ["provider": "42"]) + logging.history.assertExist(level: .warning, message: "test", metadata: ["provider": "42"]) + logging.history.assertExist(level: .error, message: "test", metadata: ["provider": "42"]) + logging.history.assertExist(level: .critical, message: "test", metadata: ["provider": "42"]) + + enum TestIDKey: BaggageKey { + typealias Value = String + } + #endif + } + + @available(macOS 10.15, iOS 13, tvOS 13, watchOS 6, *) + func testLoggingMergesOneOffMetadataWithProvidedMetadataFromTaskLocalBaggage() throws { + #if swift(>=5.5) && canImport(_Concurrency) + let logging = TestLogging() + LoggingSystem.bootstrapInternal(logging.makeWithMetadataProvider) + + let logger = Logger(label: #function, metadataProvider: .init { + [ + "common": "provider", + "provider": "42", + ] + }) + + Baggage.$current.withValue(.topLevel) { + 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"]) + #endif + } + + func testLoggingMergesOneOffMetadataWithProvidedMetadataFromExplicitlyPassedBaggage() throws { + let logging = TestLogging() + LoggingSystem.bootstrapInternal(logging.makeWithMetadataProvider) + + 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"]) + } + + @available(macOS 10.15, iOS 13, tvOS 13, watchOS 6, *) + func testLoggingIncludesExplicitBaggageOverTaskLocal() { + #if swift(>=5.5) && canImport(_Concurrency) + let logging = TestLogging() + LoggingSystem.bootstrapInternal(logging.makeWithMetadataProvider) + + var logger = Logger(label: #function, metadataProvider: .init { + guard let baggage = Baggage.current else { + return [:] + } + var metadata: Logger.Metadata = [:] + + if let testID = baggage[TestIDKey.self] { + metadata["overriden-contextual"] = .string(testID) + } + if let onlyLocal = baggage[OnlyLocalIDKey.self] { + metadata["only-local"] = .string(onlyLocal) + } + if let onlyExplicitlyProvidedToHandler = baggage[OnlyExplicitlyProvidedIDKey.self] { + metadata["only-explicitly"] = .string(onlyExplicitlyProvidedToHandler) + } + return metadata + }) + logger.logLevel = .trace + + var taskLocalBaggage = Baggage.topLevel + taskLocalBaggage[TestIDKey.self] = "task-local" + taskLocalBaggage[OnlyLocalIDKey.self] = "task-local" + + var explicitBaggage = Baggage.topLevel + explicitBaggage[TestIDKey.self] = "explicit" + explicitBaggage[OnlyExplicitlyProvidedIDKey.self] = "provided-to-handler" + + Baggage.$current.withValue(taskLocalBaggage) { + logger.provideMetadata(from: explicitBaggage) + logger.trace("test", metadata: ["one-off": "42"]) + logger.debug("test", metadata: ["one-off": "42"]) + logger.info("test", metadata: ["one-off": "42"]) + logger.notice("test", metadata: ["one-off": "42"]) + logger.warning("test", metadata: ["one-off": "42"]) + logger.error("test", metadata: ["one-off": "42"]) + logger.critical("test", metadata: ["one-off": "42"]) + } + + // ["one-off": 42, "only-local": task-local, "only-explicitly": provided-to-handler, "overriden-contextual": task-local] + let expectedMetadata: Logger.Metadata = [ + // explicitly set on handler by `logger.provideMetadata`: + "only-explicitly": "provided-to-handler", + // passed in-line by end user at log statement level: + "one-off": "42", + // concetual metadata, if present, still wins over the provided to handler, + // which allows for "default value if no contextual is present" (which the "only-explicit" is an example of): + "overriden-contextual": "task-local", + // task-local is picked up as usual if no conflicts: + "only-local": "task-local", + ] + + logging.history.assertExist(level: .trace, message: "test", metadata: expectedMetadata) + logging.history.assertExist(level: .debug, message: "test", metadata: expectedMetadata) + logging.history.assertExist(level: .info, message: "test", metadata: expectedMetadata) + logging.history.assertExist(level: .notice, message: "test", metadata: expectedMetadata) + logging.history.assertExist(level: .warning, message: "test", metadata: expectedMetadata) + logging.history.assertExist(level: .error, message: "test", metadata: expectedMetadata) + logging.history.assertExist(level: .critical, message: "test", metadata: expectedMetadata) + + enum TestIDKey: BaggageKey { + typealias Value = String + } + enum OnlyLocalIDKey: BaggageKey { + typealias Value = String + } + enum OnlyExplicitlyProvidedIDKey: BaggageKey { + typealias Value = String + } + #endif + } + + 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") + } +} + +extension Logger.MetadataProvider { + static var simpleTestProvider: Self { + .init { + ["test": "provided"] + } + } +} + +public struct LogHandlerThatDidNotImplementMetadataProviders: LogHandler { + let testLogging: TestLogging + init(testLogging: TestLogging) { + self.testLogging = testLogging + } + + public subscript(metadataKey _: String) -> Logging.Logger.Metadata.Value? { + get { + 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) + } +} diff --git a/Tests/InstrumentationTests/InstrumentTests.swift b/Tests/InstrumentationTests/InstrumentTests.swift index aaea30a..cada7ed 100644 --- a/Tests/InstrumentationTests/InstrumentTests.swift +++ b/Tests/InstrumentationTests/InstrumentTests.swift @@ -52,7 +52,7 @@ private struct DictionaryExtractor: Extractor { } } -private final class FirstFakeTracer: Instrument { +private final class FirstFakeTracer: InstrumentProtocol { enum TraceIDKey: BaggageKey { typealias Value = String @@ -77,7 +77,7 @@ private final class FirstFakeTracer: Instrument { } } -private final class SecondFakeTracer: Instrument { +private final class SecondFakeTracer: InstrumentProtocol { enum TraceIDKey: BaggageKey { typealias Value = String diff --git a/Tests/InstrumentationTests/InstrumentationSystemTests.swift b/Tests/InstrumentationTests/InstrumentationSystemTests.swift index 87a7be5..5f0a2c8 100644 --- a/Tests/InstrumentationTests/InstrumentationSystemTests.swift +++ b/Tests/InstrumentationTests/InstrumentationSystemTests.swift @@ -17,7 +17,7 @@ import InstrumentationBaggage import XCTest extension InstrumentationSystem { - public static func _instrument(of instrumentType: I.Type) -> I? where I: Instrument { + public static func _instrument(of instrumentType: I.Type) -> I? where I: InstrumentProtocol { self._findInstrument(where: { $0 is I }) as? I } } @@ -48,7 +48,7 @@ final class InstrumentationSystemTests: XCTestCase { } } -private final class FakeTracer: Instrument { +private final class FakeTracer: InstrumentProtocol { func inject( _ baggage: Baggage, into carrier: inout Carrier, @@ -68,7 +68,7 @@ private final class FakeTracer: Instrument { Carrier == Extract.Carrier {} } -private final class FakeInstrument: Instrument { +private final class FakeInstrument: InstrumentProtocol { func inject( _ baggage: Baggage, into carrier: inout Carrier, diff --git a/Tests/InstrumentationTests/TestLogger.swift b/Tests/InstrumentationTests/TestLogger.swift new file mode 100644 index 0000000..3653b88 --- /dev/null +++ b/Tests/InstrumentationTests/TestLogger.swift @@ -0,0 +1,412 @@ +//===----------------------------------------------------------------------===// +// +// 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 +// +//===----------------------------------------------------------------------===// +import Foundation +@testable import Logging +import XCTest +#if os(Windows) +import WinSDK +#endif + +internal struct TestLogging { + private let _config = Config() // shared among loggers + private let recorder = Recorder() // shared among loggers + + func make(label: String) -> LogHandler { + return TestLogHandler( + label: label, + config: self.config, + recorder: self.recorder, + metadataProvider: LoggingSystem.metadataProviderFactory(label) + ) + } + + 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 } + var history: History { return self.recorder } +} + +internal struct TestLogHandler: LogHandler { + private let recorder: Recorder + private let config: Config + private var logger: Logger // the actual logger + + let label: String + 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 + } + + 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.metadataProviderFactory(label) + } + + 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.provideMetadata() + if !contextualMetadata.isEmpty { + metadata = metadata.merging(contextualMetadata, uniquingKeysWith: { _, contextual in contextual }) + } + // override using any explicit metadata passed for this log statement: + if let explicitMetadata = explicitMetadata { + metadata = metadata.merging(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) + } + + private var _logLevel: Logger.Level? + var logLevel: Logger.Level { + get { + // get from config unless set + return self._logLevel ?? self.config.get(key: self.label) + } + set { + self._logLevel = newValue + } + } + + private var _metadataSet = false + private var _metadata = Logger.Metadata() { + didSet { + self._metadataSet = true + } + } + + public var metadata: Logger.Metadata { + get { + return self._metadata + } + set { + self._metadata = newValue + } + } + + // TODO: would be nice to delegate to local copy of logger but StdoutLogger is a reference type. why? + subscript(metadataKey metadataKey: Logger.Metadata.Key) -> Logger.Metadata.Value? { + get { + return self._metadata[metadataKey] + } + set { + self._metadata[metadataKey] = newValue + } + } +} + +internal class Config { + private static let ALL = "*" + + private let lock = NSLock() + private var storage = [String: Logger.Level]() + + func get(key: String) -> Logger.Level { + return self.get(key) ?? self.get(Config.ALL) ?? Logger.Level.debug + } + + func get(_ key: String) -> Logger.Level? { + guard let value = (self.lock.withLock { self.storage[key] }) else { + return nil + } + return value + } + + func set(key: String = Config.ALL, value: Logger.Level) { + self.lock.withLock { self.storage[key] = value } + } + + func clear() { + self.lock.withLock { self.storage.removeAll() } + } +} + +internal class Recorder: History { + private let lock = NSLock() + private var _entries = [LogEntry]() + + func record(level: Logger.Level, metadata: Logger.Metadata?, message: Logger.Message, source: String) { + return self.lock.withLock { + self._entries.append(LogEntry(level: level, metadata: metadata, message: message.description, source: source)) + } + } + + var entries: [LogEntry] { + return self.lock.withLock { self._entries } + } +} + +internal protocol History { + var entries: [LogEntry] { get } +} + +internal extension History { + func atLevel(level: Logger.Level) -> [LogEntry] { + return self.entries.filter { entry in + level == entry.level + } + } + + var trace: [LogEntry] { + return self.atLevel(level: .debug) + } + + var debug: [LogEntry] { + return self.atLevel(level: .debug) + } + + var info: [LogEntry] { + return self.atLevel(level: .info) + } + + var warning: [LogEntry] { + return self.atLevel(level: .warning) + } + + var error: [LogEntry] { + return self.atLevel(level: .error) + } +} + +internal struct LogEntry { + let level: Logger.Level + let metadata: Logger.Metadata? + let message: String + let source: String +} + +extension History { + #if compiler(>=5.3) + func assertExist(level: Logger.Level, + message: String, + metadata: Logger.Metadata? = nil, + source: String? = nil, + file: StaticString = #file, + fileID: String = #fileID, + line: UInt = #line) { + let source = source ?? Logger.currentModule(fileID: "\(fileID)") + let entry = self.find(level: level, message: message, metadata: metadata, source: source) + XCTAssertNotNil(entry, "entry not found: \(level), \(source), \(String(describing: metadata)), \(message)", + file: file, line: line) + } + + func assertNotExist(level: Logger.Level, + message: String, + metadata: Logger.Metadata? = nil, + source: String? = nil, + file: StaticString = #file, + fileID: String = #file, + line: UInt = #line) { + let source = source ?? Logger.currentModule(fileID: "\(fileID)") + let entry = self.find(level: level, message: message, metadata: metadata, source: source) + XCTAssertNil(entry, "entry was found: \(level), \(source), \(String(describing: metadata)), \(message)", + file: file, line: line) + } + + #else +func assertExist(level: Logger.Level, +message: String, +metadata: Logger.Metadata? = nil, +source: String? = nil, +file: StaticString = #file, +line: UInt = #line) { +let source = source ?? Logger.currentModule(filePath: "\(file)") +let entry = self.find(level: level, message: message, metadata: metadata, source: source) +XCTAssertNotNil(entry, "entry not found: \(level), \(source), \(String(describing: metadata)), \(message)", +file: file, line: line) +} + +func assertNotExist(level: Logger.Level, +message: String, +metadata: Logger.Metadata? = nil, +source: String? = nil, +file: StaticString = #file, +line: UInt = #line) { +let source = source ?? Logger.currentModule(filePath: "\(file)") +let entry = self.find(level: level, message: message, metadata: metadata, source: source) +XCTAssertNil(entry, "entry was found: \(level), \(source), \(String(describing: metadata)), \(message)", +file: file, line: line) +} + #endif + + func find(level: Logger.Level, message: String, metadata: Logger.Metadata? = nil, source: String) -> LogEntry? { + return self.entries.first { entry in + 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 + } + } +} + +public class MDC { + private let lock = NSLock() + private var storage = [Int: Logger.Metadata]() + + public static var global = MDC() + + private init() {} + + public subscript(metadataKey: String) -> Logger.Metadata.Value? { + get { + return self.lock.withLock { + self.storage[self.threadId]?[metadataKey] + } + } + set { + self.lock.withLock { + if self.storage[self.threadId] == nil { + self.storage[self.threadId] = Logger.Metadata() + } + self.storage[self.threadId]![metadataKey] = newValue + } + } + } + + public var metadata: Logger.Metadata { + return self.lock.withLock { + self.storage[self.threadId] ?? [:] + } + } + + public func clear() { + self.lock.withLock { + _ = self.storage.removeValue(forKey: self.threadId) + } + } + + public func with(metadata: Logger.Metadata, _ body: () throws -> Void) rethrows { + metadata.forEach { self[$0] = $1 } + defer { + metadata.keys.forEach { self[$0] = nil } + } + try body() + } + + public func with(metadata: Logger.Metadata, _ body: () throws -> T) rethrows -> T { + metadata.forEach { self[$0] = $1 } + defer { + metadata.keys.forEach { self[$0] = nil } + } + return try body() + } + + // for testing + internal func flush() { + self.lock.withLock { + self.storage.removeAll() + } + } + + private var threadId: Int { + #if os(macOS) || os(iOS) || os(tvOS) || os(watchOS) + return Int(pthread_mach_thread_np(pthread_self())) + #elseif os(Windows) + return Int(GetCurrentThreadId()) + #else + return Int(pthread_self()) + #endif + } +} + +internal extension NSLock { + func withLock(_ body: () -> T) -> T { + self.lock() + defer { + self.unlock() + } + return body() + } +} + +internal struct TestLibrary { + private let logger = Logger(label: "TestLibrary") + private let queue = DispatchQueue(label: "TestLibrary") + + public init() {} + + public func doSomething() { + self.logger.info("TestLibrary::doSomething") + } + + public func doSomethingAsync(completion: @escaping () -> Void) { + // libraries that use global loggers and async, need to make sure they propagate the + // logging metadata when creating a new thread + let metadata = MDC.global.metadata + self.queue.asyncAfter(deadline: .now() + 0.1) { + MDC.global.with(metadata: metadata) { + self.logger.info("TestLibrary::doSomethingAsync") + completion() + } + } + } +} + +// Sendable + +#if compiler(>=5.6) +extension TestLogHandler: @unchecked Sendable {} +extension Recorder: @unchecked Sendable {} +extension Config: @unchecked Sendable {} +extension MDC: @unchecked Sendable {} +#endif diff --git a/Tests/LinuxMain.swift b/Tests/LinuxMain.swift index c8bf729..eb271ed 100644 --- a/Tests/LinuxMain.swift +++ b/Tests/LinuxMain.swift @@ -34,6 +34,7 @@ class LinuxMainRunnerImpl: LinuxMainRunner { @available(*, deprecated, message: "not actually deprecated. Just deprecated to allow deprecated tests (which test deprecated functionality) without warnings") func run() { XCTMain([ + testCase(BaggageLoggingTest.allTests), testCase(DynamicTracepointTracerTests.allTests), testCase(InstrumentTests.allTests), testCase(InstrumentationSystemTests.allTests), diff --git a/Tests/TracingTests/TestTracer.swift b/Tests/TracingTests/TestTracer.swift index e9ec3a3..64e593e 100644 --- a/Tests/TracingTests/TestTracer.swift +++ b/Tests/TracingTests/TestTracer.swift @@ -18,7 +18,7 @@ import Instrumentation import InstrumentationBaggage import Tracing -final class TestTracer: Tracer { +final class TestTracer: TracerProtocol { private(set) var spans = [TestSpan]() var onEndSpan: (Span) -> Void = { _ in } diff --git a/Tests/TracingTests/TracedLockTests.swift b/Tests/TracingTests/TracedLockTests.swift index 81ad3d9..e62e51f 100644 --- a/Tests/TracingTests/TracedLockTests.swift +++ b/Tests/TracingTests/TracedLockTests.swift @@ -58,7 +58,7 @@ enum TaskIDKey: BaggageKey { // ==== ------------------------------------------------------------------------ // MARK: PrintLn Tracer -private final class TracedLockPrintlnTracer: Tracer { +private final class TracedLockPrintlnTracer: TracerProtocol { func startSpan( _ operationName: String, baggage: Baggage, diff --git a/Tests/TracingTests/TracerTests+XCTest.swift b/Tests/TracingTests/TracerTests+XCTest.swift index 360df37..67df9b7 100644 --- a/Tests/TracingTests/TracerTests+XCTest.swift +++ b/Tests/TracingTests/TracerTests+XCTest.swift @@ -32,6 +32,7 @@ extension TracerTests { ("testWithSpan_throws", testWithSpan_throws), ("testWithSpan_automaticBaggagePropagation_sync", testWithSpan_automaticBaggagePropagation_sync), ("testWithSpan_automaticBaggagePropagation_sync_throws", testWithSpan_automaticBaggagePropagation_sync_throws), + ("testWithSpan_operation_withoutSpanPassed", testWithSpan_operation_withoutSpanPassed), ("testWithSpan_automaticBaggagePropagation_async", testWithSpan_automaticBaggagePropagation_async), ("testWithSpan_enterFromNonAsyncCode_passBaggage_asyncOperation", testWithSpan_enterFromNonAsyncCode_passBaggage_asyncOperation), ("testWithSpan_automaticBaggagePropagation_async_throws", testWithSpan_automaticBaggagePropagation_async_throws), diff --git a/Tests/TracingTests/TracerTests.swift b/Tests/TracingTests/TracerTests.swift index 987f3e7..bb5638e 100644 --- a/Tests/TracingTests/TracerTests.swift +++ b/Tests/TracingTests/TracerTests.swift @@ -116,7 +116,7 @@ final class TracerTests: XCTestCase { "world" } - let value = tracer.withSpan("hello") { (span: Span) -> String in + let value = tracer.withSpan("hello") { span -> String in XCTAssertEqual(span.baggage.traceID, Baggage.current?.traceID) return operation(span: span) } @@ -156,6 +156,32 @@ final class TracerTests: XCTestCase { #endif } + func testWithSpan_operation_withoutSpanPassed() throws { + #if swift(>=5.5) && canImport(_Concurrency) + guard #available(macOS 10.15, iOS 13.0, tvOS 13.0, watchOS 6.0, *) else { + throw XCTSkip("Task locals are not supported on this platform.") + } + + let tracer = TestTracer() + InstrumentationSystem.bootstrapInternal(tracer) + defer { + InstrumentationSystem.bootstrapInternal(nil) + } + + var spansEnded = 0 + tracer.onEndSpan = { _ in spansEnded += 1 } + + tracer.withSpan("hello") { + // ... + } + tracer.withSpan("hello-again", baggage: .topLevel) { + // ... + } + + XCTAssertEqual(spansEnded, 2) + #endif + } + func testWithSpan_automaticBaggagePropagation_async() throws { #if swift(>=5.5) && canImport(_Concurrency) guard #available(macOS 10.15, iOS 13.0, tvOS 13.0, watchOS 6.0, *) else { @@ -176,7 +202,7 @@ final class TracerTests: XCTestCase { } try self.testAsync { - let value = try await tracer.withSpan("hello") { (span: Span) -> String in + let value = try await tracer.withSpan("hello") { span -> String in XCTAssertEqual(span.baggage.traceID, Baggage.current?.traceID) return try await operation(span: span) } @@ -209,7 +235,7 @@ final class TracerTests: XCTestCase { self.testAsync { var fromNonAsyncWorld = Baggage.topLevel fromNonAsyncWorld.traceID = "1234-5678" - let value = await tracer.withSpan("hello", baggage: fromNonAsyncWorld) { (span: Span) -> String in + let value = await tracer.withSpan("hello", baggage: fromNonAsyncWorld) { span -> String in XCTAssertEqual(span.baggage.traceID, Baggage.current?.traceID) XCTAssertEqual(span.baggage.traceID, fromNonAsyncWorld.traceID) return await operation(span: span) diff --git a/Tests/TracingTests/TracingInstrumentationSystemTests.swift b/Tests/TracingTests/TracingInstrumentationSystemTests.swift index 5e68ea5..0c9650a 100644 --- a/Tests/TracingTests/TracingInstrumentationSystemTests.swift +++ b/Tests/TracingTests/TracingInstrumentationSystemTests.swift @@ -17,11 +17,11 @@ import Tracing import XCTest extension InstrumentationSystem { - public static func _tracer(of tracerType: T.Type) -> T? where T: Tracer { + public static func _tracer(of tracerType: T.Type) -> T? where T: TracerProtocol { self._findInstrument(where: { $0 is T }) as? T } - public static func _instrument(of instrumentType: I.Type) -> I? where I: Instrument { + public static func _instrument(of instrumentType: I.Type) -> I? where I: InstrumentProtocol { self._findInstrument(where: { $0 is I }) as? I } }