diff --git a/Cargo.lock b/Cargo.lock index 61ec1da84..7c2bb0941 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -494,7 +494,7 @@ dependencies = [ "find-msvc-tools", "jobserver", "libc", - "shlex 2.0.1", + "shlex", ] [[package]] @@ -1804,7 +1804,6 @@ dependencies = [ "crossterm", "dyn-clone", "fuzzy-matcher", - "tempfile", "unicode-segmentation", "unicode-width", ] @@ -2778,7 +2777,6 @@ dependencies = [ "radicle-job", "radicle-search", "radicle-surf", - "radicle-term", "serde", "serde_json", "tempfile", @@ -2788,7 +2786,6 @@ dependencies = [ "tower", "tower-http", "tracing", - "tracing-logfmt", "tracing-subscriber", "url", "uuid", @@ -2852,17 +2849,6 @@ dependencies = [ "tracing-subscriber", ] -[[package]] -name = "radicle-signals" -version = "0.12.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "137929529ba88f1f82cce97d29c14bd26a234a747db23fc7f6643796a37cc956" -dependencies = [ - "libc", - "signals_receipts", - "windows 0.62.2", -] - [[package]] name = "radicle-surf" version = "0.29.0" @@ -2881,26 +2867,6 @@ dependencies = [ "url", ] -[[package]] -name = "radicle-term" -version = "0.19.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8f7059000b2441b45d30d0584d26c22dfd97907c22a329d281fb427002f9458e" -dependencies = [ - "anstyle-query", - "crossterm", - "indicatif", - "inquire", - "libc", - "radicle-signals", - "shlex 1.3.0", - "thiserror 2.0.19", - "unicode-display-width", - "unicode-segmentation", - "winsplit", - "zeroize", -] - [[package]] name = "rand" version = "0.8.7" @@ -3228,18 +3194,6 @@ dependencies = [ "zeroize", ] -[[package]] -name = "sem_safe" -version = "0.2.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "be9665e92f9b596cf2b20a8c0f55126cfee3514307740a859f1b25bc929e4947" -dependencies = [ - "base64 0.22.1", - "errno", - "getrandom 0.2.17", - "libc", -] - [[package]] name = "semver" version = "1.0.28" @@ -3387,12 +3341,6 @@ dependencies = [ "lazy_static", ] -[[package]] -name = "shlex" -version = "1.3.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0fda2ff0d084019ba4d7c6f371c95d8fd75ce3524c3cb8fb653a3023f6323e64" - [[package]] name = "shlex" version = "2.0.1" @@ -3430,18 +3378,6 @@ dependencies = [ "libc", ] -[[package]] -name = "signals_receipts" -version = "0.2.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8400878c2b53f6e3e224fcbdf20d87743a5c6547129f0a6a227f8282b6c6910b" -dependencies = [ - "cfg-if", - "errno", - "libc", - "sem_safe", -] - [[package]] name = "signature" version = "1.6.4" @@ -3999,15 +3935,13 @@ dependencies = [ ] [[package]] -name = "tracing-logfmt" -version = "0.3.7" +name = "tracing-serde" +version = "0.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a250055a3518b5efba928a18ffac8d32d42ea607a9affff4532144cd5b2e378e" +checksum = "704b1aeb7be0d0a84fc9828cae51dab5970fee5088f83d1dd7ee6f6246fc6ff1" dependencies = [ - "time", - "tracing", + "serde", "tracing-core", - "tracing-subscriber", ] [[package]] @@ -4020,10 +3954,13 @@ dependencies = [ "nu-ansi-term", "once_cell", "regex-automata", + "serde", + "serde_json", "sharded-slab", "thread_local", "tracing", "tracing-core", + "tracing-serde", ] [[package]] @@ -4061,15 +3998,6 @@ version = "2.9.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "dbc4bc3a9f746d862c45cb89d705aa10f187bb96c76001afab07a0d35ce60142" -[[package]] -name = "unicode-display-width" -version = "0.3.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9a43273b656140aa2bb8e65351fe87c255f0eca706b2538a9bd4a590a3490bf3" -dependencies = [ - "unicode-segmentation", -] - [[package]] name = "unicode-ident" version = "1.0.24" @@ -4358,27 +4286,6 @@ dependencies = [ "windows-targets", ] -[[package]] -name = "windows" -version = "0.62.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "527fadee13e0c05939a6a05d5bd6eec6cd2e3dbd648b9f8e447c6518133d8580" -dependencies = [ - "windows-collections", - "windows-core 0.62.2", - "windows-future", - "windows-numerics", -] - -[[package]] -name = "windows-collections" -version = "0.3.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "23b2d95af1a8a14a3c7367e1ed4fc9c20e0a26e79551b1454d72583c97cc6610" -dependencies = [ - "windows-core 0.62.2", -] - [[package]] name = "windows-core" version = "0.58.0" @@ -4405,17 +4312,6 @@ dependencies = [ "windows-strings 0.5.1", ] -[[package]] -name = "windows-future" -version = "0.3.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "e1d6f90251fe18a279739e78025bd6ddc52a7e22f921070ccdc67dde84c605cb" -dependencies = [ - "windows-core 0.62.2", - "windows-link", - "windows-threading", -] - [[package]] name = "windows-implement" version = "0.58.0" @@ -4466,16 +4362,6 @@ version = "0.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f0805222e57f7521d6a62e36fa9163bc891acd422f971defe97d64e70d0a4fe5" -[[package]] -name = "windows-numerics" -version = "0.3.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "6e2e40844ac143cdb44aead537bbf727de9b044e107a0f1220392177d15b0f26" -dependencies = [ - "windows-core 0.62.2", - "windows-link", -] - [[package]] name = "windows-result" version = "0.2.0" @@ -4547,15 +4433,6 @@ dependencies = [ "windows_x86_64_msvc", ] -[[package]] -name = "windows-threading" -version = "0.2.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3949bd5b99cafdf1c7ca86b43ca564028dfe27d66958f2470940f73d86d75b37" -dependencies = [ - "windows-link", -] - [[package]] name = "windows_aarch64_gnullvm" version = "0.52.6" @@ -4614,15 +4491,9 @@ dependencies = [ "log", "rand 0.8.7", "sync-ptr", - "windows 0.58.0", + "windows", ] -[[package]] -name = "winsplit" -version = "0.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3ab703352da6a72f35c39a533526393725640575bb211f61987a2748323ad956" - [[package]] name = "wit-bindgen" version = "0.57.1" diff --git a/crates/radicle-httpd/Cargo.toml b/crates/radicle-httpd/Cargo.toml index f7df79b18..66ba3e722 100644 --- a/crates/radicle-httpd/Cargo.toml +++ b/crates/radicle-httpd/Cargo.toml @@ -14,9 +14,6 @@ default = ["artifacts"] artifacts = [ "dep:radicle-artifact", ] -logfmt = [ - "tracing-logfmt", -] [[bin]] name = "radicle-httpd" @@ -40,7 +37,6 @@ radicle-artifact = { version = "0.18", optional = true } radicle-job = { version = "0.6.0" } radicle-search = { path = "../radicle-search" } radicle-surf = { workspace = true, features = ["serde"] } -radicle-term = { version = "0.19.1", default-features = false } serde.workspace = true serde_json = { workspace = true, features = ["preserve_order"] } thiserror.workspace = true @@ -48,8 +44,7 @@ tokio = { workspace = true, features = ["macros", "rt-multi-thread", "signal", " tokio-util = { version = "0.7.18", default-features = false, features = ["io"] } tower-http = { version = "0.6.6", default-features = false, features = ["trace", "cors", "set-header", "decompression-full"] } tracing.workspace = true -tracing-logfmt = { version = "0.3.5", optional = true } -tracing-subscriber = { workspace = true, features = ["env-filter"] } +tracing-subscriber = { workspace = true, features = ["env-filter", "json"] } url = { version = "2.5.4", features = ["serde"] } uuid = { version = "1.13.1", features = ["serde"] } diff --git a/crates/radicle-httpd/src/lib.rs b/crates/radicle-httpd/src/lib.rs index ad389df30..9491d1c63 100644 --- a/crates/radicle-httpd/src/lib.rs +++ b/crates/radicle-httpd/src/lib.rs @@ -32,12 +32,13 @@ use radicle::identity::RepoId; use radicle::Profile; use crate::api::RADICLE_VERSION; -use crate::tracing_extra::{tracing_middleware, ColoredStatus, Paint, RequestId, TracingInfo}; +use crate::tracing_extra::{log_response, tracing_middleware, RequestId, TracingInfo}; mod api; mod axum_extra; mod cache; mod git; +pub mod logger; mod raw; #[cfg(test)] mod test; @@ -142,27 +143,12 @@ pub async fn run(options: Options) -> anyhow::Result<()> { .on_response( |response: &hyper::Response, latency: Duration, _span: &Span| { if let Some(info) = response.extensions().get::() { - tracing::info!( - "{} \"{} {} {:?}\" {} {:?} {}", - match info.connect_info.0 { - DualAddr::Tcp(c) => c.to_string(), - #[cfg(unix)] - DualAddr::Uds(_) => "unix-socket".into() - }, - info.method, - info.uri, - info.version, - ColoredStatus(response.status()), + log_response( + logger::format(), + info, + response.status(), latency, - Paint::dim( - response - .body() - .size_hint() - .exact() - .map(|n| n.to_string()) - .unwrap_or("0".to_string()) - .into() - ), + response.body().size_hint().exact(), ); } else { tracing::info!("Processed"); @@ -236,36 +222,6 @@ async fn root_index_handler() -> impl IntoResponse { Json(response) } -pub mod logger { - use tracing::dispatcher::Dispatch; - - pub fn init() -> Result<(), tracing::subscriber::SetGlobalDefaultError> { - tracing::dispatcher::set_global_default(Dispatch::new(subscriber())) - } - - #[cfg(feature = "logfmt")] - pub fn subscriber() -> impl tracing::Subscriber { - use tracing_subscriber::layer::SubscriberExt as _; - use tracing_subscriber::EnvFilter; - - tracing_subscriber::Registry::default() - .with(EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"))) - .with(tracing_logfmt::layer()) - } - - #[cfg(not(feature = "logfmt"))] - pub fn subscriber() -> impl tracing::Subscriber { - use tracing_subscriber::EnvFilter; - - tracing_subscriber::FmtSubscriber::builder() - .with_target(false) - .with_env_filter( - EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info")), - ) - .finish() - } -} - #[cfg(test)] mod routes { use std::collections::HashMap; diff --git a/crates/radicle-httpd/src/logger.rs b/crates/radicle-httpd/src/logger.rs new file mode 100644 index 000000000..bb2876fc2 --- /dev/null +++ b/crates/radicle-httpd/src/logger.rs @@ -0,0 +1,111 @@ +use std::sync::OnceLock; + +use tracing::dispatcher::Dispatch; +use tracing_subscriber::fmt::MakeWriter; +use tracing_subscriber::layer::{Layered, SubscriberExt as _}; +use tracing_subscriber::registry::LookupSpan; +use tracing_subscriber::{EnvFilter, Layer, Registry}; + +pub const LOG_FORMAT_VAR: &str = "RADICLE_HTTPD_LOG_FORMAT"; + +type Filtered = Layered; +type BoxedLayer = Box + Send + Sync>; + +#[derive(Debug, Clone, Copy, PartialEq, Eq, Default)] +pub enum LogFormat { + #[default] + Text, + Json, +} + +impl LogFormat { + pub fn parse(value: Option<&str>) -> LogFormat { + match value.map(str::trim).map(str::to_lowercase).as_deref() { + None | Some("") | Some("text") => LogFormat::Text, + Some("json") => LogFormat::Json, + Some(other) => { + eprintln!("{LOG_FORMAT_VAR}: unknown format {other:?}, falling back to \"text\""); + LogFormat::Text + } + } + } + + pub fn from_env() -> LogFormat { + LogFormat::parse(std::env::var(LOG_FORMAT_VAR).ok().as_deref()) + } +} + +static FORMAT: OnceLock = OnceLock::new(); + +pub fn format() -> LogFormat { + *FORMAT.get_or_init(LogFormat::from_env) +} + +pub fn init() -> Result<(), tracing::subscriber::SetGlobalDefaultError> { + tracing::dispatcher::set_global_default(Dispatch::new(subscriber())) +} + +pub fn subscriber() -> impl tracing::Subscriber { + let filtered = Registry::default() + .with(EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"))); + + let layer: BoxedLayer = match format() { + LogFormat::Text => Box::new(text_layer(std::io::stdout)), + LogFormat::Json => Box::new(json_layer(std::io::stdout)), + }; + + filtered.with(layer) +} + +pub fn text_layer(writer: W) -> impl Layer +where + S: tracing::Subscriber + for<'a> LookupSpan<'a>, + W: for<'a> MakeWriter<'a> + Send + Sync + 'static, +{ + tracing_subscriber::fmt::layer() + .with_target(false) + .with_writer(writer) +} + +pub fn json_layer(writer: W) -> impl Layer +where + S: tracing::Subscriber + for<'a> LookupSpan<'a>, + W: for<'a> MakeWriter<'a> + Send + Sync + 'static, +{ + tracing_subscriber::fmt::layer() + .json() + .flatten_event(true) + .with_current_span(true) + .with_span_list(false) + .with_writer(writer) +} + +#[cfg(test)] +mod tests { + use super::LogFormat; + + #[test] + fn unset_variable_selects_text() { + assert_eq!(LogFormat::parse(None), LogFormat::Text); + } + + #[test] + fn json_selects_json() { + assert_eq!(LogFormat::parse(Some("json")), LogFormat::Json); + } + + #[test] + fn value_is_case_and_whitespace_insensitive() { + assert_eq!(LogFormat::parse(Some(" JSON \n")), LogFormat::Json); + } + + #[test] + fn unrecognised_value_falls_back_to_text() { + assert_eq!(LogFormat::parse(Some("yaml")), LogFormat::Text); + } + + #[test] + fn empty_value_selects_text() { + assert_eq!(LogFormat::parse(Some("")), LogFormat::Text); + } +} diff --git a/crates/radicle-httpd/src/main.rs b/crates/radicle-httpd/src/main.rs index d21ce9d3b..7f6babf0e 100644 --- a/crates/radicle-httpd/src/main.rs +++ b/crates/radicle-httpd/src/main.rs @@ -35,6 +35,8 @@ Environment RUST_LOG Set the log level (e.g. RUST_LOG=warn, or RUST_LOG=radicle_httpd=debug). Defaults to "info". + RADICLE_HTTPD_LOG_FORMAT Log rendering: text (default) or json. + Unrecognised values fall back to "text". "#; #[tokio::main] diff --git a/crates/radicle-httpd/src/tracing_extra.rs b/crates/radicle-httpd/src/tracing_extra.rs index af2f094cb..ad55332c6 100644 --- a/crates/radicle-httpd/src/tracing_extra.rs +++ b/crates/radicle-httpd/src/tracing_extra.rs @@ -1,6 +1,6 @@ -use std::fmt; use std::sync::atomic::{AtomicU64, Ordering}; use std::sync::Arc; +use std::time::Duration; use axum::body::Body; use axum::extract::ConnectInfo; @@ -11,7 +11,7 @@ use axum::Extension; use axum_listener::DualAddr; use hyper::{Method, StatusCode, Uri, Version}; -pub use radicle_term::ansi::Paint; +use crate::logger::LogFormat; #[derive(Clone)] pub struct RequestId(Arc); @@ -34,16 +34,40 @@ pub struct TracingInfo { pub uri: Uri, } -pub struct ColoredStatus(pub StatusCode); +pub fn log_response( + format: LogFormat, + info: &TracingInfo, + status: StatusCode, + latency: Duration, + bytes: Option, +) { + let client = match info.connect_info.0 { + DualAddr::Tcp(addr) => addr.to_string(), + #[cfg(unix)] + DualAddr::Uds(_) => "unix-socket".to_string(), + }; -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)), - } + match format { + LogFormat::Json => tracing::info!( + client = %client, + method = %info.method, + uri = %info.uri, + version = ?info.version, + status = status.as_u16(), + latency_ms = latency.as_micros() as f64 / 1000.0, + bytes = bytes.unwrap_or(0), + "request completed", + ), + LogFormat::Text => tracing::info!( + "{} \"{} {} {:?}\" {} {:?} {}", + client, + info.method, + info.uri, + info.version, + status, + latency, + bytes.unwrap_or(0), + ), } } @@ -69,3 +93,140 @@ pub async fn tracing_middleware(request: Request, next: Next) -> impl Into (Extension(tracing_info), response) } + +#[cfg(test)] +mod tests { + use std::io; + use std::net::SocketAddr; + use std::sync::{Arc, Mutex}; + use std::time::Duration; + + use tracing_subscriber::fmt::MakeWriter; + use tracing_subscriber::layer::SubscriberExt as _; + use tracing_subscriber::Layer; + + use super::*; + use crate::logger::{json_layer, text_layer, LogFormat}; + + #[derive(Clone, Default)] + struct Buffer(Arc>>); + + impl Buffer { + fn contents(&self) -> String { + String::from_utf8(self.0.lock().unwrap().clone()).unwrap() + } + } + + impl io::Write for Buffer { + fn write(&mut self, buf: &[u8]) -> io::Result { + self.0.lock().unwrap().write(buf) + } + + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } + } + + impl<'a> MakeWriter<'a> for Buffer { + type Writer = Buffer; + + fn make_writer(&'a self) -> Self::Writer { + self.clone() + } + } + + fn info() -> TracingInfo { + TracingInfo { + connect_info: ConnectInfo(DualAddr::Tcp(SocketAddr::from(([1, 2, 3, 4], 5678)))), + method: Method::GET, + version: hyper::Version::HTTP_11, + uri: "/api/v1/node".parse().unwrap(), + } + } + + fn capture(layer: L, f: impl FnOnce()) + where + L: Layer + Send + Sync + 'static, + { + let subscriber = tracing_subscriber::Registry::default().with(layer); + tracing::subscriber::with_default(subscriber, f); + } + + #[test] + fn json_format_logs_the_response_as_fields() { + let buffer = Buffer::default(); + capture(json_layer(buffer.clone()), || { + log_response( + LogFormat::Json, + &info(), + StatusCode::NOT_FOUND, + Duration::from_millis(7), + Some(1024), + ); + }); + + let record: serde_json::Value = serde_json::from_str(buffer.contents().trim()).unwrap(); + assert_eq!(record["client"], "1.2.3.4:5678"); + assert_eq!(record["method"], "GET"); + assert_eq!(record["uri"], "/api/v1/node"); + assert_eq!(record["version"], "HTTP/1.1"); + assert_eq!(record["status"], 404); + assert_eq!(record["latency_ms"], 7.0); + assert_eq!(record["bytes"], 1024); + } + + #[test] + fn json_format_reports_a_missing_body_size_as_zero_bytes() { + let buffer = Buffer::default(); + capture(json_layer(buffer.clone()), || { + log_response( + LogFormat::Json, + &info(), + StatusCode::OK, + Duration::from_millis(1), + None, + ); + }); + + let record: serde_json::Value = serde_json::from_str(buffer.contents().trim()).unwrap(); + assert_eq!(record["bytes"], 0); + } + + #[test] + fn text_format_keeps_the_single_line_layout() { + let buffer = Buffer::default(); + capture(text_layer(buffer.clone()), || { + log_response( + LogFormat::Text, + &info(), + StatusCode::NOT_FOUND, + Duration::from_millis(12), + Some(1024), + ); + }); + + let out = buffer.contents(); + assert!( + out.contains("1.2.3.4:5678 \"GET /api/v1/node HTTP/1.1\" 404 Not Found 12ms 1024"), + "got: {out:?}" + ); + } + + #[test] + fn text_format_adds_no_structured_fields() { + let buffer = Buffer::default(); + capture(text_layer(buffer.clone()), || { + log_response( + LogFormat::Text, + &info(), + StatusCode::OK, + Duration::from_millis(1), + Some(7), + ); + }); + + let out = buffer.contents(); + assert!(!out.contains("status="), "got: {out:?}"); + assert!(!out.contains("latency_ms="), "got: {out:?}"); + } +}