From 5aba1862c9ccf9f44098d3cf630babcaf3853e8a Mon Sep 17 00:00:00 2001 From: Ryan Walters Date: Mon, 8 Sep 2025 13:49:36 -0500 Subject: [PATCH] feat: improve tracing logs application-wide --- Cargo.toml | 2 +- src/app.rs | 27 ++++++++++++++++++----- src/asset.rs | 9 +++++++- src/game.rs | 47 +++++++++++++++++++++++++++++++++++++++- src/map/builder.rs | 8 +++++++ src/platform/desktop.rs | 14 ++++++------ src/systems/audio.rs | 19 ++++++++++++++++ src/systems/collision.rs | 7 ++++++ src/systems/ghost.rs | 6 +++++ src/systems/item.rs | 6 +++++ src/systems/player.rs | 23 ++++++++++++++++++++ src/systems/render.rs | 6 ++++- src/systems/state.rs | 13 ++++++++++- src/texture/sprite.rs | 11 ++++++---- 14 files changed, 177 insertions(+), 21 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index d387a98..4e3c1eb 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -21,7 +21,7 @@ default-run = "pacman" bevy_ecs = "0.16.1" glam = "0.30.5" pathfinding = "4.14" -tracing = { version = "0.1.41", features = ["max_level_debug", "release_max_level_debug"]} +tracing = { version = "0.1.41", features = ["max_level_trace", "release_max_level_debug"]} tracing-error = "0.2.0" tracing-subscriber = {version = "0.3.20", features = ["env-filter"]} time = { version = "0.3.43", features = ["formatting", "macros"] } diff --git a/src/app.rs b/src/app.rs index a8ffb31..dd25af9 100644 --- a/src/app.rs +++ b/src/app.rs @@ -10,7 +10,7 @@ use crate::platform; use sdl2::pixels::PixelFormatEnum; use sdl2::render::RendererInfo; use sdl2::{AudioSubsystem, Sdl}; -use tracing::debug; +use tracing::{debug, info, trace}; /// Main application wrapper that manages SDL initialization, window lifecycle, and the game loop. pub struct App { @@ -30,12 +30,20 @@ impl App { /// Returns `GameError::Sdl` if any SDL initialization step fails, or propagates /// errors from `Game::new()` during game state setup. pub fn new() -> GameResult { + info!("Initializing SDL2 application"); let sdl_context = sdl2::init().map_err(|e| GameError::Sdl(e.to_string()))?; + debug!("Initializing SDL2 subsystems"); let ttf_context = sdl2::ttf::init().map_err(|e| GameError::Sdl(e.to_string()))?; let video_subsystem = sdl_context.video().map_err(|e| GameError::Sdl(e.to_string()))?; let audio_subsystem = sdl_context.audio().map_err(|e| GameError::Sdl(e.to_string()))?; let event_pump = sdl_context.event_pump().map_err(|e| GameError::Sdl(e.to_string()))?; + trace!( + width = (CANVAS_SIZE.x as f32 * SCALE).round() as u32, + height = (CANVAS_SIZE.y as f32 * SCALE).round() as u32, + scale = SCALE, + "Creating game window" + ); let window = video_subsystem .window( "Pac-Man", @@ -64,7 +72,7 @@ impl App { { let mut names = drivers.keys().collect::>(); names.sort_by_key(|k| get_driver(k)); - debug!("Drivers: {names:?}") + trace!("Drivers: {names:?}") } // Count the number of times each pixel format is supported by each driver @@ -76,11 +84,12 @@ impl App { counts }); - debug!("Pixel format counts: {pixel_format_counts:?}"); + trace!(pixel_format_counts = ?pixel_format_counts, "Available pixel formats per driver"); let index = get_driver("direct3d"); - debug!("Driver index: {index:?}"); + trace!(driver_index = ?index, "Selected graphics driver"); + trace!("Creating hardware-accelerated canvas"); let mut canvas = window .into_canvas() .accelerated() @@ -88,15 +97,23 @@ impl App { .build() .map_err(|e| GameError::Sdl(e.to_string()))?; + trace!( + logical_width = CANVAS_SIZE.x, + logical_height = CANVAS_SIZE.y, + "Setting canvas logical size" + ); canvas .set_logical_size(CANVAS_SIZE.x, CANVAS_SIZE.y) .map_err(|e| GameError::Sdl(e.to_string()))?; - debug!("Renderer: {:?}", canvas.info()); + debug!(renderer_info = ?canvas.info(), "Canvas renderer initialized"); + trace!("Creating texture factory"); let texture_creator = canvas.texture_creator(); + info!("Starting game initialization"); let game = Game::new(canvas, ttf_context, texture_creator, event_pump)?; + info!("Application initialization completed successfully"); Ok(App { game, focused: true, diff --git a/src/asset.rs b/src/asset.rs index 9593e84..2328559 100644 --- a/src/asset.rs +++ b/src/asset.rs @@ -48,6 +48,7 @@ mod imp { use super::*; use crate::error::AssetError; use crate::platform; + use tracing::trace; /// Loads asset bytes using the appropriate platform-specific method. /// @@ -61,7 +62,13 @@ mod imp { /// Returns `AssetError::NotFound` if the asset file cannot be located (Emscripten only), /// or `AssetError::Io` for filesystem I/O failures. pub fn get_asset_bytes(asset: Asset) -> Result, AssetError> { - platform::get_asset_bytes(asset) + trace!(asset = ?asset, path = asset.path(), "Loading game asset"); + let result = platform::get_asset_bytes(asset); + match &result { + Ok(bytes) => trace!(asset = ?asset, size_bytes = bytes.len(), "Asset loaded successfully"), + Err(e) => trace!(asset = ?asset, error = ?e, "Asset loading failed"), + } + result } } diff --git a/src/game.rs b/src/game.rs index 21f09a2..3af20c8 100644 --- a/src/game.rs +++ b/src/game.rs @@ -3,6 +3,7 @@ include!(concat!(env!("OUT_DIR"), "/atlas_data.rs")); use std::collections::HashMap; +use tracing::{debug, info, trace, warn}; use crate::constants::{self, animation, MapTile, CANVAS_SIZE}; use crate::error::{GameError, GameResult}; @@ -89,31 +90,45 @@ impl Game { texture_creator: TextureCreator, mut event_pump: EventPump, ) -> GameResult { + info!("Starting game initialization"); + + debug!("Disabling unnecessary SDL events"); Self::disable_sdl_events(&mut event_pump); + debug!("Setting up textures and fonts"); let (backbuffer, mut map_texture, debug_texture, ttf_atlas) = Self::setup_textures_and_fonts(&mut canvas, &texture_creator, ttf_context)?; + debug!("Initializing audio subsystem"); let audio = crate::audio::Audio::new(); + debug!("Loading sprite atlas and map tiles"); let (mut atlas, map_tiles) = Self::load_atlas_and_map_tiles(&texture_creator)?; + debug!("Rendering static map to texture cache"); canvas .with_texture_canvas(&mut map_texture, |map_canvas| { MapRenderer::render_map(map_canvas, &mut atlas, &map_tiles); }) .map_err(|e| GameError::Sdl(e.to_string()))?; + debug!("Building navigation graph from map layout"); let map = Map::new(constants::RAW_BOARD)?; + debug!("Creating player animations and bundle"); let (player_animation, player_start_sprite) = Self::create_player_animations(&atlas)?; let player_bundle = Self::create_player_bundle(&map, player_animation, player_start_sprite); + debug!("Creating death animation sequence"); let death_animation = Self::create_death_animation(&atlas)?; + debug!("Initializing ECS world and system schedule"); let mut world = World::default(); let mut schedule = Schedule::default(); + debug!("Setting up ECS event registry and observers"); Self::setup_ecs(&mut world); + + debug!("Inserting resources into ECS world"); Self::insert_resources( &mut world, map, @@ -127,12 +142,18 @@ impl Game { ttf_atlas, death_animation, )?; + + debug!("Configuring system execution schedule"); Self::configure_schedule(&mut schedule); + debug!("Spawning player entity"); world.spawn(player_bundle).insert((Frozen, Hidden)); + + info!("Spawning game entities"); Self::spawn_ghosts(&mut world)?; Self::spawn_items(&mut world)?; + info!("Game initialization completed successfully"); Ok(Game { world, schedule }) } @@ -224,6 +245,7 @@ impl Game { } fn load_atlas_and_map_tiles(texture_creator: &TextureCreator) -> GameResult<(SpriteAtlas, Vec)> { + trace!("Loading atlas image from embedded assets"); let atlas_bytes = get_asset_bytes(Asset::AtlasImage)?; let atlas_texture = texture_creator.load_texture_bytes(&atlas_bytes).map_err(|e| { if e.to_string().contains("format") || e.to_string().contains("unsupported") { @@ -235,11 +257,13 @@ impl Game { } })?; + debug!(frame_count = ATLAS_FRAMES.len(), "Creating sprite atlas from texture"); let atlas_mapper = AtlasMapper { frames: ATLAS_FRAMES.into_iter().map(|(k, v)| (k.to_string(), *v)).collect(), }; let atlas = SpriteAtlas::new(atlas_texture, atlas_mapper); + trace!("Extracting map tile sprites from atlas"); let mut map_tiles = Vec::with_capacity(35); for i in 0..35 { let tile_name = GameSprite::Maze(MazeSprite::Tile(i)).to_path(); @@ -482,6 +506,7 @@ impl Game { } fn spawn_items(world: &mut World) -> GameResult<()> { + trace!("Loading item sprites from atlas"); let pellet_sprite = SpriteAtlas::get_tile( world.non_send_resource::(), &GameSprite::Maze(MazeSprite::Pellet).to_path(), @@ -506,6 +531,12 @@ impl Game { }) .collect(); + info!( + pellet_count = nodes.iter().filter(|(_, t, _, _)| *t == EntityType::Pellet).count(), + power_pellet_count = nodes.iter().filter(|(_, t, _, _)| *t == EntityType::PowerPellet).count(), + "Spawning collectible items" + ); + for (id, item_type, sprite, size) in nodes { let mut item = world.spawn(ItemBundle { position: Position::Stopped { node: id }, @@ -529,6 +560,7 @@ impl Game { /// Returns `GameError::Texture` if any ghost sprite cannot be found in the atlas, /// typically indicating missing or misnamed sprite files. fn spawn_ghosts(world: &mut World) -> GameResult<()> { + trace!("Spawning ghost entities with AI personalities"); // Extract the data we need first to avoid borrow conflicts let ghost_start_positions = { let map = world.resource::(); @@ -569,9 +601,11 @@ impl Game { } }; - world.spawn(ghost).insert((Frozen, Hidden)); + let entity = world.spawn(ghost).insert((Frozen, Hidden)).id(); + trace!(ghost = ?ghost_type, entity = ?entity, start_node, "Spawned ghost entity"); } + info!("All ghost entities spawned successfully"); Ok(()) } @@ -680,6 +714,17 @@ impl Game { ) { let new_tick = timing.increment_tick(); timings.add_total_timing(total_duration, new_tick); + + // Log performance warnings for slow frames + if total_duration.as_millis() > 20 { + // Warn if frame takes more than 20ms + warn!( + duration_ms = total_duration.as_millis(), + frame_dt = ?std::time::Duration::from_secs_f32(dt), + tick = new_tick, + "Frame took longer than expected" + ); + } } let state = self diff --git a/src/map/builder.rs b/src/map/builder.rs index cc89614..410b842 100644 --- a/src/map/builder.rs +++ b/src/map/builder.rs @@ -56,11 +56,17 @@ impl Map { /// This function will panic if the board layout contains unknown characters or if /// the house door is not defined by exactly two '=' characters. pub fn new(raw_board: [&str; BOARD_CELL_SIZE.y as usize]) -> GameResult { + debug!("Starting map construction from character layout"); let parsed_map = MapTileParser::parse_board(raw_board)?; let map = parsed_map.tiles; let house_door = parsed_map.house_door; let tunnel_ends = parsed_map.tunnel_ends; + debug!( + house_door_count = house_door.len(), + tunnel_ends_count = tunnel_ends.len(), + "Parsed map special locations" + ); let mut graph = Graph::new(); let mut grid_to_node = HashMap::new(); @@ -157,8 +163,10 @@ impl Map { }; // Build tunnel connections + debug!("Building tunnel connections"); Self::build_tunnels(&mut graph, &grid_to_node, &tunnel_ends)?; + debug!(node_count = graph.nodes().count(), "Map construction completed successfully"); Ok(Map { graph, grid_to_node, diff --git a/src/platform/desktop.rs b/src/platform/desktop.rs index 92acc08..8d70abf 100644 --- a/src/platform/desktop.rs +++ b/src/platform/desktop.rs @@ -21,7 +21,7 @@ pub fn init_console() -> Result<(), PlatformError> { #[cfg(windows)] { use crate::platform::tracing_buffer::setup_switchable_subscriber; - use tracing::{debug, info}; + use tracing::{debug, info, trace}; use windows::Win32::System::Console::GetConsoleWindow; // Setup buffered tracing subscriber that will buffer logs until console is ready @@ -32,13 +32,13 @@ pub fn init_console() -> Result<(), PlatformError> { debug!("Already have a console window"); return Ok(()); } else { - debug!("No existing console window found"); + trace!("No existing console window found"); } if let Some(file_type) = is_output_setup()? { - debug!(r#type = file_type, "Existing output detected"); + trace!(r#type = file_type, "Existing output detected"); } else { - debug!("No existing output detected"); + trace!("No existing output detected"); // Try to attach to parent console for direct cargo run attach_to_parent_console()?; @@ -46,7 +46,7 @@ pub fn init_console() -> Result<(), PlatformError> { } // Now that console is initialized, flush buffered logs and switch to direct output - debug!("Switching to direct logging mode and flushing buffer..."); + trace!("Switching to direct logging mode and flushing buffer..."); if let Err(error) = switchable_writer.switch_to_direct_mode() { use tracing::warn; @@ -79,7 +79,7 @@ pub fn rng() -> ThreadRng { /// Windows-only #[cfg(windows)] fn is_output_setup() -> Result, PlatformError> { - use tracing::{debug, warn}; + use tracing::{trace, warn}; use windows::Win32::Storage::FileSystem::{ GetFileType, FILE_TYPE_CHAR, FILE_TYPE_DISK, FILE_TYPE_PIPE, FILE_TYPE_REMOTE, FILE_TYPE_UNKNOWN, @@ -114,7 +114,7 @@ fn is_output_setup() -> Result, PlatformError> { } }; - debug!("File type: {file_type:?}, well known: {well_known}"); + trace!("File type: {file_type:?}, well known: {well_known}"); // If it's anything recognizable and valid, assume that a parent process has setup an output stream Ok(well_known.then_some(file_type)) diff --git a/src/systems/audio.rs b/src/systems/audio.rs index d5cad81..94aa7c0 100644 --- a/src/systems/audio.rs +++ b/src/systems/audio.rs @@ -9,6 +9,7 @@ use bevy_ecs::{ resource::Resource, system::{NonSendMut, ResMut}, }; +use tracing::{debug, trace}; use crate::{audio::Audio, error::GameError}; @@ -49,6 +50,7 @@ pub fn audio_system( ) { // Set mute state if it has changed if audio.0.is_muted() != audio_state.muted { + debug!(muted = audio_state.muted, "Audio mute state changed"); audio.0.set_mute(audio_state.muted); } @@ -57,20 +59,37 @@ pub fn audio_system( match event { AudioEvent::PlayEat => { if !audio.0.is_disabled() && !audio_state.muted { + trace!(sound_index = audio_state.sound_index, "Playing eat sound"); audio.0.eat(); // Update the sound index for cycling through sounds audio_state.sound_index = (audio_state.sound_index + 1) % 4; // 4 eat sounds available + } else { + debug!( + disabled = audio.0.is_disabled(), + muted = audio_state.muted, + "Skipping eat sound due to audio state" + ); } } AudioEvent::PlayDeath => { if !audio.0.is_disabled() && !audio_state.muted { + trace!("Playing death sound"); audio.0.death(); + } else { + debug!( + disabled = audio.0.is_disabled(), + muted = audio_state.muted, + "Skipping death sound due to audio state" + ); } } AudioEvent::StopAll => { if !audio.0.is_disabled() { + debug!("Stopping all audio"); audio.0.stop_all(); + } else { + debug!("Audio disabled, ignoring stop all request"); } } } diff --git a/src/systems/collision.rs b/src/systems/collision.rs index a394f27..ceee8ef 100644 --- a/src/systems/collision.rs +++ b/src/systems/collision.rs @@ -5,6 +5,7 @@ use bevy_ecs::{ query::With, system::{Commands, Query, Res, ResMut}, }; +use tracing::{debug, trace, warn}; use crate::error::GameError; use crate::events::{GameEvent, StageTransition}; @@ -82,6 +83,7 @@ pub fn collision_system( match check_collision(pacman_pos, pacman_collider, item_pos, item_collider, &map) { Ok(colliding) => { if colliding { + trace!(pacman_entity = ?pacman_entity, item_entity = ?item_entity, "Item collision detected"); events.write(GameEvent::Collision(pacman_entity, item_entity)); } } @@ -99,6 +101,7 @@ pub fn collision_system( match check_collision(pacman_pos, pacman_collider, ghost_pos, ghost_collider, &map) { Ok(colliding) => { if colliding { + trace!(pacman_entity = ?pacman_entity, ghost_entity = ?ghost_entity, "Ghost collision detected"); events.write(GameEvent::Collision(pacman_entity, ghost_entity)); } } @@ -143,6 +146,7 @@ pub fn ghost_collision_system( if matches!(*ghost_state, GhostState::Frightened { .. }) { // Pac-Man eats the ghost // Add score (200 points per ghost eaten) + debug!(ghost_entity = ?ghost_ent, score_added = 200, new_score = score.0 + 200, "Pacman ate frightened ghost"); score.0 += 200; // Enter short pause to show bonus points, hide ghost, then set Eyes after pause @@ -153,10 +157,13 @@ pub fn ghost_collision_system( events.write(AudioEvent::PlayEat); } else if matches!(*ghost_state, GhostState::Normal) { // Pac-Man dies + warn!(ghost_entity = ?ghost_ent, "Pacman hit by normal ghost, player dies"); *game_state = GameStage::PlayerDying(DyingSequence::Frozen { remaining_ticks: 60 }); commands.entity(pacman_entity).insert(Frozen); commands.entity(ghost_entity).insert(Frozen); events.write(AudioEvent::StopAll); + } else { + trace!(ghost_state = ?*ghost_state, "Ghost collision ignored due to state"); } } } diff --git a/src/systems/ghost.rs b/src/systems/ghost.rs index 0fae9d5..432b8d8 100644 --- a/src/systems/ghost.rs +++ b/src/systems/ghost.rs @@ -13,6 +13,7 @@ use crate::{ movement::{Position, Velocity}, }, }; +use tracing::{debug, trace, warn}; use crate::systems::GhostAnimations; use bevy_ecs::query::Without; @@ -45,8 +46,10 @@ pub fn ghost_movement_system( let new_edge: Edge = if non_opposite_options.is_empty() { if let Some(edge) = intersection.get(opposite) { + trace!(node = current_node, ghost = ?_ghost, direction = ?opposite, "Ghost forced to reverse direction"); edge } else { + warn!(node = current_node, ghost = ?_ghost, "Ghost stuck with no available directions"); break; } } else { @@ -118,6 +121,7 @@ pub fn eaten_ghost_system( // Reached target node, check if we're at ghost house center if to == ghost_house_center { // Respawn the ghost - set state back to normal + debug!(ghost = ?ghost_type, "Eaten ghost reached ghost house, respawning as normal"); *ghost_state = GhostState::Normal; // Reset to stopped at ghost house center *position = Position::Stopped { @@ -194,6 +198,7 @@ pub fn ghost_state_system( // Only update animation if the animation state actually changed let current_animation_state = ghost_state.animation_state(); if last_animation_state.0 != current_animation_state { + trace!(ghost = ?ghost_type, old_state = ?last_animation_state.0, new_state = ?current_animation_state, "Ghost animation state changed"); match current_animation_state { GhostAnimation::Frightened { flash } => { // Remove DirectionalAnimation, add LinearAnimation with Looping component @@ -212,6 +217,7 @@ pub fn ghost_state_system( } GhostAnimation::Eyes => { // Remove LinearAnimation and Looping, add DirectionalAnimation (eyes animation) + trace!(ghost = ?ghost_type, "Switching to eyes animation for eaten ghost"); commands .entity(entity) .remove::<(LinearAnimation, Looping)>() diff --git a/src/systems/item.rs b/src/systems/item.rs index d6478f6..9186709 100644 --- a/src/systems/item.rs +++ b/src/systems/item.rs @@ -4,6 +4,7 @@ use bevy_ecs::{ query::With, system::{Commands, Query, ResMut}, }; +use tracing::{debug, trace}; use crate::{ constants::animation::FRIGHTENED_FLASH_START_TICKS, @@ -45,6 +46,7 @@ pub fn item_system( // Get the item type and update score if let Ok((item_ent, entity_type)) = item_query.get(item_entity) { if let Some(score_value) = entity_type.score_value() { + trace!(item_entity = ?item_ent, item_type = ?entity_type, score_value, new_score = score.0 + score_value, "Item collected by player"); score.0 += score_value; // Remove the collected item @@ -59,13 +61,17 @@ pub fn item_system( if *entity_type == EntityType::PowerPellet { // Convert seconds to frames (assumes 60 FPS) let total_ticks = 60 * 5; // 5 seconds total + debug!(duration_ticks = total_ticks, "Power pellet collected, frightening ghosts"); // Set all ghosts to frightened state, except those in Eyes state + let mut frightened_count = 0; for mut ghost_state in ghost_query.iter_mut() { if !matches!(*ghost_state, GhostState::Eyes) { *ghost_state = GhostState::new_frightened(total_ticks, FRIGHTENED_FLASH_START_TICKS); + frightened_count += 1; } } + debug!(frightened_count, "Ghosts set to frightened state"); } } } diff --git a/src/systems/player.rs b/src/systems/player.rs index 71a6d76..8973fdf 100644 --- a/src/systems/player.rs +++ b/src/systems/player.rs @@ -3,6 +3,7 @@ use bevy_ecs::{ query::{With, Without}, system::{Query, Res, ResMut}, }; +use tracing::trace; use crate::{ error::GameError, @@ -52,6 +53,7 @@ pub fn player_control_system( } }; + trace!(direction = ?*direction, "Player direction buffered for movement"); *buffered_direction = BufferedDirection::Some { direction: *direction, remaining_time: 0.25, @@ -86,6 +88,7 @@ pub fn player_movement_system( (&MovementModifiers, &mut Position, &mut Velocity, &mut BufferedDirection), (With, Without), >, + mut last_stopped_node: bevy_ecs::system::Local>, ) { for (modifiers, mut position, mut velocity, mut buffered_direction) in entities.iter_mut() { // Decrement the buffered direction remaining time @@ -95,6 +98,7 @@ pub fn player_movement_system( } = *buffered_direction { if remaining_time <= 0.0 { + trace!("Buffered direction expired"); *buffered_direction = BufferedDirection::None; } else { *buffered_direction = BufferedDirection::Some { @@ -115,6 +119,8 @@ pub fn player_movement_system( if let Some(edge) = map.graph.find_edge_in_direction(position.current_node(), direction) { // If there is an edge in that direction (and it's traversable), start moving towards it and consume the buffered direction. if can_traverse(EntityType::Player, edge) { + trace!(from = position.current_node(), to = edge.target, direction = ?direction, "Player started moving using buffered direction"); + *last_stopped_node = None; // Reset stopped state when starting to move velocity.direction = edge.direction; *position = Position::Moving { from: position.current_node(), @@ -129,6 +135,8 @@ pub fn player_movement_system( // If there is no buffered direction (or it's not yet valid), continue in the current direction. if let Some(edge) = map.graph.find_edge_in_direction(position.current_node(), velocity.direction) { if can_traverse(EntityType::Player, edge) { + trace!(from = position.current_node(), to = edge.target, direction = ?velocity.direction, "Player continued in current direction"); + *last_stopped_node = None; // Reset stopped state when starting to move velocity.direction = edge.direction; *position = Position::Moving { from: position.current_node(), @@ -138,6 +146,11 @@ pub fn player_movement_system( } } else { // No edge in our current direction either, erase the buffered direction and stop. + let current_node = position.current_node(); + if *last_stopped_node != Some(current_node) { + trace!(node = current_node, direction = ?velocity.direction, "Player stopped - no valid edge in current direction"); + *last_stopped_node = Some(current_node); + } *buffered_direction = BufferedDirection::None; break; } @@ -162,6 +175,16 @@ pub fn player_tunnel_slowdown_system(map: Res, mut q: Query<(&Position, &mu .tile_at_node(node) .map(|t| t == crate::constants::MapTile::Tunnel) .unwrap_or(false); + + if modifiers.tunnel_slowdown_active != in_tunnel { + trace!( + node, + in_tunnel, + speed_multiplier = if in_tunnel { 0.6 } else { 1.0 }, + "Player tunnel slowdown state changed" + ); + } + modifiers.tunnel_slowdown_active = in_tunnel; modifiers.speed_multiplier = if in_tunnel { 0.6 } else { 1.0 }; } diff --git a/src/systems/render.rs b/src/systems/render.rs index feae6ae..9a43313 100644 --- a/src/systems/render.rs +++ b/src/systems/render.rs @@ -44,7 +44,11 @@ pub fn dirty_render_system( removed_hidden: RemovedComponents, removed_renderables: RemovedComponents, ) { - if !changed.is_empty() || !removed_hidden.is_empty() || !removed_renderables.is_empty() { + let changed_count = changed.iter().count(); + let removed_hidden_count = removed_hidden.len(); + let removed_renderables_count = removed_renderables.len(); + + if changed_count > 0 || removed_hidden_count > 0 || removed_renderables_count > 0 { dirty.0 = true; } } diff --git a/src/systems/state.rs b/src/systems/state.rs index a8dabca..b6e5a23 100644 --- a/src/systems/state.rs +++ b/src/systems/state.rs @@ -1,4 +1,5 @@ use std::mem::discriminant; +use tracing::{debug, info, warn}; use crate::events::StageTransition; use crate::{ @@ -137,6 +138,7 @@ pub fn stage_system( .map(|(_, pos)| pos.current_node()) .unwrap_or(map.start_positions.pacman); + debug!(ghost_entity = ?ghost_entity, node = pac_node, "Ghost eaten, entering pause state"); new_state = Some(GameStage::GhostEatenPause { remaining_ticks: 30, ghost_entity, @@ -152,6 +154,7 @@ pub fn stage_system( remaining_ticks: remaining_ticks - 1, }) } else { + debug!("Transitioning from text-only to characters visible startup stage"); GameStage::Starting(StartupSequence::CharactersVisible { remaining_ticks: 60 }) } } @@ -161,6 +164,7 @@ pub fn stage_system( remaining_ticks: remaining_ticks - 1, }) } else { + info!("Startup sequence completed, beginning gameplay"); GameStage::Playing } } @@ -178,6 +182,7 @@ pub fn stage_system( node, } } else { + debug!("Ghost eaten pause ended, resuming gameplay"); GameStage::Playing } } @@ -190,6 +195,7 @@ pub fn stage_system( } else { let death_animation = &player_death_animation.0; let remaining_ticks = (death_animation.tiles.len() * death_animation.frame_duration as usize) as u32; + debug!(animation_frames = remaining_ticks, "Starting player death animation"); GameStage::PlayerDying(DyingSequence::Animating { remaining_ticks }) } } @@ -211,14 +217,19 @@ pub fn stage_system( player_lives.0 = player_lives.0.saturating_sub(1); if player_lives.0 > 0 { + info!(remaining_lives = player_lives.0, "Player died, restarting level"); GameStage::LevelRestarting } else { + warn!("All lives lost, game over"); GameStage::GameOver } } } }, - GameStage::LevelRestarting => GameStage::Starting(StartupSequence::CharactersVisible { remaining_ticks: 60 }), + GameStage::LevelRestarting => { + debug!("Level restart complete, returning to startup sequence"); + GameStage::Starting(StartupSequence::CharactersVisible { remaining_ticks: 60 }) + } GameStage::GameOver => GameStage::GameOver, }; diff --git a/src/texture/sprite.rs b/src/texture/sprite.rs index b5e8d1a..8761b11 100644 --- a/src/texture/sprite.rs +++ b/src/texture/sprite.rs @@ -4,6 +4,7 @@ use sdl2::pixels::Color; use sdl2::rect::Rect; use sdl2::render::{Canvas, RenderTarget, Texture}; use std::collections::HashMap; +use tracing::debug; use crate::error::TextureError; @@ -90,8 +91,10 @@ pub struct SpriteAtlas { impl SpriteAtlas { pub fn new(texture: Texture, mapper: AtlasMapper) -> Self { + let tile_count = mapper.frames.len(); let tiles = mapper.frames.into_iter().collect(); + debug!(tile_count, "Created sprite atlas"); Self { texture, tiles, @@ -107,10 +110,10 @@ impl SpriteAtlas { /// atlas. The returned tile can be used for immediate rendering or stored /// for repeated use in animations and entity sprites. pub fn get_tile(&self, name: &str) -> Result { - let frame = self - .tiles - .get(name) - .ok_or_else(|| TextureError::AtlasTileNotFound(name.to_string()))?; + let frame = self.tiles.get(name).ok_or_else(|| { + debug!(tile_name = name, "Atlas tile not found"); + TextureError::AtlasTileNotFound(name.to_string()) + })?; Ok(AtlasTile { pos: frame.pos, size: frame.size,