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

Reviewed-on: #6

.gitea/workflows/smoke-tests.yml

@@ -61,6 +61,35 @@ jobs:
           set -e
           [[ $r -eq 0 || $r -eq 255 ]]
 
+      - name: Smoke - weather and time
+        run: |
+          set -euo pipefail
+          RUST_LOG=info ./target/debug/mudserver -d "$TEST_DB" &
+          MUD_PID=$!
+          trap 'kill $MUD_PID 2>/dev/null || true' EXIT
+          bash scripts/ci/wait-for-tcp.sh 127.0.0.1 2222
+          set +e
+          ssh -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -p 2222 smoketest@localhost <<'EOF' > weather_test.out
+          go south
+          go down
+          look
+          quit
+          EOF
+          r=$?
+          set -e
+          [[ $r -eq 0 || $r -eq 255 ]]
+          if ! grep -q "The sky is\|raining\|storm\|snow\|fog" weather_test.out; then
+            echo "Error: Weather info not found in look output"
+            cat weather_test.out
+            exit 1
+          fi
+          if ! grep -q "\[Night\]\|\[Morning\]\|\[Afternoon\]\|\[Evening\]" weather_test.out; then
+            echo "Error: Time of day info not found in look output"
+            cat weather_test.out
+            exit 1
+          fi
+          rm weather_test.out
+
       - name: Smoke - persistence (reconnect)
         run: |
           set -euo pipefail
@@ -139,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
@@ -173,20 +202,30 @@ jobs:
 
       - name: Verify logging
         run: |
+          set +e
           if [ ! -d "logs" ]; then
             echo "Error: logs directory not found"
             exit 1
           fi
-          if ! ls logs/mudserver_*.log >/dev/null 2>&1; then
-            echo "Error: no log files found"
+          
+          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
-          LOG_FILE=$(ls -t logs/mudserver_*.log | head -n 1)
-          echo "Checking log file: $LOG_FILE"
-          grep -q "World '.*': .* rooms" "$LOG_FILE"
-          grep -q "MUD server listening on" "$LOG_FILE"
-          grep -q "New character created: smoketest" "$LOG_FILE"
-          grep -q "Admin action: registration setting updated: '.*'" "$LOG_FILE"
-          grep -q "Combat: Player 'smoketest' (ID .*) killed NPC 'Shadowy Thief'" "$LOG_FILE"
-          grep -q "New character created: rpctest" "$LOG_FILE"
-          grep -q "New JSON-RPC connection from" "$LOG_FILE"
+          echo "Logging verification passed."

.gitignore

@@ -2,3 +2,5 @@
 *.db
 *.db-shm
 *.db-wal
+/logs
+/manual_logs

PLANNED.md

@@ -3,6 +3,8 @@
 - **Shops / economy** — NPCs that buy and sell; currency and pricing.
 - **Enhanced NPC Interactions** — Keyword-based dialogue system.
 - **Aggressive NPC AI** — NPCs with Aggressive attitude now correctly initiate combat.
+- **Weather** — Weather system (e.g., rain, snow, fog) affecting areas or atmosphere.
+- **Day/night or time of day** — Time cycle affecting room descriptions, spawns, or NPC behavior.
 
 ## Easy
 
@@ -18,8 +20,7 @@ Content-only or minimal code; add TOML/data and existing systems already support
 
 New state, commands, or mechanics with bounded scope.
 
-- **Weather** — Weather system (e.g., rain, snow, fog) affecting areas or atmosphere; scope TBD.
-- **Day/night or time of day** — Time cycle affecting room descriptions, spawns, or NPC behavior; lighter than full weather.
+- **Robust Logging** — Structured logging, rotation, and persistence; better visibility into server state and player actions.
 - **Quests or objectives** — Simple “kill X” / “bring Y” goals; quest state in DB and hooks in combat/loot/NPCs.
 - **Player parties** — Group formation, shared objectives, party-only chat or visibility; new state and commands.
 - **PvP** — Player-vs-player combat; consent/flagging, safe zones, and balance TBD.

TESTING.md

@@ -113,6 +113,13 @@ Run through the checks below before every commit to ensure consistent feature co
 - [ ] Negative status effects cleared on player death/respawn
 - [ ] Status effects on offline players resolve by wall-clock time on next login
 
+## Weather & Time
+- [ ] Outdoor rooms display time of day (e.g., `[Night]`, `[Morning]`).
+- [ ] Outdoor rooms display current weather (e.g., `The sky is clear`, `It is raining`).
+- [ ] Indoor rooms do not show weather or time of day.
+- [ ] Rain or storm applies the `wet` status effect to players in outdoor rooms.
+- [ ] Weather changes periodically and broadcasts messages to players in outdoor rooms.
+
 ## Guilds
 - [ ] `guild list` shows all available guilds with descriptions
 - [ ] `guild info <name>` shows guild details, growth stats, and spell list

run-tests.sh

@@ -44,6 +44,25 @@ flee
 quit
 EOF
 
+ssh_mud smoketest@localhost <<'EOF' > weather_test.out
+go south
+go down
+look
+quit
+EOF
+
+if ! grep -q "The sky is\|raining\|storm\|snow\|fog" weather_test.out; then
+  echo "Error: Weather info not found in look output"
+  cat weather_test.out
+  exit 1
+fi
+if ! grep -q "\[Night\]\|\[Morning\]\|\[Afternoon\]\|\[Evening\]" weather_test.out; then
+  echo "Error: Time of day info not found in look output"
+  cat weather_test.out
+  exit 1
+fi
+rm weather_test.out
+
 ssh_mud smoketest@localhost <<'EOF'
 look
 stats

src/combat.rs

@@ -70,7 +70,7 @@ 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!("Combat: Player '{}' (ID {}) killed NPC '{}' ({})", player_name, player_id, npc_template.name, npc_id);
+                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;
@@ -355,7 +355,7 @@ pub fn player_death_respawn(player_id: usize, state: &mut GameState) -> String {
         .map(|c| c.player.name.clone())
         .unwrap_or_else(|| "Unknown".into());
 
-    log::info!("Combat: Player '{}' (ID {}) died and respawned at {}", player_name, player_id, spawn_room);
+    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;

src/commands.rs

@@ -180,6 +180,14 @@ fn attitude_color(att: Attitude) -> &'static str {
     }
 }
 
+pub fn get_time_of_day(tick: u64) -> &'static str {
+    let day_tick = tick % 1440;
+    if day_tick < 360 { "Night" }
+    else if day_tick < 720 { "Morning" }
+    else if day_tick < 1080 { "Afternoon" }
+    else { "Evening" }
+}
+
 pub fn render_room_view(
     room_id: &str,
     player_id: usize,
@@ -195,13 +203,19 @@ pub fn render_room_view(
         .map(|c| c.player.name.as_str())
         .unwrap_or("");
 
+    let time_of_day = get_time_of_day(st.tick_count);
     let mut out = format!(
-        "\r\n{} {}\r\n  {}\r\n",
+        "\r\n{} {} {}\r\n  {}\r\n",
         ansi::room_name(&room.name),
         ansi::system_msg(&format!("[{}]", room.region)),
+        ansi::color(ansi::YELLOW, &format!("[{}]", time_of_day)),
         room.description
     );
 
+    if room.outdoors {
+        out.push_str(&format!("  {}\r\n", ansi::color(ansi::CYAN, st.weather.kind.description())));
+    }
+
     let npc_strs: Vec<String> = room
         .npcs
         .iter()
@@ -1222,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{}",

src/game.rs

@@ -9,6 +9,35 @@ use russh::ChannelId;
 use crate::db::{GameDb, SavedPlayer};
 use crate::world::{Attitude, Class, Object, Race, World};
 
+#[derive(Debug, Clone, Copy, PartialEq, Eq)]
+pub enum WeatherKind {
+    Clear,
+    Cloudy,
+    Rain,
+    Storm,
+    Snow,
+    Fog,
+}
+
+impl WeatherKind {
+    pub fn description(&self) -> &'static str {
+        match self {
+            WeatherKind::Clear => "The sky is clear.",
+            WeatherKind::Cloudy => "The sky is overcast with clouds.",
+            WeatherKind::Rain => "It is raining.",
+            WeatherKind::Storm => "A powerful storm is raging.",
+            WeatherKind::Snow => "Soft snowflakes are falling from the sky.",
+            WeatherKind::Fog => "A thick fog blankets the area.",
+        }
+    }
+}
+
+#[derive(Debug, Clone)]
+pub struct WeatherState {
+    pub kind: WeatherKind,
+    pub remaining_ticks: u32,
+}
+
 #[derive(Clone)]
 pub struct PlayerStats {
     pub max_hp: i32,
@@ -142,6 +171,7 @@ pub struct GameState {
     pub npc_instances: HashMap<String, NpcInstance>,
     pub rng: XorShift64,
     pub tick_count: u64,
+    pub weather: WeatherState,
 }
 
 pub type SharedState = Arc<Mutex<GameState>>;
@@ -226,6 +256,10 @@ impl GameState {
             npc_instances,
             rng,
             tick_count: 0,
+            weather: WeatherState {
+                kind: WeatherKind::Clear,
+                remaining_ticks: 100,
+            },
         }
     }
 

src/main.rs

@@ -2,6 +2,7 @@ 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 _;
@@ -78,17 +79,36 @@ 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::BufferAndFlush)
+        .write_mode(WriteMode::Direct)
+        .add_writer("combat", Box::new(combat_writer))
         .start()
         .unwrap_or_else(|e| {
             eprintln!("Failed to initialize logger: {e}");

src/tick.rs

@@ -26,6 +26,48 @@ pub async fn run_tick_engine(state: SharedState) {
         st.tick_count += 1;
         let tick = st.tick_count;
 
+        let mut weather_msg = None;
+        st.weather.remaining_ticks = st.weather.remaining_ticks.saturating_sub(1);
+        if st.weather.remaining_ticks == 0 {
+            let old_kind = st.weather.kind;
+            st.weather.kind = match st.rng.next_range(0, 5) {
+                0 => crate::game::WeatherKind::Clear,
+                1 => crate::game::WeatherKind::Cloudy,
+                2 => crate::game::WeatherKind::Rain,
+                3 => crate::game::WeatherKind::Storm,
+                4 => crate::game::WeatherKind::Snow,
+                5 => crate::game::WeatherKind::Fog,
+                _ => crate::game::WeatherKind::Clear,
+            };
+            st.weather.remaining_ticks = st.rng.next_range(100, 400) as u32;
+
+            if old_kind != st.weather.kind {
+                weather_msg = Some(format!(
+                    "\r\n  {}\r\n",
+                    ansi::color(ansi::CYAN, st.weather.kind.description())
+                ));
+            }
+        }
+
+        // Apply "wet" effect if raining/storming
+        if st.weather.kind == crate::game::WeatherKind::Rain
+            || st.weather.kind == crate::game::WeatherKind::Storm
+        {
+            let wet_players: Vec<String> = st
+                .players
+                .values()
+                .filter_map(|c| {
+                    st.world
+                        .get_room(&c.player.room_id)
+                        .filter(|r| r.outdoors)
+                        .map(|_| c.player.name.clone())
+                })
+                .collect();
+            for name in wet_players {
+                st.db.save_effect(&name, "wet", 10, 0);
+            }
+        }
+
         st.check_respawns();
 
         // --- NPC auto-aggro: hostile NPCs initiate combat with players in their room ---
@@ -60,6 +102,16 @@ pub async fn run_tick_engine(state: SharedState) {
 
         let mut messages: HashMap<usize, String> = HashMap::new();
 
+        if let Some(msg) = weather_msg {
+            for (&pid, conn) in st.players.iter() {
+                if let Some(room) = st.world.get_room(&conn.player.room_id) {
+                    if room.outdoors {
+                        messages.entry(pid).or_default().push_str(&msg);
+                    }
+                }
+            }
+        }
+
         for (pid, npc_id) in &new_combats {
             let npc_name = st
                 .world
@@ -183,6 +235,24 @@ pub async fn run_tick_engine(state: SharedState) {
                         }
                     }
                 }
+                "wet" => {
+                    let online_pid = st
+                        .players
+                        .iter()
+                        .find(|(_, c)| c.player.name == eff.player_name)
+                        .map(|(&id, _)| id);
+
+                    if let Some(pid) = online_pid {
+                        if let Some(_conn) = st.players.get_mut(&pid) {
+                            if eff.remaining_ticks <= 0 {
+                                messages.entry(pid).or_default().push_str(&format!(
+                                    "\r\n  {} You dry off.\r\n",
+                                    ansi::color(ansi::CYAN, "~~"),
+                                ));
+                            }
+                        }
+                    }
+                }
                 "regen" => {
                     let heal = eff.magnitude;
                     let online_pid = st

src/world.rs

@@ -77,6 +77,8 @@ pub struct RoomFile {
     pub description: String,
     #[serde(default)]
     pub exits: HashMap<String, String>,
+    #[serde(default)]
+    pub outdoors: bool,
 }
 
 #[derive(Deserialize, Clone)]
@@ -413,6 +415,7 @@ pub struct Room {
     pub exits: HashMap<String, String>,
     pub npcs: Vec<String>,
     pub objects: Vec<String>,
+    pub outdoors: bool,
 }
 
 #[derive(Clone)]
@@ -665,7 +668,7 @@ impl World {
 
             load_entities_from_dir(&region_path.join("rooms"), &region_name, &mut |id, content| {
                 let rf: RoomFile = toml::from_str(content).map_err(|e| format!("Bad room {id}: {e}"))?;
-                rooms.insert(id.clone(), Room { id: id.clone(), region: region_name.clone(), name: rf.name, description: rf.description, exits: rf.exits, npcs: Vec::new(), objects: Vec::new() });
+                rooms.insert(id.clone(), Room { id: id.clone(), region: region_name.clone(), name: rf.name, description: rf.description, exits: rf.exits, npcs: Vec::new(), objects: Vec::new(), outdoors: rf.outdoors });
                 Ok(())
             })?;
 

world/town/rooms/gate.toml

@@ -3,6 +3,7 @@ description = """\
 Towering iron-reinforced wooden gates mark the southern edge of town. \
 Guards in dented armor lean on their spears, watching the dusty road \
 that stretches into the wilderness beyond."""
+outdoors = true
 
 [exits]
 north = "town:dark_alley"

world/town/rooms/market.toml

@@ -3,6 +3,7 @@ description = """\
 Colorful stalls line both sides of a narrow street. Merchants hawk their \
 wares — bolts of cloth, exotic spices, gleaming trinkets. The air is thick \
 with competing smells and the chatter of commerce."""
+outdoors = true
 
 [exits]
 west = "town:town_square"

world/town/rooms/town_square.toml

@@ -3,6 +3,7 @@ description = """\
 You stand in the heart of Thornwall. A worn stone fountain sits at the \
 center, water trickling quietly. Cobblestone paths branch in every \
 direction. The sounds of merchants and travelers fill the air."""
+outdoors = true
 
 [exits]
 north = "town:tavern"

world/whispering_woods/rooms/forest_entrance.toml

@@ -4,6 +4,7 @@ The well-maintained cobblestone of Thornwall yields to a winding dirt \
 path that disappears into the dense, dark eaves of the forest. The air \
 is cooler here, smelling of damp earth and pine needles. The city \
 gates loom to the north."""
+outdoors = true
 
 [exits]
 north = "town:gate"