enhanced logging implementation

src/logger.rs

@@ -2,10 +2,39 @@ use std::io::Write;
 use std::sync::mpsc::{channel, Sender};
 use std::thread::{self, JoinHandle};
 use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH};
+use std::fmt;
+use std::sync::Arc;
+
+
+
+/// Differnt log levels
+#[derive(Debug, Clone, PartialEq, Eq, Ord, PartialOrd, Copy)]
+#[allow(dead_code)]
+pub enum LogLevel {
+    INFO,
+    WARN,
+    DEBUG,
+    ERROR,
+    FATAL,
+    TRACE,
+}
+
+impl fmt::Display for LogLevel {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        match self {
+            LogLevel::DEBUG => write!(f, "DEBUG"),
+            LogLevel::INFO => write!(f, "INFO"),
+            LogLevel::WARN => write!(f, "WARN"),
+            LogLevel::ERROR => write!(f, "ERROR"),
+            LogLevel::FATAL => write!(f, "FATAL"),
+            LogLevel::TRACE => write!(f, "TRACE"),
+        }
+    }
+}
 
 struct SimpleTime;
 impl SimpleTime {
-    fn epoch_to_ymdhms(seconds: u64) -> (i32, u32, u32, u32, u32, u32) {
+    fn epoch_to_ymdhms(seconds: u64, nanos: u32) -> (i32, u32, u32, u32, u32, u32, u32) {
         // Constants for time calculations
         const SECONDS_IN_MINUTE: u64 = 60;
         const SECONDS_IN_HOUR: u64 = 3600;
@@ -55,29 +84,51 @@ impl SimpleTime {
         let minute = ((remaining_seconds % SECONDS_IN_HOUR) / SECONDS_IN_MINUTE) as u32;
         let second = (remaining_seconds % SECONDS_IN_MINUTE) as u32;
 
-        (year, month as u32 + 1, day as u32, hour, minute, second)
+        // calculate millisecs from nanosecs
+        let millis = nanos / 1_000_000;
+
+        (year, month as u32 + 1, day as u32, hour, minute, second, millis)
     }
     pub fn get_current_timestamp() -> String {
         let now = SystemTime::now();
         let since_epoch = now.duration_since(UNIX_EPOCH).expect("Time went backwards");
         let secs = since_epoch.as_secs();
-        let (year, month, day, hour, minute, second) = Self::epoch_to_ymdhms(secs);
+        let nanos = since_epoch.subsec_nanos();
+        let (year, month, day, hour, minute, second, millis) = Self::epoch_to_ymdhms(secs, nanos);
 
         format!(
-            "{:04}/{:02}/{:02} - {:02}:{:02}:{:02}",
-            year, month, day, hour, minute, second
+            "{:04}-{:02}-{:02} {:02}:{:02}:{:02}.{:03}",
+            year, month, day, hour, minute, second, millis
         )
     }
 }
 
-pub struct Logger {
-    tx: Sender<String>,
+// Log message with metadata
+struct LogMessage {
+    timestamp: String,
+    level: LogLevel,
+    component: String,
+    content: String,
+}
+
+struct LoggerCore {
+    tx: Sender<LogMessage>,
     _thread: JoinHandle<()>,
 }
 
+pub struct Logger {
+    core: Arc<LoggerCore>,
+    component: Arc<String>,
+    min_level: LogLevel,
+}
+
 impl Logger {
-    pub fn new<W: Sized + Write + Send + Sync + 'static>(mut writer: W) -> Logger {
-        let (tx, rx) = channel::<String>();
+    pub fn new<W: Sized + Write + Send + Sync + 'static>(
+        mut writer: W,
+        min_level: LogLevel,
+        component: &str
+    ) -> Logger {
+        let (tx, rx) = channel::<LogMessage>();
         let thread = thread::spawn(move || {
             let mut last_flush = Instant::now();
             let mut buff = Vec::new();
@@ -86,7 +137,13 @@ impl Logger {
             loop {
                 let msg = rx.recv_timeout(timeout);
                 match msg {
-                    Ok(msg) => buff.push(msg),
+                    Ok(msg) => {
+                        let formatted = format!(
+                            "{} [{}] [{}] {}\n",
+                            msg.timestamp, msg.level, msg.component, msg.content
+                        );
+                        buff.push(formatted);
+                    },
                     Err(std::sync::mpsc::RecvTimeoutError::Timeout) => {}
                     Err(_) => break,
                 }
@@ -100,7 +157,7 @@ impl Logger {
                         }
                         let wr = writer.write_all(buff.join("").as_bytes());
                         if wr.is_err() {
-                            println!("{:?}", wr);
+                            println!("Failed to write to log: {:?}", wr);
                         }
                         let _ = writer.flush();
 
@@ -110,23 +167,85 @@ impl Logger {
                 }
             }
         });
+
+        Logger {
+            core: Arc::new(LoggerCore {
+                tx,
+                _thread: thread,
+            }),
+            component: Arc::new(component.to_string()),
+            min_level,
+        }
+    }
+
+    // New logger with different component but sharing same output
+    pub fn with_component(&self, component: &str) -> Logger {
         Logger {
-            tx,
-            _thread: thread,
+            core: Arc::clone(&self.core),
+            component: Arc::new(component.to_string()),
+            min_level: self.min_level,
         }
     }
 
-    pub fn msg(&self, content: String) {
-        let content = format!("[{}] - {}\n", SimpleTime::get_current_timestamp(), content);
-        let _ = self.tx.send(content);
+    pub fn log(&self, level: LogLevel, content: String) {
+        if level < self.min_level {
+            return;
+        }
+
+        let log_msg = LogMessage {
+            timestamp: SimpleTime::get_current_timestamp(),
+            level,
+            component: (*self.component).clone(),
+            content,
+        };
+        // Send the log message to the channel
+        let _ = self.core.tx.send(log_msg);
+    }
+
+    pub fn debug(&self, content: String) {
+        self.log(LogLevel::DEBUG, content);
+    }
+
+    /// Log a message with INFO level
+    pub fn info(&self, content: String) {
+        self.log(LogLevel::INFO, content);
     }
-}
 
-// #[cfg(test)]
-// use std::io::stdout;
+    /// Log a message with WARN level
+    pub fn warn(&self, content: String) {
+        self.log(LogLevel::WARN, content);
+    }
 
-// #[test]
-// fn test_basic() {
-//     let mut logs = Logger::new(stdout());
-//     logs.msg("test".to_string());
-// }
+    /// Log a message with ERROR level
+    pub fn error(&self, content: String) {
+        self.log(LogLevel::ERROR, content);
+    }
+
+    /// Log a message with FATAL level
+    #[allow(dead_code)]
+    pub fn fatal(&self, content: String) {
+        self.log(LogLevel::FATAL, content);
+    }
+    /// Log a message with TRACE level 
+    #[allow(dead_code)] 
+    pub fn trace(&self, content: String) {
+        self.log(LogLevel::TRACE, content);
+    }
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+    use std::io::stdout;
+
+    #[test]
+    fn test_basic() {
+        let logs = Logger::new(stdout(), LogLevel::DEBUG, "test");
+        logs.info("test message".to_string());
+        logs.debug("debug info".to_string());
+
+        // Create a sub-logger with a different component
+        let sub_logger = logs.with_component("sub-component");
+        sub_logger.warn("warning from sub-component".to_string());
+    }
+}

src/main.rs

@@ -15,7 +15,8 @@ use config::Config;
 use hteapot::{Hteapot, HttpRequest, HttpResponse, HttpStatus};
 use utils::get_mime_tipe;
 
-use logger::Logger;
+use logger::{Logger, LogLevel};
+use std::time::Instant;
 
 const VERSION: &str = env!("CARGO_PKG_VERSION");
 
@@ -95,37 +96,66 @@ fn main() {
     let logger = match config.log_file.clone() {
         Some(file_name) => {
             let file = fs::File::create(file_name.clone());
-            let file = file.unwrap();
-            Logger::new(file)
+            match file {
+                Ok(file) => Logger::new(file, LogLevel::INFO, "main"),
+                Err(e) => {
+                    println!("Failed to create log file: {:?}. Using stdout instead.", e);
+                    Logger::new(io::stdout(), LogLevel::INFO, "main")
+                }
+            }
         }
-        None => Logger::new(io::stdout()),
+        None => Logger::new(io::stdout(), LogLevel::INFO, "main"),
     };
 
     let cache: Mutex<Cache> = Mutex::new(Cache::new(config.cache_ttl as u64));
     let server = Hteapot::new_threaded(config.host.as_str(), config.port, config.threads);
-    logger.msg(format!(
+    logger.info(format!(
         "Server started at http://{}:{}",
         config.host, config.port
     ));
     if config.cache {
-        logger.msg("Cache Enabled".to_string());
+        logger.info("Cache Enabled".to_string());
     }
     if proxy_only {
         logger
-            .msg("WARNING: All requests are proxied to /. Local paths won’t be used.".to_string());
+            .warn("WARNING: All requests are proxied to /. Local paths won’t be used.".to_string());
     }
+
+    // Create component loggers
+    let proxy_logger = logger.with_component("proxy");
+    let cache_logger = logger.with_component("cache");
+    let http_logger = logger.with_component("http");
+
+
     server.listen(move |req| {
         // SERVER CORE
         // for each request
-        logger.msg(format!("Request {} {}", req.method.to_str(), req.path));
+        let start_time = Instant::now();
+        let req_method = req.method.to_str();
+        let req_path = req.path.clone();
+
+
+        http_logger.info(format!("Request {} {}", req.method.to_str(), req.path));
+
         let is_proxy = is_proxy(&config, req.clone());
 
         if proxy_only || is_proxy.is_some() {
             let (host, proxy_req) = is_proxy.unwrap();
+            proxy_logger.info(format!(
+                "Proxying request {} {} to {}",
+                req_method, req_path, host
+            ));
             let res = proxy_req.brew(host.as_str());
+            let elapsed = start_time.elapsed();
             if res.is_ok() {
-                return res.unwrap();
+                let response = res.unwrap();
+                proxy_logger.info(format!(
+                    "Proxy request processed in {:.6}ms",
+                    elapsed.as_secs_f64() * 1000.0
+                ));
+                return response;
             } else {
+                proxy_logger.error(format!("Proxy request failed: {:?}", res.err()));
                 return HttpResponse::new(
                     HttpStatus::InternalServerError,
                     "Internal Server Error",
@@ -141,23 +171,40 @@ fn main() {
         }
 
         if !Path::new(full_path.as_str()).exists() {
-            logger.msg(format!("path {} does not exist", req.path));
+            http_logger.warn(format!("Path {} does not exist", req.path));
             return HttpResponse::new(HttpStatus::NotFound, "Not found", None);
         }
         let mimetype = get_mime_tipe(&full_path);
         let content: Option<Vec<u8>> = if config.cache {
             let mut cachee = cache.lock().expect("Error locking cache");
+            let cache_start = Instant::now();
             let mut r = cachee.get(req.path.clone());
             if r.is_none() {
+                cache_logger.debug(format!("cache miss for {}", req.path));
                 r = serve_file(&full_path);
                 if r.is_some() {
+                    cache_logger.info(format!("Adding {} to cache", req.path));
                     cachee.set(req.path.clone(), r.clone().unwrap());
                 }
+            } else {
+                cache_logger.debug(format!("cache hit for {}", req.path));
             }
+
+            let cache_elapsed = cache_start.elapsed();
+            cache_logger.debug(format!(
+                "Cache operation completed in {:.6}µs", 
+                cache_elapsed.as_micros()
+            ));
             r
         } else {
             serve_file(&full_path)
         };
+
+        let elapsed = start_time.elapsed();
+        http_logger.info(format!(
+            "Request processed in {:.6}ms",
+            elapsed.as_secs_f64() * 1000.0
+        ));
         match content {
             Some(c) => HttpResponse::new(HttpStatus::OK, c, headers!("Content-Type" => mimetype)),
             None => HttpResponse::new(HttpStatus::NotFound, "Not found", None),