From 3d1f05a0f92f2a82d5b1725d72c1f1e5574f07ca Mon Sep 17 00:00:00 2001 From: samwuel simiyu Date: Thu, 10 Apr 2025 12:32:48 +0300 Subject: [PATCH] enhanced logging implementation --- src/logger.rs | 167 ++++++++++++++++++++++++++++++++++++++++++-------- src/main.rs | 67 +++++++++++++++++--- 2 files changed, 200 insertions(+), 34 deletions(-) diff --git a/src/logger.rs b/src/logger.rs index d6c4f8f..f61b19f 100644 --- a/src/logger.rs +++ b/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, +// Log message with metadata +struct LogMessage { + timestamp: String, + level: LogLevel, + component: String, + content: String, +} + +struct LoggerCore { + tx: Sender, _thread: JoinHandle<()>, } +pub struct Logger { + core: Arc, + component: Arc, + min_level: LogLevel, +} + impl Logger { - pub fn new(mut writer: W) -> Logger { - let (tx, rx) = channel::(); + pub fn new( + mut writer: W, + min_level: LogLevel, + component: &str + ) -> Logger { + let (tx, rx) = channel::(); 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()); + } +} \ No newline at end of file diff --git a/src/main.rs b/src/main.rs index ada2202..ffb911b 100644 --- a/src/main.rs +++ b/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 = 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> = 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),