log: the client keeps its own log, and says which zone and room it thinks it is in

A player sees something wrong for two seconds and quits. What the client said at
that moment lived only in the terminal it was launched from — which, for a player
who starts it from a desktop, is nowhere. So three things, all aimed at the next
report being answerable from the machine it happened on.

**The session log.** `benilla-config/Logs/benilla.log` now holds every line that
goes to stderr, with the previous two runs kept beside it as `benilla-1.log` and
`benilla-2.log`. The ring that feeds the crash report already formats these lines
([`log_ring`]), so the file is one more sink on it: the ring's backlog replays into
the file when it opens, so the boot lines are not lost to the attach being late,
and writes are unbuffered because the point of the file is to survive the crash
that made someone read it. 64 MiB cap, then one line saying so. A capture run
resolves no state folder and writes none. Player chat is logged at `debug` and so
is not in it; server notices are.

**The zone line.** One line per change naming the whole chain: the leaf area id
the terrain chunk under the player carries, the zone it rolls up to, and what the
world map selected from that. This is unanswerable otherwise — the ids live for a
frame, and the map only shows the end of the chain. It is already earning itself:
the player reported the map naming a far-away zone in a custom area, and the
terrain says why. `Azeroth_36_43.adt` (the server's own, out of `patch-A.mpq`)
tags 44 of its 256 chunks `5599 "Rugford's Mountain Rest"` — the custom area the
quest is in — and **53 of them `3 "Badlands"`**, in a block that starts a few
chunks south of it. Walk off the rest and the client reads Badlands off their
terrain and moves the map there, exactly as the reference would.

**The interior line.** One line per room change saying whether the camera is
inside a WMO group and which, because that claim decides whether the open world is
drawn at all: inside, the exterior is culled to what the portal flood reaches. "It
all went grey but I could see at some angles" is a description of that state, and
from the outside a wrong claim and a right one look identical.

`log_ring::attach_file` and `FILE_CAP_BYTES` are published engine API: the engine
owns the log, the app owns where this player's state lives. The wall caught both
the moment they crossed, which is what re-baselining it was for.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn

crates/benilla-app/src/lib.rs

@@ -408,6 +408,22 @@ pub fn run(build: BuildId) -> AppExit {
         start: run_mode::start_state(),
     });
 
+    // The session's own log file, opened once the subscriber exists so the backlog replays into
+    // it. A player who sees something wrong for two seconds and quits can only be answered from
+    // what the client said at the time, and until now that lived in the terminal it was launched
+    // from — which, for a player who double-clicks the binary, is nowhere. `WOW_CAPTURE` runs
+    // resolve no state folder and so write none.
+    if let Some(path) = local_state::rotate_session_logs() {
+        match benilla_world::log_ring::attach_file(&path) {
+            Ok(replayed) => info!(
+                "log: this session also writes {} ({replayed} boot lines replayed, cap {} MiB)",
+                path.display(),
+                benilla_world::log_ring::FILE_CAP_BYTES / (1024 * 1024)
+            ),
+            Err(e) => warn!("log: cannot write {}: {e}", path.display()),
+        }
+    }
+
     // benilla-assets' loaders go into the live `AssetServer`, so they register after `AssetPlugin`.
     benilla_assets::register_asset_loaders(&mut app);
 

crates/benilla-app/src/local_state.rs

@@ -214,6 +214,28 @@ pub(crate) fn logs_dir() -> Option<PathBuf> {
     home().map(|h| h.join("Logs"))
 }
 
+/// `benilla-config/Logs/benilla.log`: this session's own log, the lines that also went to stderr
+/// ([`benilla_world::log_ring`]). The previous session's file is kept beside it as
+/// `benilla-1.log`, and the one before that as `benilla-2.log`, so a player who notices something
+/// odd and quits still has the run it happened in.
+pub(crate) fn session_log_path() -> Option<PathBuf> {
+    logs_dir().map(|d| d.join("benilla.log"))
+}
+
+/// Shift the kept session logs down one and return where this session should write. `benilla-2`
+/// is dropped, `benilla-1` becomes `benilla-2`, `benilla.log` becomes `benilla-1`. Rename
+/// failures are ignored: a missing older file is the normal case, and a log that cannot rotate
+/// is still worth writing.
+pub(crate) fn rotate_session_logs() -> Option<PathBuf> {
+    let path = session_log_path()?;
+    let dir = path.parent()?;
+    let nth = |n: u32| dir.join(format!("benilla-{n}.log"));
+    let _ = std::fs::remove_file(nth(2));
+    let _ = std::fs::rename(nth(1), nth(2));
+    let _ = std::fs::rename(&path, nth(1));
+    Some(path)
+}
+
 /// `benilla-config/shots.txt`: the framing instrument's camera poses (`/shot`, dev builds).
 pub(crate) fn shots_path() -> Option<PathBuf> {
     home().map(|h| h.join("shots.txt"))
@@ -553,6 +575,44 @@ mod tests {
         std::fs::remove_dir_all(&tmp).ok();
     }
 
+    /// Each session's log steps down one slot, and the oldest falls off the end.
+    #[test]
+    fn the_session_log_keeps_the_two_runs_before_it() {
+        let _l = ENV_LOCK
+            .lock()
+            .unwrap_or_else(std::sync::PoisonError::into_inner);
+        let tmp = std::env::temp_dir().join(format!("benilla-logrot-{}", std::process::id()));
+        std::fs::remove_dir_all(&tmp).ok();
+        let _home = test_env::EnvGuard::set("BENILLA_HOME", tmp.to_str().expect("utf-8"));
+        let _cap = test_env::EnvGuard::unset("WOW_CAPTURE");
+        let logs = logs_dir().expect("a state folder");
+        std::fs::create_dir_all(&logs).expect("the Logs folder");
+        for run in ["first", "second", "third"] {
+            let path = rotate_session_logs().expect("a log path");
+            std::fs::write(&path, run).expect("write the session's log");
+        }
+        assert_eq!(
+            std::fs::read_to_string(logs.join("benilla.log")).unwrap(),
+            "third"
+        );
+        assert_eq!(
+            std::fs::read_to_string(logs.join("benilla-1.log")).unwrap(),
+            "second"
+        );
+        assert_eq!(
+            std::fs::read_to_string(logs.join("benilla-2.log")).unwrap(),
+            "first"
+        );
+        // A fourth run drops the oldest.
+        let path = rotate_session_logs().expect("a log path");
+        std::fs::write(&path, "fourth").expect("write");
+        assert_eq!(
+            std::fs::read_to_string(logs.join("benilla-2.log")).unwrap(),
+            "second"
+        );
+        std::fs::remove_dir_all(&tmp).ok();
+    }
+
     /// The bulk write gives up the flush, not the atomicity: the same bytes land, the temp file
     /// is renamed away, and a replacement is still whole or absent.
     #[test]

crates/benilla-app/src/ui_world_map.rs

@@ -567,6 +567,9 @@ struct FeedMemos {
     landmarks: Option<LandmarkKey>,
     /// The world-enter sync has run: the reference's `old == 0` gate.
     map_synced: bool,
+    /// The last `(map, leaf area, top zone, selection)` logged, so the zone line prints on change
+    /// rather than every frame.
+    zone_logged: Option<(u32, u32, u32, u32, u32)>,
 }
 
 /// The `AreaPOI.dbc` half of the landmark list (`0x4a6819`'s walk), in file order: every row the
@@ -649,6 +652,44 @@ fn feed_world_map(
     let top_zone = world.area().and_then(|aid| areas.0.top_zone(aid));
     let player_sel = resolve_player_selection(&data, map.0, top_zone);
 
+    // One line per change, because the whole chain is otherwise invisible: the leaf id comes off
+    // the terrain chunk under the player, the zone is its one-hop rollup, and the map selection is
+    // an index into the continent's zone list. A player reporting "the map said I was somewhere
+    // else" can only be answered from these four numbers at that moment — on a server with custom
+    // zones, any of them can be the one that is wrong.
+    {
+        let leaf = world.area().unwrap_or(0);
+        let (ci, zi) = player_sel.zone.unwrap_or((0, 0));
+        let key = (map.0, leaf, top_zone.unwrap_or(0), ci, zi);
+        let memo = memo.get(&script);
+        if memo.zone_logged != Some(key) {
+            memo.zone_logged = Some(key);
+            let name = |id: u32| areas.0.name(id).unwrap_or("?").to_string();
+            let picked = data
+                .continents
+                .get(ci.wrapping_sub(1) as usize)
+                .and_then(|c| {
+                    if zi == 0 {
+                        // The continent sheet itself, named by its map.
+                        Some(format!("the continent map of map {}", c.map_id))
+                    } else {
+                        c.zones
+                            .get(zi.wrapping_sub(1) as usize)
+                            .map(|z| name(z.area_id))
+                    }
+                })
+                .or_else(|| player_sel.direct.map(|id| format!("instance map row {id}")))
+                .unwrap_or_else(|| "the world view".to_string());
+            info!(
+                "zone: map {} · chunk area {leaf} \"{}\" · zone {} \"{}\" · world map shows \"{picked}\" (continent {ci}, zone {zi})",
+                map.0,
+                name(leaf),
+                top_zone.unwrap_or(0),
+                name(top_zone.unwrap_or(0)),
+            );
+        }
+    }
+
     // First world enter: the zone updater `0x494780` (`crate::area`), finding the cached zone id
     // 0, selects the player's zone itself through `0x4a6650` and the setter `0x4a67a0` before any
     // Lua asks. Once per VM, each login being a first enter.

crates/benilla-app/tests/world_api_wall.rs

@@ -82,6 +82,13 @@ fn is_instrument_consumer(rel: &str) -> bool {
 /// (`wall`: published without one). Adding a row is a claim made in review, with its record.
 const PUBLISHED: &[(&str, &str)] = &[
     ("bgwin::BgWinPlugin", "wall"),
+    // The engine owns the log; the app owns where this player's state lives, so "attach the log
+    // to this path" is the seam between them. Published rather than filed as a leak because the
+    // composition root is the only caller there can be: `crash.rs` already reads the same ring,
+    // and a session log that only an instrument build wrote would be missing from every player
+    // build, which is the one place it is needed.
+    ("log_ring::FILE_CAP_BYTES", "wall"),
+    ("log_ring::attach_file", "wall"),
     ("bgwin::background_run", "record"),
     ("bgwin::no_pixel_run", "record"),
     ("billboard::BillboardCard", "record"),

crates/benilla-world/src/log_ring.rs

@@ -2,9 +2,17 @@
 //! doing when it died. Installed as [`bevy::log::LogPlugin::custom_layer`] by
 //! [`crate::boot::tuned_default_plugins`], under the same `EnvFilter` as stderr, so it holds
 //! exactly the lines stderr showed. Read with [`recent`].
+//!
+//! The same lines also go to a **file**, once a caller that knows where state lives opens one
+//! ([`attach_file`]) — the app does it at boot. A player reporting "it looked wrong for a second"
+//! can only be answered from what the client said at the time, and a client whose log exists only
+//! in the terminal it was launched from says nothing an hour later. The backlog the ring already
+//! holds is replayed into the file first, so the boot lines are not lost to the attach being late.
 
 use std::collections::VecDeque;
 use std::fmt::Write as _;
+use std::io::Write as _;
+use std::path::Path;
 use std::sync::{Mutex, OnceLock};
 use std::time::Instant;
 
@@ -19,6 +27,72 @@ pub const CAPACITY: usize = 200;
 static RING: Mutex<VecDeque<String>> = Mutex::new(VecDeque::new());
 static START: OnceLock<Instant> = OnceLock::new();
 
+/// The session's log file and what it has written, once [`attach_file`] opened one.
+static FILE: Mutex<Option<Sink>> = Mutex::new(None);
+
+/// How much one session's file may hold before it stops growing: a runaway warn loop must not
+/// fill the player's disk, and 64 MiB is far more than any session has produced (the longest
+/// measured, with the reload burst in it, was 1 MiB).
+pub const FILE_CAP_BYTES: u64 = 64 * 1024 * 1024;
+
+/// The open log file. Unbuffered on purpose: the point of the file is to survive the crash that
+/// made someone read it, and a line costs one `write` into the page cache.
+struct Sink {
+    file: std::fs::File,
+    written: u64,
+    capped: bool,
+}
+
+impl Sink {
+    fn write_line(&mut self, line: &str) {
+        if self.capped {
+            return;
+        }
+        if self.written >= FILE_CAP_BYTES {
+            self.capped = true;
+            let _ = writeln!(
+                self.file,
+                "— log file capped at {} MiB; the rest of this session is in the terminal only —",
+                FILE_CAP_BYTES / (1024 * 1024)
+            );
+            return;
+        }
+        if writeln!(self.file, "{line}").is_ok() {
+            self.written += line.len() as u64 + 1;
+        }
+    }
+}
+
+/// Send every line from here on to `path`, after replaying the ring's backlog into it. Returns
+/// how many backlog lines were replayed, or the error that stopped the file being opened — the
+/// caller logs it, because logging is this module's whole business and a failure must not be
+/// silent. Opening a second file replaces the first.
+pub fn attach_file(path: &Path) -> std::io::Result<usize> {
+    if let Some(dir) = path.parent() {
+        std::fs::create_dir_all(dir)?;
+    }
+    let file = std::fs::File::create(path)?;
+    let mut sink = Sink {
+        file,
+        written: 0,
+        capped: false,
+    };
+    let backlog = recent();
+    for line in &backlog {
+        sink.write_line(line);
+    }
+    *FILE.lock().unwrap_or_else(|p| p.into_inner()) = Some(sink);
+    Ok(backlog.len())
+}
+
+/// Whether a file is attached, for the tests and for a caller deciding whether to say where it is.
+pub fn file_attached() -> bool {
+    FILE.lock()
+        .unwrap_or_else(|p| p.into_inner())
+        .as_ref()
+        .is_some()
+}
+
 /// The layer; its state is a static so the panic hook, which has no handle to the subscriber, can
 /// read it.
 pub struct LogRing;
@@ -34,6 +108,9 @@ impl<S: Subscriber> Layer<S> for LogRing {
             meta.target()
         );
         event.record(&mut MessageVisitor(&mut line));
+        if let Some(sink) = FILE.lock().unwrap_or_else(|p| p.into_inner()).as_mut() {
+            sink.write_line(&line);
+        }
         let mut ring = RING.lock().unwrap_or_else(|p| p.into_inner());
         if ring.len() >= CAPACITY {
             ring.pop_front();
@@ -78,30 +155,54 @@ mod tests {
     use super::*;
     use bevy::log::tracing_subscriber::layer::SubscriberExt;
 
-    /// One test for the whole contract, since the ring is a process-wide static.
+    /// One test for the whole contract, since the ring **and the file** are process-wide statics
+    /// and a second test would interleave with this one's lines.
     #[test]
-    fn the_ring_keeps_the_last_lines_in_order() {
+    fn the_ring_keeps_the_last_lines_in_order_and_the_file_takes_the_backlog() {
+        let dir = std::env::temp_dir().join(format!("benilla-logring-{}", std::process::id()));
+        let _ = std::fs::remove_dir_all(&dir);
+        let path = dir.join("nested/benilla.log");
         let subscriber = bevy::log::tracing_subscriber::registry().with(LogRing);
-        bevy::log::tracing::subscriber::with_default(subscriber, || {
+        let body = bevy::log::tracing::subscriber::with_default(subscriber, || {
             for i in 0..(CAPACITY + 5) {
                 bevy::log::tracing::info!(n = i, "ring line");
             }
+            // The ring first, while nothing else has been logged into it.
+            let lines = recent();
+            assert_eq!(lines.len(), CAPACITY, "bounded at CAPACITY");
+            let first = &lines[0];
+            assert!(
+                first.contains("ring line n=5"),
+                "oldest surviving line: {first}"
+            );
+            assert!(first.contains(" INFO "), "level rendered: {first}");
+            assert!(
+                lines
+                    .last()
+                    .unwrap()
+                    .contains(&format!("n={}", CAPACITY + 4)),
+                "newest last: {}",
+                lines.last().unwrap()
+            );
+
+            // Then the file, which opens late as the app's does: the backlog goes in first, the
+            // live lines after.
+            let replayed = attach_file(&path).expect("the directory is created and the file opens");
+            assert_eq!(replayed, CAPACITY, "the whole ring replayed");
+            assert!(file_attached());
+            bevy::log::tracing::info!("after the file opened: LIVE_MARK");
+            std::fs::read_to_string(&path).expect("the file is on disk")
         });
-        let lines = recent();
-        assert_eq!(lines.len(), CAPACITY, "bounded at CAPACITY");
-        let first = &lines[0];
         assert!(
-            first.contains("ring line n=5"),
-            "oldest surviving line: {first}"
+            body.contains(&format!("n={}", CAPACITY + 4)),
+            "the backlog's newest line reached the file"
         );
-        assert!(first.contains(" INFO "), "level rendered: {first}");
         assert!(
-            lines
-                .last()
-                .unwrap()
-                .contains(&format!("n={}", CAPACITY + 4)),
-            "newest last: {}",
-            lines.last().unwrap()
+            body.contains("LIVE_MARK"),
+            "and so did a line logged after it opened"
         );
+        // Close the sink before the directory goes, so nothing later writes into a deleted path.
+        *FILE.lock().unwrap_or_else(|p| p.into_inner()) = None;
+        let _ = std::fs::remove_dir_all(&dir);
     }
 }

crates/benilla-world/src/wmo_portal/mod.rs

@@ -463,6 +463,23 @@ fn compute_wmo_pvs(
         camera_fog.0 = fog_target;
     }
     if camera_claim.0 != claim {
+        // One line per ROOM change, because this claim decides whether the open world is drawn at
+        // all: inside, the exterior is culled to what the portal flood reaches. A player reporting
+        // "everything went grey but I could see at some angles" is describing exactly a claim that
+        // should not be there, and from the outside the two states look identical — so the log has
+        // to say which one the camera was in, and in which building's group.
+        let room = |c: &Option<InteriorClaim>| c.map(|c| (c.room.instance, c.room.group));
+        if room(&camera_claim.0) != room(&claim) {
+            match claim {
+                Some(c) => bevy::log::info!(
+                    "interior: camera is INSIDE {:?} group {} — the exterior draws only through \
+                     the portal flood",
+                    c.room.instance,
+                    c.room.group
+                ),
+                None => bevy::log::info!("interior: camera is outside — the exterior draws whole"),
+            }
+        }
         camera_claim.0 = claim;
     }
     let want_windows = match windows {