Add RADICLE_HTTPD_LOG_FORMAT runtime switch

- Select text (default) or json log format at startup, not at
  compile time
- Emit the access log as structured fields (client, method, uri,
  version, status, latency_ms, bytes) in json
- Log status and size as plain text, since tracing-subscriber
  escapes ANSI codes
- Remove the logfmt feature and tracing-logfmt dependency
- Drop the radicle-term dependency
- Split format setup from lib.rs into logger.rs

Co-Authored-By: Daniel Norman <daniel@norman.life>

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"

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"] }
 

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<Body>, latency: Duration, _span: &Span| {
                         if let Some(info) = response.extensions().get::<TracingInfo>() {
-                            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;

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<EnvFilter, Registry>;
+type BoxedLayer = Box<dyn Layer<Filtered> + 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<LogFormat> = 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<S, W>(writer: W) -> impl Layer<S>
+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<S, W>(writer: W) -> impl Layer<S>
+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);
+    }
+}

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]

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<AtomicU64>);
@@ -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<u64>,
+) {
+    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<Body>, 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<Mutex<Vec<u8>>>);
+
+    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<usize> {
+            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<L>(layer: L, f: impl FnOnce())
+    where
+        L: Layer<tracing_subscriber::Registry> + 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:?}");
+    }
+}