feat: enhence log format (#692)

src/http_logger.rs

@@ -1,8 +1,15 @@
-use std::{collections::HashMap, str::FromStr};
+use std::{
+    collections::HashMap,
+    str::FromStr,
+    time::{SystemTime, UNIX_EPOCH},
+};
+
+use chrono::{Local, SecondsFormat};
 
 use crate::{auth::get_auth_user, server::Request, utils::decode_uri};
 
-pub const DEFAULT_LOG_FORMAT: &str = r#"$remote_addr "$request" $status"#;
+pub const DEFAULT_LOG_FORMAT: &str =
+    r#"$time_iso8601 $log_level - $remote_addr "$request" $status"#;
 
 #[derive(Debug, Clone, PartialEq)]
 pub struct HttpLogger {
@@ -28,12 +35,17 @@ impl HttpLogger {
         for element in self.elements.iter() {
             match element {
                 LogElement::Variable(name) => match name.as_str() {
-                    "request" => {
+                    "request" | "request_method" | "request_uri" => {
                         let uri = req.uri().to_string();
-                        let uri = decode_uri(&uri)
+                        let decoded_uri = decode_uri(&uri)
                             .map(|s| sanitize_log_value(&s))
-                            .unwrap_or(uri);
+                            .unwrap_or_else(|| uri.clone());
-                        data.insert(name.to_string(), format!("{} {uri}", req.method()));
+                        data.entry("request".to_string())
+                            .or_insert_with(|| format!("{} {decoded_uri}", req.method()));
+                        data.entry("request_method".to_string())
+                            .or_insert_with(|| req.method().to_string());
+                        data.entry("request_uri".to_string())
+                            .or_insert_with(|| decoded_uri);
                     }
                     "remote_user" => {
                         if let Some(user) =
@@ -59,22 +71,62 @@ impl HttpLogger {
         if self.elements.is_empty() {
             return;
         }
+        let is_error = err.is_some();
+        let now = Local::now();
+        let time_local = now.to_rfc3339_opts(SecondsFormat::Secs, false);
+        let time_iso8601 = now.to_rfc3339_opts(SecondsFormat::Secs, true);
+        let msec = SystemTime::now()
+            .duration_since(UNIX_EPOCH)
+            .map(|d| format!("{:.3}", d.as_secs_f64()))
+            .unwrap_or_default();
+        let log_level = if is_error { "ERROR" } else { "INFO" };
+
         let mut output = String::new();
         for element in self.elements.iter() {
             match element {
                 LogElement::Literal(value) => output.push_str(value.as_str()),
-                LogElement::Header(name) | LogElement::Variable(name) => {
+                LogElement::Variable(name) => {
-                    output.push_str(data.get(name).map(|v| v.as_str()).unwrap_or("-"))
+                    let resolved = match name.as_str() {
+                        "time_local" => Some(time_local.as_str()),
+                        "time_iso8601" => Some(time_iso8601.as_str()),
+                        "msec" => Some(msec.as_str()),
+                        "log_level" => Some(log_level),
+                        _ => None,
+                    };
+                    let val = resolved
+                        .or_else(|| data.get(name.as_str()).map(|v| v.as_str()))
+                        .unwrap_or("-");
+                    output.push_str(val);
+                }
+                LogElement::Header(name) => {
+                    output.push_str(data.get(name.as_str()).map(|v| v.as_str()).unwrap_or("-"))
                 }
             }
         }
         match err {
-            Some(err) => error!("{output} {err}"),
+            Some(err) => emit_http_access(&format!("{output} {err}"), true),
-            None => info!("{output}"),
+            None => emit_http_access(&output, false),
         }
     }
 }
 
+/// Emit via the `log` crate with target `http_access` so the system logger
+/// prints the line verbatim (no extra timestamp/level prefix).
+fn emit_http_access(msg: &str, is_error: bool) {
+    let level = if is_error {
+        log::Level::Error
+    } else {
+        log::Level::Info
+    };
+    log::logger().log(
+        &log::Record::builder()
+            .args(format_args!("{}", msg))
+            .level(level)
+            .target("http_access")
+            .build(),
+    );
+}
+
 impl FromStr for HttpLogger {
     type Err = anyhow::Error;
     fn from_str(s: &str) -> Result<Self, Self::Err> {
@@ -109,12 +161,11 @@ impl FromStr for HttpLogger {
 
 fn sanitize_log_value(s: &str) -> String {
     s.chars()
-        .flat_map(|c| {
+        .flat_map(|c| match c {
-            if c.is_control() {
+            '\\' => vec!['\\', '\\'],
-                format!("\\x{:02x}", c as u32).chars().collect::<Vec<_>>()
+            '"' => vec!['\\', '"'],
-            } else {
+            c if c.is_control() => format!("\\x{:02x}", c as u32).chars().collect::<Vec<_>>(),
-                vec![c]
+            c => vec![c],
-            }
         })
         .collect()
 }

src/logger.rs

@@ -1,5 +1,4 @@
 use anyhow::{Context, Result};
-use chrono::{Local, SecondsFormat};
 use log::{Level, LevelFilter, Metadata, Record};
 use std::fs::{File, OpenOptions};
 use std::io::Write;
@@ -17,8 +16,7 @@ impl log::Log for SimpleLogger {
 
     fn log(&self, record: &Record) {
         if self.enabled(record.metadata()) {
-            let timestamp = Local::now().to_rfc3339_opts(SecondsFormat::Secs, true);
+            let text = record.args().to_string();
-            let text = format!("{} {} - {}", timestamp, record.level(), record.args());
             match &self.file {
                 Some(file) => {
                     if let Ok(mut file) = file.lock() {