Merge pull request 'Implement robust logging and enhanced event coverage' (#6) from feature/robust-logging into main

Reviewed-on: #6
2026-03-19 21:16:40 -06:00
parent 93b1c1e301 7bab50b431
commit 394a9b8355
9 changed files with 157 additions and 130 deletions
--- a/.gitea/workflows/smoke-tests.yml
+++ b/.gitea/workflows/smoke-tests.yml
@@ -168,7 +168,7 @@ jobs:
            echo "go down"
            echo "go south"
            echo "attack thief"
-            sleep 8
+            sleep 15
            echo "stats"
            echo "quit"
          ) | ssh -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -p 2222 smoketest@localhost
@@ -199,3 +199,33 @@ jobs:
          grep -q '"shop"' rpc_resp.json
          rm rpc_resp.json
          ./target/debug/mudtool -d "$TEST_DB" players delete rpctest
+
+      - name: Verify logging
+        run: |
+          set +e
+          if [ ! -d "logs" ]; then
+            echo "Error: logs directory not found"
+            exit 1
+          fi
+          
+          FAILED=0
+          
+          echo "Checking mudserver logs..."
+          grep -q "World '.*': .* rooms" logs/mudserver_*.log || { echo "Failed: World loading log missing"; FAILED=1; }
+          grep -q "MUD server listening on" logs/mudserver_*.log || { echo "Failed: Listen log missing"; FAILED=1; }
+          grep -q "New character created: smoketest" logs/mudserver_*.log || { echo "Failed: smoketest creation log missing"; FAILED=1; }
+          grep -q "Admin action: registration setting updated: '.*'" logs/mudserver_*.log || { echo "Failed: Admin action log missing"; FAILED=1; }
+          
+          echo "Checking combat logs..."
+          grep -q "Combat: Player 'smoketest' (ID .*) engaged NPC 'Shadowy Thief'" logs/combat_*.log || { echo "Failed: Combat engagement log missing"; FAILED=1; }
+          grep -q "Combat: Player 'smoketest' (ID .*) killed NPC 'Shadowy Thief'" logs/combat_*.log || { echo "Failed: NPC kill log missing"; FAILED=1; }
+          
+          if [ $FAILED -ne 0 ]; then
+            echo "--- LOG VERIFICATION FAILED ---"
+            echo "--- MUDSERVER LOG CONTENTS ---"
+            cat logs/mudserver_*.log
+            echo "--- COMBAT LOG CONTENTS ---"
+            cat logs/combat_*.log
+            exit 1
+          fi
+          echo "Logging verification passed."
--- a/.gitignore
+++ b/.gitignore
@@ -2,3 +2,5 @@
 *.db
 *.db-shm
 *.db-wal
+/logs
+/manual_logs
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -61,56 +61,6 @@ dependencies = [
 "libc",
 ]

-[[package]]
-name = "anstream"
-version = "0.6.21"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "43d5b281e737544384e969a5ccad3f1cdd24b48086a0fc1b2a5262a26b8f4f4a"
-dependencies = [
- "anstyle",
- "anstyle-parse",
- "anstyle-query",
- "anstyle-wincon",
- "colorchoice",
- "is_terminal_polyfill",
- "utf8parse",
-]
-
-[[package]]
-name = "anstyle"
-version = "1.0.14"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "940b3a0ca603d1eade50a4846a2afffd5ef57a9feac2c0e2ec2e14f9ead76000"
-
-[[package]]
-name = "anstyle-parse"
-version = "0.2.7"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "4e7644824f0aa2c7b9384579234ef10eb7efb6a0deb83f9630a49594dd9c15c2"
-dependencies = [
- "utf8parse",
-]
-
-[[package]]
-name = "anstyle-query"
-version = "1.1.5"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "40c48f72fd53cd289104fc64099abca73db4166ad86ea0b4341abe65af83dadc"
-dependencies = [
- "windows-sys 0.61.2",
-]
-
-[[package]]
-name = "anstyle-wincon"
-version = "3.0.11"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "291e6a250ff86cd4a820112fb8898808a366d8f9f58ce16d1f538353ad55747d"
-dependencies = [
- "anstyle",
- "once_cell_polyfill",
- "windows-sys 0.61.2",
-]
-
 [[package]]
 name = "anyhow"
 version = "1.0.102"
@@ -335,12 +285,6 @@ dependencies = [
 "inout",
 ]

-[[package]]
-name = "colorchoice"
-version = "1.0.5"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "1d07550c9036bf2ae0c684c4297d503f838287c83c53686d05370d0e139ae570"
-
 [[package]]
 name = "compact_str"
 version = "0.9.0"
@@ -385,6 +329,30 @@ dependencies = [
 "libc",
 ]

+[[package]]
+name = "crossbeam-channel"
+version = "0.5.15"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "82b8f8f868b36967f9606790d1903570de9ceaf870a7bf9fbbd3016d636a2cb2"
+dependencies = [
+ "crossbeam-utils",
+]
+
+[[package]]
+name = "crossbeam-queue"
+version = "0.3.12"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "0f58bbc28f91df819d0aa2a2c00cd19754769c2fad90579b3592b1c9ba7a3115"
+dependencies = [
+ "crossbeam-utils",
+]
+
+[[package]]
+name = "crossbeam-utils"
+version = "0.8.21"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d0a5c400df2834b80a4c3327b3aad3a4c4cd4de0629063962b03235697506a28"
+
 [[package]]
 name = "crossterm"
 version = "0.28.1"
@@ -694,29 +662,6 @@ dependencies = [
 "syn 2.0.117",
 ]

-[[package]]
-name = "env_filter"
-version = "1.0.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "7a1c3cc8e57274ec99de65301228b537f1e4eedc1b8e0f9411c6caac8ae7308f"
-dependencies = [
- "log",
- "regex",
-]
-
-[[package]]
-name = "env_logger"
-version = "0.11.9"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "b2daee4ea451f429a58296525ddf28b45a3b64f1acf6587e2067437bb11e218d"
-dependencies = [
- "anstream",
- "anstyle",
- "env_filter",
- "jiff",
- "log",
-]
-
 [[package]]
 name = "equivalent"
 version = "1.0.2"
@@ -809,6 +754,21 @@ version = "0.4.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "0ce7134b9999ecaf8bcd65542e436736ef32ddca1b3e06094cb6ec5755203b80"

+[[package]]
+name = "flexi_logger"
+version = "0.29.8"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "88a5a6882b2e137c4f2664562995865084eb5a00611fba30c582ef10354c4ad8"
+dependencies = [
+ "chrono",
+ "crossbeam-channel",
+ "crossbeam-queue",
+ "log",
+ "nu-ansi-term",
+ "regex",
+ "thiserror 2.0.18",
+]
+
 [[package]]
 name = "fnv"
 version = "1.0.7"
@@ -1166,12 +1126,6 @@ dependencies = [
 "zeroize",
 ]

-[[package]]
-name = "is_terminal_polyfill"
-version = "1.70.2"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "a6cb138bb79a146c1bd460005623e142ef0181e3d0219cb493e02f7d08a35695"
-
 [[package]]
 name = "itertools"
 version = "0.14.0"
@@ -1187,30 +1141,6 @@ version = "1.0.17"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "92ecc6618181def0457392ccd0ee51198e065e016d1d527a7ac1b6dc7c1f09d2"

-[[package]]
-name = "jiff"
-version = "0.2.23"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "1a3546dc96b6d42c5f24902af9e2538e82e39ad350b0c766eb3fbf2d8f3d8359"
-dependencies = [
- "jiff-static",
- "log",
- "portable-atomic",
- "portable-atomic-util",
- "serde_core",
-]
-
-[[package]]
-name = "jiff-static"
-version = "0.2.23"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "2a8c8b344124222efd714b73bb41f8b5120b27a7cc1c75593a6ff768d9d05aa4"
-dependencies = [
- "proc-macro2",
- "quote",
- "syn 2.0.117",
-]
-
 [[package]]
 name = "js-sys"
 version = "0.3.91"
@@ -1387,7 +1317,7 @@ name = "mudserver"
 version = "0.2.0"
 dependencies = [
 "crossterm 0.28.1",
- "env_logger",
+ "flexi_logger",
 "log",
 "rand",
 "ratatui",
@@ -1423,6 +1353,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.61.2",
+]
+
 [[package]]
 name = "num-bigint"
 version = "0.4.6"
@@ -1512,12 +1451,6 @@ version = "1.21.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "9f7c3e4beb33f85d45ae3e3a1792185706c8e16d043238c593331cc7cd313b50"

-[[package]]
-name = "once_cell_polyfill"
-version = "1.70.2"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "384b8ab6d37215f3c5301a95a4accb5d64aa607f1fcb26a11b5303878451b4fe"
-
 [[package]]
 name = "opaque-debug"
 version = "0.3.1"
@@ -1815,15 +1748,6 @@ version = "1.13.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "c33a9471896f1c69cecef8d20cbe2f7accd12527ce60845ff44c153bb2a21b49"

-[[package]]
-name = "portable-atomic-util"
-version = "0.2.6"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "091397be61a01d4be58e7841595bd4bfedb15f1cd54977d79b8271e94ed799a3"
-dependencies = [
- "portable-atomic",
-]
-
 [[package]]
 name = "powerfmt"
 version = "0.2.0"
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -13,6 +13,6 @@ rusqlite = { version = "0.35", features = ["bundled"] }
 ratatui = "0.30"
 crossterm = "0.28"
 log = "0.4"
-env_logger = "0.11"
+flexi_logger = { version = "0.29", features = ["async"] }
 regex = "1"
 rand = "0.8"
--- a/src/admin.rs
+++ b/src/admin.rs
@@ -74,6 +74,7 @@ async fn admin_promote(target: &str, state: &SharedState) -> CommandResult {
    if target.is_empty() {
        return simple(&format!("{}\r\n", ansi::error_msg("Usage: admin promote <player>")));
    }
+    log::info!("Admin action: promote player '{}'", target);
    let st = state.lock().await;
    if st.db.set_admin(target, true) {
        // Also update in-memory if online
@@ -124,6 +125,7 @@ async fn admin_demote(target: &str, state: &SharedState) -> CommandResult {
    if target.is_empty() {
        return simple(&format!("{}\r\n", ansi::error_msg("Usage: admin demote <player>")));
    }
+    log::info!("Admin action: demote player '{}'", target);
    let st = state.lock().await;
    if st.db.set_admin(target, false) {
        simple(&format!(
@@ -142,6 +144,7 @@ async fn admin_kick(target: &str, player_id: usize, state: &SharedState) -> Comm
    if target.is_empty() {
        return simple(&format!("{}\r\n", ansi::error_msg("Usage: admin kick <player>")));
    }
+    log::info!("Admin action: kick player '{}'", target);
    let mut st = state.lock().await;
    let low = target.to_lowercase();

@@ -237,6 +240,7 @@ async fn admin_teleport(room_id: &str, player_id: usize, state: &SharedState) ->
            ansi::error_msg("Usage: admin teleport <room_id>")
        ));
    }
+    log::info!("Admin action: teleport player ID {} to '{}'", player_id, room_id);
    let mut st = state.lock().await;
    if st.world.get_room(room_id).is_none() {
        let rooms: Vec<&String> = st.world.rooms.keys().collect();
@@ -329,6 +333,7 @@ async fn admin_teleport(room_id: &str, player_id: usize, state: &SharedState) ->
 }

 async fn admin_registration(args: &str, state: &SharedState) -> CommandResult {
+    log::info!("Admin action: registration setting updated: '{}'", args);
    let st = state.lock().await;
    match args.to_lowercase().as_str() {
        "on" | "true" | "open" => {
@@ -365,6 +370,7 @@ async fn admin_announce(msg: &str, player_id: usize, state: &SharedState) -> Com
            ansi::error_msg("Usage: admin announce <message>")
        ));
    }
+    log::info!("Admin action: announcement by player ID {}: '{}'", player_id, msg);
    let st = state.lock().await;
    let announcement = CryptoVec::from(
        format!(
@@ -405,6 +411,7 @@ async fn admin_announce(msg: &str, player_id: usize, state: &SharedState) -> Com
 }

 async fn admin_heal(args: &str, player_id: usize, state: &SharedState) -> CommandResult {
+    log::info!("Admin action: heal player '{}' (empty means self)", args);
    let mut st = state.lock().await;

    if args.is_empty() {
@@ -564,6 +571,7 @@ async fn admin_info(target: &str, state: &SharedState) -> CommandResult {
 }

 async fn admin_setattitude(args: &str, state: &SharedState) -> CommandResult {
+    log::info!("Admin action: setattitude '{}'", args);
    let parts: Vec<&str> = args.splitn(3, ' ').collect();
    if parts.len() < 3 {
        return simple(&format!(
--- a/src/combat.rs
+++ b/src/combat.rs
@@ -69,6 +69,8 @@ pub fn resolve_combat_tick(
            ));

            if new_npc_hp <= 0 {
+                let player_name = state.players.get(&player_id).map(|c| c.player.name.clone()).unwrap_or_else(|| "Unknown".into());
+                log::info!(target: "{combat}", "Combat: Player '{}' (ID {}) killed NPC '{}' ({})", player_name, player_id, npc_template.name, npc_id);
                if let Some(inst) = state.npc_instances.get_mut(&npc_id) {
                    inst.alive = false;
                    inst.hp = 0;
@@ -351,7 +353,9 @@ pub fn player_death_respawn(player_id: usize, state: &mut GameState) -> String {
        .players
        .get(&player_id)
        .map(|c| c.player.name.clone())
-        .unwrap_or_default();
+        .unwrap_or_else(|| "Unknown".into());
+
+    log::info!(target: "{combat}", "Combat: Player '{}' (ID {}) died and respawned at {}", player_name, player_id, spawn_room);

    if let Some(conn) = state.players.get_mut(&player_id) {
        conn.player.stats.hp = conn.player.stats.max_hp;
--- a/src/commands.rs
+++ b/src/commands.rs
@@ -1236,6 +1236,8 @@ async fn cmd_attack(pid: usize, target: &str, state: &SharedState) -> CommandRes
        });
    }

+    log::info!(target: "{combat}", "Combat: Player '{}' (ID {}) engaged NPC '{}' ({}) in combat", pname, pid, npc_name, npc_id);
+
    CommandResult {
        output: format!(
            "{}\r\n{}\r\n{}",
--- a/src/main.rs
+++ b/src/main.rs
@@ -2,6 +2,8 @@ use std::path::PathBuf;
 use std::sync::Arc;
 use tokio::sync::Mutex;

+use flexi_logger::writers::FileLogWriter;
+use flexi_logger::{Cleanup, Criterion, Duplicate, FileSpec, Logger, Naming, WriteMode};
 use russh::keys::ssh_key::rand_core::OsRng;
 use russh::server::Server as _;
 use tokio::net::TcpListener;
@@ -18,12 +20,12 @@ const DEFAULT_DB_PATH: &str = "./mudserver.db";

 #[tokio::main]
 async fn main() {
-    env_logger::Builder::from_env(env_logger::Env::default().default_filter_or("info")).init();
-
    let mut port = DEFAULT_PORT;
    let mut jsonrpc_port = 2223;
    let mut world_dir = PathBuf::from(DEFAULT_WORLD_DIR);
    let mut db_path = PathBuf::from(DEFAULT_DB_PATH);
+    let mut log_dir = "logs".to_string();
+    let mut log_level = "info".to_string();

    let args: Vec<String> = std::env::args().collect();
    let mut i = 1;
@@ -51,12 +53,22 @@ async fn main() {
                i += 1;
                db_path = PathBuf::from(args.get(i).expect("--db requires a path"));
            }
+            "--log-dir" => {
+                i += 1;
+                log_dir = args.get(i).expect("--log-dir requires a path").to_string();
+            }
+            "--log-level" => {
+                i += 1;
+                log_level = args.get(i).expect("--log-level requires a level").to_string();
+            }
            "--help" => {
                eprintln!("Usage: mudserver [OPTIONS]");
                eprintln!("  --port, -p      SSH listen port (default: {DEFAULT_PORT})");
                eprintln!("  --rpc-port      JSON-RPC listen port (default: 2223)");
                eprintln!("  --world, -w     World directory (default: {DEFAULT_WORLD_DIR})");
                eprintln!("  --db, -d        Database path (default: {DEFAULT_DB_PATH})");
+                eprintln!("  --log-dir       Directory for log files (default: logs)");
+                eprintln!("  --log-level     Logging level (default: info)");
                std::process::exit(0);
            }
            other => {
@@ -67,6 +79,42 @@ async fn main() {
        i += 1;
    }

+    // Ensure log directory exists
+    std::fs::create_dir_all(&log_dir).unwrap_or_else(|e| {
+        eprintln!("Failed to create log directory: {e}");
+        std::process::exit(1);
+    });
+
+    // Initialize logger
+    let combat_writer = FileLogWriter::builder(FileSpec::default().directory(&log_dir).basename("combat"))
+        .rotate(
+            Criterion::Size(10_000_000), // 10 MB
+            Naming::Numbers,
+            Cleanup::KeepLogFiles(7),
+        )
+        .append()
+        .write_mode(WriteMode::Direct)
+        .try_build()
+        .unwrap();
+
+    Logger::try_with_str(&log_level)
+        .unwrap()
+        .log_to_file(FileSpec::default().directory(&log_dir).basename("mudserver"))
+        .append()
+        .duplicate_to_stderr(Duplicate::All)
+        .rotate(
+            Criterion::Size(10_000_000), // 10 MB
+            Naming::Numbers,
+            Cleanup::KeepLogFiles(7),
+        )
+        .write_mode(WriteMode::Direct)
+        .add_writer("combat", Box::new(combat_writer))
+        .start()
+        .unwrap_or_else(|e| {
+            eprintln!("Failed to initialize logger: {e}");
+            std::process::exit(1);
+        });
+
    log::info!("Loading world from: {}", world_dir.display());
    let loaded_world = world::World::load(&world_dir).unwrap_or_else(|e| {
        eprintln!("Failed to load world: {e}");
--- a/src/ssh.rs
+++ b/src/ssh.rs
@@ -83,6 +83,8 @@ impl MudHandler {
            state.load_existing_player(self.id, saved, Some(channel), Some(handle));
            drop(state);

+            log::info!("Player '{}' (id={}) logged in", self.username, self.id);
+
            let msg = format!(
                "{}\r\n",
                ansi::system_msg("Welcome back! Your character has been restored.")
@@ -171,6 +173,13 @@ impl MudHandler {
            .map(|c| c.name.clone())
            .unwrap_or_default();

+        log::info!(
+            "New character created: {} (Race: {}, Class: {})",
+            self.username,
+            race_name,
+            class_name
+        );
+
        state.create_new_player(
            self.id,
            self.username.clone(),