Selaa lähdekoodia

Add scheduler diagnostic logging for queue stall debugging (#616)

  When the print queue scheduler finds pending items but doesn't start
  any, there was no logging to explain why. Added INFO-level summary
  after each queue check showing skip reasons (manual_start,
  scheduled_future) and busy printer details (state, connected,
  plate_cleared). Also added DEBUG-level logging in _is_printer_idle()
  for the specific condition that failed.
maziggy 2 kuukautta sitten
vanhempi
sitoutus
0bff20662c
2 muutettua tiedostoa jossa 37 lisäystä ja 1 poistoa
  1. 3 0
      CHANGELOG.md
  2. 34 1
      backend/app/services/print_scheduler.py

+ 3 - 0
CHANGELOG.md

@@ -7,6 +7,9 @@ All notable changes to Bambuddy will be documented in this file.
 ### New Features
 - **AMS Info Card & Custom Labels** ([#570](https://github.com/maziggy/bambuddy/pull/570)) — Hovering an AMS label (e.g. "AMS-A") on the Printers page now shows a popover with serial number, firmware version, and an editable friendly name. Custom labels are stored by AMS serial number so they persist when the unit is moved to a different printer. Slot numbers are now displayed inside each filament color circle with auto-inverted contrast for readability. Labels also appear in the Inventory page's location column. Contributed by @cadtoolbox.
 
+### Improved
+- **Print Queue Scheduler Diagnostics** ([#616](https://github.com/maziggy/bambuddy/issues/616)) — Added diagnostic logging to the print queue scheduler to help diagnose why queued prints aren't starting. After each queue check, the scheduler now logs a skip summary (how many items were skipped due to manual_start, scheduled_time, etc.) and for each busy printer, logs the exact state preventing it from being considered idle (connected status, printer state, plate_cleared flag). Previously the scheduler only logged "found N pending items" with no visibility into why items were skipped.
+
 ### Fixed
 - **Windows: Server Shuts Down After 60 Seconds** ([#605](https://github.com/maziggy/bambuddy/issues/605)) — On Windows, terminating orphaned ffmpeg camera processes broadcast `CTRL_C_EVENT` to the entire process group, causing uvicorn to interpret it as a user-initiated shutdown. ffmpeg is now spawned in its own process group (`CREATE_NEW_PROCESS_GROUP`) so cleanup no longer affects the server. Reported by @Reactantvr.
 

+ 34 - 1
backend/app/services/print_scheduler.py

@@ -78,6 +78,9 @@ class PrintScheduler:
             # Track busy printers to avoid assigning multiple items to same printer
             busy_printers: set[int] = set()
 
+            # Log skip reasons once per queue check (not per item)
+            skip_reasons: dict[str, int] = {}
+
             for item in items:
                 # Check scheduled time first (scheduled_time is stored in UTC from ISO string)
                 if item.scheduled_time:
@@ -85,10 +88,12 @@ class PrintScheduler:
                     if sched.tzinfo is None:
                         sched = sched.replace(tzinfo=timezone.utc)
                     if sched > datetime.now(timezone.utc):
+                        skip_reasons["scheduled_future"] = skip_reasons.get("scheduled_future", 0) + 1
                         continue
 
                 # Skip items that require manual start
                 if item.manual_start:
+                    skip_reasons["manual_start"] = skip_reasons.get("manual_start", 0) + 1
                     continue
 
                 if item.printer_id:
@@ -261,6 +266,24 @@ class PrintScheduler:
                         await self._start_print(db, item)
                         busy_printers.add(printer_id)
 
+            # Log summary of skip reasons (helps diagnose why queue items aren't starting)
+            if skip_reasons:
+                logger.info("Queue skip summary: %s", skip_reasons)
+            if busy_printers:
+                # Log why each printer was busy (first time it was checked)
+                for pid in busy_printers:
+                    state = printer_manager.get_status(pid)
+                    connected = printer_manager.is_connected(pid)
+                    plate_cleared = printer_manager.is_plate_cleared(pid)
+                    state_name = state.state if state else "NO_STATUS"
+                    logger.info(
+                        "Queue: printer %d not available — connected=%s, state=%s, plate_cleared=%s",
+                        pid,
+                        connected,
+                        state_name,
+                        plate_cleared,
+                    )
+
     async def _find_idle_printer_for_model(
         self,
         db: AsyncSession,
@@ -821,17 +844,27 @@ class PrintScheduler:
     def _is_printer_idle(self, printer_id: int) -> bool:
         """Check if a printer is connected and idle."""
         if not printer_manager.is_connected(printer_id):
+            logger.debug("Printer %d: not connected", printer_id)
             return False
 
         state = printer_manager.get_status(printer_id)
         if not state:
+            logger.debug("Printer %d: no status available", printer_id)
             return False
 
         # IDLE = ready for next print
         # FINISH/FAILED = ready only if user confirmed plate is cleared
-        return state.state == "IDLE" or (
+        idle = state.state == "IDLE" or (
             state.state in ("FINISH", "FAILED") and printer_manager.is_plate_cleared(printer_id)
         )
+        if not idle:
+            logger.debug(
+                "Printer %d: not idle — state=%s, plate_cleared=%s",
+                printer_id,
+                state.state,
+                printer_manager.is_plate_cleared(printer_id),
+            )
+        return idle
 
     async def _get_smart_plug(self, db: AsyncSession, printer_id: int) -> SmartPlug | None:
         """Get the smart plug associated with a printer."""