diff --git a/DEBUGGING_SHUTTLE_TRANSFER_LOGGING.md b/DEBUGGING_SHUTTLE_TRANSFER_LOGGING.md new file mode 100644 index 00000000000..c733bcd7949 --- /dev/null +++ b/DEBUGGING_SHUTTLE_TRANSFER_LOGGING.md @@ -0,0 +1,226 @@ +# Shuttle Transfer Debug Logging Recommendations + +## Critical Areas to Add Logging + +### 1. **Pre/Post Transfer Validation** +Add logging before and after `initiate_docking()` to verify complete transfer: + +```dm +// In controlled_ship_datum.dm, complete_dock proc +/datum/overmap/ship/controlled/complete_dock(datum/overmap/dock_target, datum/docking_ticket/ticket) + // LOG: Pre-dock state + log_shuttle("[src] [REF(src)] PRE-DOCK: shuttle_port=[REF(shuttle_port)] z=[shuttle_port.z] virtual_z=[shuttle_port.virtual_z()] turf_count=[shuttle_port.turf_count]") + log_shuttle("[src] [REF(src)] PRE-DOCK: target_port=[REF(ticket.target_port)] z=[ticket.target_port.z] virtual_z=[ticket.target_port.virtual_z()]") + + var/list/pre_turfs = shuttle_port.return_ordered_turfs(shuttle_port.x, shuttle_port.y, shuttle_port.z, shuttle_port.dir) + log_shuttle("[src] [REF(src)] PRE-DOCK: Counted [pre_turfs.len] turfs before dock") + + shuttle_port.initiate_docking(ticket.target_port) + + // LOG: Post-dock validation + var/list/post_turfs = shuttle_port.return_ordered_turfs(shuttle_port.x, shuttle_port.y, shuttle_port.z, shuttle_port.dir) + log_shuttle("[src] [REF(src)] POST-DOCK: Now at z=[shuttle_port.z] virtual_z=[shuttle_port.virtual_z()] turf_count=[shuttle_port.turf_count]") + log_shuttle("[src] [REF(src)] POST-DOCK: Counted [post_turfs.len] turfs after dock") + + if(pre_turfs.len != post_turfs.len) + log_shuttle("WARNING: [src] [REF(src)] TURF COUNT MISMATCH: [pre_turfs.len] -> [post_turfs.len]") + message_admins("CRITICAL: Ship [src] experienced turf count mismatch during docking! Check shuttle logs.") + + . = ..() + log_shuttle("[src] [REF(src)] COMPLETE DOCK: FINISHED DOCKING TO [dock_target] AT [ticket.target_port]") +``` + +### 2. **Exception Tracking in initiate_docking()** +Add detailed exception logging: + +```dm +// In docking.dm, preflight_check proc +/obj/docking_port/mobile/proc/preflight_check(list/old_turfs, list/new_turfs, list/areas_to_move, rotation) + var/list/exceptions_list = list() + var/new_turf_count = 0 + + for(var/i = 1, i <= old_turfs.len, i++) + try + // ... existing code ... + catch(var/exception/e2) + log_shuttle("EXCEPTION in preflight_check [src] [REF(src)] turf [i]/[old_turfs.len]: [e2]") + log_shuttle("EXCEPTION DETAILS: oldT=[old_turfs[i]] newT=[new_turfs[i]]") + exceptions_list += e2 + + turf_count = new_turf_count + + if(exceptions_list.len > 0) + log_shuttle("WARNING: [src] [REF(src)] preflight_check had [exceptions_list.len] exceptions") + + for(var/exception/e3 in exceptions_list) + CHECK_TICK + log_shuttle("THROWING EXCEPTION: [e3]") + throw_exception(e3) +``` + +### 3. **Per-Turf Transfer Verification** +Track individual turf transfers: + +```dm +// In docking.dm, takeoff proc +/obj/docking_port/mobile/proc/takeoff(...) + var/turfs_moved = 0 + var/atoms_moved = 0 + + // After MOVE_CONTENTS loop + for(var/i = 1, i <= old_turfs.len, i++) + try + var/turf/oldT = old_turfs[i] + var/turf/newT = new_turfs[i] + var/move_mode = old_turfs[oldT] + if(move_mode & MOVE_CONTENTS) + for(var/k in oldT) + try + var/atom/movable/moving_atom = k + if(moving_atom.loc != oldT) + continue + if(moving_atom.onShuttleMove(newT, oldT, movement_force, movement_direction, old_dock, src, all_towed_shuttles)) + moved_atoms[moving_atom] = oldT + atoms_moved++ + catch(var/exception/e1) + log_shuttle("EXCEPTION moving atom [moving_atom] from [oldT] to [newT]: [e1]") + exceptions_list += e1 + catch(var/exception/e1) + log_shuttle("EXCEPTION in MOVE_CONTENTS loop turf [i]: [e1]") + exceptions_list += e1 + + // After MOVE_TURF loop + log_shuttle("[src] [REF(src)] TAKEOFF PHASE: Moved [atoms_moved] atoms across [old_turfs.len] turfs") +``` + +### 4. **Virtual Z-Level Consistency Check** +Add periodic validation: + +```dm +// New proc in docking_port/mobile +/obj/docking_port/mobile/proc/validate_virtual_z_consistency() + var/list/turfs = return_ordered_turfs(x, y, z, dir) + var/list/virtual_z_counts = list() + + for(var/turf/T in turfs) + var/vz = T.virtual_z() + if(!virtual_z_counts["[vz]"]) + virtual_z_counts["[vz]"] = 0 + virtual_z_counts["[vz]"]++ + + if(virtual_z_counts.len > 1) + log_shuttle("CRITICAL: [src] [REF(src)] VIRTUAL_Z SPLIT DETECTED:") + for(var/vz_key in virtual_z_counts) + log_shuttle(" Virtual Z [vz_key]: [virtual_z_counts[vz_key]] turfs") + return FALSE + + return TRUE + +// Call after docking completes +/datum/overmap/ship/controlled/complete_dock(datum/overmap/dock_target, datum/docking_ticket/ticket) + shuttle_port.initiate_docking(ticket.target_port) + . = ..() + + if(!shuttle_port.validate_virtual_z_consistency()) + message_admins("CRITICAL: Ship [src] has split virtual z-levels after docking! Immediate investigation needed.") + log_shuttle("EMERGENCY: [src] [REF(src)] FAILED VIRTUAL Z CONSISTENCY CHECK AFTER DOCK") +``` + +### 5. **Towed Shuttle Relationship Tracking** +Log towed shuttle state changes: + +```dm +// In docking.dm, takeoff proc after towed shuttle handling +if(old_dock && old_dock.owner_ship) + log_shuttle("[src] [REF(src)] TOWED: Removing from old parent [old_dock.owner_ship] [REF(old_dock.owner_ship)]") + old_dock.owner_ship.towed_shuttles -= src + +if(new_dock.owner_ship) + log_shuttle("[src] [REF(src)] TOWED: Adding to new parent [new_dock.owner_ship] [REF(new_dock.owner_ship)]") + new_dock.owner_ship.towed_shuttles |= src + parent_shuttles += new_dock.owner_ship + +// Later, after area updates +log_shuttle("[src] [REF(src)] TOWED SHUTTLES STATE: [all_towed_shuttles.len] towed shuttles") +for(var/obj/docking_port/mobile/M in all_towed_shuttles) + log_shuttle(" - [M] [REF(M)] parent=[M.docked?.owner_ship ? M.docked.owner_ship : "NONE"]") +``` + +### 6. **Undock Validation** +Similar validation for undocking: + +```dm +/datum/overmap/ship/controlled/complete_undock() + log_shuttle("[src] [REF(src)] UNDOCK: Pre-undock z=[shuttle_port.z] virtual_z=[shuttle_port.virtual_z()]") + + var/obj/docking_port/stationary/target_transit = shuttle_port.assigned_transit + if(!target_transit) + log_shuttle("CRITICAL: [src] [REF(src)] UNDOCK: No assigned transit port!") + message_admins("CRITICAL: Ship [src] attempting to undock without assigned transit port!") + + shuttle_port.initiate_docking(shuttle_port.assigned_transit) + log_shuttle("[src] [REF(src)] UNDOCK: Post-undock z=[shuttle_port.z] virtual_z=[shuttle_port.virtual_z()]") + + if(!shuttle_port.validate_virtual_z_consistency()) + message_admins("CRITICAL: Ship [src] has split virtual z-levels after undocking!") + + log_shuttle("[src] [REF(src)] COMPLETE UNDOCK: FINISHED UNDOCK FROM [docked_to]") + return ..() +``` + +### 7. **Real-time Alert System** +Add admin alerts for critical issues: + +```dm +/obj/docking_port/mobile/proc/emergency_shuttle_alert(message) + log_shuttle("EMERGENCY: [src] [REF(src)]: [message]") + message_admins("SHUTTLE EMERGENCY - [src]: [message] [ADMIN_JMP(src)]") + // Optionally send to Discord webhook or other monitoring +``` + +## Monitoring Dashboard + +Create an admin verb to check shuttle health: + +```dm +/client/proc/check_shuttle_health() + set name = "Check Shuttle Health" + set category = "Debug" + + if(!check_rights(R_ADMIN)) + return + + var/output = "=== SHUTTLE HEALTH CHECK ===\n" + + for(var/datum/overmap/ship/controlled/ship in SSovermap.controlled_ships) + output += "\n[ship.name] ([REF(ship)]):\n" + output += " Z-Level: [ship.shuttle_port.z]\n" + output += " Virtual Z: [ship.shuttle_port.virtual_z()]\n" + output += " Docked: [ship.docked_to ? "Yes to [ship.docked_to]" : "No"]\n" + output += " Docking: [ship.docking ? "Yes" : "No"]\n" + output += " Turf Count: [ship.shuttle_port.turf_count]\n" + + var/vz_valid = ship.shuttle_port.validate_virtual_z_consistency() + output += " VZ Consistent: [vz_valid ? "YES" : "NO - CRITICAL!"]\n" + + if(ship.towed_shuttles.len) + output += " Towed Shuttles: [ship.towed_shuttles.len]\n" + + to_chat(src, output) + log_admin("[key_name(src)] checked shuttle health") +``` + +## Files to Modify + +1. **code/modules/overmap/ships/controlled_ship_datum.dm** - Lines 204-234 (complete_dock and complete_undock) +2. **code/modules/shuttle/docking.dm** - Lines 9-103 (initiate_docking, preflight_check, takeoff, cleanup_runway) +3. **code/modules/shuttle/shuttle.dm** - Add new validation procs +4. **code/modules/admin/verbs/shuttlepanel.dm** - Add health check verb + +## Configuration + +Add to config.txt: +``` +## Enables verbose shuttle transfer logging +LOG_SHUTTLE_VERBOSE +``` diff --git a/SHUTTLE_LOG_CURRENT_AND_IMPROVEMENTS.md b/SHUTTLE_LOG_CURRENT_AND_IMPROVEMENTS.md new file mode 100644 index 00000000000..7d992f40292 --- /dev/null +++ b/SHUTTLE_LOG_CURRENT_AND_IMPROVEMENTS.md @@ -0,0 +1,418 @@ +# Shuttle Log - Current State and Proposed Improvements + +## Current shuttle.log Contents + +The shuttle.log is controlled by the `LOG_SHUTTLE` config flag and logs with the prefix "OVERMAP:". + +### Currently Logged Events: + +#### 1. **Ship Docking Events** (controlled_ship_datum.dm) +``` +OVERMAP: [ShipName] [REF] DOCKING: STARTED REQUEST FOR [TargetShip] AT [DockingPort] +OVERMAP: [ShipName] [REF] COMPLETE DOCK: FINISHED DOCKING TO [TargetShip] AT [DockingPort] +``` + +#### 2. **Ship Undocking Events** (controlled_ship_datum.dm) +``` +OVERMAP: [ShipName] [REF] UNDOCK: STARTED UNDOCK FROM [DockedTarget] +OVERMAP: [ShipName] [REF] COMPLETE UNDOCK: FINISHED UNDOCK FROM [DockedTarget] +``` + +#### 3. **Dynamic Encounter Spawning** (subsystem/overmap.dm) +``` +OVERMAP: SSOVERMAP: SPAWNING DYNAMIC ENCOUNTER STARTED +OVERMAP: SSOVERMAP: START_DYN_E: RUNNING MAPGEN REF [REF] FOR VLEV [VlevelID] OF TYPE [MapgenType] +``` + +#### 4. **Static Encounter Spawning** (subsystem/overmap.dm) +``` +OVERMAP: SSOVERMAP: SPAWNING STATIC ENCOUNTER STARTED +``` + +#### 5. **Dynamic/Static Unloading** (overmap/objects/) +``` +OVERMAP: [OvermapObject] [REF] UNLOAD +OVERMAP: [OvermapObject] [REF] LEVEL_INIT +``` + +#### 6. **Outpost Initialization** (outpost.dm) +``` +OVERMAP: [Outpost] [REF] OUTPOST MAP LEVEL INIT +OVERMAP: [Outpost] [Type] [REF] OUTPOST HANGAR INIT +``` + +#### 7. **Docking Port Adjustments** (shuttle.dm & _overmap_datum.dm) +``` +OVERMAP: [Port] [REF] DOCKING: ADJUST [Port] [REF] TO [Shuttle] [REF] +``` + +#### 8. **Map Generator Events** (_MapGenerator.dm & _PlanetGenerator.dm) +Various mapgen logging messages + +--- + +## What's MISSING (Critical for Debugging) + +### 1. **No Pre-Flight State Logging** +- Current turf count before movement +- Virtual z-level before movement +- Location coordinates (x, y, z) +- Docked state + +### 2. **No Post-Transfer Verification** +- Turf count after movement +- Virtual z-level after movement +- Success/failure confirmation + +### 3. **No Exception/Error Logging** +- Exceptions during preflight_check() +- Exceptions during takeoff() +- Exceptions during cleanup_runway() +- Failed dock attempts (returns early with error codes) + +### 4. **No Turf/Atom Movement Tracking** +- How many turfs were moved +- How many atoms were moved +- Which turfs failed to move + +### 5. **No Virtual Z-Level Consistency Checks** +- Ship split across multiple virtual z-levels +- Towed shuttle virtual z mismatches + +### 6. **No Towed Shuttle Relationship Logging** +- Parent/child relationships +- Towed shuttle list changes +- underlying_turf_area updates + +### 7. **No Timing Information** +- How long dock/undock operations take +- When operations start vs complete + +--- + +## Proposed Improvements + +### Phase 1: Critical Debugging (Immediate Need) + +Add to **controlled_ship_datum.dm complete_dock()**: +```dm +/datum/overmap/ship/controlled/complete_dock(datum/overmap/dock_target, datum/docking_ticket/ticket) + // Pre-dock state + var/pre_z = shuttle_port.z + var/pre_vz = shuttle_port.virtual_z() + var/list/pre_turfs = shuttle_port.return_ordered_turfs(shuttle_port.x, shuttle_port.y, shuttle_port.z, shuttle_port.dir) + log_shuttle("[src] [REF(src)] PRE-DOCK STATE: z=[pre_z] vz=[pre_vz] coords=([shuttle_port.x],[shuttle_port.y]) turfs=[pre_turfs.len] turf_count_var=[shuttle_port.turf_count]") + log_shuttle("[src] [REF(src)] PRE-DOCK TARGET: [dock_target] [REF(dock_target)] port=[REF(ticket.target_port)] z=[ticket.target_port.z] vz=[ticket.target_port.virtual_z()]") + + // Perform dock + var/dock_result = shuttle_port.initiate_docking(ticket.target_port) + + // Post-dock validation + var/post_z = shuttle_port.z + var/post_vz = shuttle_port.virtual_z() + var/list/post_turfs = shuttle_port.return_ordered_turfs(shuttle_port.x, shuttle_port.y, shuttle_port.z, shuttle_port.dir) + log_shuttle("[src] [REF(src)] POST-DOCK STATE: result=[dock_result] z=[post_z] vz=[post_vz] coords=([shuttle_port.x],[shuttle_port.y]) turfs=[post_turfs.len]") + + // Validation checks + if(pre_turfs.len != post_turfs.len) + log_shuttle("CRITICAL: [src] [REF(src)] TURF COUNT MISMATCH: [pre_turfs.len] -> [post_turfs.len]") + message_admins("CRITICAL: Ship [src] turf count mismatch during docking! [pre_turfs.len] -> [post_turfs.len] [ADMIN_JMP(shuttle_port)]") + + if(dock_result != DOCKING_SUCCESS) + log_shuttle("ERROR: [src] [REF(src)] DOCK FAILED: result=[dock_result]") + message_admins("ERROR: Ship [src] docking failed with result [dock_result] [ADMIN_JMP(shuttle_port)]") + + if(!shuttle_port.validate_virtual_z_consistency()) + log_shuttle("CRITICAL: [src] [REF(src)] VIRTUAL Z SPLIT AFTER DOCK") + message_admins("CRITICAL: Ship [src] has split virtual z-levels after docking! [ADMIN_JMP(shuttle_port)]") + + . = ..() + log_shuttle("[src] [REF(src)] COMPLETE DOCK: FINISHED DOCKING TO [dock_target] AT [ticket.target_port]") +``` + +Add to **controlled_ship_datum.dm complete_undock()**: +```dm +/datum/overmap/ship/controlled/complete_undock() + var/pre_z = shuttle_port.z + var/pre_vz = shuttle_port.virtual_z() + var/old_docked_to = docked_to + + log_shuttle("[src] [REF(src)] PRE-UNDOCK STATE: z=[pre_z] vz=[pre_vz] from=[old_docked_to]") + + if(!shuttle_port.assigned_transit) + log_shuttle("CRITICAL: [src] [REF(src)] NO ASSIGNED TRANSIT PORT FOR UNDOCK") + message_admins("CRITICAL: Ship [src] has no assigned transit port for undocking! [ADMIN_JMP(shuttle_port)]") + + var/dock_result = shuttle_port.initiate_docking(shuttle_port.assigned_transit) + + var/post_z = shuttle_port.z + var/post_vz = shuttle_port.virtual_z() + log_shuttle("[src] [REF(src)] POST-UNDOCK STATE: result=[dock_result] z=[post_z] vz=[post_vz]") + + if(!shuttle_port.validate_virtual_z_consistency()) + log_shuttle("CRITICAL: [src] [REF(src)] VIRTUAL Z SPLIT AFTER UNDOCK") + message_admins("CRITICAL: Ship [src] has split virtual z-levels after undocking! [ADMIN_JMP(shuttle_port)]") + + log_shuttle("[src] [REF(src)] COMPLETE UNDOCK: FINISHED UNDOCK FROM [old_docked_to]") + return ..() +``` + +Add **virtual z consistency validator** to **shuttle.dm**: +```dm +/obj/docking_port/mobile/proc/validate_virtual_z_consistency() + var/list/turfs = return_ordered_turfs(x, y, z, dir) + if(!turfs.len) + log_shuttle("WARNING: [src] [REF(src)] validate_virtual_z: No turfs found") + return TRUE + + var/list/virtual_z_counts = list() + for(var/turf/T in turfs) + if(!T) + continue + var/vz = T.virtual_z() + if(!virtual_z_counts["[vz]"]) + virtual_z_counts["[vz]"] = 0 + virtual_z_counts["[vz]"]++ + + if(virtual_z_counts.len > 1) + log_shuttle("CRITICAL: [src] [REF(src)] VIRTUAL_Z SPLIT DETECTED: [virtual_z_counts.len] different zones") + for(var/vz_key in virtual_z_counts) + log_shuttle(" Virtual Z [vz_key]: [virtual_z_counts[vz_key]] turfs ([round(virtual_z_counts[vz_key] / turfs.len * 100, 0.1)]%)") + return FALSE + + return TRUE +``` + +### Phase 2: Exception and Error Tracking + +Add to **docking.dm initiate_docking()**: +```dm +/obj/docking_port/mobile/proc/initiate_docking(obj/docking_port/stationary/new_dock, movement_direction, force=FALSE) + log_shuttle("[src] [REF(src)] INITIATE_DOCK: Starting dock to [new_dock] [REF(new_dock)] force=[force]") + log_shuttle("[src] [REF(src)] INITIATE_DOCK: Current state - z=[z] vz=[virtual_z()] coords=([x],[y])") + + if(new_dock.docked == src) + log_shuttle("[src] [REF(src)] INITIATE_DOCK: Already docked, returning SUCCESS") + remove_ripples() + return DOCKING_SUCCESS + + if(!force) + if(!check_dock(new_dock)) + log_shuttle("ERROR: [src] [REF(src)] INITIATE_DOCK: check_dock FAILED for [new_dock] [REF(new_dock)]") + remove_ripples() + return DOCKING_BLOCKED + if(!can_move()) + log_shuttle("ERROR: [src] [REF(src)] INITIATE_DOCK: can_move FAILED - shuttle immobilized") + remove_ripples() + return DOCKING_IMMOBILIZED + + // ... existing code ... + + var/preflight_result = preflight_check(old_turfs, new_turfs, areas_to_move, rotation) + if(preflight_result) + log_shuttle("ERROR: [src] [REF(src)] INITIATE_DOCK: preflight_check FAILED with code [preflight_result]") + remove_ripples() + return preflight_result + + log_shuttle("[src] [REF(src)] INITIATE_DOCK: preflight_check PASSED - [old_turfs.len] turfs, [areas_to_move.len] areas, rotation=[rotation]") + + // ... rest of existing code ... + + log_shuttle("[src] [REF(src)] INITIATE_DOCK: Successfully completed dock to [new_dock]") + return DOCKING_SUCCESS +``` + +Add to **docking.dm preflight_check()**: +```dm +/obj/docking_port/mobile/proc/preflight_check(list/old_turfs, list/new_turfs, list/areas_to_move, rotation) + var/list/exceptions_list = list() + var/new_turf_count = 0 + var/failed_turfs = 0 + + for(var/i = 1, i <= old_turfs.len, i++) + try + CHECK_TICK + var/turf/oldT = old_turfs[i] + var/turf/newT = new_turfs[i] + if(!newT) + log_shuttle("ERROR: [src] [REF(src)] preflight turf [i]/[old_turfs.len]: newT is null") + return DOCKING_NULL_DESTINATION + if(!oldT) + log_shuttle("ERROR: [src] [REF(src)] preflight turf [i]/[old_turfs.len]: oldT is null") + return DOCKING_NULL_SOURCE + + // ... existing code ... + + catch(var/exception/e2) + failed_turfs++ + log_shuttle("EXCEPTION: [src] [REF(src)] preflight turf [i]/[old_turfs.len]: [e2]") + log_shuttle("EXCEPTION: oldT=[old_turfs[i]] type=[old_turfs[i]?.type] newT=[new_turfs[i]] type=[new_turfs[i]?.type]") + exceptions_list += e2 + + turf_count = new_turf_count + + if(exceptions_list.len > 0) + log_shuttle("WARNING: [src] [REF(src)] preflight had [exceptions_list.len] exceptions, [failed_turfs] failed turfs") + + for(var/exception/e3 in exceptions_list) + CHECK_TICK + throw_exception(e3) +``` + +Add to **docking.dm takeoff()**: +```dm +/obj/docking_port/mobile/proc/takeoff(list/old_turfs, list/new_turfs, list/moved_atoms, rotation, movement_direction, obj/docking_port/stationary/old_dock, obj/docking_port/stationary/new_dock, area/underlying_old_area, list/all_towed_shuttles) + var/list/exceptions_list = list() + var/atoms_moved = 0 + var/atoms_failed = 0 + var/turfs_moved = 0 + var/areas_moved = 0 + + log_shuttle("[src] [REF(src)] TAKEOFF: Processing [old_turfs.len] turfs, [all_towed_shuttles.len] towed shuttles") + + // Log towed shuttle relationships + if(old_dock && old_dock.owner_ship) + log_shuttle("[src] [REF(src)] TAKEOFF: Removing from parent [old_dock.owner_ship] [REF(old_dock.owner_ship)]") + if(new_dock.owner_ship) + log_shuttle("[src] [REF(src)] TAKEOFF: Adding to parent [new_dock.owner_ship] [REF(new_dock.owner_ship)]") + + // ... existing MOVE_CONTENTS loop ... + for(var/i = 1, i <= old_turfs.len, i++) + try + // ... existing code ... + if(move_mode & MOVE_CONTENTS) + for(var/k in oldT) + try + var/atom/movable/moving_atom = k + if(moving_atom.loc != oldT) + continue + if(moving_atom.onShuttleMove(newT, oldT, movement_force, movement_direction, old_dock, src, all_towed_shuttles)) + moved_atoms[moving_atom] = oldT + atoms_moved++ + catch(var/exception/e1) + atoms_failed++ + log_shuttle("EXCEPTION: [src] [REF(src)] TAKEOFF CONTENTS: Moving [moving_atom] [moving_atom.type] from [oldT] to [newT]: [e1]") + exceptions_list += e1 + catch(var/exception/e1) + log_shuttle("EXCEPTION: [src] [REF(src)] TAKEOFF CONTENTS turf [i]: [e1]") + exceptions_list += e1 + + log_shuttle("[src] [REF(src)] TAKEOFF CONTENTS: Moved [atoms_moved] atoms, [atoms_failed] failed") + + // ... existing MOVE_TURF loop ... + for(var/i = 1, i <= old_turfs.len, i++) + try + // ... existing code ... + if(move_mode & MOVE_TURF) + // ... existing code ... + turfs_moved++ + catch(var/exception/e2) + log_shuttle("EXCEPTION: [src] [REF(src)] TAKEOFF TURF loop turf [i]: [e2]") + exceptions_list += e2 + + log_shuttle("[src] [REF(src)] TAKEOFF TURFS: Moved [turfs_moved] turfs") + + // ... existing MOVE_AREA loop ... + for(var/i = 1, i <= old_turfs.len, i++) + try + // ... existing code ... + if(move_mode & MOVE_AREA) + areas_moved++ + // ... existing area handling code ... + + if(istype(new_area) && new_area.mobile_port && !(new_area.mobile_port in parent_shuttles) && (M in new_area.mobile_port.towed_shuttles)) + log_shuttle("[src] [REF(src)] TAKEOFF AREA: Removing [M] from old parent [new_area.mobile_port]") + if(istype(target_area) && target_area.mobile_port) + log_shuttle("[src] [REF(src)] TAKEOFF AREA: Adding [M] to new parent [target_area.mobile_port]") + catch(var/exception/e3) + log_shuttle("EXCEPTION: [src] [REF(src)] TAKEOFF AREA loop turf [i]: [e3]") + exceptions_list += e3 + + log_shuttle("[src] [REF(src)] TAKEOFF AREAS: Processed [areas_moved] area turfs") + + if(exceptions_list.len > 0) + log_shuttle("WARNING: [src] [REF(src)] TAKEOFF: [exceptions_list.len] total exceptions during takeoff") + + for(var/exception/e4 in exceptions_list) + CHECK_TICK + throw_exception(e4) +``` + +### Phase 3: Performance and Timing + +Add timing tracking: +```dm +/datum/overmap/ship/controlled/complete_dock(datum/overmap/dock_target, datum/docking_ticket/ticket) + var/start_time = world.time + log_shuttle("[src] [REF(src)] DOCK_TIMING: Starting at world.time=[start_time]") + + // ... existing dock code ... + + var/end_time = world.time + var/duration = end_time - start_time + log_shuttle("[src] [REF(src)] DOCK_TIMING: Completed in [duration] deciseconds ([duration/10] seconds)") + + if(duration > 50) // More than 5 seconds + log_shuttle("WARNING: [src] [REF(src)] DOCK_TIMING: Dock took longer than expected: [duration/10]s") + message_admins("Warning: Ship [src] docking took [duration/10] seconds (expected <5s)") +``` + +### Phase 4: Periodic Health Checks + +Add automated health check system: +```dm +/datum/controller/subsystem/shuttle/proc/validate_all_shuttles() + for(var/obj/docking_port/mobile/M in mobile) + if(!M.docked) + continue + + if(!M.validate_virtual_z_consistency()) + log_shuttle("AUTO_CHECK: [M] [REF(M)] FAILED virtual z consistency") + message_admins("AUTO CHECK: Shuttle [M] failed virtual z consistency check! [ADMIN_JMP(M)]") + + var/list/turfs = M.return_ordered_turfs(M.x, M.y, M.z, M.dir) + if(turfs.len != M.turf_count) + log_shuttle("AUTO_CHECK: [M] [REF(M)] turf count mismatch: expected [M.turf_count], found [turfs.len]") + +// Call this periodically or on-demand +/datum/controller/subsystem/shuttle/proc/fire() + // ... existing code ... + + if(world.time % 6000 == 0) // Every 10 minutes + validate_all_shuttles() +``` + +--- + +## Summary of Improvements + +### What We're Adding: +1. ✅ Pre/post state logging for all dock/undock operations +2. ✅ Virtual z-level consistency validation +3. ✅ Exception tracking with full context +4. ✅ Turf/atom movement statistics +5. ✅ Towed shuttle relationship tracking +6. ✅ Timing information for performance monitoring +7. ✅ Automated periodic health checks +8. ✅ Admin alerts for critical issues + +### Impact on Log Size: +- **Current**: ~10-20 lines per dock/undock operation +- **With improvements**: ~40-60 lines per dock/undock operation +- **Trade-off**: 3-5x more log data, but complete visibility into what happened + +### Configuration: +Keep existing `LOG_SHUTTLE` flag, optionally add: +``` +## Enable verbose shuttle transfer logging (includes detailed state tracking) +LOG_SHUTTLE_VERBOSE +``` + +Then in code: +```dm +/proc/log_shuttle_verbose(text) + if (CONFIG_GET(flag/log_shuttle_verbose)) + log_shuttle(text) +``` + +Use `log_shuttle()` for critical events, `log_shuttle_verbose()` for detailed tracking. diff --git a/code/modules/overmap/ships/controlled_ship_datum.dm b/code/modules/overmap/ships/controlled_ship_datum.dm index 1a4136a95a7..1c703f0b920 100644 --- a/code/modules/overmap/ships/controlled_ship_datum.dm +++ b/code/modules/overmap/ships/controlled_ship_datum.dm @@ -211,7 +211,41 @@ shuttle_port.play_engine_sound(ticket.target_port, shuttle_port.landing_sound) /datum/overmap/ship/controlled/complete_dock(datum/overmap/dock_target, datum/docking_ticket/ticket) - shuttle_port.initiate_docking(ticket.target_port) + // Log pre-dock state for debugging + var/pre_z = shuttle_port.z + var/pre_vz = shuttle_port.virtual_z() + var/list/pre_turfs = shuttle_port.return_ordered_turfs(shuttle_port.x, shuttle_port.y, shuttle_port.z, shuttle_port.dir) + var/start_time = world.time + log_shuttle("[src] [REF(src)] PRE-DOCK STATE: z=[pre_z] vz=[pre_vz] coords=([shuttle_port.x],[shuttle_port.y]) turfs=[pre_turfs.len] turf_count_var=[shuttle_port.turf_count]") + log_shuttle("[src] [REF(src)] PRE-DOCK TARGET: [dock_target] [REF(dock_target)] port=[REF(ticket.target_port)] z=[ticket.target_port.z] vz=[ticket.target_port.virtual_z()]") + + // Perform the actual docking + var/dock_result = shuttle_port.initiate_docking(ticket.target_port) + + // Log post-dock state and validate + var/post_z = shuttle_port.z + var/post_vz = shuttle_port.virtual_z() + var/list/post_turfs = shuttle_port.return_ordered_turfs(shuttle_port.x, shuttle_port.y, shuttle_port.z, shuttle_port.dir) + var/end_time = world.time + var/duration = end_time - start_time + log_shuttle("[src] [REF(src)] POST-DOCK STATE: result=[dock_result] z=[post_z] vz=[post_vz] coords=([shuttle_port.x],[shuttle_port.y]) turfs=[post_turfs.len] duration=[duration]ds") + + // Critical validation checks + if(pre_turfs.len != post_turfs.len) + log_shuttle("CRITICAL: [src] [REF(src)] TURF COUNT MISMATCH: [pre_turfs.len] -> [post_turfs.len]") + message_admins("CRITICAL: Ship [src] turf count mismatch during docking! [pre_turfs.len] -> [post_turfs.len] [ADMIN_JMP(shuttle_port)]") + + if(dock_result != DOCKING_SUCCESS) + log_shuttle("ERROR: [src] [REF(src)] DOCK FAILED: result=[dock_result]") + message_admins("ERROR: Ship [src] docking failed with result [dock_result] [ADMIN_JMP(shuttle_port)]") + + if(!shuttle_port.validate_virtual_z_consistency()) + log_shuttle("CRITICAL: [src] [REF(src)] VIRTUAL Z SPLIT AFTER DOCK") + message_admins("CRITICAL: Ship [src] has split virtual z-levels after docking! [ADMIN_JMP(shuttle_port)]") + + if(duration > 50) + log_shuttle("WARNING: [src] [REF(src)] DOCK_TIMING: Dock took [duration/10]s (expected <5s)") + . = ..() log_shuttle("[src] [REF(src)] COMPLETE DOCK: FINISHED DOCKING TO [dock_target] AT [ticket.target_port]") @@ -233,8 +267,35 @@ dock_time = dock_time_temp // Set it back to the original value if it was changed /datum/overmap/ship/controlled/complete_undock() - shuttle_port.initiate_docking(shuttle_port.assigned_transit) - log_shuttle("[src] [REF(src)] COMPLETE UNDOCK: FINISHED UNDOCK FROM [docked_to]") + // Log pre-undock state + var/pre_z = shuttle_port.z + var/pre_vz = shuttle_port.virtual_z() + var/old_docked_to = docked_to + var/start_time = world.time + log_shuttle("[src] [REF(src)] PRE-UNDOCK STATE: z=[pre_z] vz=[pre_vz] from=[old_docked_to]") + + if(!shuttle_port.assigned_transit) + log_shuttle("CRITICAL: [src] [REF(src)] NO ASSIGNED TRANSIT PORT FOR UNDOCK") + message_admins("CRITICAL: Ship [src] has no assigned transit port for undocking! [ADMIN_JMP(shuttle_port)]") + + // Perform the actual undocking + var/dock_result = shuttle_port.initiate_docking(shuttle_port.assigned_transit) + + // Log post-undock state and validate + var/post_z = shuttle_port.z + var/post_vz = shuttle_port.virtual_z() + var/end_time = world.time + var/duration = end_time - start_time + log_shuttle("[src] [REF(src)] POST-UNDOCK STATE: result=[dock_result] z=[post_z] vz=[post_vz] duration=[duration]ds") + + if(!shuttle_port.validate_virtual_z_consistency()) + log_shuttle("CRITICAL: [src] [REF(src)] VIRTUAL Z SPLIT AFTER UNDOCK") + message_admins("CRITICAL: Ship [src] has split virtual z-levels after undocking! [ADMIN_JMP(shuttle_port)]") + + if(duration > 50) + log_shuttle("WARNING: [src] [REF(src)] UNDOCK_TIMING: Undock took [duration/10]s (expected <5s)") + + log_shuttle("[src] [REF(src)] COMPLETE UNDOCK: FINISHED UNDOCK FROM [old_docked_to]") return ..() /datum/overmap/ship/controlled/pre_docked(datum/overmap/ship/controlled/dock_requester, override_dock) diff --git a/code/modules/shuttle/docking.dm b/code/modules/shuttle/docking.dm index a86c8f98116..28ac33ef9e5 100644 --- a/code/modules/shuttle/docking.dm +++ b/code/modules/shuttle/docking.dm @@ -1,15 +1,21 @@ /// This is the main proc. It instantly moves our mobile port to stationary port `new_dock`. /obj/docking_port/mobile/proc/initiate_docking(obj/docking_port/stationary/new_dock, movement_direction, force=FALSE) // Crashing this ship with NO SURVIVORS + log_shuttle("[src] [REF(src)] INITIATE_DOCK: Starting dock to [new_dock] [REF(new_dock)] force=[force]") + log_shuttle("[src] [REF(src)] INITIATE_DOCK: Current state - z=[z] vz=[virtual_z()] coords=([x],[y])") + if(new_dock.docked == src) + log_shuttle("[src] [REF(src)] INITIATE_DOCK: Already docked, returning SUCCESS") remove_ripples() return DOCKING_SUCCESS if(!force) if(!check_dock(new_dock)) + log_shuttle("ERROR: [src] [REF(src)] INITIATE_DOCK: check_dock FAILED for [new_dock] [REF(new_dock)]") remove_ripples() return DOCKING_BLOCKED if(!can_move()) + log_shuttle("ERROR: [src] [REF(src)] INITIATE_DOCK: can_move FAILED - shuttle immobilized") remove_ripples() return DOCKING_IMMOBILIZED @@ -54,14 +60,19 @@ . = preflight_check(old_turfs, new_turfs, areas_to_move, rotation) if(.) + log_shuttle("ERROR: [src] [REF(src)] INITIATE_DOCK: preflight_check FAILED with code [.]") remove_ripples() return + log_shuttle("[src] [REF(src)] INITIATE_DOCK: preflight_check PASSED - [old_turfs.len] turfs, [areas_to_move.len] areas, rotation=[rotation]") + if(!force) if(!check_dock(new_dock)) + log_shuttle("ERROR: [src] [REF(src)] INITIATE_DOCK: Second check_dock FAILED") remove_ripples() return DOCKING_BLOCKED if(!can_move()) + log_shuttle("ERROR: [src] [REF(src)] INITIATE_DOCK: Second can_move FAILED") remove_ripples() return DOCKING_IMMOBILIZED @@ -92,6 +103,7 @@ play_engine_sound(src, launch_sound) play_engine_sound(old_dock, launch_sound) + log_shuttle("[src] [REF(src)] INITIATE_DOCK: Successfully completed dock to [new_dock]") return DOCKING_SUCCESS /obj/docking_port/mobile/proc/throw_exception(exception/e) @@ -101,14 +113,18 @@ var/list/exceptions_list = list() // Recount turfs since we've got them all anyways var/new_turf_count = 0 - for(var/i in 1 to old_turfs.len) + var/failed_turfs = 0 + // C-like for loop; see top of file for explanation + for(var/i = 1, i <= old_turfs.len, i++) try CHECK_TICK var/turf/oldT = old_turfs[i] var/turf/newT = new_turfs[i] if(!newT) + log_shuttle("ERROR: [src] [REF(src)] preflight turf [i]/[old_turfs.len]: newT is null") return DOCKING_NULL_DESTINATION if(!oldT) + log_shuttle("ERROR: [src] [REF(src)] preflight turf [i]/[old_turfs.len]: oldT is null") return DOCKING_NULL_SOURCE var/move_mode @@ -142,21 +158,36 @@ old_turfs[oldT] = move_mode catch(var/exception/e2) + failed_turfs++ + log_shuttle("EXCEPTION: [src] [REF(src)] preflight turf [i]/[old_turfs.len]: [e2]") + log_shuttle("EXCEPTION: oldT=[old_turfs[i]] type=[old_turfs[i]?.type] newT=[new_turfs[i]] type=[new_turfs[i]?.type]") exceptions_list += e2 turf_count = new_turf_count + if(exceptions_list.len > 0) + log_shuttle("WARNING: [src] [REF(src)] preflight had [exceptions_list.len] exceptions, [failed_turfs] failed turfs") + for(var/exception/e3 in exceptions_list) CHECK_TICK throw_exception(e3) /obj/docking_port/mobile/proc/takeoff(list/old_turfs, list/new_turfs, list/moved_atoms, rotation, movement_direction, obj/docking_port/stationary/old_dock, obj/docking_port/stationary/new_dock, area/underlying_old_area, list/all_towed_shuttles) var/list/exceptions_list = list() + var/atoms_moved = 0 + var/atoms_failed = 0 + var/turfs_moved = 0 + var/areas_moved = 0 + + log_shuttle("[src] [REF(src)] TAKEOFF: Processing [old_turfs.len] turfs, [all_towed_shuttles.len] towed shuttles") + //Keep track of what shuttles we're landing on in case we're relanding on a shuttle we were on. var/list/parent_shuttles = list() if(old_dock && old_dock.owner_ship) + log_shuttle("[src] [REF(src)] TAKEOFF: Removing from parent [old_dock.owner_ship] [REF(old_dock.owner_ship)]") old_dock.owner_ship.towed_shuttles -= src if(new_dock.owner_ship) + log_shuttle("[src] [REF(src)] TAKEOFF: Adding to parent [new_dock.owner_ship] [REF(new_dock.owner_ship)]") new_dock.owner_ship.towed_shuttles |= src parent_shuttles += new_dock.owner_ship //Matrix multiply to get from current coords to new coords @@ -169,23 +200,30 @@ var/move_mode = old_turfs[oldT] if(move_mode & MOVE_CONTENTS) for(var/k in oldT) + var/atom/movable/moving_atom = k try - var/atom/movable/moving_atom = k if(moving_atom.loc != oldT) //fix for multi-tile objects continue if(moving_atom.onShuttleMove(newT, oldT, movement_force, movement_direction, old_dock, src, all_towed_shuttles)) //atoms moved_atoms[moving_atom] = oldT + atoms_moved++ catch(var/exception/e1) + atoms_failed++ + log_shuttle("EXCEPTION: [src] [REF(src)] TAKEOFF CONTENTS: Moving [moving_atom] [moving_atom.type] from [oldT] to [newT]: [e1]") exceptions_list += e1 catch(var/exception/e1) + log_shuttle("EXCEPTION: [src] [REF(src)] TAKEOFF CONTENTS turf [i]: [e1]") exceptions_list += e1 + log_shuttle("[src] [REF(src)] TAKEOFF CONTENTS: Moved [atoms_moved] atoms, [atoms_failed] failed") + for(var/i in 1 to old_turfs.len) try var/turf/oldT = old_turfs[i] var/turf/newT = new_turfs[i] var/move_mode = old_turfs[oldT] if(move_mode & MOVE_TURF) + turfs_moved++ var/area/ship/A = oldT.loc var/obj/docking_port/mobile/top_shuttle = A?.mobile_port var/obj/docking_port/mobile/M = A.mobile_port @@ -204,14 +242,18 @@ if(shuttle_layers > 0) oldT.onShuttleMove(newT, movement_force, movement_direction, shuttle_layers) //turfs catch(var/exception/e2) + log_shuttle("EXCEPTION: [src] [REF(src)] TAKEOFF TURF loop turf [i]: [e2]") exceptions_list += e2 + log_shuttle("[src] [REF(src)] TAKEOFF TURFS: Moved [turfs_moved] turfs") + for(var/i in 1 to old_turfs.len) try var/turf/oldT = old_turfs[i] var/turf/newT = new_turfs[i] var/move_mode = old_turfs[oldT] if(move_mode & MOVE_AREA) + areas_moved++ var/area/ship/shuttle_area = oldT.loc //The area on the shuttle, typecasted for the checks further down var/area/ship/target_area = newT.loc //The area we're landing on var/area/ship/new_area //The area that we leave behind @@ -232,16 +274,24 @@ if(!new_area) //This shouldn't happen, but just in case new_area = GLOB.areas_by_type[SHUTTLE_DEFAULT_UNDERLYING_AREA] if(istype(new_area) && new_area.mobile_port && !(new_area.mobile_port in parent_shuttles) && (M in new_area.mobile_port.towed_shuttles)) //Remove bottom shuttle from old parent shuttle's towed_shuttles + log_shuttle("[src] [REF(src)] TAKEOFF AREA: Removing [M] from old parent [new_area.mobile_port]") new_area.mobile_port.towed_shuttles -= M if(istype(target_area) && target_area.mobile_port) //Add bottom shuttle to new parent shuttle's towed_shuttles + log_shuttle("[src] [REF(src)] TAKEOFF AREA: Adding [M] to new parent [target_area.mobile_port]") target_area.mobile_port.towed_shuttles |= M parent_shuttles |= target_area.mobile_port //for use in the check above so we don't remove this shuttle from the towed shuttles of a shuttle that we're immediately relanding on. underlying_old_area |= new_area //lists are objects, which aren't popped off the stack, so this is the same list that is passed to cleanup runway shuttle_area.onShuttleMove(oldT, newT, new_area) //areas catch(var/exception/e3) + log_shuttle("EXCEPTION: [src] [REF(src)] TAKEOFF AREA loop turf [i]: [e3]") exceptions_list += e3 + log_shuttle("[src] [REF(src)] TAKEOFF AREAS: Processed [areas_moved] area turfs") + + if(exceptions_list.len > 0) + log_shuttle("WARNING: [src] [REF(src)] TAKEOFF: [exceptions_list.len] total exceptions during takeoff") + for(var/obj/docking_port/stationary/docking_point in docking_points) try if(!(docking_point in moved_atoms)) @@ -350,3 +400,30 @@ var/turf/open/T = turfs[i] if(istype(T)) T.air.copy_from_turf(T) + +/** + * Validates that all turfs in this shuttle are on the same virtual z-level + * Returns TRUE if consistent, FALSE if split detected + */ +/obj/docking_port/mobile/proc/validate_virtual_z_consistency() + var/list/turfs = return_ordered_turfs(x, y, z, dir) + if(!turfs.len) + log_shuttle("WARNING: [src] [REF(src)] validate_virtual_z: No turfs found") + return TRUE + + var/list/virtual_z_counts = list() + for(var/turf/T in turfs) + if(!T) + continue + var/vz = T.virtual_z() + if(!virtual_z_counts["[vz]"]) + virtual_z_counts["[vz]"] = 0 + virtual_z_counts["[vz]"]++ + + if(virtual_z_counts.len > 1) + log_shuttle("CRITICAL: [src] [REF(src)] VIRTUAL_Z SPLIT DETECTED: [virtual_z_counts.len] different zones") + for(var/vz_key in virtual_z_counts) + log_shuttle(" Virtual Z [vz_key]: [virtual_z_counts[vz_key]] turfs ([round(virtual_z_counts[vz_key] / turfs.len * 100, 0.1)]%)") + return FALSE + + return TRUE