diff --git a/Cargo.lock b/Cargo.lock index 1bb1a5ec5..5e6d7cd5e 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -43,15 +43,6 @@ version = "0.1.6" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4b46cbb362ab8752921c97e041f5e366ee6297bd428a31275b9fcf1e380f7299" -[[package]] -name = "ansi_term" -version = "0.12.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2" -dependencies = [ - "winapi", -] - [[package]] name = "anstream" version = "0.6.21" @@ -119,9 +110,9 @@ dependencies = [ [[package]] name = "async-compression" -version = "0.4.37" +version = "0.4.39" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d10e4f991a553474232bc0a31799f6d24b034a84c0971d80d2e2f78b2e576e40" +checksum = "68650b7df54f0293fd061972a0fb05aaf4fc0879d3b3d21a638a182c5c543b9f" dependencies = [ "compression-codecs", "compression-core", @@ -410,7 +401,7 @@ version = "3.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "faf9468729b8cbcea668e36183cb69d317348c2e08e994829fb56ebfdfbaac34" dependencies = [ - "windows-sys 0.61.2", + "windows-sys 0.52.0", ] [[package]] @@ -894,7 +885,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "39cab71617ae0d63f51a36d69f866391735b51691dbda63cf6f96d042b63efeb" dependencies = [ "libc", - "windows-sys 0.61.2", + "windows-sys 0.52.0", ] [[package]] @@ -1620,6 +1611,15 @@ version = "0.11.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "08ab2867e3eeeca90e844d1940eab391c9dc5228783db2ed999acbc0a9ed375a" +[[package]] +name = "matchers" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9" +dependencies = [ + "regex-automata", +] + [[package]] name = "matchit" version = "0.8.4" @@ -1712,6 +1712,15 @@ dependencies = [ "minimal-lexical", ] +[[package]] +name = "nu-ansi-term" +version = "0.50.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5" +dependencies = [ + "windows-sys 0.59.0", +] + [[package]] name = "num-bigint" version = "0.4.6" @@ -1767,15 +1776,6 @@ dependencies = [ "libc", ] -[[package]] -name = "num_threads" -version = "0.1.7" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "5c7398b9c8b70908f6371f47ed36737907c87c52af34c268fed0bf0ceb92ead9" -dependencies = [ - "libc", -] - [[package]] name = "once_cell" version = "1.21.3" @@ -2155,12 +2155,14 @@ dependencies = [ "serde_json", "sha1", "sha2 0.11.0-rc.4", - "simplelog", "tempfile", "thiserror", "time", "tokio", "tokio-util", + "tracing", + "tracing-log", + "tracing-subscriber", "ureq", "uuid", ] @@ -2354,8 +2356,8 @@ dependencies = [ [[package]] name = "rand" -version = "0.10.0-rc.8" -source = "git+https://github.com/rust-random/rand#9c98f59e8b042e5c7c714e933e49b384a4ce75a6" +version = "0.10.0-rc.9" +source = "git+https://github.com/rust-random/rand#72afe1e973fcd83d840cf597888223072bbdb04c" dependencies = [ "chacha20", "getrandom 0.4.0-rc.1", @@ -2494,7 +2496,7 @@ dependencies = [ "errno", "libc", "linux-raw-sys", - "windows-sys 0.61.2", + "windows-sys 0.52.0", ] [[package]] @@ -2761,18 +2763,6 @@ version = "0.3.8" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e320a6c5ad31d271ad523dcf3ad13e2767ad8b1cb8f047f75a8aeaf8da139da2" -[[package]] -name = "simplelog" -version = "0.12.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "16257adbfaef1ee58b1363bdc0664c9b8e1e30aed86049635fb5f147d065a9c0" -dependencies = [ - "ansi_term", - "log", - "termcolor", - "time", -] - [[package]] name = "siphasher" version = "1.0.2" @@ -2903,16 +2893,7 @@ dependencies = [ "fastrand", "once_cell", "rustix", - "windows-sys 0.61.2", -] - -[[package]] -name = "termcolor" -version = "1.4.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "06794f8f6c5c898b3275aebefa6b8a1cb24cd2c6c79397ab15774837a0bc5755" -dependencies = [ - "winapi-util", + "windows-sys 0.52.0", ] [[package]] @@ -2952,9 +2933,7 @@ checksum = "9da98b7d9b7dad93488a84b8248efc35352b0b2657397d4167e7ad67e5d535e5" dependencies = [ "deranged", "itoa", - "libc", "num-conv", - "num_threads", "powerfmt", "serde_core", "time-core", @@ -3192,15 +3171,34 @@ dependencies = [ "valuable", ] +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.22" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "2f30143827ddab0d256fd843b7a66d164e9f271cfa0dde49142c5ca0ca291f1e" dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex-automata", "sharded-slab", + "smallvec", "thread_local", + "time", + "tracing", "tracing-core", + "tracing-log", ] [[package]] @@ -3507,7 +3505,7 @@ version = "0.1.11" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c2a7b1c03c876122aa43f3020e6c3c3ee5c05081c9a00739faf7503aeba10d22" dependencies = [ - "windows-sys 0.61.2", + "windows-sys 0.52.0", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index 2036b4249..c2ff0cca2 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -108,7 +108,7 @@ serde_json = "1.0" tempfile = { version = "3.24.0", default-features = false } proc-macro-error2 = "2" aes = "0.8" -async-compression = "0.4.37" +async-compression = "0.4.39" base64 = "0.22.1" bitflags = "2.10.0" cesu8 = "1.1" @@ -158,7 +158,9 @@ serde_json5 = "0.2.1" sha1 = "=0.11.0-rc.4" sha2 = "=0.11.0-rc.4" signature = "2.2.0" -simplelog = "0.12.2" +tracing = "0.1.44" +tracing-subscriber = { version = "0.3", features = ["env-filter", "fmt", "time"] } +tracing-log = "0.2.0" slotmap = "1.1" take_mut = "0.2.2" temp-dir = "0.1.16" diff --git a/pumpkin/Cargo.toml b/pumpkin/Cargo.toml index eed7c66f7..43da370bb 100644 --- a/pumpkin/Cargo.toml +++ b/pumpkin/Cargo.toml @@ -74,7 +74,9 @@ sha2.workspace = true base64.workspace = true # logging -simplelog = { workspace = true, features = ["ansi_term"] } +tracing.workspace = true +tracing-subscriber.workspace = true +tracing-log.workspace = true # Remove time in favor of chrono? time = { workspace = true, features = ["parsing", "macros"] } diff --git a/pumpkin/src/command/mod.rs b/pumpkin/src/command/mod.rs index b141cffce..2971c6f75 100644 --- a/pumpkin/src/command/mod.rs +++ b/pumpkin/src/command/mod.rs @@ -76,7 +76,7 @@ impl CommandSender { block_entity.as_any().downcast_ref().unwrap(); let mut last_output = command_entity.last_output.lock().await; - let now = time::OffsetDateTime::now_local().unwrap(); + let now = time::OffsetDateTime::now_utc(); let format = time::macros::format_description!("[hour]:[minute]:[second]"); let timestamp = now.format(&format).unwrap(); diff --git a/pumpkin/src/lib.rs b/pumpkin/src/lib.rs index d3cff2b27..ed654c3f8 100644 --- a/pumpkin/src/lib.rs +++ b/pumpkin/src/lib.rs @@ -8,7 +8,7 @@ use crate::net::java::{JavaClient, PacketHandlerResult}; use crate::net::{ClientPlatform, DisconnectReason}; use crate::net::{lan_broadcast::LANBroadcast, query, rcon::RCONServer}; use crate::server::{Server, ticker::Ticker}; -use log::{Level, LevelFilter}; +use log::LevelFilter; use plugin::server::server_command::ServerCommandEvent; use pumpkin_config::{AdvancedConfiguration, BasicConfiguration}; use pumpkin_macros::send_cancellable; @@ -29,6 +29,8 @@ use tokio::sync::Mutex; use tokio::time::sleep; use tokio_util::sync::CancellationToken; use tokio_util::task::TaskTracker; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::util::SubscriberInitExt; pub mod block; pub mod command; @@ -46,36 +48,12 @@ pub type LoggerOption = Option<(ReadlineLogWrapper, LevelFilter)>; pub static LOGGER_IMPL: LazyLock>> = LazyLock::new(|| Arc::new(OnceLock::new())); +#[expect(clippy::print_stderr)] pub fn init_logger(advanced_config: &AdvancedConfiguration) { - use simplelog::{ConfigBuilder, SharedLogger, SimpleLogger, WriteLogger}; + use tracing_subscriber::EnvFilter; + use tracing_subscriber::fmt; let logger = advanced_config.logging.enabled.then(|| { - let mut config = ConfigBuilder::new(); - - if advanced_config.logging.timestamp { - config.set_time_format_custom(time::macros::format_description!( - "[year]-[month]-[day] [hour]:[minute]:[second]" - )); - config.set_time_level(LevelFilter::Error); - let _ = config.set_time_offset_to_local(); - } else { - config.set_time_level(LevelFilter::Off); - } - - if advanced_config.logging.color { - config.set_write_log_enable_colors(true); - } else { - for level in Level::iter() { - config.set_level_color(level, None); - } - } - - if advanced_config.logging.threads { - config.set_thread_level(LevelFilter::Info); - } else { - config.set_thread_level(LevelFilter::Off); - } - let level = std::env::var("RUST_LOG") .ok() .as_deref() @@ -83,29 +61,29 @@ pub fn init_logger(advanced_config: &AdvancedConfiguration) { .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, - ) + let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| { + let level_str = match level { + LevelFilter::Off => "off", + LevelFilter::Error => "error", + LevelFilter::Warn => "warn", + LevelFilter::Info => "info", + LevelFilter::Debug => "debug", + LevelFilter::Trace => "trace", }; + EnvFilter::new(level_str) + }); + + let file_logger: Option = if advanced_config.logging.file.is_empty() { + None + } else { + Some( + GzipRollingLogger::new(level, advanced_config.logging.file.clone()) + .expect("Failed to initialize file logger."), + ) + }; let (logger, rl): ( - Box, + Box, Option>, ) = if advanced_config.commands.use_tty && stdin().is_terminal() { let rl_config = Config::builder() @@ -118,22 +96,51 @@ pub fn init_logger(advanced_config: &AdvancedConfiguration) { match Editor::with_config(rl_config) { Ok(mut rl) => { rl.set_helper(Some(helper)); - ( - WriteLogger::new(level, config.build(), std::io::stdout()), - Some(rl), - ) + (Box::new(std::io::stdout()), Some(rl)) } Err(e) => { - log::warn!( + eprintln!( "Failed to initialize console input ({e}); falling back to simple logger" ); - (SimpleLogger::new(level, config.build()), None) + (Box::new(std::io::stdout()), None) } } } else { - (SimpleLogger::new(level, config.build()), None) + (Box::new(std::io::stdout()), None) }; - (ReadlineLogWrapper::new(logger, file_logger, rl), level) + + let fmt_layer = fmt::layer() + .with_writer(std::sync::Mutex::new(logger)) + .with_ansi(advanced_config.logging.color) + .with_target(false) + .with_thread_names(advanced_config.logging.threads) + .with_thread_ids(advanced_config.logging.threads); + + if advanced_config.logging.timestamp { + let fmt_layer = fmt_layer.with_timer(fmt::time::UtcTime::new( + time::macros::format_description!("[year]-[month]-[day] [hour]:[minute]:[second]"), + )); + let registry = tracing_subscriber::registry() + .with(env_filter) + .with(fmt_layer); + if let Some(file_logger) = file_logger { + registry.with(file_logger).init(); + } else { + registry.init(); + } + } else { + let fmt_layer = fmt_layer.without_time(); + let registry = tracing_subscriber::registry() + .with(env_filter) + .with(fmt_layer); + if let Some(file_logger) = file_logger { + registry.with(file_logger).init(); + } else { + registry.init(); + } + } + + (ReadlineLogWrapper::new(rl), level) }); assert!( diff --git a/pumpkin/src/logging.rs b/pumpkin/src/logging.rs index 60598f997..28717fb57 100644 --- a/pumpkin/src/logging.rs +++ b/pumpkin/src/logging.rs @@ -2,22 +2,22 @@ #![allow(clippy::print_stdout)] use flate2::write::GzEncoder; -use log::{LevelFilter, Log, Record}; +use log::LevelFilter; use rustyline::completion::Completer; use rustyline::highlight::Highlighter; use rustyline::hint::Hinter; use rustyline::history::FileHistory; use rustyline::validate::Validator; use rustyline::{Editor, Helper}; -use simplelog::{CombinedLogger, Config, SharedLogger, WriteLogger}; use std::borrow::Cow; use std::collections::VecDeque; -use std::fmt::format; use std::fs::File; -use std::io::{self, BufWriter}; +use std::io::{self, BufWriter, Write}; use std::path::PathBuf; use std::sync::Arc; -use time::{Duration, OffsetDateTime, UtcOffset}; +use time::{Duration, OffsetDateTime}; +use tracing::Subscriber; +use tracing_subscriber::Layer; use crate::command::CommandSender; use crate::command::tree::NodeType; @@ -29,43 +29,26 @@ const MAX_ATTEMPTS: u32 = 100; /// 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, + pub file: BufWriter, latest_filename: String, } pub struct GzipRollingLogger { log_level: LevelFilter, data: std::sync::Mutex, - config: Config, -} - -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 GzipRollingLogger { pub fn new( log_level: LevelFilter, - config: Config, filename: String, - ) -> Result, Box> { + ) -> Result> { let now = time::OffsetDateTime::now_utc(); std::fs::create_dir_all(LOG_DIR)?; @@ -93,23 +76,21 @@ impl GzipRollingLogger { std::fs::remove_file(&latest_path)?; } - let new_logger = WriteLogger::new(log_level, config.clone(), File::create(&latest_path)?); + let file = BufWriter::new(File::create(&latest_path)?); - Ok(Box::new(Self { + Ok(Self { log_level, data: std::sync::Mutex::new(GzipRollingLoggerData { current_day_of_month: now.day(), last_rotate_time: now, latest_filename: filename, - latest_logger: *new_logger, + file, }), - config, - })) + }) } pub fn new_filename(yesterday: bool) -> Result> { - let local_offset = UtcOffset::current_local_offset().unwrap_or(UtcOffset::UTC); - let mut now = OffsetDateTime::now_utc().to_offset(local_offset); + let mut now = OffsetDateTime::now_utc(); if yesterday { now -= Duration::days(1); @@ -139,6 +120,14 @@ impl GzipRollingLogger { let new_gz_path = Self::new_filename(true)?; let latest_path = PathBuf::from(LOG_DIR).join(&data.latest_filename); + + // Flush and drop the current file + data.file.flush()?; + drop(std::mem::replace( + &mut data.file, + BufWriter::new(File::create("/dev/null")?), + )); + let mut file = File::open(&latest_path)?; let mut encoder = GzEncoder::new( BufWriter::new(File::create(&new_gz_path)?), @@ -149,11 +138,7 @@ impl GzipRollingLogger { 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(&latest_path)?, - ); + data.file = BufWriter::new(File::create(&latest_path)?); Ok(()) } } @@ -176,30 +161,46 @@ fn remove_ansi_color_code(s: &str) -> String { result } -impl Log for GzipRollingLogger { - fn enabled(&self, metadata: &log::Metadata) -> bool { - metadata.level() <= self.log_level - } +impl Layer for GzipRollingLogger +where + S: Subscriber, +{ + fn on_event( + &self, + event: &tracing::Event<'_>, + _ctx: tracing_subscriber::layer::Context<'_, S>, + ) { + let metadata = event.metadata(); + let level = metadata.level(); - fn log(&self, record: &Record) { - if !self.enabled(record.metadata()) { + // Check if we should log this event based on level + let should_log = match *level { + tracing::Level::ERROR => self.log_level >= LevelFilter::Error, + tracing::Level::WARN => self.log_level >= LevelFilter::Warn, + tracing::Level::INFO => self.log_level >= LevelFilter::Info, + tracing::Level::DEBUG => self.log_level >= LevelFilter::Debug, + tracing::Level::TRACE => self.log_level >= LevelFilter::Trace, + }; + + if !should_log { return; } let now = time::OffsetDateTime::now_utc(); - if let Ok(data) = self.data.lock() { - let original_string = format(*record.args()); - let string = remove_ansi_color_code(&original_string); - data.latest_logger.log( - &Record::builder() - .args(format_args!("{string}")) - .metadata(record.metadata().clone()) - .module_path(record.module_path()) - .file(record.file()) - .line(record.line()) - .build(), - ); + if let Ok(mut data) = self.data.lock() { + // Format the event + let mut visitor = StringVisitor::default(); + event.record(&mut visitor); + let message = visitor.0; + + let clean_message = remove_ansi_color_code(&message); + + // Write to file + let _ = writeln!(data.file, "[{level}] {clean_message}"); + let _ = data.file.flush(); + + // Check if we need to rotate if data.current_day_of_month != now.day() { drop(data); if let Err(e) = self.rotate_log() { @@ -208,24 +209,27 @@ impl Log for GzipRollingLogger { } } } +} - fn flush(&self) { - if let Ok(data) = self.data.lock() { - data.latest_logger.flush(); +#[derive(Default)] +struct StringVisitor(String); + +impl tracing::field::Visit for StringVisitor { + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + if field.name() == "message" { + self.0 = format!("{value:?}"); + // Remove quotes if present + if self.0.starts_with('"') && self.0.ends_with('"') { + self.0 = self.0[1..self.0.len() - 1].to_string(); + } } } } impl ReadlineLogWrapper { #[must_use] - pub fn new( - log: Box, - file_logger: Option>, - rl: Option>, - ) -> Self { - let loggers: Vec>> = vec![Some(log), file_logger]; + pub const fn new(rl: Option>) -> Self { Self { - internal: CombinedLogger::new(loggers.into_iter().flatten().collect()), readline: std::sync::Mutex::new(rl), } } @@ -244,21 +248,6 @@ impl ReadlineLogWrapper { } } -// 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); - } - - fn flush(&self) { - self.internal.flush(); - } - - fn enabled(&self, metadata: &log::Metadata) -> bool { - self.internal.enabled(metadata) - } -} - #[derive(Clone, Default)] pub struct PumpkinCommandCompleter { pub server: Arc>>>, diff --git a/pumpkin/src/main.rs b/pumpkin/src/main.rs index 101037368..82707c6ee 100644 --- a/pumpkin/src/main.rs +++ b/pumpkin/src/main.rs @@ -60,11 +60,6 @@ async fn main() { pumpkin::init_logger(&advanced_config); - if let Some((logger_impl, level)) = pumpkin::LOGGER_IMPL.wait() { - log::set_logger(logger_impl).unwrap(); - log::set_max_level(*level); - } - let default_panic = std::panic::take_hook(); std::panic::set_hook(Box::new(move |info| { default_panic(info); diff --git a/pumpkin/src/plugin/api/context.rs b/pumpkin/src/plugin/api/context.rs index e78387f42..95f5a0b69 100644 --- a/pumpkin/src/plugin/api/context.rs +++ b/pumpkin/src/plugin/api/context.rs @@ -306,8 +306,8 @@ impl Context { let static_logger = Box::leak(Box::new(logger_arc)); - if let Some(Some((logger_impl, level))) = static_logger.get() { - log::set_logger(logger_impl).unwrap(); + if let Some(Some((_logger_impl, level))) = static_logger.get() { + // TODO log::set_max_level(*level); } }