From 36319db10e1f72bc42315234a985f7c0836ee1f7 Mon Sep 17 00:00:00 2001 From: "glm-5.1" Date: Thu, 11 Jun 2026 12:47:19 +0000 Subject: [PATCH] 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 --- Cargo.lock | 79 ++++++++++++++++++ Cargo.toml | 2 +- src/logging/format.rs | 189 +++++++++++++++++++++++++++++++++++++++++- src/logging/mod.rs | 111 +++++++++++++++++++++++++ src/tls/config.rs | 30 +++++-- 5 files changed, 400 insertions(+), 11 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 07fd9ce..5ac2c75 100644 --- 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]] diff --git a/Cargo.toml b/Cargo.toml index 8f6ca51..64b2969 100644 --- 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"] } diff --git a/src/logging/format.rs b/src/logging/format.rs index beaa712..56745f6 100644 --- 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 = 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); + } +} diff --git a/src/logging/mod.rs b/src/logging/mod.rs index db7b59d..5bc25d6 100644 --- 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::().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, 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, 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"); + } +} diff --git a/src/tls/config.rs b/src/tls/config.rs index a6c917e..1b705b7 100644 --- 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()); } -} \ No newline at end of file +}