Implement structured logging with tracing, dual output, and fail2ban-compatible format

- Add logging::init() with dual output (file + stdout) via tracing-subscriber Layer composition - Support configurable log level via LoggingConfig.level and JSON/text format via LoggingConfig.format - Create log file and parent directories when log_file_path is configured - Add KvVisitor for custom key=value event field formatting - Add log_request!, log_rate_limit!, log_upstream_error!, log_config_reload! macros with REQUEST, RATE_LIMIT, UPSTREAM_ERROR, CONFIG_RELOAD prefixes - Add format_event_fields() for extracting structured fields from tracing events - Add tracing-subscriber env-filter and json features to Cargo.toml - Add unit tests for KvVisitor formatting, log macros, and init function - Apply cargo fmt to existing tls/config.rs tests
2026-06-11 12:47:19 +00:00
parent 468adb21de
commit 36319db10e
5 changed files with 400 additions and 11 deletions
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -17,6 +17,15 @@ version = "2.0.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "320119579fcad9c21884f5c4861d16174d0e06250625266f50fe6898340abefa"

+[[package]]
+name = "aho-corasick"
+version = "1.1.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ddd31a130427c27518df266943a5308ed92d4b226cc639f5a8f1002816174301"
+dependencies = [
+ "memchr",
+]
+
 [[package]]
 name = "android_system_properties"
 version = "0.1.5"
@@ -1136,6 +1145,15 @@ version = "0.4.32"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "953f07c43838f8e6f9758cab68bf5bed85465e7587ebe0b823f1bcd81978ad3a"

+[[package]]
+name = "matchers"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558"
+dependencies = [
+ "regex-automata 0.1.10",
+]
+
 [[package]]
 name = "matchit"
 version = "0.8.4"
@@ -1474,6 +1492,50 @@ dependencies = [
 "bitflags",
 ]

+[[package]]
+name = "regex"
+version = "1.12.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f1292b7759ae1cb9ec195452d1390a074f0cd8541ab7a5a8c31cd6db45d4a6ba"
+dependencies = [
+ "aho-corasick",
+ "memchr",
+ "regex-automata 0.4.14",
+ "regex-syntax 0.8.11",
+]
+
+[[package]]
+name = "regex-automata"
+version = "0.1.10"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132"
+dependencies = [
+ "regex-syntax 0.6.29",
+]
+
+[[package]]
+name = "regex-automata"
+version = "0.4.14"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "6e1dd4122fc1595e8162618945476892eefca7b88c52820e74af6262213cae8f"
+dependencies = [
+ "aho-corasick",
+ "memchr",
+ "regex-syntax 0.8.11",
+]
+
+[[package]]
+name = "regex-syntax"
+version = "0.6.29"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1"
+
+[[package]]
+name = "regex-syntax"
+version = "0.8.11"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d6f6ff9a378485b298a5286656da665ba74413d36db0979633275d2e708145d4"
+
 [[package]]
 name = "reqwest"
 version = "0.12.28"
@@ -2213,18 +2275,35 @@ dependencies = [
 "tracing-core",
 ]

+[[package]]
+name = "tracing-serde"
+version = "0.2.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "704b1aeb7be0d0a84fc9828cae51dab5970fee5088f83d1dd7ee6f6246fc6ff1"
+dependencies = [
+ "serde",
+ "tracing-core",
+]
+
 [[package]]
 name = "tracing-subscriber"
 version = "0.3.19"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "e8189decb5ac0fa7bc8b96b7cb9b2701d60d48805aca84a238004d665fcc4008"
 dependencies = [
+ "matchers",
 "nu-ansi-term",
+ "once_cell",
+ "regex",
+ "serde",
+ "serde_json",
 "sharded-slab",
 "smallvec",
 "thread_local",
+ "tracing",
 "tracing-core",
 "tracing-log",
+ "tracing-serde",
 ]

 [[package]]
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -24,7 +24,7 @@ serde = { version = "=1.0.228", features = ["derive"] }
 toml = "=0.8.23"
 arc-swap = "=1.7.1"
 tracing = "=0.1.41"
-tracing-subscriber = "=0.3.19"
+tracing-subscriber = { version = "=0.3.19", features = ["env-filter", "json"] }
 rustls-pemfile = "=2.2.0"
 rustls-pki-types = "=1.12.0"
 clap = { version = "=4.6.1", features = ["derive"] }
--- a/src/logging/format.rs
+++ b/src/logging/format.rs
@@ -1,2 +1,187 @@
-#[allow(dead_code)]
-pub struct LogFormat;
+#[derive(Default)]
+struct KvVisitor {
+    pairs: Vec<(String, String)>,
+}
+
+impl KvVisitor {
+    fn format(&self) -> String {
+        let parts: Vec<String> = self
+            .pairs
+            .iter()
+            .map(|(k, v)| {
+                if v.contains(' ') || v.contains('"') {
+                    format!(r#"{}="{}""#, k, v.replace('"', "\\\""))
+                } else {
+                    format!("{}={}", k, v)
+                }
+            })
+            .collect();
+        parts.join(" ")
+    }
+}
+
+impl tracing::field::Visit for KvVisitor {
+    fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
+        self.pairs
+            .push((field.name().to_string(), value.to_string()));
+    }
+
+    fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
+        self.pairs
+            .push((field.name().to_string(), format!("{:?}", value)));
+    }
+
+    fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
+        self.pairs
+            .push((field.name().to_string(), value.to_string()));
+    }
+
+    fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
+        self.pairs
+            .push((field.name().to_string(), value.to_string()));
+    }
+
+    fn record_bool(&mut self, field: &tracing::field::Field, value: bool) {
+        self.pairs
+            .push((field.name().to_string(), value.to_string()));
+    }
+}
+
+pub fn format_event_fields(event: &tracing::Event<'_>) -> String {
+    let mut visitor = KvVisitor::default();
+    event.record(&mut visitor);
+    visitor.format()
+}
+
+#[macro_export]
+macro_rules! log_request {
+    ($client_ip:expr, $host:expr, $method:expr, $path:expr, $status:expr, $upstream:expr, $duration_ms:expr) => {
+        tracing::info!(
+            prefix = "REQUEST",
+            client_ip = %$client_ip,
+            host = %$host,
+            method = %$method,
+            path = %$path,
+            status = %$status,
+            upstream = %$upstream,
+            duration_ms = %$duration_ms,
+        )
+    };
+}
+
+#[macro_export]
+macro_rules! log_rate_limit {
+    ($client_ip:expr, $host:expr, $path:expr, $status:expr) => {
+        tracing::warn!(
+            prefix = "RATE_LIMIT",
+            client_ip = %$client_ip,
+            host = %$host,
+            path = %$path,
+            status = %$status,
+        )
+    };
+}
+
+#[macro_export]
+macro_rules! log_upstream_error {
+    ($host:expr, $upstream:expr, $error:expr) => {
+        tracing::warn!(
+            prefix = "UPSTREAM_ERROR",
+            host = %$host,
+            upstream = %$upstream,
+            error = %$error,
+        )
+    };
+}
+
+#[macro_export]
+macro_rules! log_config_reload {
+    ($status:expr, $sites:expr) => {
+        tracing::info!(
+            prefix = "CONFIG_RELOAD",
+            status = %$status,
+            sites = %$sites,
+        )
+    };
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+
+    #[test]
+    fn kv_visitor_formats_simple_key_value() {
+        let mut visitor = KvVisitor::default();
+        visitor
+            .pairs
+            .push(("client_ip".to_string(), "203.0.113.50".to_string()));
+        visitor
+            .pairs
+            .push(("status".to_string(), "200".to_string()));
+        assert_eq!(visitor.format(), "client_ip=203.0.113.50 status=200");
+    }
+
+    #[test]
+    fn kv_visitor_quotes_values_with_spaces() {
+        let mut visitor = KvVisitor::default();
+        visitor
+            .pairs
+            .push(("error".to_string(), "connection refused".to_string()));
+        assert_eq!(visitor.format(), r#"error="connection refused""#);
+    }
+
+    #[test]
+    fn kv_visitor_escapes_quotes_in_values() {
+        let mut visitor = KvVisitor::default();
+        visitor
+            .pairs
+            .push(("error".to_string(), r#"connection "timeout""#.to_string()));
+        let formatted = visitor.format();
+        assert!(
+            formatted.contains(r#"connection \"timeout\""#),
+            "got: {}",
+            formatted
+        );
+    }
+
+    #[test]
+    fn kv_visitor_handles_numeric_values() {
+        let mut visitor = KvVisitor::default();
+        visitor
+            .pairs
+            .push(("status".to_string(), "200".to_string()));
+        visitor
+            .pairs
+            .push(("duration_ms".to_string(), "45".to_string()));
+        let formatted = visitor.format();
+        assert!(formatted.contains("status=200"));
+        assert!(formatted.contains("duration_ms=45"));
+    }
+
+    #[test]
+    fn kv_visitor_handles_empty() {
+        let visitor = KvVisitor::default();
+        assert_eq!(visitor.format(), "");
+    }
+
+    #[test]
+    fn log_macros_compile() {
+        use tracing_subscriber::layer::SubscriberExt;
+
+        let subscriber = tracing_subscriber::registry().with(tracing_subscriber::fmt::layer());
+        let _guard = tracing::subscriber::set_default(subscriber);
+
+        log_request!(
+            "203.0.113.50",
+            "git.alk.dev",
+            "GET",
+            "/user/repo",
+            200,
+            "127.0.0.1:3000",
+            45u64
+        );
+        log_rate_limit!("10.0.0.1", "example.com", "/login", 429u16);
+        log_upstream_error!("git.alk.dev", "127.0.0.1:3000", "connection refused");
+        log_config_reload!("success", 1u32);
+    }
+}
--- a/src/logging/mod.rs
+++ b/src/logging/mod.rs
@@ -1 +1,112 @@
 pub mod format;
+
+use crate::config::static_config::LoggingConfig;
+use anyhow::Result;
+use std::fs::File;
+use std::sync::Arc;
+use tracing::Level;
+use tracing_subscriber::layer::SubscriberExt;
+use tracing_subscriber::util::SubscriberInitExt;
+use tracing_subscriber::EnvFilter;
+use tracing_subscriber::Layer;
+
+pub fn init(config: &LoggingConfig) -> Result<()> {
+    let level = config.level.parse::<Level>().unwrap_or(Level::INFO);
+
+    let env_filter = make_env_filter(level);
+
+    match config.format.as_str() {
+        "json" => init_json(env_filter, &config.log_file_path, level),
+        _ => init_text(env_filter, &config.log_file_path, level),
+    }
+}
+
+fn make_env_filter(level: Level) -> EnvFilter {
+    EnvFilter::from_default_env().add_directive(level.into())
+}
+
+fn init_json(env_filter: EnvFilter, log_file_path: &Option<String>, level: Level) -> Result<()> {
+    match log_file_path {
+        Some(path) => {
+            if let Some(parent) = std::path::Path::new(path).parent() {
+                if !parent.as_os_str().is_empty() {
+                    std::fs::create_dir_all(parent)?;
+                }
+            }
+            let file = File::create(path)?;
+            let file_writer = Arc::new(file);
+
+            let file_env_filter = make_env_filter(level);
+            let stdout_layer = tracing_subscriber::fmt::layer()
+                .json()
+                .with_filter(env_filter);
+            let file_layer = tracing_subscriber::fmt::layer()
+                .json()
+                .with_writer(file_writer)
+                .with_filter(file_env_filter);
+            tracing_subscriber::registry()
+                .with(stdout_layer)
+                .with(file_layer)
+                .try_init()?;
+        }
+        None => {
+            let layer = tracing_subscriber::fmt::layer()
+                .json()
+                .with_filter(env_filter);
+            tracing_subscriber::registry().with(layer).try_init()?;
+        }
+    }
+
+    Ok(())
+}
+
+fn init_text(env_filter: EnvFilter, log_file_path: &Option<String>, level: Level) -> Result<()> {
+    match log_file_path {
+        Some(path) => {
+            if let Some(parent) = std::path::Path::new(path).parent() {
+                if !parent.as_os_str().is_empty() {
+                    std::fs::create_dir_all(parent)?;
+                }
+            }
+            let file = File::create(path)?;
+            let file_writer = Arc::new(file);
+
+            let file_env_filter = make_env_filter(level);
+            let stdout_layer = tracing_subscriber::fmt::layer().with_filter(env_filter);
+            let file_layer = tracing_subscriber::fmt::layer()
+                .with_writer(file_writer)
+                .with_filter(file_env_filter);
+            tracing_subscriber::registry()
+                .with(stdout_layer)
+                .with(file_layer)
+                .try_init()?;
+        }
+        None => {
+            let layer = tracing_subscriber::fmt::layer().with_filter(env_filter);
+            tracing_subscriber::registry().with(layer).try_init()?;
+        }
+    }
+
+    Ok(())
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+    use crate::config::static_config::LoggingConfig;
+
+    #[test]
+    fn init_creates_log_directory_and_file() {
+        let dir = tempfile::tempdir().unwrap();
+        let log_path = dir.path().join("logs").join("access.log");
+        let config = LoggingConfig {
+            level: "info".to_string(),
+            format: "text".to_string(),
+            log_file_path: Some(log_path.to_string_lossy().to_string()),
+        };
+
+        let result = init(&config);
+        assert!(result.is_ok(), "init failed: {:?}", result.err());
+        assert!(log_path.exists(), "log file should be created");
+    }
+}
--- a/src/tls/config.rs
+++ b/src/tls/config.rs
@@ -207,13 +207,27 @@ mod tests {
            .map(|cs| format!("{cs:?}"))
            .collect();

-        assert!(cipher_suites.iter().any(|cs| cs.contains("AES_256_GCM_SHA384")));
-        assert!(cipher_suites.iter().any(|cs| cs.contains("AES_128_GCM_SHA256")));
-        assert!(cipher_suites.iter().any(|cs| cs.contains("CHACHA20_POLY1305_SHA256")));
-        assert!(cipher_suites.iter().any(|cs| cs.contains("ECDHE_ECDSA_WITH_AES_256_GCM_SHA384")));
-        assert!(cipher_suites.iter().any(|cs| cs.contains("ECDHE_ECDSA_WITH_AES_128_GCM_SHA256")));
-        assert!(cipher_suites.iter().any(|cs| cs.contains("ECDHE_RSA_WITH_AES_256_GCM_SHA384")));
-        assert!(cipher_suites.iter().any(|cs| cs.contains("ECDHE_RSA_WITH_AES_128_GCM_SHA256")));
+        assert!(cipher_suites
+            .iter()
+            .any(|cs| cs.contains("AES_256_GCM_SHA384")));
+        assert!(cipher_suites
+            .iter()
+            .any(|cs| cs.contains("AES_128_GCM_SHA256")));
+        assert!(cipher_suites
+            .iter()
+            .any(|cs| cs.contains("CHACHA20_POLY1305_SHA256")));
+        assert!(cipher_suites
+            .iter()
+            .any(|cs| cs.contains("ECDHE_ECDSA_WITH_AES_256_GCM_SHA384")));
+        assert!(cipher_suites
+            .iter()
+            .any(|cs| cs.contains("ECDHE_ECDSA_WITH_AES_128_GCM_SHA256")));
+        assert!(cipher_suites
+            .iter()
+            .any(|cs| cs.contains("ECDHE_RSA_WITH_AES_256_GCM_SHA384")));
+        assert!(cipher_suites
+            .iter()
+            .any(|cs| cs.contains("ECDHE_RSA_WITH_AES_128_GCM_SHA256")));
    }

    #[test]
@@ -310,4 +324,4 @@ mod tests {
        let result = load_private_key("/nonexistent/path/key.pem");
        assert!(result.is_err());
    }
-}
+}