From 7da6ea91ac9642f7a29da6ed7e5030a79235a8a4 Mon Sep 17 00:00:00 2001 From: Luca Palmieri Date: Sun, 25 Apr 2021 12:19:27 +0100 Subject: [PATCH] Adopt OpenTelemetry's semantic convention (#15) * Add http.route. * Align all fields with OpenTelemetry's semantic conventions. * Add span kind. * Emit event for errors. Add OTEL status code. * Create otel.status_code field as empty. * Fix errors. * Add (feature-gated) support for OpenTelemetry span propagation. * Capture the trace id as an attribute on the span. * Change message. * Log the newly-generated trace id if there is no parent context. * Define a root_span macro as a stepping stone to allow crate users to add their own fields to the root span. * Add comments. * mut is no longer necessary. * Allow users to customise generation of the root span. Split recording fields on span end from emission of log record. Make log record on error optional via feature flag. * Provide constructor + default implementation. * Explode into multiple modules. Fix various paths/private imports in root_span. * Rename module to root_span_macro. * Add a new extractor to retrieve the root span. * Document crate. * Docs! * Add section on OTEL. * Mention actix-web-opentelemetry. * Add OpenTelemetry example. * Improve readme. * Add custom root span example. Co-authored-by: LukeMathWalker --- Cargo.toml | 10 + examples/custom-root-span/Cargo.toml | 17 + examples/custom-root-span/README.md | 38 +++ examples/custom-root-span/src/main.rs | 93 ++++++ examples/opentelemetry/Cargo.toml | 17 + examples/opentelemetry/README.md | 33 ++ examples/opentelemetry/src/main.rs | 60 ++++ src/lib.rs | 444 ++++++++++++++------------ src/middleware.rs | 162 ++++++++++ src/otel.rs | 21 ++ src/request_id.rs | 64 ++++ src/root_span.rs | 57 ++++ src/root_span_builder.rs | 59 ++++ src/root_span_macro.rs | 189 +++++++++++ 14 files changed, 1057 insertions(+), 207 deletions(-) create mode 100644 examples/custom-root-span/Cargo.toml create mode 100644 examples/custom-root-span/README.md create mode 100644 examples/custom-root-span/src/main.rs create mode 100644 examples/opentelemetry/Cargo.toml create mode 100644 examples/opentelemetry/README.md create mode 100644 examples/opentelemetry/src/main.rs create mode 100644 src/middleware.rs create mode 100644 src/otel.rs create mode 100644 src/request_id.rs create mode 100644 src/root_span.rs create mode 100644 src/root_span_builder.rs create mode 100644 src/root_span_macro.rs diff --git a/Cargo.toml b/Cargo.toml index 77269c4b3..cfe3cead4 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,3 +1,6 @@ +[workspace] +members = [".", "examples/opentelemetry", "examples/custom-root-span"] + [package] name = "tracing-actix-web" version = "0.3.0-beta.3" @@ -15,12 +18,19 @@ description = "Structured logging middleware for actix-web." keywords = ["http", "actix-web", "tracing", "logging"] categories = ["asynchronous", "web-programming"] +[features] +default = ["opentelemetry_0_13", "emit_event_on_error"] +opentelemetry_0_13 = ["opentelemetry", "tracing-opentelemetry"] +emit_event_on_error = [] + [dependencies] actix-web = "4.0.0-beta.6" tracing = "0.1.19" tracing-futures = "0.2.4" futures = "0.3.5" uuid = { version = "0.8.1", features = ["v4"] } +opentelemetry = { version = "0.13", optional = true } +tracing-opentelemetry = { version = "0.12", optional = true } [dev-dependencies] tracing-subscriber = { version = "0.2.12", features = ["registry", "env-filter"] } diff --git a/examples/custom-root-span/Cargo.toml b/examples/custom-root-span/Cargo.toml new file mode 100644 index 000000000..57ae59f6b --- /dev/null +++ b/examples/custom-root-span/Cargo.toml @@ -0,0 +1,17 @@ +[package] +name = "custom-root-span" +version = "0.1.0" +authors = ["LukeMathWalker "] +edition = "2018" + +# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html + +[dependencies] +actix-web = "4.0.0-beta.6" +opentelemetry = { version = "0.13", features = ["rt-tokio-current-thread"] } +opentelemetry-jaeger = { version = "0.12", features = ["tokio"] } +tracing-opentelemetry = { version = "0.12" } +tracing = "0.1.19" +tracing-subscriber = { version = "0.2.12", features = ["registry", "env-filter"] } +tracing-bunyan-formatter = "0.1.6" +tracing-actix-web = { path = "../.." } diff --git a/examples/custom-root-span/README.md b/examples/custom-root-span/README.md new file mode 100644 index 000000000..e4d8bfe04 --- /dev/null +++ b/examples/custom-root-span/README.md @@ -0,0 +1,38 @@ +# Custom root span + +## Running + +You can launch this example with + +```bash +cargo run +``` + +An `actix-web` application will be listening on port `8080`. +You can fire requests to it with: + +```bash +curl -v http://localhost:8080/hello +``` +```text +Hello world! +``` + +or + +```bash +curl -v http://localhost:8080/hello/my-name +``` +```text +Hello my-name! +``` + +## Visualising traces + +Spans will be also printed to the console in JSON format, as structured log records. + +You can look at the exported spans in your browser by visiting [http://localhost:16686](http://localhost:16686) if you launch a Jaeger instance: + +```bash +docker run -d -p6831:6831/udp -p6832:6832/udp -p16686:16686 jaegertracing/all-in-one:latest +``` diff --git a/examples/custom-root-span/src/main.rs b/examples/custom-root-span/src/main.rs new file mode 100644 index 000000000..1b83256ef --- /dev/null +++ b/examples/custom-root-span/src/main.rs @@ -0,0 +1,93 @@ +use actix_web::dev::{ServiceRequest, ServiceResponse}; +use actix_web::{web, App, Error, HttpServer}; +use opentelemetry::{ + global, runtime::TokioCurrentThread, sdk::propagation::TraceContextPropagator, +}; +use std::io; +use tracing::Span; +use tracing_actix_web::{DefaultRootSpanBuilder, RootSpan, RootSpanBuilder, TracingLogger}; +use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer}; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::{EnvFilter, Registry}; + +/// We will define a custom root span builder to capture additional fields, specific +/// to our application, on top of the ones provided by `DefaultRootSpanBuilder` out of the box. +pub struct CustomRootSpanBuilder; + +impl RootSpanBuilder for CustomRootSpanBuilder { + fn on_request_start(request: &ServiceRequest) -> Span { + // Not sure why you'd be keen to capture this, but it's an example and we try to keep it simple + let n_headers = request.headers().len(); + // We set `cloud_provider` to a constant value. + // + // `name` is not known at this point - we delegate the responsibility to populate it + // to the `personal_hello` handler. We MUST declare the field though, otherwise + // `span.record("caller_name", XXX)` will just be silently ignored by `tracing`. + tracing_actix_web::root_span!( + request, + n_headers, + cloud_provider = "localhost", + caller_name = tracing::field::Empty + ) + } + + fn on_request_end(span: Span, outcome: &Result, Error>) { + // Capture the standard fields when the request finishes. + DefaultRootSpanBuilder::on_request_end(span, outcome); + } +} + +async fn hello() -> &'static str { + "Hello world!" +} + +async fn personal_hello(root_span: RootSpan, name: web::Path) -> String { + // Add more context to the root span of the request. + root_span.record("caller_name", &name.as_str()); + format!("Hello {}!", name) +} + +#[actix_web::main] +async fn main() -> io::Result<()> { + init_telemetry(); + + HttpServer::new(move || { + App::new() + .wrap(TracingLogger::::new()) + .service(web::resource("/hello").to(hello)) + .service(web::resource("/hello/{name}").to(personal_hello)) + }) + .bind("127.0.0.1:8080")? + .run() + .await?; + + // Ensure all spans have been shipped to Jaeger. + opentelemetry::global::shutdown_tracer_provider(); + + Ok(()) +} + +/// Init a `tracing` subscriber that prints spans to stdout as well as +/// ships them to Jaeger. +/// +/// Check the `opentelemetry` example for more details. +fn init_telemetry() { + let app_name = "tracing-actix-web-demo"; + + global::set_text_map_propagator(TraceContextPropagator::new()); + let tracer = opentelemetry_jaeger::new_pipeline() + .with_service_name(app_name) + .install_batch(TokioCurrentThread) + .expect("Failed to install OpenTelemetry tracer."); + + let env_filter = EnvFilter::try_from_default_env().unwrap_or(EnvFilter::new("info")); + let telemetry = tracing_opentelemetry::layer().with_tracer(tracer); + let formatting_layer = BunyanFormattingLayer::new(app_name.into(), std::io::stdout); + let subscriber = Registry::default() + .with(env_filter) + .with(telemetry) + .with(JsonStorageLayer) + .with(formatting_layer); + tracing::subscriber::set_global_default(subscriber) + .expect("Failed to install `tracing` subscriber.") +} diff --git a/examples/opentelemetry/Cargo.toml b/examples/opentelemetry/Cargo.toml new file mode 100644 index 000000000..456c5fa73 --- /dev/null +++ b/examples/opentelemetry/Cargo.toml @@ -0,0 +1,17 @@ +[package] +name = "otel" +version = "0.1.0" +authors = ["Luca Palmieri "] +edition = "2018" + +license = "MIT/Apache-2.0" + +[dependencies] +actix-web = "4.0.0-beta.6" +tracing = "0.1.19" +opentelemetry = { version = "0.13", features = ["rt-tokio-current-thread"] } +opentelemetry-jaeger = { version = "0.12", features = ["tokio"] } +tracing-opentelemetry = { version = "0.12" } +tracing-subscriber = { version = "0.2.12", features = ["registry", "env-filter"] } +tracing-bunyan-formatter = "0.1.6" +tracing-actix-web = { path = "../.." } diff --git a/examples/opentelemetry/README.md b/examples/opentelemetry/README.md new file mode 100644 index 000000000..ecc241b80 --- /dev/null +++ b/examples/opentelemetry/README.md @@ -0,0 +1,33 @@ +# OpenTelemetry integration + +## Prerequisites + +To execute this example you need a running Jaeger instance. +You can launch one using Docker: + +```bash +docker run -d -p6831:6831/udp -p6832:6832/udp -p16686:16686 jaegertracing/all-in-one:latest +``` + +## Running + +You can launch this example with + +```bash +cargo run +``` + +An `actix-web` application will be listening on port `8080`. +You can fire requests to it with: + +```bash +curl -v http://localhost:8080/hello +``` +```text +Hello world! +``` + +## Traces + +You can look at the exported traces in your browser by visiting [http://localhost:16686](http://localhost:16686). +Spans will be also printed to the console in JSON format, as structured log records. \ No newline at end of file diff --git a/examples/opentelemetry/src/main.rs b/examples/opentelemetry/src/main.rs new file mode 100644 index 000000000..e1cdc684d --- /dev/null +++ b/examples/opentelemetry/src/main.rs @@ -0,0 +1,60 @@ +use actix_web::{web, App, HttpServer}; +use opentelemetry::{ + global, runtime::TokioCurrentThread, sdk::propagation::TraceContextPropagator, +}; +use std::io; +use tracing_actix_web::TracingLogger; +use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer}; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::{EnvFilter, Registry}; + +async fn hello() -> &'static str { + "Hello world!" +} + +fn init_telemetry() { + let app_name = "tracing-actix-web-demo"; + + // Start a new Jaeger trace pipeline. + // Spans are exported in batch - recommended setup for a production application. + global::set_text_map_propagator(TraceContextPropagator::new()); + let tracer = opentelemetry_jaeger::new_pipeline() + .with_service_name(app_name) + .install_batch(TokioCurrentThread) + .expect("Failed to install OpenTelemetry tracer."); + + // Filter based on level - trace, debug, info, warn, error + // Tunable via `RUST_LOG` env variable + let env_filter = EnvFilter::try_from_default_env().unwrap_or(EnvFilter::new("info")); + // Create a `tracing` layer using the Jaeger tracer + let telemetry = tracing_opentelemetry::layer().with_tracer(tracer); + // Create a `tracing` layer to emit spans as structured logs to stdout + let formatting_layer = BunyanFormattingLayer::new(app_name.into(), std::io::stdout); + // Combined them all together in a `tracing` subscriber + let subscriber = Registry::default() + .with(env_filter) + .with(telemetry) + .with(JsonStorageLayer) + .with(formatting_layer); + tracing::subscriber::set_global_default(subscriber) + .expect("Failed to install `tracing` subscriber.") +} + +#[actix_web::main] +async fn main() -> io::Result<()> { + init_telemetry(); + + HttpServer::new(move || { + App::new() + .wrap(TracingLogger::default()) + .service(web::resource("/hello").to(hello)) + }) + .bind("127.0.0.1:8080")? + .run() + .await?; + + // Ensure all spans have been shipped to Jaeger. + opentelemetry::global::shutdown_tracer_provider(); + + Ok(()) +} diff --git a/src/lib.rs b/src/lib.rs index 6fe5d4186..b3156f777 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -1,215 +1,245 @@ -//! `tracing-actix-web` provides [`TracingLogger`], a middleware to log request and response info -//! when using the [`actix-web`] framework. +//! `tracing-actix-web` provides [`TracingLogger`], a middleware to collect telemetry data from applications +//! built on top of the [`actix-web`] framework. //! -//! [`TracingLogger`] is designed as a drop-in replacement of [`actix-web`]'s [`Logger`]. +//! # How to install //! -//! [`Logger`] is built on top of the [`log`] crate: you need to use regular expressions to parse -//! the request information out of the logged message. +//! Add `tracing-actix-web` to your dependencies: +//! ```toml +//! [dependencies] +//! # ... +//! tracing-actix-web = "0.4.0-beta.1" +//! tracing = "0.1" +//! actix-web = "4.0.0-beta.6" +//! ``` //! -//! [`TracingLogger`] relies on [`tracing`], a modern instrumentation framework for structured -//! logging: all request information is captured as a machine-parsable set of key-value pairs. -//! It also enables propagation of context information to children spans. +//! `tracing-actix-web` exposes two feature flags: //! -//! [`TracingLogger`]: struct.TracingLogger.html -//! [`actix-web`]: https://docs.rs/actix-web -//! [`Logger`]: https://docs.rs/actix-web/3.0.2/actix_web/middleware/struct.Logger.html -//! [`log`]: https://docs.rs/log -//! [`tracing`]: https://docs.rs/tracing -use actix_web::dev::{Payload, Service, ServiceRequest, ServiceResponse, Transform}; -use actix_web::{Error, FromRequest, HttpMessage, HttpRequest}; -use futures::future::{ok, ready, Ready}; -use futures::task::{Context, Poll}; -use std::future::Future; -use std::pin::Pin; -use tracing::Span; -use tracing_futures::Instrument; -use uuid::Uuid; +//! - `opentelemetry_0_13`: attach [OpenTelemetry](https://github.com/open-telemetry/opentelemetry-rust)'s context to the root span; +//! - `emit_event_on_error`: emit a [`tracing`] event when request processing fails with an error. +//! +//! They are both enabled by default. +//! +//! # Getting started +//! +//! ```rust,compile_fail +//! use actix_web::{App, web, HttpServer}; +//! use tracing_actix_web::TracingLogger; +//! +//! fn main() { +//! // Init your `tracing` subscriber here! +//! +//! let server = HttpServer::new(|| { +//! App::new() +//! // Mount `TracingLogger` as a middleware +//! .wrap(TracingLogger::default()) +//! .service( /* */ ) +//! }); +//! } +//! ``` +//! +//! Check out [the examples on GitHub] to get a taste of how [`TracingLogger`] can be used to observe and monitor your +//! application. +//! +//! # `tracing`: who art thou? +//! +//! [`TracingLogger`] is built on top of [`tracing`], a modern instrumentation framework with +//! [a vibrant ecosystem](https://github.com/tokio-rs/tracing#related-crates). +//! +//! `tracing-actix-web`'s documentation provides a crash course in how to use [`tracing`] to instrument an `actix-web` application. +//! If you want to learn more check out ["Are we observable yet?"](https://www.lpalmieri.com/posts/2020-09-27-zero-to-production-4-are-we-observable-yet/) - +//! it provides an in-depth introduction to the crate and the problems it solves within the bigger picture of [observability](https://docs.honeycomb.io/learning-about-observability/). +//! +//! # The root span +//! +//! [`tracing::Span`] is the key abstraction in [`tracing`]: it represents a unit of work in your system. +//! A [`tracing::Span`] has a beginning and an end. It can include one or more **child spans** to represent sub-unit +//! of works within a larger task. +//! +//! When your application receives a request, [`TracingLogger`] creates a new span - we call it the **[root span]**. +//! All the spans created _while_ processing the request will be children of the root span. +//! +//! [`tracing`] empowers us to attach structured properties to a span as a collection of key-value pairs. +//! Those properties can then be queried in a variety of tools (e.g. ElasticSearch, Honeycomb, DataDog) to +//! understand what is happening in your system. +//! +//! # Customisation via [`RootSpanBuilder`] +//! +//! Troubleshooting becomes much easier when the root span has a _rich context_ - e.g. you can understand most of what +//! happened when processing the request just by looking at the properties attached to the corresponding root span. +//! +//! You might have heard of this technique as the [canonical log line pattern](https://stripe.com/blog/canonical-log-lines), +//! popularised by Stripe. It is more recently discussed in terms of [high-cardinality events](https://www.honeycomb.io/blog/observability-a-manifesto/) +//! by Honeycomb and other vendors in the observability space. +//! +//! [`TracingLogger`] gives you a chance to use the very same pattern: you can customise the properties attached +//! to the root span in order to capture the context relevant to your specific domain. +//! +//! [`TracingLogger::default`] is equivalent to: +//! +//! ```rust +//! use tracing_actix_web::{TracingLogger, DefaultRootSpanBuilder}; +//! +//! // Two ways to initialise TracingLogger with the default root span builder +//! let default = TracingLogger::default(); +//! let another_way = TracingLogger::::new(); +//! ``` +//! +//! We are delegating the construction of the root span to [`DefaultRootSpanBuilder`]. +//! [`DefaultRootSpanBuilder`] captures, out of the box, several dimensions that are usually relevant when looking at an HTTP +//! API: method, version, route, etc. - check out its documentation for an extensive list. +//! +//! You can customise the root span by providing your own implementation of the [`RootSpanBuilder`] trait. +//! Let's imagine, for example, that our system cares about a client identifier embedded inside an authorization header. +//! We could add a `client_id` property to the root span using a custom builder, `DomainRootSpanBuilder`: +//! +//! ```rust +//! use actix_web::dev::{ServiceResponse, ServiceRequest}; +//! use actix_web::Error; +//! use tracing_actix_web::{TracingLogger, DefaultRootSpanBuilder, RootSpanBuilder}; +//! use tracing::Span; +//! +//! pub struct DomainRootSpanBuilder; +//! +//! impl RootSpanBuilder for DomainRootSpanBuilder { +//! fn on_request_start(request: &ServiceRequest) -> Span { +//! let client_id: &str = todo!("Somehow extract it from the authorization header"); +//! tracing::info_span!("Request", client_id) +//! } +//! +//! fn on_request_end(_span: Span, _outcome: &Result, Error>) {} +//! } +//! +//! let custom_middleware = TracingLogger::::new(); +//! ``` +//! +//! There is an issue, though: `client_id` is the _only_ property we are capturing. +//! With `DomainRootSpanBuilder`, as it is, we do not get any of that useful HTTP-related information provided by +//! [`DefaultRootSpanBuilder`]. +//! +//! We can do better! +//! +//! ```rust +//! use actix_web::dev::{ServiceResponse, ServiceRequest}; +//! use actix_web::Error; +//! use tracing_actix_web::{TracingLogger, DefaultRootSpanBuilder, RootSpanBuilder}; +//! use tracing::Span; +//! +//! pub struct DomainRootSpanBuilder; +//! +//! impl RootSpanBuilder for DomainRootSpanBuilder { +//! fn on_request_start(request: &ServiceRequest) -> Span { +//! let client_id: &str = todo!("Somehow extract it from the authorization header"); +//! tracing_actix_web::root_span!(request, client_id) +//! } +//! +//! fn on_request_end(span: Span, outcome: &Result, Error>) { +//! DefaultRootSpanBuilder::on_request_end(span, outcome); +//! } +//! } +//! +//! let custom_middleware = TracingLogger::::new(); +//! ``` +//! +//! [`root_span!`] is a macro provided by `tracing-actix-web`: it creates a new span by combining all the HTTP properties tracked +//! by [`DefaultRootSpanBuilder`] with the custom ones you specify when calling it (e.g. `client_id` in our example). +//! +//! We need to use a macro because `tracing` requires all the properties attached to a span to be declared upfront, when the span is created. +//! You cannot add new ones afterwards. This makes it extremely fast, but it pushes us to reach for macros when we need some level of +//! composition. +//! +//! # The [`RootSpan`] extractor +//! +//! It often happens that not all information about a task is known upfront, encoded in the incoming request. +//! You can use the [`RootSpan`] extractor to grab the root span in your handlers and attach more information +//! to your root span as it becomes available: +//! +//! ```rust +//! use actix_web::dev::{ServiceResponse, ServiceRequest}; +//! use actix_web::{Error, HttpResponse}; +//! use tracing_actix_web::{RootSpan, DefaultRootSpanBuilder, RootSpanBuilder}; +//! use tracing::Span; +//! use actix_web::get; +//! use tracing_actix_web::RequestId; +//! use uuid::Uuid; +//! +//! #[get("/")] +//! async fn handler(root_span: RootSpan) -> HttpResponse { +//! let application_id: &str = todo!("Some domain logic"); +//! // Record the property value against the root span +//! root_span.record("application_id", &application_id); +//! +//! // [...] +//! # todo!() +//! } +//! +//! pub struct DomainRootSpanBuilder; +//! +//! impl RootSpanBuilder for DomainRootSpanBuilder { +//! fn on_request_start(request: &ServiceRequest) -> Span { +//! let client_id: &str = todo!("Somehow extract it from the authorization header"); +//! // All fields you want to capture must be declared upfront. +//! // If you don't know the value (yet), use tracing's `Empty` +//! tracing_actix_web::root_span!( +//! request, +//! client_id, application_id = tracing::field::Empty +//! ) +//! } +//! +//! fn on_request_end(span: Span, response: &Result, Error>) { +//! DefaultRootSpanBuilder::on_request_end(span, response); +//! } +//! } +//! ``` +//! +//! # The [`RequestId`] extractor +//! +//! `tracing-actix-web` generates a unique identifier for each incoming request, the **request id**. +//! +//! You can extract the request id using the [`RequestId`] extractor: +//! +//! ```rust +//! use actix_web::get; +//! use tracing_actix_web::RequestId; +//! use uuid::Uuid; +//! +//! #[get("/")] +//! async fn index(request_id: RequestId) -> String { +//! format!("{}", request_id) +//! } +//! ``` +//! +//! # OpenTelemetry integration +//! +//! `tracing-actix-web` follows [OpenTelemetry's semantic convention](https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/overview.md#spancontext) +//! for field names. +//! Furthermore, if you have not disabled the `opentelemetry_0_13` feature flag, `tracing-actix-web` automatically +//! performs trace propagation according to the OpenTelemetry standard. +//! It tries to extract the OpenTelemetry context out of the headers of incoming requests and, when it finds one, it sets +//! it as the remote context for the current root span. +//! +//! If you add [`tracing-opentelemetry::OpenTelemetryLayer`](https://docs.rs/tracing-opentelemetry/0.12.0/tracing_opentelemetry/struct.OpenTelemetryLayer.html) +//! in your `tracing::Subscriber` you will be able to export the root span (and all its children) as OpenTelemetry spans. +//! +//! Check out the [relevant example in the GitHub repository] for reference. +//! +//! You can find an alternative integration of `actix-web` with OpenTelemetry in [`actix-web-opentelemetry`](https://github.com/OutThereLabs/actix-web-opentelemetry) +//! - parts of this project were heavily inspired by their implementation. They provide support for metrics +//! and instrumentation for the `awc` HTTP client, both out of scope for `tracing-actix-web`. +//! +//! [root span]: crate::RootSpan +//! [`actix-web`]: https://docs.rs/actix-web/4.0.0-beta.6/actix_web/index.html +mod middleware; +mod request_id; +mod root_span; +mod root_span_builder; -/// `TracingLogger` is a middleware to log request and response info in a structured format. -/// -/// `TracingLogger` is designed as a drop-in replacement of [`actix-web`]'s [`Logger`]. -/// -/// [`Logger`] is built on top of the [`log`] crate: you need to use regular expressions to parse -/// the request information out of the logged message. -/// -/// `TracingLogger` relies on [`tracing`], a modern instrumentation framework for structured -/// logging: all request information is captured as a machine-parsable set of key-value pairs. -/// It also enables propagation of context information to children spans. -/// -/// ## Usage -/// -/// Register `TracingLogger` as a middleware for your application using `.wrap` on `App`. -/// Add a `Subscriber` implementation to output logs to the console. -/// -/// ```rust -/// use actix_web::middleware::Logger; -/// use actix_web::App; -/// use tracing::{Subscriber, subscriber::set_global_default}; -/// use tracing_actix_web::TracingLogger; -/// use tracing_log::LogTracer; -/// use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer}; -/// use tracing_subscriber::{layer::SubscriberExt, EnvFilter, Registry}; -/// -/// /// Compose multiple layers into a `tracing`'s subscriber. -/// pub fn get_subscriber( -/// name: String, -/// env_filter: String -/// ) -> impl Subscriber + Send + Sync { -/// let env_filter = EnvFilter::try_from_default_env() -/// .unwrap_or(EnvFilter::new(env_filter)); -/// let formatting_layer = BunyanFormattingLayer::new( -/// name.into(), -/// std::io::stdout -/// ); -/// Registry::default() -/// .with(env_filter) -/// .with(JsonStorageLayer) -/// .with(formatting_layer) -/// } -/// -/// /// Register a subscriber as global default to process span data. -/// /// -/// /// It should only be called once! -/// pub fn init_subscriber(subscriber: impl Subscriber + Send + Sync) { -/// LogTracer::init().expect("Failed to set logger"); -/// set_global_default(subscriber).expect("Failed to set subscriber"); -/// } -/// -/// fn main() { -/// let subscriber = get_subscriber("app".into(), "info".into()); -/// init_subscriber(subscriber); -/// -/// let app = App::new().wrap(TracingLogger); -/// } -/// ``` -/// -/// [`actix-web`]: https://docs.rs/actix-web -/// [`Logger`]: https://docs.rs/actix-web/3.0.2/actix_web/middleware/struct.Logger.html -/// [`log`]: https://docs.rs/log -/// [`tracing`]: https://docs.rs/tracing -pub struct TracingLogger; - -impl Transform for TracingLogger -where - S: Service, Error = Error>, - S::Future: 'static, - B: 'static, -{ - type Response = ServiceResponse; - type Error = Error; - type Transform = TracingLoggerMiddleware; - type InitError = (); - type Future = Ready>; - - fn new_transform(&self, service: S) -> Self::Future { - ok(TracingLoggerMiddleware { service }) - } -} +pub use middleware::TracingLogger; +pub use request_id::RequestId; +pub use root_span::RootSpan; +pub use root_span_builder::{DefaultRootSpanBuilder, RootSpanBuilder}; #[doc(hidden)] -pub struct TracingLoggerMiddleware { - service: S, -} +pub mod root_span_macro; -/// A unique identifier for each incomming request. This ID is added to the logger span, even if -/// the `RequestId` is never extracted. -/// -/// Extracting a `RequestId` when the `TracingLogger` middleware is not registered, will result in -/// a internal server error. -/// -/// # Usage -/// ```rust -/// use actix_web::get; -/// use tracing_actix_web::RequestId; -/// use uuid::Uuid; -/// -/// #[get("/")] -/// async fn index(request_id: RequestId) -> String { -/// format!("{}", request_id) -/// } -/// -/// #[get("/2")] -/// async fn index2(request_id: RequestId) -> String { -/// let uuid: Uuid = request_id.into(); -/// format!("{}", uuid) -/// } -/// ``` -#[derive(Clone, Copy)] -pub struct RequestId(Uuid); - -impl std::ops::Deref for RequestId { - type Target = Uuid; - - fn deref(&self) -> &Self::Target { - &self.0 - } -} - -impl std::convert::Into for RequestId { - fn into(self) -> Uuid { - self.0 - } -} - -impl std::fmt::Display for RequestId { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { - write!(f, "{}", self.0) - } -} - -impl Service for TracingLoggerMiddleware -where - S: Service, Error = Error>, - S::Future: 'static, - B: 'static, -{ - type Response = ServiceResponse; - type Error = Error; - type Future = Pin>>>; - - fn poll_ready(&self, cx: &mut Context<'_>) -> Poll> { - self.service.poll_ready(cx) - } - - fn call(&self, req: ServiceRequest) -> Self::Future { - let user_agent = req - .headers() - .get("User-Agent") - .map(|h| h.to_str().unwrap_or("")) - .unwrap_or(""); - let request_id = RequestId(Uuid::new_v4()); - let span = tracing::info_span!( - "Request", - http.method = %req.method(), - request_path = %req.path(), - user_agent = %user_agent, - client_ip_address = %req.connection_info().realip_remote_addr().unwrap_or(""), - request_id = %request_id.0, - status_code = tracing::field::Empty, - ); - req.extensions_mut().insert(request_id); - let fut = self.service.call(req); - Box::pin( - async move { - let outcome = fut.await; - let status_code = match &outcome { - Ok(response) => response.response().status(), - Err(error) => error.as_response_error().status_code(), - }; - Span::current().record("status_code", &status_code.as_u16()); - outcome - } - .instrument(span), - ) - } -} - -impl FromRequest for RequestId { - type Error = (); - type Future = Ready>; - type Config = (); - - fn from_request(req: &HttpRequest, _: &mut Payload) -> Self::Future { - ready(req.extensions().get::().copied().ok_or(())) - } -} +#[cfg(feature = "opentelemetry_0_13")] +mod otel; diff --git a/src/middleware.rs b/src/middleware.rs new file mode 100644 index 000000000..48efd5ad4 --- /dev/null +++ b/src/middleware.rs @@ -0,0 +1,162 @@ +use crate::{DefaultRootSpanBuilder, RequestId, RootSpan, RootSpanBuilder}; +use actix_web::dev::{Service, ServiceRequest, ServiceResponse, Transform}; +use actix_web::{Error, HttpMessage}; +use futures::future::{ok, Ready}; +use futures::task::{Context, Poll}; +use std::future::Future; +use std::pin::Pin; +use tracing::Span; +use tracing_futures::Instrument; + +/// `TracingLogger` is a middleware to capture structured diagnostic when processing an HTTP request. +/// Check the crate-level documentation for an in-depth introduction. +/// +/// `TracingLogger` is designed as a drop-in replacement of [`actix-web`]'s [`Logger`]. +/// +/// # Usage +/// +/// Register `TracingLogger` as a middleware for your application using `.wrap` on `App`. +/// In this example we add a [`tracing::Subscriber`] to output structured logs to the console. +/// +/// ```rust +/// use actix_web::middleware::Logger; +/// use actix_web::App; +/// use tracing::{Subscriber, subscriber::set_global_default}; +/// use tracing_actix_web::TracingLogger; +/// use tracing_log::LogTracer; +/// use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer}; +/// use tracing_subscriber::{layer::SubscriberExt, EnvFilter, Registry}; +/// +/// /// Compose multiple layers into a `tracing`'s subscriber. +/// pub fn get_subscriber( +/// name: String, +/// env_filter: String +/// ) -> impl Subscriber + Send + Sync { +/// let env_filter = EnvFilter::try_from_default_env() +/// .unwrap_or(EnvFilter::new(env_filter)); +/// let formatting_layer = BunyanFormattingLayer::new( +/// name.into(), +/// std::io::stdout +/// ); +/// Registry::default() +/// .with(env_filter) +/// .with(JsonStorageLayer) +/// .with(formatting_layer) +/// } +/// +/// /// Register a subscriber as global default to process span data. +/// /// +/// /// It should only be called once! +/// pub fn init_subscriber(subscriber: impl Subscriber + Send + Sync) { +/// LogTracer::init().expect("Failed to set logger"); +/// set_global_default(subscriber).expect("Failed to set subscriber"); +/// } +/// +/// fn main() { +/// let subscriber = get_subscriber("app".into(), "info".into()); +/// init_subscriber(subscriber); +/// +/// let app = App::new().wrap(TracingLogger::default()); +/// } +/// ``` +/// +/// [`actix-web`]: https://docs.rs/actix-web +/// [`Logger`]: https://docs.rs/actix-web/3.0.2/actix_web/middleware/struct.Logger.html +/// [`tracing`]: https://docs.rs/tracing +pub struct TracingLogger { + root_span_builder: std::marker::PhantomData, +} + +impl Clone for TracingLogger { + fn clone(&self) -> Self { + Self::new() + } +} + +impl Default for TracingLogger { + fn default() -> Self { + TracingLogger::new() + } +} + +impl TracingLogger { + pub fn new() -> TracingLogger { + TracingLogger { + root_span_builder: Default::default(), + } + } +} + +impl Transform for TracingLogger +where + S: Service, Error = Error>, + S::Future: 'static, + B: 'static, + RootSpan: RootSpanBuilder, +{ + type Response = ServiceResponse; + type Error = Error; + type Transform = TracingLoggerMiddleware; + type InitError = (); + type Future = Ready>; + + fn new_transform(&self, service: S) -> Self::Future { + ok(TracingLoggerMiddleware { + service, + root_span_builder: std::marker::PhantomData::default(), + }) + } +} + +#[doc(hidden)] +pub struct TracingLoggerMiddleware { + service: S, + root_span_builder: std::marker::PhantomData, +} + +impl Service for TracingLoggerMiddleware +where + S: Service, Error = Error>, + S::Future: 'static, + B: 'static, + RootSpanType: RootSpanBuilder, +{ + type Response = ServiceResponse; + type Error = Error; + type Future = Pin>>>; + + fn poll_ready(&self, cx: &mut Context<'_>) -> Poll> { + self.service.poll_ready(cx) + } + + fn call(&self, req: ServiceRequest) -> Self::Future { + req.extensions_mut().insert(RequestId::generate()); + let root_span = RootSpanType::on_request_start(&req); + + let root_span_wrapper = RootSpan::new(root_span.clone()); + req.extensions_mut().insert(root_span_wrapper); + + let fut = self.service.call(req); + Box::pin( + async move { + let outcome = fut.await; + RootSpanType::on_request_end(Span::current(), &outcome); + + #[cfg(feature = "emit_event_on_error")] + if let Err(error) = &outcome { + let response_error = error.as_response_error(); + let status_code = response_error.status_code(); + let error_msg_prefix = + "Error encountered while processing the incoming HTTP request"; + if status_code.is_client_error() { + tracing::warn!("{}: {:?}", error_msg_prefix, response_error); + } else { + tracing::error!("{}: {:?}", error_msg_prefix, response_error); + } + } + outcome + } + .instrument(root_span), + ) + } +} diff --git a/src/otel.rs b/src/otel.rs new file mode 100644 index 000000000..8c9a67142 --- /dev/null +++ b/src/otel.rs @@ -0,0 +1,21 @@ +use opentelemetry::propagation::Extractor; + +pub(crate) struct RequestHeaderCarrier<'a> { + headers: &'a actix_web::http::HeaderMap, +} + +impl<'a> RequestHeaderCarrier<'a> { + pub(crate) fn new(headers: &'a actix_web::http::HeaderMap) -> Self { + RequestHeaderCarrier { headers } + } +} + +impl<'a> Extractor for RequestHeaderCarrier<'a> { + fn get(&self, key: &str) -> Option<&str> { + self.headers.get(key).and_then(|v| v.to_str().ok()) + } + + fn keys(&self) -> Vec<&str> { + self.headers.keys().map(|header| header.as_str()).collect() + } +} diff --git a/src/request_id.rs b/src/request_id.rs new file mode 100644 index 000000000..47d41f702 --- /dev/null +++ b/src/request_id.rs @@ -0,0 +1,64 @@ +use actix_web::dev::Payload; +use actix_web::{FromRequest, HttpRequest}; +use std::future::{ready, Ready}; +use uuid::Uuid; + +/// A unique identifier generated for each incoming request. +/// +/// Extracting a `RequestId` when the `TracingLogger` middleware is not registered will result in +/// an internal server error. +/// +/// # Usage +/// ```rust +/// use actix_web::get; +/// use tracing_actix_web::RequestId; +/// use uuid::Uuid; +/// +/// #[get("/")] +/// async fn index(request_id: RequestId) -> String { +/// format!("{}", request_id) +/// } +/// +/// #[get("/2")] +/// async fn index2(request_id: RequestId) -> String { +/// let uuid: Uuid = request_id.into(); +/// format!("{}", uuid) +/// } +/// ``` +#[derive(Clone, Copy)] +pub struct RequestId(Uuid); + +impl RequestId { + pub(crate) fn generate() -> Self { + Self(Uuid::new_v4()) + } +} + +impl std::ops::Deref for RequestId { + type Target = Uuid; + + fn deref(&self) -> &Self::Target { + &self.0 + } +} + +impl std::convert::Into for RequestId { + fn into(self) -> Uuid { + self.0 + } +} + +impl std::fmt::Display for RequestId { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "{}", self.0) + } +} +impl FromRequest for RequestId { + type Error = (); + type Future = Ready>; + type Config = (); + + fn from_request(req: &HttpRequest, _: &mut Payload) -> Self::Future { + ready(req.extensions().get::().copied().ok_or(())) + } +} diff --git a/src/root_span.rs b/src/root_span.rs new file mode 100644 index 000000000..4e09d8c37 --- /dev/null +++ b/src/root_span.rs @@ -0,0 +1,57 @@ +use actix_web::dev::Payload; +use actix_web::{FromRequest, HttpRequest}; +use std::future::{ready, Ready}; +use tracing::Span; + +#[derive(Clone)] +/// The root span associated to the in-flight current request. +/// +/// It can be used to populate additional properties using values computed or retrieved in the request +/// handler - see the crate-level documentation for more details. +/// +/// Extracting a `RootSpan` when the `TracingLogger` middleware is not registered will result in +/// an internal server error. +/// +/// # Usage +/// ```rust +/// use actix_web::get; +/// use tracing_actix_web::RootSpan; +/// use uuid::Uuid; +/// +/// #[get("/")] +/// async fn index(root_span: RootSpan) -> String { +/// root_span.record("route", &"/"); +/// # "Hello".to_string() +/// } +/// ``` +pub struct RootSpan(Span); + +impl RootSpan { + pub(crate) fn new(span: Span) -> Self { + Self(span) + } +} + +impl std::ops::Deref for RootSpan { + type Target = Span; + + fn deref(&self) -> &Self::Target { + &self.0 + } +} + +impl std::convert::Into for RootSpan { + fn into(self) -> Span { + self.0 + } +} + +impl FromRequest for RootSpan { + type Error = (); + type Future = Ready>; + type Config = (); + + fn from_request(req: &HttpRequest, _: &mut Payload) -> Self::Future { + ready(req.extensions().get::().cloned().ok_or(())) + } +} diff --git a/src/root_span_builder.rs b/src/root_span_builder.rs new file mode 100644 index 000000000..da39a3fcd --- /dev/null +++ b/src/root_span_builder.rs @@ -0,0 +1,59 @@ +use crate::root_span; +use actix_web::dev::{ServiceRequest, ServiceResponse}; +use actix_web::Error; +use tracing::Span; + +/// `RootSpanBuilder` allows you to customise the root span attached by +/// [`TracingLogger`] to incoming requests. +/// +/// [`TracingLogger`]: crate::TracingLogger +pub trait RootSpanBuilder { + fn on_request_start(request: &ServiceRequest) -> Span; + fn on_request_end(span: Span, outcome: &Result, Error>); +} + +/// The default [`RootSpanBuilder`] for [`TracingLogger`]. +/// +/// It captures: +/// - HTTP method (`http.method`); +/// - HTTP route (`http.route`), with templated parameters; +/// - HTTP version (`http.flavor`); +/// - HTTP host (`http.host`); +/// - Client IP (`http.client_ip`); +/// - User agent (`http.user_agent`); +/// - Request path (`http.target`); +/// - Status code (`http.status_code`); +/// - [Request id](crate::RequestId) (`request_id`); +/// - [OpenTelemetry trace identifier](https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/overview.md#spancontext) (`trace_id`). Empty if the feature is not enabled; +/// - OpenTelemetry span kind, set to `server` (`otel.kind`). +/// +/// All field names follow [OpenTelemetry's semantic convention](https://github.com/open-telemetry/opentelemetry-specification/tree/main/specification/trace/semantic_conventions). +/// +/// [`TracingLogger`]: crate::TracingLogger +pub struct DefaultRootSpanBuilder; + +impl RootSpanBuilder for DefaultRootSpanBuilder { + fn on_request_start(request: &ServiceRequest) -> Span { + root_span!(request) + } + + fn on_request_end(span: Span, outcome: &Result, Error>) { + match &outcome { + Ok(response) => { + span.record("http.status_code", &response.response().status().as_u16()); + span.record("otel.status_code", &"OK"); + } + Err(error) => { + let response_error = error.as_response_error(); + let status_code = response_error.status_code(); + span.record("http.status_code", &status_code.as_u16()); + + if status_code.is_client_error() { + span.record("otel.status_code", &"OK"); + } else { + span.record("otel.status_code", &"ERROR"); + } + } + }; + } +} diff --git a/src/root_span_macro.rs b/src/root_span_macro.rs new file mode 100644 index 000000000..db6217e50 --- /dev/null +++ b/src/root_span_macro.rs @@ -0,0 +1,189 @@ +#[macro_export] +/// [`root_span!`] creates a new [`tracing::Span`]. +/// It empowers you to add custom properties to the root span on top of the HTTP properties tracked +/// by [`DefaultRootSpanBuilder`]. +/// +/// # Why a macro? +/// +/// `tracing` requires all the properties attached to a span to be declared upfront, when the span is created. +/// You cannot add new ones afterwards. +/// This makes it extremely fast, but it pushes us to reach for macros when we need some level of composition. +/// +/// # Macro syntax +/// +/// The first argument passed to `root_span!` must be a reference to an [`actix_web::dev::ServiceRequest`]. +/// +/// ```rust +/// use actix_web::dev::{ServiceResponse, ServiceRequest}; +/// use actix_web::Error; +/// use tracing_actix_web::{TracingLogger, DefaultRootSpanBuilder, RootSpanBuilder, root_span}; +/// use tracing::Span; +/// +/// pub struct CustomRootSpanBuilder; +/// +/// impl RootSpanBuilder for CustomRootSpanBuilder { +/// fn on_request_start(request: &ServiceRequest) -> Span { +/// root_span!(request) +/// } +/// +/// fn on_request_end(span: Span, outcome: &Result, Error>) { +/// DefaultRootSpanBuilder::on_request_end(span, outcome); +/// } +/// } +/// ``` +/// +/// If nothing else is specified, the span generated by `root_span!` is identical to the one you'd +/// get by using `DefaultRootSpanBuilder`. +/// +/// You can define new fields following the same syntax of `tracing::info_span!` for fields: +/// +/// ```rust,should_panic +/// # let request: &actix_web::dev::ServiceRequest = todo!(); +/// +/// // Define a `client_id` field as empty. It might be populated later. +/// tracing_actix_web::root_span!(request, client_id = tracing::field::Empty); +/// +/// // Define a `name` field with a known value, `AppName`. +/// tracing_actix_web::root_span!(request, name = "AppName"); +/// +/// // Define an `app_id` field using the variable with the same name as value. +/// let app_id = "XYZ"; +/// tracing_actix_web::root_span!(request, app_id); +/// +/// // All together +/// tracing_actix_web::root_span!(request, client_id = tracing::field::Empty, name = "AppName", app_id); +/// ``` +/// +/// [`DefaultRootSpanBuilder`]: crate::DefaultRootSpanBuilder +macro_rules! root_span { + // Vanilla root span, with no additional fields + ($request:ident) => { + root_span!($request,) + }; + // One or more additional fields, comma separated + ($request:ident, $($field:tt)*) => { + { + let user_agent = $request + .headers() + .get("User-Agent") + .map(|h| h.to_str().unwrap_or("")) + .unwrap_or(""); + let http_route: std::borrow::Cow<'static, str> = $request + .match_pattern() + .map(Into::into) + .unwrap_or_else(|| "default".into()); + let http_method = $crate::root_span_macro::private::http_method_str($request.method()); + let connection_info = $request.connection_info(); + let request_id = $crate::root_span_macro::private::get_request_id($request); + let span = $crate::root_span_macro::private::tracing::info_span!( + "HTTP request", + http.method = %http_method, + http.route = %http_route, + http.flavor = %$crate::root_span_macro::private::http_flavor($request.version()), + http.scheme = %$crate::root_span_macro::private::http_scheme(connection_info.scheme()), + http.host = %connection_info.host(), + http.client_ip = %$request.connection_info().realip_remote_addr().unwrap_or(""), + http.user_agent = %user_agent, + http.target = %$request.uri().path_and_query().map(|p| p.as_str()).unwrap_or(""), + http.status_code = $crate::root_span_macro::private::tracing::field::Empty, + otel.kind = "server", + otel.status_code = $crate::root_span_macro::private::tracing::field::Empty, + trace_id = $crate::root_span_macro::private::tracing::field::Empty, + request_id = %request_id, + $($field)* + ); + std::mem::drop(connection_info); + + $crate::root_span_macro::private::set_otel_parent(&$request, &span); + span + } + }; +} + +#[doc(hidden)] +pub mod private { + //! This module exposes and re-exports various functions and traits as public in order to leverage them + //! in the code generated by the `root_span` macro. + //! Items in this module are not part of the public interface of `tracing-actix-web` - they are considered + //! implementation details and will change without notice in patch, minor and major releases. + use crate::RequestId; + use actix_web::dev::ServiceRequest; + use actix_web::http::{Method, Version}; + use std::borrow::Cow; + + pub use tracing; + + #[cfg(not(feature = "opentelemetry_0_13"))] + #[doc(hidden)] + pub fn set_otel_parent(_req: &ServiceRequest, _span: &tracing::Span) { + // No-op if the OpenTelemetry feature is not active + } + + #[cfg(feature = "opentelemetry_0_13")] + #[doc(hidden)] + pub fn set_otel_parent(req: &ServiceRequest, span: &tracing::Span) { + use opentelemetry::trace::TraceContextExt as _; + use tracing_opentelemetry::OpenTelemetrySpanExt as _; + + let parent_context = opentelemetry::global::get_text_map_propagator(|propagator| { + propagator.extract(&crate::otel::RequestHeaderCarrier::new(req.headers())) + }); + span.set_parent(parent_context); + // If we have a remote parent span, this will be the parent's trace identifier. + // If not, it will be the newly generated trace identifier with this request as root span. + let trace_id = span.context().span().span_context().trace_id().to_hex(); + span.record("trace_id", &tracing::field::display(trace_id)); + } + + #[doc(hidden)] + #[inline] + pub fn http_method_str(method: &Method) -> Cow<'static, str> { + match method { + &Method::OPTIONS => "OPTIONS".into(), + &Method::GET => "GET".into(), + &Method::POST => "POST".into(), + &Method::PUT => "PUT".into(), + &Method::DELETE => "DELETE".into(), + &Method::HEAD => "HEAD".into(), + &Method::TRACE => "TRACE".into(), + &Method::CONNECT => "CONNECT".into(), + &Method::PATCH => "PATCH".into(), + other => other.to_string().into(), + } + } + + #[doc(hidden)] + #[inline] + pub fn http_flavor(version: Version) -> Cow<'static, str> { + match version { + Version::HTTP_09 => "0.9".into(), + Version::HTTP_10 => "1.0".into(), + Version::HTTP_11 => "1.1".into(), + Version::HTTP_2 => "2.0".into(), + Version::HTTP_3 => "3.0".into(), + other => format!("{:?}", other).into(), + } + } + + #[doc(hidden)] + #[inline] + pub fn http_scheme(scheme: &str) -> Cow<'static, str> { + match scheme { + "http" => "http".into(), + "https" => "https".into(), + other => other.to_string().into(), + } + } + + #[doc(hidden)] + pub fn generate_request_id() -> RequestId { + RequestId::generate() + } + + #[doc(hidden)] + pub fn get_request_id(request: &ServiceRequest) -> RequestId { + use actix_web::HttpMessage; + + request.extensions().get::().cloned().unwrap() + } +}