From 27dd80830f099a9196e5f4d8a18797e2c3e9d7b8 Mon Sep 17 00:00:00 2001 From: Daniel Flanagan Date: Wed, 15 May 2024 17:13:41 -0500 Subject: [PATCH] Tracing with axum/tower_http via layer --- Cargo.lock | 11 ---------- Cargo.toml | 8 +++---- src/cli.rs | 9 +++++++- src/observe.rs | 18 +++++++++++++--- src/router.rs | 58 ++++++++++++++++++++++++++++++++++++++++++++++++-- 5 files changed, 82 insertions(+), 22 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 3637d2b..dd61458 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -814,11 +814,9 @@ dependencies = [ "minijinja", "notify", "pathdiff", - "redact", "serde", "thiserror", "tokio", - "tower", "tower-http", "tower-livereload", "tracing", @@ -1123,15 +1121,6 @@ dependencies = [ "proc-macro2", ] -[[package]] -name = "redact" -version = "0.1.9" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b7301863b5e5486c9f18320ccc1aedce9a5fdf3056ae89fa021933d6f054430f" -dependencies = [ - "serde", -] - [[package]] name = "redox_syscall" version = "0.4.1" diff --git a/Cargo.toml b/Cargo.toml index 7861f31..f1e342c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -19,20 +19,18 @@ panic = "abort" # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html [dependencies] -axum = { version = "0.7.5", features = ["macros", "tokio"] } -clap = { version = "4.5.4", features = ["derive"] } +axum = { version = "0.7.5", features = ["macros", "tokio", "tracing"] } +clap = { version = "4.5.4", features = ["derive", "env"] } color-eyre = "0.6.3" config = "0.14.0" futures = "0.3.30" minijinja = { version = "2.0.1", features = ["loader"] } notify = "6.1.1" pathdiff = "0.2.1" -redact = { version = "0.1.9", features = ["serde"] } serde = "1.0.201" thiserror = "1.0.60" tokio = { version = "1.37.0", features = ["full"] } -tower = "0.4.13" -tower-http = { version = "0.5.2", features = ["fs"] } +tower-http = { version = "0.5.2", features = ["fs", "trace"] } tower-livereload = "0.9.2" tracing = "0.1.40" tracing-subscriber = { version = "0.3.18", features = ["env-filter"] } diff --git a/src/cli.rs b/src/cli.rs index e1a14f2..dd51b89 100644 --- a/src/cli.rs +++ b/src/cli.rs @@ -1,4 +1,4 @@ -use crate::{prelude::*, router::NewRouterError}; +use crate::{observe, prelude::*, router::NewRouterError}; use prelude::*; use thiserror::Error; @@ -13,6 +13,9 @@ mod prelude { pub struct Cli { #[command(subcommand)] command: Commands, + + #[arg(global = true, long, value_enum, default_value = "info,lyrs=trace")] + log_env_filter: String, } #[derive(Subcommand)] @@ -64,10 +67,14 @@ pub fn cli() -> Cli { pub enum ExecError { #[error("run error: {0}")] Run(#[from] RunError), + + #[error("{0}")] + Eyre(#[from] color_eyre::Report), } impl Cli { pub async fn exec(self) -> Result<(), ExecError> { + observe::setup_logging(&self.log_env_filter)?; match self.command { Commands::Run(args) => Ok(args.run().await?), } diff --git a/src/observe.rs b/src/observe.rs index 6e10124..e2e66ff 100644 --- a/src/observe.rs +++ b/src/observe.rs @@ -1,11 +1,23 @@ -pub fn setup_logging() { - color_eyre::install().expect("Failed to install color_eyre"); +use crate::prelude::*; + +pub fn setup_logging(env_filter: &str) -> Result<(), color_eyre::Report> { + color_eyre::install()?; let filter = tracing_subscriber::EnvFilter::builder() .with_default_directive(::from( tracing::level_filters::LevelFilter::TRACE, )) - .parse_lossy("info,lyrs=trace"); + .parse_lossy(env_filter); tracing_subscriber::fmt().with_env_filter(filter).init(); + + let filter = tracing_subscriber::EnvFilter::builder() + .with_default_directive(::from( + tracing::level_filters::LevelFilter::TRACE, + )) + .parse_lossy(env_filter); + + info!("{filter}"); + + Ok(()) } diff --git a/src/router.rs b/src/router.rs index f177579..b1812a9 100644 --- a/src/router.rs +++ b/src/router.rs @@ -1,3 +1,5 @@ +use std::time::Duration; + use crate::{ file_watcher::FileWatcher, prelude::*, @@ -5,16 +7,19 @@ use crate::{ static_files, }; use axum::{ - extract::State, - http::StatusCode, + body::Bytes, + extract::{MatchedPath, State}, + http::{HeaderMap, Request, Response, StatusCode}, response::{Html, IntoResponse}, routing::get, Router, }; use minijinja::context; +use tower_http::{classify::ServerErrorsFailureClass, trace::TraceLayer}; use tower_livereload::LiveReloadLayer; use thiserror::Error; +use tracing::{info_span, Span}; #[derive(Error, Debug)] pub enum NewRouterError { @@ -71,6 +76,52 @@ pub async fn router( .route("/", get(index)) .route("/about", get(about)) .nest_service("/static", static_file_service) + // `TraceLayer` is provided by tower-http so you have to add that as a dependency. + // It provides good defaults but is also very customizable. + // + // See https://docs.rs/tower-http/0.1.1/tower_http/trace/index.html for more details. + // + // If you want to customize the behavior using closures here is how. + .layer( + TraceLayer::new_for_http() + .make_span_with(|request: &Request<_>| { + // Log the matched route's path (with placeholders not filled in). + // Use request.uri() or OriginalUri if you want the real path. + let matched_path = request + .extensions() + .get::() + .map(MatchedPath::as_str); + + info_span!( + "http_request", + method = ?request.method(), + matched_path, + some_other_field = tracing::field::Empty, + ) + }) + .on_request(|_request: &Request<_>, _span: &Span| { + // You can use `_span.record("some_other_field", value)` in one of these + // closures to attach a value to the initially empty field in the info_span + // created above. + }) + .on_response(|response: &Response<_>, latency: Duration, _span: &Span| { + trace!("on_response: {response:?} in {latency:?}"); + }) + .on_body_chunk(|_chunk: &Bytes, _latency: Duration, _span: &Span| { + // ... + }) + .on_eos( + |_trailers: Option<&HeaderMap>, _stream_duration: Duration, _span: &Span| { + // ... + }, + ) + .on_failure( + |error: ServerErrorsFailureClass, latency: Duration, _span: &Span| { + error!("on_failure: {error:?} in {latency:?}"); + // ... + }, + ), + ) .with_state(state.clone()); if let Some(lr) = live_reload_layer { @@ -82,6 +133,7 @@ pub async fn router( Ok((result, watchers)) } +#[instrument(skip(state))] async fn index(State(state): State) -> ReqResult> { Ok(Html( state @@ -90,6 +142,8 @@ async fn index(State(state): State) -> ReqResult> { .await?, )) } + +#[instrument(skip(state))] async fn about(State(state): State) -> ReqResult> { Ok(Html( state