diff --git a/.gitignore b/.gitignore index 2f7795a34..cd7af25b9 100644 --- a/.gitignore +++ b/.gitignore @@ -101,6 +101,7 @@ plugins/**/*.so plugins/**/*.dylib plugins/**/*.dll world/* +logs/ # docker-compose data/* @@ -134,4 +135,4 @@ result result-* # Generated Data -pumpkin-data/src/generated \ No newline at end of file +pumpkin-data/src/generated diff --git a/Cargo.lock b/Cargo.lock index 2af6efc8f..550700976 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1969,6 +1969,7 @@ dependencies = [ "chrono", "crossbeam", "dhat", + "flate2", "futures", "git-version", "hmac", diff --git a/pumpkin-config/src/logging.rs b/pumpkin-config/src/logging.rs index 064026922..4506f8bdc 100644 --- a/pumpkin-config/src/logging.rs +++ b/pumpkin-config/src/logging.rs @@ -7,6 +7,7 @@ pub struct LoggingConfig { pub threads: bool, pub color: bool, pub timestamp: bool, + pub file: String, } impl Default for LoggingConfig { @@ -16,6 +17,7 @@ impl Default for LoggingConfig { threads: true, color: true, timestamp: true, + file: "latest.log".to_string(), } } } diff --git a/pumpkin/Cargo.toml b/pumpkin/Cargo.toml index f5b6ad061..c04eed96d 100644 --- a/pumpkin/Cargo.toml +++ b/pumpkin/Cargo.toml @@ -91,6 +91,8 @@ tokio-util = { version = "0.7.15", features = ["rt"] } # Memory profiling dhat = { version = "0.3.3", optional = true } +flate2 = "1.1.2" + [build-dependencies] git-version = "0.3" diff --git a/pumpkin/src/lib.rs b/pumpkin/src/lib.rs index 82960a48b..96ae9e495 100644 --- a/pumpkin/src/lib.rs +++ b/pumpkin/src/lib.rs @@ -1,12 +1,13 @@ // Not warn event sending macros #![allow(unused_labels)] +use crate::logging::{GzipRollingLogger, ReadlineLogWrapper}; use crate::net::bedrock::BedrockClientPlatform; use crate::net::java::JavaClientPlatform; use crate::net::{lan_broadcast, query, rcon::RCONServer}; use crate::server::{Server, ticker::Ticker}; use bytes::Bytes; -use log::{Level, LevelFilter, Log}; +use log::{Level, LevelFilter}; use net::authentication::fetch_mojang_public_keys; use plugin::PluginManager; use plugin::server::server_command::ServerCommandEvent; @@ -15,6 +16,7 @@ use pumpkin_macros::send_cancellable; use pumpkin_util::permission::{PermissionManager, PermissionRegistry}; use pumpkin_util::text::TextComponent; use rustyline_async::{Readline, ReadlineEvent}; +use simplelog::SharedLogger; use std::collections::HashMap; use std::io::{Cursor, IsTerminal, stdin}; use std::str::FromStr; @@ -32,6 +34,7 @@ pub mod data; pub mod entity; pub mod error; pub mod item; +pub mod logging; pub mod net; pub mod plugin; pub mod server; @@ -62,62 +65,6 @@ pub static PERMISSION_MANAGER: LazyLock>> = LazyLo ))) }); -/// A wrapper for our logger to hold the terminal input while no input is expected in order to -/// properly flush logs to the output while they happen instead of batched -pub struct ReadlineLogWrapper { - internal: Box, - readline: std::sync::Mutex>, -} - -impl ReadlineLogWrapper { - fn new(log: impl Log + 'static, rl: Option) -> Self { - Self { - internal: Box::new(log), - readline: std::sync::Mutex::new(rl), - } - } - - fn take_readline(&self) -> Option { - if let Ok(mut result) = self.readline.lock() { - result.take() - } else { - None - } - } - - fn return_readline(&self, rl: Readline) { - if let Ok(mut result) = self.readline.lock() { - println!("Returned rl"); - let _ = result.insert(rl); - } - } -} - -// Writing to `stdout` is expensive anyway, so I don't think having a `Mutex` here is a big deal. -impl Log for ReadlineLogWrapper { - fn log(&self, record: &log::Record) { - self.internal.log(record); - if let Ok(mut lock) = self.readline.lock() { - if let Some(rl) = lock.as_mut() { - let _ = rl.flush(); - } - } - } - - fn flush(&self) { - self.internal.flush(); - if let Ok(mut lock) = self.readline.lock() { - if let Some(rl) = lock.as_mut() { - let _ = rl.flush(); - } - } - } - - fn enabled(&self, metadata: &log::Metadata) -> bool { - self.internal.enabled(metadata) - } -} - pub static LOGGER_IMPL: LazyLock> = LazyLock::new(|| { if advanced_config().logging.enabled { let mut config = simplelog::ConfigBuilder::new(); @@ -126,7 +73,7 @@ pub static LOGGER_IMPL: LazyLock> = La config.set_time_format_custom(time::macros::format_description!( "[year]-[month]-[day] [hour]:[minute]:[second]" )); - config.set_time_level(LevelFilter::Trace); + config.set_time_level(LevelFilter::Error); } else { config.set_time_level(LevelFilter::Off); } @@ -153,23 +100,47 @@ pub static LOGGER_IMPL: LazyLock> = La .and_then(Result::ok) .unwrap_or(LevelFilter::Info); + let file_logger: Option> = + if advanced_config().logging.file.is_empty() { + None + } else { + Some( + GzipRollingLogger::new( + level, + { + let mut config = config.clone(); + for level in Level::iter() { + config.set_level_color(level, None); + } + config.build() + }, + advanced_config().logging.file.clone(), + ) + .expect("Failed to initialize file logger.") + as Box, + ) + }; + if advanced_config().commands.use_tty && stdin().is_terminal() { match Readline::new("$ ".to_owned()) { Ok((rl, stdout)) => { let logger = simplelog::WriteLogger::new(level, config.build(), stdout); - Some((ReadlineLogWrapper::new(logger, Some(rl)), level)) + Some(( + ReadlineLogWrapper::new(logger, file_logger, Some(rl)), + level, + )) } Err(e) => { log::warn!( "Failed to initialize console input ({e}); falling back to simple logger" ); let logger = simplelog::SimpleLogger::new(level, config.build()); - Some((ReadlineLogWrapper::new(logger, None), level)) + Some((ReadlineLogWrapper::new(logger, file_logger, None), level)) } } } else { let logger = simplelog::SimpleLogger::new(level, config.build()); - Some((ReadlineLogWrapper::new(logger, None), level)) + Some((ReadlineLogWrapper::new(logger, file_logger, None), level)) } } else { None diff --git a/pumpkin/src/logging.rs b/pumpkin/src/logging.rs new file mode 100644 index 000000000..1e8c2c7cb --- /dev/null +++ b/pumpkin/src/logging.rs @@ -0,0 +1,205 @@ +use flate2::write::GzEncoder; +use log::{LevelFilter, Log}; +use rustyline_async::Readline; +use simplelog::{CombinedLogger, Config, SharedLogger, WriteLogger}; +use std::fs::File; +use std::io::BufWriter; +use std::path::Path; + +/// A wrapper for our logger to hold the terminal input while no input is expected in order to +/// properly flush logs to the output while they happen instead of batched +pub struct ReadlineLogWrapper { + internal: Box, + readline: std::sync::Mutex>, +} + +struct GzipRollingLoggerData { + pub current_day_of_month: u8, + pub last_rotate_time: time::OffsetDateTime, + pub latest_logger: WriteLogger, + latest_filename: String, +} + +pub struct GzipRollingLogger { + log_level: LevelFilter, + data: std::sync::Mutex, + config: Config, +} + +impl GzipRollingLogger { + pub fn new( + log_level: LevelFilter, + config: Config, + filename: String, + ) -> Result, Box> { + let now = time::OffsetDateTime::now_utc(); + std::fs::create_dir_all("logs")?; + + // If latest.log exists, we will gzip it + if Path::new(&format!("logs/{filename}")).exists() { + let new_filename = Self::new_filename(false); + let mut file = File::open(format!("logs/{filename}"))?; + let mut encoder = GzEncoder::new( + BufWriter::new(File::create(&new_filename)?), + flate2::Compression::default(), + ); + println!("logs/{filename}"); + std::io::copy(&mut file, &mut encoder)?; + encoder.finish()?; + } + + Ok(Box::new(Self { + log_level, + data: std::sync::Mutex::new(GzipRollingLoggerData { + current_day_of_month: now.day(), + last_rotate_time: now, + latest_filename: filename.clone(), + latest_logger: *WriteLogger::new( + log_level, + config.clone(), + File::create(format!("logs/{filename}")).unwrap(), + ), + }), + config, + })) + } + + pub fn new_filename(yesterday: bool) -> String { + let mut now = time::OffsetDateTime::now_utc() + .to_offset(time::UtcOffset::current_local_offset().unwrap_or(time::UtcOffset::UTC)); + if yesterday { + now -= time::Duration::days(1) + } + let base_filename = format!("{}-{:02}-{:02}", now.year(), now.month() as u8, now.day()); + + let mut id = 1; + loop { + let filename = format!("logs/{base_filename}-{id}.log.gz"); + if !Path::new(&filename).exists() { + return filename; + } + id += 1; + } + } + + fn rotate_log(&self) -> Result<(), Box> { + let now = time::OffsetDateTime::now_utc(); + let mut data = self.data.lock().unwrap(); + + let new_filename = Self::new_filename(true); + let mut file = File::open(format!("logs/{}", data.latest_filename))?; + let mut encoder = GzEncoder::new( + BufWriter::new(File::create(format!("logs/{new_filename}"))?), + flate2::Compression::default(), + ); + std::io::copy(&mut file, &mut encoder)?; + encoder.finish()?; + + data.current_day_of_month = now.day(); + data.last_rotate_time = now; + data.latest_logger = *WriteLogger::new( + self.log_level, + self.config.clone(), + File::create(format!("logs/{}", data.latest_filename)).unwrap(), + ); + Ok(()) + } +} + +impl Log for GzipRollingLogger { + fn enabled(&self, metadata: &log::Metadata) -> bool { + metadata.level() <= self.log_level + } + + fn log(&self, record: &log::Record) { + if !self.enabled(record.metadata()) { + return; + } + + let now = time::OffsetDateTime::now_utc(); + + if let Ok(data) = self.data.lock() { + data.latest_logger.log(record); + if data.current_day_of_month != now.day() { + drop(data); + if let Err(e) = self.rotate_log() { + eprintln!("Failed to rotate log: {e}"); + } + } + } + } + + fn flush(&self) { + if let Ok(data) = self.data.lock() { + data.latest_logger.flush(); + } + } +} + +impl SharedLogger for GzipRollingLogger { + fn level(&self) -> LevelFilter { + self.log_level + } + + fn config(&self) -> Option<&Config> { + Some(&self.config) + } + + fn as_log(self: Box) -> Box { + Box::new(*self) + } +} + +impl ReadlineLogWrapper { + pub fn new( + log: Box, + file_logger: Option>, + rl: Option, + ) -> Self { + let loggers: Vec>> = vec![Some(log), file_logger]; + Self { + internal: CombinedLogger::new(loggers.into_iter().flatten().collect()), + readline: std::sync::Mutex::new(rl), + } + } + + pub(crate) fn take_readline(&self) -> Option { + if let Ok(mut result) = self.readline.lock() { + result.take() + } else { + None + } + } + + pub(crate) fn return_readline(&self, rl: Readline) { + if let Ok(mut result) = self.readline.lock() { + println!("Returned rl"); + let _ = result.insert(rl); + } + } +} + +// Writing to `stdout` is expensive anyway, so I don't think having a `Mutex` here is a big deal. +impl Log for ReadlineLogWrapper { + fn log(&self, record: &log::Record) { + self.internal.log(record); + if let Ok(mut lock) = self.readline.lock() { + if let Some(rl) = lock.as_mut() { + let _ = rl.flush(); + } + } + } + + fn flush(&self) { + self.internal.flush(); + if let Ok(mut lock) = self.readline.lock() { + if let Some(rl) = lock.as_mut() { + let _ = rl.flush(); + } + } + } + + fn enabled(&self, metadata: &log::Metadata) -> bool { + self.internal.enabled(metadata) + } +}