From 196ff9cec4964125286724473ecb8f0118d15508 Mon Sep 17 00:00:00 2001 From: popertots Date: Sat, 4 Apr 2026 11:50:10 +0100 Subject: [PATCH] Fix job pathfinding: allow idle dorfs to be candidates + add debug logging KEY FIX: Changed candidate filter to allow dorfs with Idle tasks: - Before: Only dorfs with empty queues were candidates - After: Dorfs with empty queue OR Idle task are candidates - This fixes deadlock where all dorfs had Idle tasks and were excluded Debug logging added: - job_pathfinding.rs: Log job processing, candidate counts, path results - queue_debug.rs: Show job state (Unclaimed/Calculating/Claimed/Suspended), retry count, and dorf idle status The bug was that job_pathfinding_system filtered out ALL dorfs because: 1. job_assignment_system gave Idle tasks to dorfs with empty queues 2. task_executor_system promoted them to Active 3. job_pathfinding_system then excluded Active dorfs AND non-empty queues --- src/entities/tasks/job_pathfinding.rs | 160 +++++++++++++++++++++----- src/entities/tasks/queue_debug.rs | 53 +++++++-- 2 files changed, 178 insertions(+), 35 deletions(-) diff --git a/src/entities/tasks/job_pathfinding.rs b/src/entities/tasks/job_pathfinding.rs index 2faa0c9..736f885 100644 --- a/src/entities/tasks/job_pathfinding.rs +++ b/src/entities/tasks/job_pathfinding.rs @@ -38,7 +38,12 @@ pub fn job_pathfinding_system( pri_b.cmp(&pri_a) }); + info!("[PATHFIND] Processing {} unclaimed jobs", unclaimed.len()); + let locked_dorfs = job_queue.get_locked_dorfs(); + if !locked_dorfs.is_empty() { + info!("[PATHFIND] Locked dorfs: {:?}", locked_dorfs.len()); + } for job_idx in unclaimed.into_iter().take(MAX_JOBS_PER_TICK) { let (kind, state, _) = match job_queue.get_job_at(job_idx) { @@ -47,35 +52,85 @@ pub fn job_pathfinding_system( }; if !matches!(state, JobState::Unclaimed) { + info!( + "[PATHFIND] Job idx={} state={:?} - skipping", + job_idx, state + ); continue; } let kind = kind.clone(); let target_pos = kind.target(); let scope = job_queue.get_scope_for_job(job_idx); + let retry_count = job_queue.get_job_retry_count(job_idx).unwrap_or(0); - let mut candidate_dorfs: Vec<(Entity, IVec3)> = dorf_query + info!( + "[PATHFIND] Job idx={} kind={:?} target={:?} scope={} retry_count={}", + job_idx, kind, target_pos, scope, retry_count + ); + + // Collect all dorfs and their current task status for debugging + let mut total_dorfs = 0; + let mut locked_count = 0; + let mut not_standable_count = 0; + let mut not_idle_count = 0; + let mut active_count = 0; + + let candidate_dorfs: Vec<(Entity, IVec3)> = dorf_query .iter_mut() - .filter(|(entity, queue, state, transform, _)| { - if locked_dorfs.contains(entity) { - return false; + .filter_map(|(entity, queue, state, transform, _)| { + total_dorfs += 1; + + if locked_dorfs.contains(&entity) { + locked_count += 1; + return None; } + let pos = transform.translation.as_ivec3(); if !tilemap.is_standable(pos) { - return false; + not_standable_count += 1; + return None; } - if !queue.is_empty() { - return false; + + // Check if dorf is idle: queue is empty OR current task is Idle + let current_task = queue.current(); + let is_idle = queue.is_empty() + || current_task + .map(|t| matches!(t, Task::Idle { .. })) + .unwrap_or(false); + + if !is_idle { + not_idle_count += 1; + return None; } + + // Allow Pending state (about to run) OR Completed/Failed states + // Only exclude Active dorfs (currently executing a task) let state_val: &TaskState = &*state; if matches!(state_val, TaskState::Active) { - return false; + active_count += 1; + return None; } - true + + Some((entity, pos)) }) - .map(|(entity, _, _, transform, _)| (entity, transform.translation.as_ivec3())) .collect(); + info!( + "[PATHFIND] Dorfs: total={} locked={} not_standable={} not_idle={} active={} candidates={}", + total_dorfs, locked_count, not_standable_count, not_idle_count, active_count, candidate_dorfs.len() + ); + + if candidate_dorfs.is_empty() { + info!( + "[PATHFIND] No candidate dorfs for job idx={} - incrementing retry", + job_idx + ); + job_queue.increment_retry(job_idx); + continue; + } + + let mut candidate_dorfs = candidate_dorfs; candidate_dorfs.sort_by_key(|(_, pos)| { (pos.x - target_pos.x).abs() + (pos.y - target_pos.y).abs() @@ -84,12 +139,23 @@ pub fn job_pathfinding_system( let dorfs_to_try: Vec<_> = candidate_dorfs.into_iter().take(scope as usize).collect(); + info!( + "[PATHFIND] Trying {} dorfs for job idx={}", + dorfs_to_try.len(), + job_idx + ); + if dorfs_to_try.is_empty() { + job_queue.increment_retry(job_idx); continue; } let dorf_entities: Vec = dorfs_to_try.iter().map(|(e, _)| *e).collect(); if !job_queue.set_job_calculating(job_idx, dorf_entities.clone()) { + info!( + "[PATHFIND] Failed to set jobCalculating for idx={}", + job_idx + ); continue; } @@ -98,7 +164,17 @@ pub fn job_pathfinding_system( match kind { JobKind::FellTree { trunk_pos } => { let approach_tiles = find_all_standable_adjacent(&trunk_pos, &tilemap); + info!( + "[PATHFIND] FellTree at {:?}: found {} approach tiles", + trunk_pos, + approach_tiles.len() + ); + if approach_tiles.is_empty() { + info!( + "[PATHFIND] No approach tiles for tree at {:?} - suspending job", + trunk_pos + ); job_queue.suspend_job(job_idx); continue; } @@ -107,20 +183,25 @@ pub fn job_pathfinding_system( let mut best_for_dorf: Option<(IVec3, i32)> = None; for approach_tile in &approach_tiles { - if let Ok(distance) = - calculate_traversal_distance(&tilemap, *dorf_pos, *approach_tile) - { - match best_for_dorf { + match calculate_traversal_distance(&tilemap, *dorf_pos, *approach_tile) { + Ok(distance) => match best_for_dorf { None => best_for_dorf = Some((*approach_tile, distance)), Some((_, best_dist)) if distance < best_dist => { best_for_dorf = Some((*approach_tile, distance)); } _ => {} + }, + Err(()) => { + // Path not found for this tile } } } if let Some((approach, dist)) = best_for_dorf { + info!( + "[PATHFIND] Dorf at {:?} can reach tree via {:?} (dist={})", + dorf_pos, approach, dist + ); match best_result { None => best_result = Some((*dorf_entity, approach, dist)), Some((_, _, best_dist)) if dist < best_dist => { @@ -128,27 +209,49 @@ pub fn job_pathfinding_system( } _ => {} } + } else { + info!( + "[PATHFIND] Dorf at {:?} CANNOT reach tree at {:?}", + dorf_pos, trunk_pos + ); } } } JobKind::HaulCargo { cargo_pos, .. } => { + info!("[PATHFIND] HaulCargo at {:?}", cargo_pos); + for (dorf_entity, dorf_pos) in &dorfs_to_try { - if let Ok(distance) = - calculate_traversal_distance(&tilemap, *dorf_pos, cargo_pos) - { - match best_result { - None => best_result = Some((*dorf_entity, cargo_pos, distance)), - Some((_, _, best_dist)) if distance < best_dist => { - best_result = Some((*dorf_entity, cargo_pos, distance)); + match calculate_traversal_distance(&tilemap, *dorf_pos, cargo_pos) { + Ok(distance) => { + info!( + "[PATHFIND] Dorf at {:?} can reach cargo (dist={})", + dorf_pos, distance + ); + match best_result { + None => best_result = Some((*dorf_entity, cargo_pos, distance)), + Some((_, _, best_dist)) if distance < best_dist => { + best_result = Some((*dorf_entity, cargo_pos, distance)); + } + _ => {} } - _ => {} + } + Err(()) => { + info!( + "[PATHFIND] Dorf at {:?} CANNOT reach cargo at {:?}", + dorf_pos, cargo_pos + ); } } } } } - if let Some((dorf_entity, approach_target, _)) = best_result { + if let Some((dorf_entity, approach_target, dist)) = best_result { + info!( + "[PATHFIND] Best dorf {:?} with approach {:?} (dist={})", + dorf_entity, approach_target, dist + ); + if let Some(job_id) = job_queue.assign_job(job_idx, dorf_entity, approach_target) { if let Ok((_, mut queue, mut state, _, mut ambulatory)) = dorf_query.get_mut(dorf_entity) @@ -189,18 +292,23 @@ pub fn job_pathfinding_system( ambulatory.path_index = 0; info!( - "[PATHFIND] Assigned job {:?} to dorf {:?} with approach {:?}", + "[PATHFIND] SUCCESS: Assigned job {:?} to dorf {:?} with approach {:?}", job_id, dorf_entity, approach_target ); } } } else { + info!("[PATHFIND] NO PATH FOUND for any dorf - retry_count will increment"); job_queue.increment_retry(job_idx); - if !dorf_entities.is_empty() { - job_queue.unclaim_jobs_for_entity(dorf_entities[0]); + for entity in &dorf_entities { + job_queue.unclaim_jobs_for_entity(*entity); } let retry_count = job_queue.get_job_retry_count(job_idx).unwrap_or(0); if retry_count >= 10 { + info!( + "[PATHFIND] Job idx={} suspended after {} retries", + job_idx, retry_count + ); job_queue.suspend_job(job_idx); } } diff --git a/src/entities/tasks/queue_debug.rs b/src/entities/tasks/queue_debug.rs index ebfb491..fc6e098 100644 --- a/src/entities/tasks/queue_debug.rs +++ b/src/entities/tasks/queue_debug.rs @@ -1,6 +1,6 @@ use crate::entities::behaviour::EntityType; -use crate::entities::tasks::components::{TaskQueue, TaskState}; -use crate::entities::tasks::job_queue::{JobKind, JobQueue}; +use crate::entities::tasks::components::{Task, TaskQueue, TaskState}; +use crate::entities::tasks::job_queue::{JobKind, JobQueue, JobState}; use bevy::prelude::*; pub fn queue_debug_system( @@ -22,9 +22,21 @@ pub fn queue_debug_system( ); for (i, kind) in job_queue.iter().enumerate() { + let state_str = match job_queue.get_job_state(i) { + Some(JobState::Unclaimed) => "Unclaimed", + Some(JobState::Calculating(_)) => "Calculating", + Some(JobState::Claimed(e)) => &format!("Claimed({:?})", e), + Some(JobState::Suspended) => "SUSPENDED", + Some(JobState::Complete) => "Complete", + None => "?", + }; + let retry = job_queue.get_job_retry_count(i).unwrap_or(0); match kind { JobKind::FellTree { trunk_pos } => { - info!(" [{}] FellTree at {:?}", i, trunk_pos); + info!( + " [{}] FellTree at {:?} state={} retry={}", + i, trunk_pos, state_str, retry + ); } JobKind::HaulCargo { cargo_entity, @@ -32,29 +44,52 @@ pub fn queue_debug_system( dest, } => { info!( - " [{}] HaulCargo entity:{:?} from {:?} to {:?}", - i, cargo_entity, cargo_pos, dest + " [{}] HaulCargo entity:{:?} from {:?} to {:?} state={} retry={}", + i, cargo_entity, cargo_pos, dest, state_str, retry ); } } } + let mut idle_count = 0; + let mut active_count = 0; + let mut pending_count = 0; + info!("=== DORFS ==="); for (queue, state, transform) in dorf_query.iter() { let pos = transform.translation.truncate(); let current_task = queue.current().map(|t| t.name()).unwrap_or("EMPTY"); + let is_idle = queue + .current() + .map(|t| matches!(t, Task::Idle { .. })) + .unwrap_or(false); + if is_idle { + idle_count += 1; + } let state_str = match *state { - TaskState::Pending => "PENDING", - TaskState::Active => "ACTIVE", + TaskState::Pending => { + pending_count += 1; + "PENDING" + } + TaskState::Active => { + active_count += 1; + "ACTIVE" + } TaskState::Completed => "COMPLETED", TaskState::Failed => "FAILED", }; info!( - " Dorf at {:?}: task={} state={} queue_len={}", + " Dorf at {:?}: task={} state={} queue_len={} is_idle={}", pos, current_task, state_str, - queue.tasks.len() + queue.tasks.len(), + is_idle ); } + + info!( + "=== SUMMARY === idle={} active={}, pending={}", + idle_count, active_count, pending_count + ); }