From e47ea57db21125372aeeae87ce555855a98adaab Mon Sep 17 00:00:00 2001 From: David Knaack Date: Wed, 4 Jan 2023 09:22:02 +0100 Subject: [PATCH] feat(logger): delete old logs & avoid more dup logs (#4348) * feat(logger): delete old logs & avoid more dup logs * `match` -> `let else` where possible --- Cargo.toml | 2 +- src/logger.rs | 385 +++++++++++++++++++++++++++++++++++++++++------- src/main.rs | 6 + src/test/mod.rs | 9 +- 4 files changed, 342 insertions(+), 60 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 67446753..85d2892c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -23,7 +23,7 @@ license = "ISC" readme = "README.md" repository = "https://github.com/starship/starship" # Note: MSRV is only intended as a hint, and only the latest version is officially supported in starship. -rust-version = "1.64" +rust-version = "1.65" description = """ The minimal, blazing-fast, and infinitely customizable prompt for any shell! ☄🌌️ """ diff --git a/src/logger.rs b/src/logger.rs index ca0c21be..7e86c10b 100644 --- a/src/logger.rs +++ b/src/logger.rs @@ -3,48 +3,109 @@ use log::{Level, LevelFilter, Metadata, Record}; use nu_ansi_term::Color; use once_cell::sync::OnceCell; use std::{ + cmp, collections::HashSet, env, fs::{self, File, OpenOptions}, io::Write, - path::PathBuf, - sync::Mutex, + path::{Path, PathBuf}, + sync::{Mutex, RwLock}, }; pub struct StarshipLogger { log_file: OnceCell>, log_file_path: PathBuf, - log_file_content: HashSet, + log_file_content: RwLock>, log_level: Level, } +/// Returns the path to the log directory. +pub fn get_log_dir() -> PathBuf { + env::var_os("STARSHIP_CACHE") + .map(PathBuf::from) + .unwrap_or_else(|| { + utils::home_dir() + .map(|home| home.join(".cache")) + .or_else(dirs_next::cache_dir) + .unwrap_or_else(std::env::temp_dir) + .join("starship") + }) +} + +/// Deletes all log files in the log directory that were modified more than 24 hours ago. +pub fn cleanup_log_files>(path: P) { + let log_dir = path.as_ref(); + let log_files = match fs::read_dir(log_dir) { + Ok(log_files) => log_files, + // Avoid noisily handling errors in this cleanup function. + Err(_) => return, + }; + + for file in log_files { + // Skip files that can't be read. + let Ok (file) = file else { + continue; + }; + + // Avoid deleting files that don't look like log files. + if !file + .path() + .file_name() + .unwrap_or_default() + .to_str() + .unwrap_or_default() + .starts_with("session_") + || file.path().extension() != Some("log".as_ref()) + { + continue; + } + + // Read metadata to check file age. + let Ok(metadata) = file.metadata() else { + continue; + }; + + // Avoid handling anything that isn't a file. + if !metadata.is_file() { + continue; + } + + // Get the file's modification time. + let Ok(modified) = metadata.modified() else { + continue; + }; + + // Delete the file if it hasn't changed in 24 hours. + if modified.elapsed().unwrap_or_default().as_secs() > 60 * 60 * 24 { + let _ = fs::remove_file(file.path()); + } + } +} + impl Default for StarshipLogger { fn default() -> Self { - let log_dir = env::var_os("STARSHIP_CACHE") - .map(PathBuf::from) - .unwrap_or_else(|| { - utils::home_dir() - .expect("Unable to find home directory") - .join(".cache/starship") - }); + let log_dir = get_log_dir(); - fs::create_dir_all(&log_dir) - .unwrap_or_else(|err| panic!("Unable to create log dir {log_dir:?}: {err:?}!")); + if let Err(err) = fs::create_dir_all(&log_dir) { + eprintln!("Unable to create log dir {log_dir:?}: {err:?}!") + }; let session_log_file = log_dir.join(format!( "session_{}.log", env::var("STARSHIP_SESSION_KEY").unwrap_or_default() )); Self { - log_file_content: fs::read_to_string(&session_log_file) - .unwrap_or_default() - .lines() - .map(std::string::ToString::to_string) - .collect(), + log_file_content: RwLock::new( + fs::read_to_string(&session_log_file) + .unwrap_or_default() + .lines() + .map(std::string::ToString::to_string) + .collect(), + ), log_file: OnceCell::new(), log_file_path: session_log_file, log_level: env::var("STARSHIP_LOG") - .map(|level| match level.to_lowercase().as_str() { + .map(|level| match level.to_ascii_lowercase().as_str() { "trace" => Level::Trace, "debug" => Level::Debug, "info" => Level::Info, @@ -66,6 +127,12 @@ impl StarshipLogger { /// Override the log level path /// This won't change anything if a log file was already opened pub fn set_log_file_path(&mut self, path: PathBuf) { + let contents = fs::read_to_string(&path) + .unwrap_or_default() + .lines() + .map(std::string::ToString::to_string) + .collect(); + self.log_file_content = RwLock::new(contents); self.log_file_path = path; } } @@ -76,6 +143,11 @@ impl log::Log for StarshipLogger { } fn log(&self, record: &Record) { + // Early return if the log level is not enabled + if !self.enabled(record.metadata()) { + return; + } + let to_print = format!( "[{}] - ({}): {}", record.level(), @@ -83,51 +155,84 @@ impl log::Log for StarshipLogger { record.args() ); - if record.metadata().level() <= Level::Warn { - self.log_file - .get_or_try_init(|| { - let m = Mutex::new( - OpenOptions::new() - .create(true) - .append(true) - .open(&self.log_file_path)?, - ); - Ok(m) - }) - .unwrap_or_else(|err: std::io::Error| { - panic!( - "Unable to open session log file {:?}: {err:?}!", - self.log_file_path - ) - }) - .lock() - .map(|mut file| writeln!(file, "{to_print}")) - .expect("Log file writer mutex was poisoned!") - .expect("Unable to write to the log file!"); + // A log message is only printed or written to the log file, + // if it's not already in the log file or has been printed in this session. + // To help with debugging, duplicate detection only runs if the log level is warn or lower + let is_debug = record.level() > Level::Warn; + let is_duplicate = { + !is_debug + && self + .log_file_content + .read() + .map(|c| c.contains(to_print.as_str())) + .unwrap_or(false) + }; + + if is_duplicate { + return; } - if self.enabled(record.metadata()) && !self.log_file_content.contains(to_print.as_str()) { - eprintln!( - "[{}] - ({}): {}", - match record.level() { - Level::Trace => Color::Blue.dimmed().paint(format!("{}", record.level())), - Level::Debug => Color::Cyan.paint(format!("{}", record.level())), - Level::Info => Color::White.paint(format!("{}", record.level())), - Level::Warn => Color::Yellow.paint(format!("{}", record.level())), - Level::Error => Color::Red.paint(format!("{}", record.level())), - }, - record.module_path().unwrap_or_default(), - record.args() - ); + // Write warning messages to the log file + // If log level is error, only write error messages to the log file + if record.level() <= cmp::min(Level::Warn, self.log_level) { + let log_file = match self.log_file.get_or_try_init(|| { + OpenOptions::new() + .create(true) + .append(true) + .open(&self.log_file_path) + .map(Mutex::new) + }) { + Ok(log_file) => log_file, + Err(err) => { + eprintln!( + "Unable to open session log file {:?}: {err:?}!", + self.log_file_path + ); + return; + } + }; + + let mut file_handle = match log_file.lock() { + Ok(file_handle) => file_handle, + Err(err) => { + eprintln!("Log file writer mutex was poisoned! {err:?}",); + return; + } + }; + if let Err(err) = writeln!(file_handle, "{to_print}") { + eprintln!("Unable to write to session log file {err:?}!",); + }; + } + + // Print messages to stderr + eprintln!( + "[{}] - ({}): {}", + match record.level() { + Level::Trace => Color::Blue.dimmed().paint(format!("{}", record.level())), + Level::Debug => Color::Cyan.paint(format!("{}", record.level())), + Level::Info => Color::White.paint(format!("{}", record.level())), + Level::Warn => Color::Yellow.paint(format!("{}", record.level())), + Level::Error => Color::Red.paint(format!("{}", record.level())), + }, + record.module_path().unwrap_or_default(), + record.args() + ); + + // Add to duplicate detection set + if let Ok(mut c) = self.log_file_content.write() { + c.insert(to_print); } } fn flush(&self) { if let Some(m) = self.log_file.get() { - m.lock() - .map(|mut writer| writer.flush()) - .expect("Log file writer mutex was poisoned!") - .expect("Unable to flush the log file!"); + let result = match m.lock() { + Ok(mut file) => file.flush(), + Err(err) => return eprintln!("Log file writer mutex was poisoned: {err:?}"), + }; + if let Err(err) = result { + eprintln!("Unable to flush the log file: {err:?}"); + } } } } @@ -136,3 +241,171 @@ pub fn init() { log::set_boxed_logger(Box::::default()).unwrap(); log::set_max_level(LevelFilter::Trace); } + +#[cfg(test)] +mod test { + use super::*; + use crate::utils::read_file; + use log::Log; + use std::io; + + #[test] + fn test_log_to_file() -> io::Result<()> { + let log_dir = tempfile::tempdir()?; + let log_file = log_dir.path().join("test.log"); + + let mut logger = StarshipLogger::default(); + logger.set_log_file_path(log_file.clone()); + logger.set_log_level(Level::Warn); + + // Load at all log levels + logger.log( + &Record::builder() + .level(Level::Error) + .args(format_args!("error")) + .build(), + ); + logger.log( + &Record::builder() + .level(Level::Warn) + .args(format_args!("warn")) + .build(), + ); + logger.log( + &Record::builder() + .level(Level::Info) + .args(format_args!("info")) + .build(), + ); + logger.log( + &Record::builder() + .level(Level::Debug) + .args(format_args!("debug")) + .build(), + ); + logger.log( + &Record::builder() + .level(Level::Trace) + .args(format_args!("trace")) + .build(), + ); + + // Print duplicate messages + logger.log( + &Record::builder() + .level(Level::Warn) + .args(format_args!("warn")) + .build(), + ); + logger.log( + &Record::builder() + .level(Level::Error) + .args(format_args!("error")) + .build(), + ); + + logger.flush(); + drop(logger); + + let content = read_file(log_file)?; + + assert_eq!(content, "[ERROR] - (): error\n[WARN] - (): warn\n"); + + log_dir.close() + } + + #[test] + fn test_dedup_from_file() -> io::Result<()> { + let log_dir = tempfile::tempdir()?; + let log_file = log_dir.path().join("test.log"); + { + let mut file = File::create(&log_file)?; + file.write_all(b"[WARN] - (): warn\n")?; + file.sync_all()?; + } + + let mut logger = StarshipLogger::default(); + logger.set_log_file_path(log_file.clone()); + logger.set_log_level(Level::Warn); + + // This message should not be printed or written to the log file + logger.log( + &Record::builder() + .level(Level::Warn) + .args(format_args!("warn")) + .build(), + ); + // This message should be printed and written to the log file + logger.log( + &Record::builder() + .level(Level::Warn) + .args(format_args!("warn2")) + .build(), + ); + + logger.flush(); + drop(logger); + + let content = read_file(log_file)?; + + assert_eq!(content, "[WARN] - (): warn\n[WARN] - (): warn2\n"); + + log_dir.close() + } + + #[test] + #[cfg(unix)] + fn test_cleanup() -> io::Result<()> { + use nix::sys::{stat::utimes, time::TimeVal}; + use std::fs::File; + + let log_dir = tempfile::tempdir()?; + + // Should not be deleted + let non_matching_file = log_dir.path().join("non-matching.log"); + let non_matching_file2 = log_dir.path().join("session_.exe"); + let new_file = log_dir.path().join("session_new.log"); + let directory = log_dir.path().join("session_dir.log"); + + // Should be deleted + let old_file = log_dir.path().join("session_old.log"); + + for file in &[ + &non_matching_file, + &non_matching_file2, + &new_file, + &old_file, + ] { + File::create(file)?; + } + fs::create_dir(&directory)?; + + // Set all files except the new file to be older than 24 hours + for file in &[ + &non_matching_file, + &non_matching_file2, + &old_file, + &directory, + ] { + utimes(file.as_path(), &TimeVal::new(0, 0), &TimeVal::new(0, 0))?; + if let Ok(f) = File::open(file) { + f.sync_all()?; + } + } + + cleanup_log_files(log_dir.path()); + + for file in &[ + &non_matching_file, + &non_matching_file2, + &new_file, + &directory, + ] { + assert!(file.exists(), "File {file:?} should exist"); + } + + assert!(!old_file.exists(), "File {old_file:?} should not exist"); + + log_dir.close() + } +} diff --git a/src/main.rs b/src/main.rs index 69bff9cf..92cbe8c1 100644 --- a/src/main.rs +++ b/src/main.rs @@ -118,6 +118,12 @@ fn main() { logger::init(); init_global_threadpool(); + // Delete old log files + rayon::spawn(|| { + let log_dir = logger::get_log_dir(); + logger::cleanup_log_files(log_dir); + }); + let args = match Cli::try_parse() { Ok(args) => args, Err(e) => { diff --git a/src/test/mod.rs b/src/test/mod.rs index c761bb98..c8e271e4 100644 --- a/src/test/mod.rs +++ b/src/test/mod.rs @@ -10,6 +10,7 @@ use once_cell::sync::Lazy; use std::fs; use std::io; use std::path::{Path, PathBuf}; +use std::sync::Once; use tempfile::TempDir; static FIXTURE_DIR: Lazy = @@ -18,7 +19,9 @@ static FIXTURE_DIR: Lazy = static GIT_FIXTURE: Lazy = Lazy::new(|| FIXTURE_DIR.join("git-repo.bundle")); static HG_FIXTURE: Lazy = Lazy::new(|| FIXTURE_DIR.join("hg-repo.bundle")); -static LOGGER: Lazy<()> = Lazy::new(|| { +static LOGGER: Once = Once::new(); + +fn init_logger() { let mut logger = StarshipLogger::default(); // Don't log to files during tests @@ -31,7 +34,7 @@ static LOGGER: Lazy<()> = Lazy::new(|| { logger.set_log_file_path(nul); log::set_boxed_logger(Box::new(logger)).unwrap(); -}); +} pub fn default_context() -> Context<'static> { let mut context = Context::new_with_shell_and_path( @@ -55,7 +58,7 @@ impl<'a> ModuleRenderer<'a> { /// Creates a new `ModuleRenderer` pub fn new(name: &'a str) -> Self { // Start logger - Lazy::force(&LOGGER); + LOGGER.call_once(init_logger); let context = default_context();