feat: logging to file (#958)

* feat: logging to file

.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
+pumpkin-data/src/generated

Cargo.lock

@@ -1969,6 +1969,7 @@ dependencies = [
  "chrono",
  "crossbeam",
  "dhat",
+ "flate2",
  "futures",
  "git-version",
  "hmac",

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(),
         }
     }
 }

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"
 

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<Arc<RwLock<PermissionManager>>> = 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<dyn Log>,
-    readline: std::sync::Mutex<Option<Readline>>,
-}
-
-impl ReadlineLogWrapper {
-    fn new(log: impl Log + 'static, rl: Option<Readline>) -> Self {
-        Self {
-            internal: Box::new(log),
-            readline: std::sync::Mutex::new(rl),
-        }
-    }
-
-    fn take_readline(&self) -> Option<Readline> {
-        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<Option<(ReadlineLogWrapper, LevelFilter)>> = LazyLock::new(|| {
     if advanced_config().logging.enabled {
         let mut config = simplelog::ConfigBuilder::new();
@@ -126,7 +73,7 @@ pub static LOGGER_IMPL: LazyLock<Option<(ReadlineLogWrapper, LevelFilter)>> = 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<Option<(ReadlineLogWrapper, LevelFilter)>> = La
             .and_then(Result::ok)
             .unwrap_or(LevelFilter::Info);
 
+        let file_logger: Option<Box<dyn SharedLogger + 'static>> =
+            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<dyn SharedLogger>,
+                )
+            };
+
         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

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<CombinedLogger>,
+    readline: std::sync::Mutex<Option<Readline>>,
+}
+
+struct GzipRollingLoggerData {
+    pub current_day_of_month: u8,
+    pub last_rotate_time: time::OffsetDateTime,
+    pub latest_logger: WriteLogger<File>,
+    latest_filename: String,
+}
+
+pub struct GzipRollingLogger {
+    log_level: LevelFilter,
+    data: std::sync::Mutex<GzipRollingLoggerData>,
+    config: Config,
+}
+
+impl GzipRollingLogger {
+    pub fn new(
+        log_level: LevelFilter,
+        config: Config,
+        filename: String,
+    ) -> Result<Box<Self>, Box<dyn std::error::Error>> {
+        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<dyn std::error::Error>> {
+        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<Self>) -> Box<dyn Log> {
+        Box::new(*self)
+    }
+}
+
+impl ReadlineLogWrapper {
+    pub fn new(
+        log: Box<dyn SharedLogger + 'static>,
+        file_logger: Option<Box<dyn SharedLogger + 'static>>,
+        rl: Option<Readline>,
+    ) -> Self {
+        let loggers: Vec<Option<Box<dyn SharedLogger + 'static>>> = 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<Readline> {
+        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)
+    }
+}