Tracing, Metrics & OpenTelemetry

A trace is the story of one request across every service it touches; it is a tree of spans. A span has a name, a kind (server for the span that handles an incoming request, client for an outgoing call, internal for work inside a process), a start and an end, key-value attributes, a status and, optionally, events and recorded errors. Spans belong together because they share a 16-byte trace id and each child names its parent’s span id; across processes, the pair travels in the W3C traceparent header (00-<trace id>-<parent span id>-<flags>), whose last field carries the sampled flag.

In swift-distributed-tracing the current position in the tree is a ServiceContext: a typed, immutable key-value bag (from the swift-service-context package) that a tracer stores the span identifiers in. withSpan(_:context:ofKind:_:) starts a span as a child of the context it is given (by default ServiceContext.current, a task-local value), runs the closure with the new span’s context as ServiceContext.current, records any error the closure throws, and ends the span when the closure returns. Because the context is task-local, child tasks and awaited calls inherit it with no parameter to pass; this is the part of Swift concurrency that makes tracing cheap to write, and the part that breaks if work escapes the task tree (an unstructured Task.detached, a callback from a library that hops to its own thread).

Vapor’s integration is a single middleware, TracingMiddleware, in 4.x an AsyncMiddleware. It is not installed by default. For each request it:

The initializer TracingMiddleware(setCustomAttributes:) takes a closure that receives the attribute bag and the request on every request, so it must be cheap and must only copy bounded, non-sensitive values. The semantic conventions are defined in OpenTelemetry: HTTP spans; the source is TracingMiddleware.swift.

Where the middleware sits decides what the span measures. The default stack is RouteLoggingMiddleware, then ErrorMiddleware (see Error Handling) (Application+Middleware.swift), then whatever you add with app.middleware.use; a middleware added with app.grouped(...) runs inside the group, after the global ones. The span therefore covers the middleware that comes after it, the router and the handler, and not the default ones. The example registers it on a route group so that the health probe is not traced at all (a probe every few seconds would otherwise be the most common span in the system). Middleware order in general is on the Middleware page.

The listing is the Bookshelf service used for every capture on this page. GET /books/:isbn asks a "remote catalog" (the same process, over HTTP, so that one process shows a two-hop trace) and wraps that in its own span.

Source: Vapor docs: Tracing

What happens at run time, from the captures of this service:

That tree was read from Jaeger’s query API (/api/traces?service=bookshelf), and the four spans share one trace id. Three details of how it came to be need spelling out.

1. withSpan nests through the task-local context, and req.serviceContext is only the server span. Inside withSpan("catalog.lookup"), ServiceContext.current is the lookup span; req.serviceContext is still the server span, because only TracingMiddleware assigns it. Code that builds a span from req.serviceContext instead of the current context therefore makes a sibling, not a child. The first version of the helper in the next section did exactly that: a test showed the client span’s parent was the server span (span-1) while the lookup was span-2. The helper now passes ServiceContext.current ?? serviceContext. Rule: prefer the task-local context, fall back to req.serviceContext only outside a withSpan.

2. traceAutoPropagation is not needed for async code. Application.traceAutoPropagation (default false) makes Vapor restore req.serviceContext as the task-local context "across Vapor-internal EventLoopFuture boundaries", and its documentation warns of performance implications. In a pure async handler the task-local context already flows from the withSpan call in TracingMiddleware into the handler: a test that ran the same request with the flag on and off (@Test(arguments: [true, false])) produced the same parent for the lookup span in both. The flag matters for code that still mixes in futures (req.eventLoop.submit, flatMap chains through libraries not yet converted). The configuration above turns it on because the demo is cheap; a pure async service can leave it off. Vapor 5 has neither the flag nor req.serviceContext; its TracingMiddleware reads ServiceContext.current.

3. A thrown error ends the span as an error, without a status code, unless an ErrorMiddleware sits inside the span. The default ErrorMiddleware sits in the global stack, outside anything you register later, so it converts a thrown Abort into a response outside the span. TracingMiddleware therefore sees a thrown error, and withSpan records it and sets the span’s status to error, even for Abort(.notFound), and http.response.status_code is never set because no response came back. The measured results in the test suite:

The configuration registers ErrorMiddleware.default(environment:) again, inside the traced group, so that the span sees the response. Client errors then stop polluting error-rate dashboards and traces carry the status the client saw. The inner middleware also logs the error inside the span, so that log line is correlated (see Logs and correlation).

4. The span records the query string. url.query is set verbatim, and so is url.path; a request to /missing?token=abc exported url.query = token=abc to Jaeger. Anything that puts a secret in a query string (a mistake, but a common one) leaks into every trace backend. setCustomAttributes can add attributes but cannot remove the standard ones, so strip them in the Collector (see Running the backends, where an attributes processor deletes url.query and the same request left no query in Jaeger) or write your own middleware instead of TracingMiddleware. Do not put user ids, e-mail addresses or tokens into attributes of a span you do not control the retention of.

Recording every span of every request is rarely affordable. swift-otel implements the standard samplers: parentBasedAlwaysOn (the default, which samples every root span and follows the parent’s decision otherwise), alwaysOn, alwaysOff, traceIDRatio, and parentBasedTraceIDRatio(ratio:). In code they are config.traces.sampler = .parentBasedTraceIDRatio(ratio: 0.1)! (the factory returns an optional that is nil for a ratio outside the range 0 to 1); in the environment OTEL_TRACES_SAMPLER=parentbased_traceidratio with OTEL_TRACES_SAMPLER_ARG=0.1.

Two measured behaviours, both with the demo configured for ratio 1.0 in code and overridden from the environment:

This is head-based sampling: the decision is made before anyone knows whether the request will be slow or fail. To keep every error and slow trace and a fraction of the rest, send all spans to the Collector and use its tail-sampling processor; that setup was not run for this page.

All metric handles are created by label and dimensions and are cheap to construct; the backend deduplicates them by (label, dimensions):

Dimensions become labels, and each distinct combination of label values is a separate time series that the backend stores forever. Use dimensions with a small, fixed set of values (a route template, a method, an outcome, a status class) and never an ISBN, a user id or a free-text message. This is the same cardinality rule as in Prometheus itself; see Data model & metric types and Instrumenting applications.

Without any code, DefaultResponder records three metrics for every request that reaches the router, unless app.http.server.configuration.reportMetrics is set to false (default true):

path is the route template (/books/:isbn), never the concrete URL. A request that matches no route is recorded with method="undefined" and path="vapor_route_undefined", so a scanner probing thousands of paths cannot create thousands of series. These three are the RED method: Rate, Errors, Duration. That is why most services need no request middleware of their own. The test vaporCountsRequestsAndErrorsPerRouteTemplate below pins both properties. The source is DefaultResponder.swift.

Vapor Queues adds dispatched.jobs.counter, jobs.in.progress.meter, a <JobName>.jobDurationTimer per job type, and success.completed.jobs.counter and error.completed.jobs.counter, read from the queues 1.18.0 sources. Their names contain dots, which is not what a Prometheus-style exporter wants, so look at the name your exporter actually exposes before writing a query.

The Bookshelf additions are an in-flight meter (the "saturation" signal RED does not cover) and two business metrics:

Source: swift-metrics documentation

The middleware uses defer so the meter is decremented when the handler throws; the handler above records the lookup duration as a Duration taken from a ContinuousClock. Metric labels use the unit in the name (_seconds, _total) as the Prometheus naming practices recommend.

Pull with swift-prometheus. The application keeps the registry and serves it; Prometheus scrapes it. Add the Prometheus product of swift-prometheus 2.3.0, and register the factory before the first metric is created:

Source: swift-prometheus documentation

Running that program and requesting /metrics after three lookups and one failure returned (histogram buckets left out):

Timers become histograms; the default duration buckets are 5 ms, 10 ms, 25 ms, 50 ms, 100 ms, 250 ms, 500 ms, 1 s, 2.5 s, 5 s and 10 s, and PrometheusMetricsFactory.durationHistogramBuckets overrides them per metric label. Serve /metrics on an internal listener or filter it at the proxy: the endpoint exposes route names and traffic volumes and has no authentication. This page’s single-listener listing is the shortest correct demo, not a production layout.

Push with swift-otel. With OTel.bootstrap the same metrics leave over OTLP every metrics.exportInterval (default 60 seconds; OTEL_METRIC_EXPORT_INTERVAL in milliseconds; the demo uses 5 seconds) and the Collector’s prometheus exporter exposes them for Prometheus to scrape. The metric names, types and labels were unchanged by the trip: the Collector’s endpoint served http_requests_total{method="GET",path="/books/:isbn",status="200"} and a http_request_duration_seconds histogram with the same buckets, plus labels that identify the source (job="bookshelf", taken from service.name, and otel_scope_*). A Meter arrived as a gauge.

swift-metrics allows only one backend at a time (MetricsSystem.bootstrap is once per process), though it ships a MultiplexMetricsHandler(factories:) for sending to several. Pick pull when Prometheus is the only consumer and you want the fewest moving parts; pick push when traces and logs already go through the Collector, so that all telemetry has one path, one resource identity and one place to change policy.

With Prometheus scraping the Collector every five seconds, the standard RED queries ran against the data above. The values are the cumulative results of that short run:

Those queries run over cumulative counters because the run was a few requests long. In a dashboard or an alert, wrap the counters and buckets in rate(...[5m]) to get per-second rates over a window.

histogram_quantile interpolates inside the bucket that contains the quantile, so with only a few requests the value is an estimate bounded by bucket edges (the 50 ms to 75 ms bucket here). Alert rules and dashboards on these queries are covered in Recording & alerting rules and Grafana dashboards & visualization.

In 5.0.0-beta.4 (see What’s New, Upgrading and Vapor 5) the metrics move out of the responder into an opt-in MetricsMiddleware that follows the OpenTelemetry HTTP metrics conventions (http.server.active_requests as a meter, request and response body size recorders, a duration timer, with http.request.method, url.scheme, http.route and http.response.status_code dimensions), so dashboards written for the http_requests_total family will need new queries on upgrade. VaporTesting gains a task-local metrics system for tests. Both are read from the beta sources, not run. See MetricsMiddleware.swift.

OTel.bootstrap(configuration:) installs the backend for each enabled signal, returns a Service that does the background work (batching, timers, exporting), and reads OTEL_* environment variables after your code, so operators can override what you set. It throws if all three signals are disabled. The service must run for anything to be exported, and it must be stopped gracefully for the last batch to leave. The bootstrapping type for this page:

Source: swift-otel 1.6.0: the Vapor example

Four decisions in it:

The same options exist per signal (metrics.otlpExporter, logs.otlpExporter), and signal-specific variables win over the shared ones. The general environment-variable contract is in the OpenTelemetry SDK configuration and OTLP exporter configuration pages.

The service returned by OTel.bootstrap is an ordinary swift-service-lifecycle Service. The entry point runs it in a ServiceGroup together with an adapter that turns Vapor’s app.execute() into a Service:

Source: swift-service-lifecycle documentation

The two flavours of shutdown were both observed:

Vapor installs its own SIGINT and SIGTERM handling inside app.execute(), so the group is created without signal configuration. A deployment platform’s termination grace period must be longer than the export timeout, or the last batch is lost anyway (see Application lifecycle & entry point for the shutdown sequence).

The logging bootstrap and log levels themselves are covered in Logging. Two designs for correlation, both run:

With the first design a line written inside the lookup span was printed as:

With the second, the Collector’s file exporter wrote log records whose traceId and spanId matched the catalog.lookup span in Jaeger (the trace in that run started with db6b53cd and the span with 58bc408a). A line is correlated only if it is logged inside a span: the RouteLoggingMiddleware line GET /books/... is written outside TracingMiddleware and carries no trace id, while the line from the handler, and the error line from the inner ErrorMiddleware, do. Use the request id for the outside lines.