diff --git a/radicle-httpd/Cargo.toml b/radicle-httpd/Cargo.toml index fa7b5c2a..7152366d 100644 --- a/radicle-httpd/Cargo.toml +++ b/radicle-httpd/Cargo.toml @@ -24,8 +24,8 @@ fastrand = { version = "1.7.0" } flate2 = { version = "1" } hyper = { version = "0.14.17", default-features = false } lexopt = { version = "0.2.1" } -radicle-surf = { version = "0.9.0", default-features = false, features = ["serde"] } nonempty = { version = "0.8.1", features = ["serialize"] } +radicle-surf = { version = "0.9.0", default-features = false, features = ["serde"] } serde = { version = "1", features = ["derive"] } serde_json = { version = "1", features = ["preserve_order"] } thiserror = { version = "1" } @@ -40,10 +40,12 @@ tracing-subscriber = { version = "0.3", default-features = false, features = ["s path = "../radicle" version = "0.2.0" +[dependencies.radicle-cli] +path = "../radicle-cli" + [dev-dependencies] hyper = { version = "0.14.17", default-features = false, features = ["client"] } pretty_assertions = { version = "1.3.0" } -radicle-cli = { path = "../radicle-cli" } radicle-crypto = { path = "../radicle-crypto" } tempfile = { version = "3.3.0" } tower = { version = "0.4", features = ["util"] } diff --git a/radicle-httpd/src/lib.rs b/radicle-httpd/src/lib.rs index f69bf097..59a25293 100644 --- a/radicle-httpd/src/lib.rs +++ b/radicle-httpd/src/lib.rs @@ -8,12 +8,15 @@ use std::str; use std::sync::Arc; use std::time::Duration; +use ::tracing::Span; use anyhow::Context as _; -use axum::body::{Body, BoxBody}; +use axum::body::{Body, BoxBody, HttpBody}; use axum::http::{Request, Response}; +use axum::middleware; use axum::Router; use tower_http::trace::TraceLayer; -use tracing::Span; + +use tracing_extra::{tracing_middleware, ColoredStatus, Paint, RequestId, TracingInfo}; mod api; mod axum_extra; @@ -21,6 +24,7 @@ mod git; mod raw; #[cfg(test)] mod test; +mod tracing_extra; #[derive(Debug, Clone)] pub struct Options { @@ -38,6 +42,7 @@ pub async fn run(options: Options) -> anyhow::Result<()> { tracing::info!("{}", str::from_utf8(&git_version)?.trim()); let profile = Arc::new(radicle::Profile::load()?); + let request_id = RequestId::new(); tracing::info!("using radicle home at {}", profile.home().display()); @@ -52,23 +57,36 @@ pub async fn run(options: Options) -> anyhow::Result<()> { .merge(git_router) .nest("/api", api_router) .nest("/raw", raw_router) + .layer(middleware::from_fn(tracing_middleware)) .layer( TraceLayer::new_for_http() - .make_span_with(|request: &Request| { - tracing::info_span!( - "request", - method = %request.method(), - uri = %request.uri(), - status = tracing::field::Empty, - latency = tracing::field::Empty, - ) + .make_span_with(move |_request: &Request| { + tracing::info_span!("request", id = %request_id.clone().next()) }) .on_response( - |response: &Response, latency: Duration, span: &Span| { - span.record("status", &tracing::field::debug(response.status())); - span.record("latency", &tracing::field::debug(latency)); - - tracing::info!("Processed"); + |response: &Response, latency: Duration, _span: &Span| { + if let Some(info) = response.extensions().get::() { + tracing::info!( + "{} \"{} {} {:?}\" {} {:?} {}", + info.connect_info.0, + info.method, + info.uri, + info.version, + ColoredStatus(response.status()), + latency, + Paint::dim( + response + .body() + .size_hint() + .exact() + .map(|n| n.to_string()) + .unwrap_or("0".to_string()) + .into() + ), + ); + } else { + tracing::info!("Processed"); + } }, ), ) diff --git a/radicle-httpd/src/main.rs b/radicle-httpd/src/main.rs index 4e13ae3b..4dac4b78 100644 --- a/radicle-httpd/src/main.rs +++ b/radicle-httpd/src/main.rs @@ -18,7 +18,9 @@ mod logger { #[cfg(not(feature = "logfmt"))] mod logger { pub fn subscriber() -> impl tracing::Subscriber { - tracing_subscriber::FmtSubscriber::new() + tracing_subscriber::FmtSubscriber::builder() + .with_target(false) + .finish() } } diff --git a/radicle-httpd/src/tracing_extra.rs b/radicle-httpd/src/tracing_extra.rs new file mode 100644 index 00000000..1e0b4c78 --- /dev/null +++ b/radicle-httpd/src/tracing_extra.rs @@ -0,0 +1,68 @@ +use std::fmt; +use std::net::SocketAddr; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::Arc; + +use axum::extract::ConnectInfo; +use axum::http::Request; +use axum::middleware::Next; +use axum::response::IntoResponse; +use axum::Extension; +use hyper::{Method, StatusCode, Uri, Version}; + +pub use radicle_cli::terminal::ansi::Paint; + +#[derive(Clone)] +pub struct RequestId(Arc); + +impl RequestId { + pub fn new() -> RequestId { + RequestId(Arc::new(0.into())) + } + + pub fn next(&mut self) -> u64 { + self.0.fetch_add(1, Ordering::SeqCst) + } +} + +pub struct TracingInfo { + pub connect_info: ConnectInfo, + pub method: Method, + pub version: Version, + pub uri: Uri, +} + +pub struct ColoredStatus(pub StatusCode); + +impl fmt::Display for ColoredStatus { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self.0.as_u16() { + 200..=299 => write!(f, "{}", Paint::green(self.0)), + 300..=399 => write!(f, "{}", Paint::blue(self.0)), + 400..=499 => write!(f, "{}", Paint::red(self.0)), + _ => write!(f, "{}", Paint::yellow(self.0)), + } + } +} + +pub async fn tracing_middleware(request: Request, next: Next) -> impl IntoResponse { + let connect_info = *request + .extensions() + .get::>() + .unwrap(); + + let method = request.method().clone(); + let version = request.version(); + let uri = request.uri().clone(); + + let tracing_info = TracingInfo { + connect_info, + method, + version, + uri, + }; + + let response = next.run(request).await; + + (Extension(tracing_info), response) +}