diff --git a/crates/benilla-app/src/lib.rs b/crates/benilla-app/src/lib.rs index 346726e3..eb0d1d13 100644 --- a/crates/benilla-app/src/lib.rs +++ b/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); diff --git a/crates/benilla-app/src/local_state.rs b/crates/benilla-app/src/local_state.rs index 232c9534..b1e818b3 100644 --- a/crates/benilla-app/src/local_state.rs +++ b/crates/benilla-app/src/local_state.rs @@ -214,6 +214,28 @@ pub(crate) fn logs_dir() -> Option { 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 { + 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 { + 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 { 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] diff --git a/crates/benilla-app/src/ui_world_map.rs b/crates/benilla-app/src/ui_world_map.rs index 8ae7e5c1..86a36545 100644 --- a/crates/benilla-app/src/ui_world_map.rs +++ b/crates/benilla-app/src/ui_world_map.rs @@ -567,6 +567,9 @@ struct FeedMemos { landmarks: Option, /// 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. diff --git a/crates/benilla-app/tests/world_api_wall.rs b/crates/benilla-app/tests/world_api_wall.rs index 45f9820b..bef7aa62 100644 --- a/crates/benilla-app/tests/world_api_wall.rs +++ b/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"), diff --git a/crates/benilla-world/src/log_ring.rs b/crates/benilla-world/src/log_ring.rs index 253b35d0..c13beeea 100644 --- a/crates/benilla-world/src/log_ring.rs +++ b/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> = Mutex::new(VecDeque::new()); static START: OnceLock = OnceLock::new(); +/// The session's log file and what it has written, once [`attach_file`] opened one. +static FILE: Mutex> = 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 { + 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 Layer 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); } } diff --git a/crates/benilla-world/src/wmo_portal/mod.rs b/crates/benilla-world/src/wmo_portal/mod.rs index 292988cc..072e5e85 100644 --- a/crates/benilla-world/src/wmo_portal/mod.rs +++ b/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| 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 {