feat: add tracing/tracing-subscriber, setup CustomPrettyFormatter & CustomJsonFormatter

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

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

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<S, N> FormatEvent<S, N> 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::<FormattedFields<N>>() {
+                    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<S, N> FormatEvent<S, N> 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<String, Value>,
+            #[serde(flatten)]
+            fields: Map<String, Value>,
+        }
+
+        let (message, fields, spans) = {
+            let mut message: Option<String> = None;
+            let mut fields: Map<String, Value> = Map::new();
+            let mut spans: Map<String, Value> = Map::new();
+
+            struct FieldVisitor<'a> {
+                message: &'a mut Option<String>,
+                fields: &'a mut Map<String, Value>,
+            }
+
+            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<String, Value> = Map::new();
+
+                    // Try to extract fields from FormattedFields
+                    let ext = span.extensions();
+                    if let Some(formatted_fields) = ext.get::<FormattedFields<N>>() {
+                        // Try to parse as JSON first
+                        if let Ok(json_fields) = serde_json::from_str::<Map<String, Value>>(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)
+    }
+}

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<dyn tracing::Subscriber + Send + Sync> = 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");
+}

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");