diff --git a/Cargo.lock b/Cargo.lock index 5087bc0..bbbd760 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1809,7 +1809,7 @@ version = "0.1.1" [[package]] name = "pacman-server" -version = "0.1.1" +version = "0.3.2" dependencies = [ "async-trait", "axum", @@ -1823,7 +1823,11 @@ dependencies = [ "serde", "serde_json", "sqlx", + "time", "tokio", + "tracing", + "tracing-subscriber", + "yansi", ] [[package]] @@ -3280,6 +3284,16 @@ 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.20" @@ -3290,12 +3304,15 @@ dependencies = [ "nu-ansi-term", "once_cell", "regex-automata", + "serde", + "serde_json", "sharded-slab", "smallvec", "thread_local", "tracing", "tracing-core", "tracing-log", + "tracing-serde", ] [[package]] diff --git a/pacman-server/Cargo.toml b/pacman-server/Cargo.toml index f3cd462..be33d7c 100644 --- a/pacman-server/Cargo.toml +++ b/pacman-server/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "pacman-server" -version = "0.1.1" +version = "0.3.2" authors.workspace = true edition.workspace = true rust-version = "1.86.0" @@ -32,4 +32,8 @@ dashmap = "6.1" axum-cookie = "0.2" async-trait = "0.1" jsonwebtoken = { version = "9.3", default-features = false } +tracing = "0.1.41" +tracing-subscriber = { version = "0.3.20", features = ["env-filter", "json"] } +time = { version = "0.3", features = ["macros", "formatting"] } +yansi = "1" # validator = { version = "0.16", features = ["derive"] } diff --git a/pacman-server/src/formatter.rs b/pacman-server/src/formatter.rs new file mode 100644 index 0000000..8f0c2c3 --- /dev/null +++ b/pacman-server/src/formatter.rs @@ -0,0 +1,244 @@ +//! Custom tracing formatter +use serde::Serialize; +use serde_json::{Map, Value}; +use std::fmt; +use time::macros::format_description; +use time::{format_description::FormatItem, OffsetDateTime}; +use tracing::field::{Field, Visit}; +use tracing::{Event, Level, Subscriber}; +use tracing_subscriber::fmt::format::Writer; +use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields, FormattedFields}; +use tracing_subscriber::registry::LookupSpan; +use yansi::Paint; + +// Cached format description for timestamps +const TIMESTAMP_FORMAT: &[FormatItem<'static>] = format_description!("[hour]:[minute]:[second].[subsecond digits:5]"); + +/// A custom formatter with enhanced timestamp formatting +/// +/// Re-implementation of the Full formatter with improved timestamp display. +pub struct CustomPrettyFormatter; + +impl FormatEvent for CustomPrettyFormatter +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event(&self, ctx: &FmtContext<'_, S, N>, mut writer: Writer<'_>, event: &Event<'_>) -> fmt::Result { + let meta = event.metadata(); + + // 1) Timestamp (dimmed when ANSI) + let now = OffsetDateTime::now_utc(); + let formatted_time = now.format(&TIMESTAMP_FORMAT).map_err(|e| { + eprintln!("Failed to format timestamp: {}", e); + fmt::Error + })?; + write_dimmed(&mut writer, formatted_time)?; + writer.write_char(' ')?; + + // 2) Colored 5-char level like Full + write_colored_level(&mut writer, meta.level())?; + writer.write_char(' ')?; + + // 3) Span scope chain (bold names, fields in braces, dimmed ':') + if let Some(scope) = ctx.event_scope() { + let mut saw_any = false; + for span in scope.from_root() { + write_bold(&mut writer, span.metadata().name())?; + saw_any = true; + write_dimmed(&mut writer, ":")?; + + let ext = span.extensions(); + if let Some(fields) = &ext.get::>() { + if !fields.fields.is_empty() { + write_bold(&mut writer, "{")?; + writer.write_str(fields.fields.as_str())?; + write_bold(&mut writer, "}")?; + } + } + write_dimmed(&mut writer, ":")?; + } + if saw_any { + writer.write_char(' ')?; + } + } + + // 4) Target (dimmed), then a space + if writer.has_ansi_escapes() { + write!(writer, "{}: ", Paint::new(meta.target()).dim())?; + } else { + write!(writer, "{}: ", meta.target())?; + } + + // 5) Event fields + ctx.format_fields(writer.by_ref(), event)?; + + // 6) Newline + writeln!(writer) + } +} + +/// A custom JSON formatter that flattens fields to root level +/// +/// Outputs logs in the format: +/// { "message": "...", "level": "...", "customAttribute": "..." } +pub struct CustomJsonFormatter; + +impl FormatEvent for CustomJsonFormatter +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event(&self, ctx: &FmtContext<'_, S, N>, mut writer: Writer<'_>, event: &Event<'_>) -> fmt::Result { + let meta = event.metadata(); + + #[derive(Serialize)] + struct EventFields { + message: String, + level: String, + target: String, + #[serde(flatten)] + spans: Map, + #[serde(flatten)] + fields: Map, + } + + let (message, fields, spans) = { + let mut message: Option = None; + let mut fields: Map = Map::new(); + let mut spans: Map = Map::new(); + + struct FieldVisitor<'a> { + message: &'a mut Option, + fields: &'a mut Map, + } + + impl<'a> Visit for FieldVisitor<'a> { + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { + let key = field.name(); + if key == "message" { + *self.message = Some(format!("{:?}", value)); + } else { + self.fields.insert(key.to_string(), Value::String(format!("{:?}", value))); + } + } + + fn record_str(&mut self, field: &Field, value: &str) { + let key = field.name(); + if key == "message" { + *self.message = Some(value.to_string()); + } else { + self.fields.insert(key.to_string(), Value::String(value.to_string())); + } + } + + fn record_i64(&mut self, field: &Field, value: i64) { + let key = field.name(); + if key != "message" { + self.fields + .insert(key.to_string(), Value::Number(serde_json::Number::from(value))); + } + } + + fn record_u64(&mut self, field: &Field, value: u64) { + let key = field.name(); + if key != "message" { + self.fields + .insert(key.to_string(), Value::Number(serde_json::Number::from(value))); + } + } + + fn record_bool(&mut self, field: &Field, value: bool) { + let key = field.name(); + if key != "message" { + self.fields.insert(key.to_string(), Value::Bool(value)); + } + } + } + + let mut visitor = FieldVisitor { + message: &mut message, + fields: &mut fields, + }; + event.record(&mut visitor); + + // Collect span information from the span hierarchy + if let Some(scope) = ctx.event_scope() { + for span in scope.from_root() { + let span_name = span.metadata().name().to_string(); + let mut span_fields: Map = Map::new(); + + // Try to extract fields from FormattedFields + let ext = span.extensions(); + if let Some(formatted_fields) = ext.get::>() { + // Try to parse as JSON first + if let Ok(json_fields) = serde_json::from_str::>(formatted_fields.fields.as_str()) { + span_fields.extend(json_fields); + } else { + // If not valid JSON, treat the entire field string as a single field + span_fields.insert("raw".to_string(), Value::String(formatted_fields.fields.as_str().to_string())); + } + } + + // Insert span as a nested object directly into the spans map + spans.insert(span_name, Value::Object(span_fields)); + } + } + + (message, fields, spans) + }; + + let json = EventFields { + message: message.unwrap_or_default(), + level: meta.level().to_string(), + target: meta.target().to_string(), + spans, + fields, + }; + + writeln!( + writer, + "{}", + serde_json::to_string(&json).unwrap_or_else(|_| "{}".to_string()) + ) + } +} + +/// Write the verbosity level with the same coloring/alignment as the Full formatter. +fn write_colored_level(writer: &mut Writer<'_>, level: &Level) -> fmt::Result { + if writer.has_ansi_escapes() { + let paint = match *level { + Level::TRACE => Paint::new("TRACE").magenta(), + Level::DEBUG => Paint::new("DEBUG").blue(), + Level::INFO => Paint::new(" INFO").green(), + Level::WARN => Paint::new(" WARN").yellow(), + Level::ERROR => Paint::new("ERROR").red(), + }; + write!(writer, "{}", paint) + } else { + // Right-pad to width 5 like Full's non-ANSI mode + match *level { + Level::TRACE => write!(writer, "{:>5}", "TRACE"), + Level::DEBUG => write!(writer, "{:>5}", "DEBUG"), + Level::INFO => write!(writer, "{:>5}", " INFO"), + Level::WARN => write!(writer, "{:>5}", " WARN"), + Level::ERROR => write!(writer, "{:>5}", "ERROR"), + } + } +} + +fn write_dimmed(writer: &mut Writer<'_>, s: impl fmt::Display) -> fmt::Result { + if writer.has_ansi_escapes() { + write!(writer, "{}", Paint::new(s).dim()) + } else { + write!(writer, "{}", s) + } +} + +fn write_bold(writer: &mut Writer<'_>, s: impl fmt::Display) -> fmt::Result { + if writer.has_ansi_escapes() { + write!(writer, "{}", Paint::new(s).bold()) + } else { + write!(writer, "{}", s) + } +} diff --git a/pacman-server/src/logging.rs b/pacman-server/src/logging.rs new file mode 100644 index 0000000..8f261f8 --- /dev/null +++ b/pacman-server/src/logging.rs @@ -0,0 +1,36 @@ +use tracing_subscriber::fmt::format::JsonFields; +use tracing_subscriber::{EnvFilter, FmtSubscriber}; + +use crate::config::Config; +use crate::formatter; + +/// Configure and initialize logging for the application +pub fn setup_logging(_config: &Config) { + // Allow RUST_LOG to override levels; default to info for our crate and warn elsewhere + let filter = + EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("warn,pacman_server=info,pacman_server::auth=info")); + + // Default to pretty for local dev; switchable later if we add CLI + let use_pretty = cfg!(debug_assertions); + + let subscriber: Box = if use_pretty { + Box::new( + FmtSubscriber::builder() + .with_target(true) + .event_format(formatter::CustomPrettyFormatter) + .with_env_filter(filter) + .finish(), + ) + } else { + Box::new( + FmtSubscriber::builder() + .with_target(true) + .event_format(formatter::CustomJsonFormatter) + .fmt_fields(JsonFields::new()) + .with_env_filter(filter) + .finish(), + ) + }; + + tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed"); +} diff --git a/pacman-server/src/main.rs b/pacman-server/src/main.rs index bbdfa43..3efc1f6 100644 --- a/pacman-server/src/main.rs +++ b/pacman-server/src/main.rs @@ -2,6 +2,8 @@ use axum::{routing::get, Router}; use axum_cookie::CookieLayer; use crate::{app::AppState, auth::AuthRegistry, config::Config}; +mod formatter; +mod logging; mod routes; mod app; @@ -10,7 +12,7 @@ mod config; mod errors; mod session; use std::sync::Arc; -use std::time::{Duration, Instant}; +use std::time::Instant; #[cfg(unix)] use tokio::signal::unix::{signal, SignalKind}; use tokio::sync::{watch, Notify}; @@ -26,6 +28,9 @@ async fn main() { // Load configuration let config: Config = config::load_config(); + // Initialize tracing subscriber + logging::setup_logging(&config); + let addr = std::net::SocketAddr::new(config.host, config.port); let shutdown_timeout = std::time::Duration::from_secs(config.shutdown_timeout_seconds as u64); let auth = AuthRegistry::new(&config).expect("auth initializer");