logging

Cargo.toml

@@ -2,6 +2,8 @@
 resolver = "2"
 members = [
     "client",
+    "logging",
+    "procmacro",
     "server",
     "utils",
 ]

client/Cargo.toml

@@ -6,6 +6,7 @@ default-run = "client"
 
 [dependencies]
 utils = { path = "../utils" }
+logging = { path = "../logging" }
 
 cursive = "0.21"
 reqwest = { version = "0.12.15", features = [ "blocking" ] }

client/src/main.rs

@@ -3,6 +3,7 @@ mod message;
 mod persistence;
 mod ui;
 
+use cursive::reexports::log;
 use cursive::views::{
     Button, Dialog, DummyView, EditView, LinearLayout, NamedView, Panel, ScrollView, SelectView,
     TextArea, TextView,
@@ -88,34 +89,48 @@ pub fn save_appdata(siv: &mut Cursive) {
     let mut file = std::fs::File::create(SAVE_FILE).expect("Failed to create savedata file.");
     file.write_all(&fuzzy_bytes)
         .expect("Failed to write savedata file.");
+
+    log::info!("Wrote savadata to file.");
 }
 
 pub fn load_appdata(siv: &mut Cursive) -> std::io::Result<()> {
+    let mut df = logging::warn_deferred("Savedata file not found; using defaults");
+
     let mut file = std::fs::File::open(SAVE_FILE)?;
 
     let mut bytes = Vec::new();
     file.read_to_end(&mut bytes)?;
     let useful_bytes = utils::binary::fuzzy_bytes(bytes, SAVE_FILE_FUZZY);
 
+    df.cancel();
+
     let Ok(savedata) = persistence::Savedata::deserialize_checked(useful_bytes) else {
         // If the file is corrupted, create a new one
+        logging::warn("Savedata file corrupted; using defaults.");
         return Ok(());
     };
 
     let appdata = Appdata::from(savedata);
     siv.set_user_data(appdata);
 
+    logging::info("Savedata file loaded.");
     Ok(())
 }
 
 fn main() {
+    if cfg!(debug_assertions) {
+        logging::set_global_log_level(logging::LogLevel::Trace);
+    } else {
+        logging::set_global_log_level(logging::LogLevel::Info);
+    }
+
     utils::rng::shuffle_rng();
 
     let mut siv = Cursive::default();
     siv.set_user_data(Appdata::new());
 
-    // TODO: Add a notice when the file is corrupted.
-    load_appdata(&mut siv);
+    // TODO (low): Add a notice when the file is corrupted.
+    let _ = load_appdata(&mut siv);
 
     // Global hotkeys
     siv.add_global_callback(event::Key::Backspace, |siv| {
@@ -192,6 +207,7 @@ fn main() {
                             appdata.local_channels.push(input.to_string());
                         });
 
+                        save_appdata(siv);
                         ui::visual_update(siv);
                         ui::keybind_close_manual_end(siv, false);
                     } else {
@@ -321,6 +337,7 @@ fn main() {
                             appdata.username = input.to_string();
                         });
 
+                        save_appdata(siv);
                         ui::visual_update(siv);
                         ui::keybind_close_manual_end(siv, false);
                     } else {
@@ -374,6 +391,7 @@ fn main() {
                         view.get_mut().remove_item(idx);
                     });
 
+                    save_appdata(siv);
                     ui::visual_update(siv);
                 });
             wordslist_view.add_all_str(&appdata.blocked_phrases);
@@ -405,6 +423,7 @@ fn main() {
                     },
                 );
 
+                save_appdata(siv);
                 ui::visual_update(siv);
             });
 
@@ -519,6 +538,7 @@ fn main() {
                         }
                     });
 
+                    save_appdata(siv);
                     ui::visual_update(siv);
                     ui::keybind_close_manual_end(siv, false);
                 })

logging/Cargo.toml

@@ -0,0 +1,8 @@
+[package]
+name = "logging"
+version = "0.1.0"
+edition = "2021"
+
+[dependencies]
+procmacro = { path = "../procmacro" }
+utils = { path = "../utils" }

logging/src/lib.rs

@@ -0,0 +1,113 @@
+use std::sync::Mutex;
+
+static LOG_LEVEL: Mutex<LogLevel> = Mutex::new(LogLevel::Info);
+
+pub use procmacro::log;
+
+#[derive(PartialEq, Eq, PartialOrd, Ord, Clone, Copy)]
+pub enum LogLevel {
+    Fatal,
+    Error,
+    Warning,
+    Info,
+    Debug,
+    Trace,
+}
+
+pub struct DeferredLog {
+    message: String,
+    level: LogLevel,
+    active: bool,
+}
+
+impl DeferredLog {
+    fn new(message: &str, level: LogLevel) -> Self {
+        Self {
+            message: message.to_string(),
+            level,
+            active: true,
+        }
+    }
+
+    pub fn cancel(&mut self) {
+        self.active = false;
+    }
+}
+
+impl Drop for DeferredLog {
+    fn drop(&mut self) {
+        if self.active && get_global_log_level() >= self.level {
+            create_log(&self.message, self.level);
+        }
+    }
+}
+
+fn create_log(message: &str, level: LogLevel) {
+    let log_id = utils::rng::random_numeric_string(3);
+
+    #[rustfmt::skip]
+    let prefix = match level {
+        LogLevel::Fatal   => "[  FATAL  ",
+        LogLevel::Error   => "[  ERROR  ",
+        LogLevel::Warning => "[ WARNING ",
+        LogLevel::Info    => "[  INFO   ",
+        LogLevel::Debug   => "[  DEBUG  ",
+        LogLevel::Trace   => "[  TRACE  ",
+    }.to_string() + &format!("{:0>3}", log_id) + " ]";
+
+    print!("{}", prefix);
+
+    for (idx, line) in message.split("\n").enumerate() {
+        if idx == 0 {
+            println!(" {line}");
+        } else {
+            println!(" {idx:>7}  {log_id:0>3} | {line}");
+        }
+    }
+
+    println!();
+}
+
+macro_rules! logger_setup {
+    ($level_fn_name:ident, $deferred_level_fn_name:ident, $level_variant:expr) => {
+        pub fn $level_fn_name(message: &str) {
+            if get_global_log_level() >= $level_variant {
+                create_log(message, $level_variant);
+            }
+        }
+
+        pub fn $deferred_level_fn_name(message: &str) -> DeferredLog {
+            DeferredLog::new(message, $level_variant)
+        }
+    };
+}
+
+logger_setup! { trace, trace_deferred, LogLevel::Trace }
+logger_setup! { debug, debug_deferred, LogLevel::Debug }
+logger_setup! { info, info_deferred, LogLevel::Info}
+logger_setup! { warn, warn_deferred, LogLevel::Warning }
+logger_setup! { error, error_deferred, LogLevel::Error }
+logger_setup! { fatal, fatal_deferred, LogLevel::Fatal }
+
+pub fn set_global_log_level(level: LogLevel) {
+    let mut guard = LOG_LEVEL.lock().expect("Logging mutex is poisoned.");
+    *guard = level;
+}
+
+pub fn get_global_log_level() -> LogLevel {
+    *LOG_LEVEL.lock().expect("Logging mutex is poisoned.")
+}
+
+#[cfg(test)]
+mod test {
+    use super::*;
+
+    #[test]
+    fn test_level_ords() {
+        assert!(LogLevel::Trace > LogLevel::Debug);
+        assert!(LogLevel::Debug > LogLevel::Info);
+        assert!(LogLevel::Info > LogLevel::Warning);
+        assert!(LogLevel::Warning > LogLevel::Error);
+        assert!(LogLevel::Error > LogLevel::Fatal);
+    }
+}

procmacro/Cargo.toml

@@ -0,0 +1,10 @@
+[package]
+name = "procmacro"
+version = "0.1.0"
+edition = "2021"
+
+[lib]
+proc-macro = true
+
+[dependencies]
+utils = { path = "../utils" }

procmacro/src/lib.rs

@@ -0,0 +1,124 @@
+extern crate proc_macro;
+use proc_macro::{TokenStream, TokenTree};
+
+#[proc_macro_attribute]
+pub fn log(_attr: TokenStream, item: TokenStream) -> TokenStream {
+    let mut tokens = item.into_iter();
+
+    let logger_function_name = "trace";
+    let skip_types = &["&mut Cursive"];
+    let log_id = utils::rng::random_numeric_string(3);
+
+    let mut function_name = String::new();
+    let mut do_function_name_check = true;
+    let mut args: Vec<(String, String)> = Vec::new();
+
+    let mut function_signature = String::new();
+    let mut function_body = String::new();
+    let mut token_start = String::new();
+    let mut token_end = String::new();
+
+    let mut in_block = false;
+
+    while let Some(token) = tokens.next() {
+        match &token {
+            TokenTree::Group(group)
+                if group.delimiter() == proc_macro::Delimiter::Brace && !in_block =>
+            {
+                let body = group.stream().to_string();
+
+                let mut args_with_values = String::new();
+
+                for (name, ty) in &args {
+                    if skip_types.contains(&ty.as_str()) {
+                        args_with_values.push_str(&format!("{name}: {ty}\n"));
+                    } else {
+                        args_with_values.push_str(&format!("{name}: {ty} = {{{name}:?}}\n"));
+                    }
+                }
+
+                args_with_values = args_with_values.trim_end_matches("\n").to_string();
+
+                token_start = format!(
+                    r#"
+    let args = format!("{args_with_values}");
+    let log_instance_id = utils::rng::random_numeric_string(3);
+    let message1 = format!("Running function call #{{log_instance_id}}\n{function_name}\n{{args}}");
+    {logger_function_name}(&message1);"#
+                );
+
+                token_end = format!(
+                    r#"
+    let message2 = message1.replacen("Running", "Finished", 1);
+    {logger_function_name}(&message2);"#
+                );
+
+                function_body = body;
+                in_block = true;
+            }
+            TokenTree::Group(group) if group.delimiter() == proc_macro::Delimiter::Parenthesis => {
+                let args_stream = group.stream().to_string();
+
+                for arg in args_stream.split(", ") {
+                    let Some((name, ty)) = arg.split_once(":") else {
+                        continue;
+                    };
+                    args.push((name.trim().to_string(), ty.trim().to_string()));
+                }
+            }
+            TokenTree::Ident(ident) if do_function_name_check => {
+                if function_name == "fn" {
+                    do_function_name_check = false;
+                }
+                function_name = ident.to_string();
+            }
+
+            _ => {}
+        }
+
+        if !in_block {
+            function_signature.push_str(&token.to_string());
+            function_signature.push(' ');
+        }
+    }
+
+    function_signature = function_signature
+        .replace("- >", "->")
+        .replace(" : : ", "::")
+        .replace(" < ", "<")
+        .replace(" > ", ">")
+        .replacen(&format!("{function_name} "), &function_name, 1);
+    function_body = function_body.replace(";", ";\n");
+
+    let mut arg_names_in_order = String::new();
+    for (idx, (name, _)) in args.iter().enumerate() {
+        arg_names_in_order.push_str(&name);
+
+        if idx < args.len() - 1 {
+            arg_names_in_order.push_str(", ");
+        }
+    }
+
+    // The original function being wrapped
+    let hidden_function_name = format!("hidden_{log_id}_{function_name}");
+    let hidden_function_signature =
+        function_signature.replacen(&function_name, &hidden_function_name, 1);
+
+    let output = format!(
+        r#"
+{hidden_function_signature} {{
+    {function_body}
+}}
+
+{function_signature} {{
+    use logging::{logger_function_name};
+    {token_start}
+    let result = {hidden_function_name}({arg_names_in_order});
+    {token_end}
+    result
+}}
+    "#
+    );
+
+    output.parse().unwrap()
+}

utils/src/rng.rs

@@ -22,6 +22,7 @@ pub fn random_numeric_string(length: usize) -> String {
 
 pub fn random_number() -> u64 {
     let mut rng = RNG.lock().expect("RNG mutex is poisoned.");
+    rng.inject_time();
     rng.next()
 }