Procházet zdrojové kódy

fix(queue): prevent duplicate dispatch and stale progress on batch prints

  Two related queue issues surfaced when scheduling an ASAP print with
  quantity > 1 on an H2D:

  1. Double-dispatch — both items in the batch ended up in 'printing'
     status on the same printer, logged as "BUG: Multiple queue items in
     'printing' status for printer N". The scheduler seeded its busy
     set empty each tick and relied on _is_printer_idle() reading live
     MQTT state, but H2D / P1 series lag several seconds between the
     print command and IDLE → RUNNING, so the next check_queue() tick
     saw IDLE and dispatched the second batch item onto the already-
     running printer. check_queue() now seeds busy_printers with every
     printer_id that has a row in 'printing' status before iterating,
     so any printer with an outstanding dispatched job is excluded
     regardless of what MQTT currently reports.

  2. Progress bar flashed 100% — immediately after dispatch the queue
     item's per-row progress bar showed the prior print's final mc_percent
     for a few seconds, then snapped back to 0% when the new print
     started ticking. QueuePage.tsx now gates progress / remaining_time /
     layer fields on status.state being RUNNING or PAUSE; in any other
     state (FINISH from the prior print, IDLE, PREPARE while heating)
     the bar renders at 0% with no stale ETA or layer count.

  Regression coverage added in test_phantom_print_hardening.py
  (TestBusyPrinterSeedingFromPrintingItems, 3 tests): seeding query
  returns only printers with 'printing' rows, empty when none exist,
  and end-to-end check_queue() does not call _start_print for a pending
  item whose printer already has a 'printing' row even when
  _is_printer_idle() is forced True.
maziggy před 1 měsícem
rodič
revize
950286ad40

+ 14 - 2
backend/app/services/print_scheduler.py

@@ -134,8 +134,20 @@ class PrintScheduler:
                 [(i.id, i.printer_id, i.archive_id, i.library_file_id) for i in items],
             )
 
-            # Track busy printers to avoid assigning multiple items to same printer
-            busy_printers: set[int] = set()
+            # Seed busy_printers with printers that already have an item in 'printing'
+            # status. _is_printer_idle() alone is not sufficient as a dispatch gate —
+            # on H2D / P1 series the MQTT state transition from IDLE to RUNNING can
+            # lag several seconds behind the print command, so the next check_queue
+            # tick still sees IDLE and would double-dispatch onto the same printer.
+            # Without this guard, two pending items targeting the same printer
+            # (e.g. a batch with quantity>1) both end up in 'printing' status —
+            # surfaced via the "BUG: Multiple queue items" warning in on_print_complete.
+            busy_result = await db.execute(
+                select(PrintQueueItem.printer_id)
+                .where(PrintQueueItem.status == "printing")
+                .where(PrintQueueItem.printer_id.is_not(None))
+            )
+            busy_printers: set[int] = {pid for (pid,) in busy_result.all() if pid is not None}
 
             # Log skip reasons once per queue check (not per item)
             skip_reasons: dict[str, int] = {}

+ 137 - 0
backend/tests/unit/test_phantom_print_hardening.py

@@ -209,3 +209,140 @@ class TestMultiplePrintingQueueItemsWarning:
         bug_warnings = [r for r in caplog.records if "BUG: Multiple queue items" in r.message]
         assert len(bug_warnings) == 1
         assert "printer 7" in bug_warnings[0].message
+
+
+class TestBusyPrinterSeedingFromPrintingItems:
+    """Regression for the duplicate-dispatch bug observed with quantity>1 batches.
+
+    The old scheduler seeded ``busy_printers`` with an empty set and relied on
+    ``_is_printer_idle()`` to gate dispatch. On H2D / P1 series the MQTT state
+    lags several seconds behind the print command, so the next ``check_queue``
+    tick saw IDLE and dispatched a second queue item onto the same printer —
+    both items ended up in 'printing' status. The fix seeds ``busy_printers``
+    up-front with every printer that already has an item in 'printing' status.
+    """
+
+    @pytest.mark.asyncio
+    async def test_seed_query_returns_printers_with_printing_items(self):
+        """The seeding query must return every printer_id that has a 'printing' item."""
+        from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker, create_async_engine
+
+        import backend.app.models  # noqa: F401
+        from backend.app.core.database import Base
+        from backend.app.models.print_queue import PrintQueueItem
+
+        engine = create_async_engine("sqlite+aiosqlite:///:memory:", echo=False)
+        async with engine.begin() as conn:
+            await conn.run_sync(Base.metadata.create_all)
+        session_maker = async_sessionmaker(engine, class_=AsyncSession, expire_on_commit=False)
+
+        async with session_maker() as db:
+            db.add_all(
+                [
+                    PrintQueueItem(printer_id=1, status="printing", position=1, archive_id=10),
+                    PrintQueueItem(printer_id=1, status="pending", position=2, archive_id=10),
+                    PrintQueueItem(printer_id=2, status="printing", position=1, archive_id=11),
+                    PrintQueueItem(printer_id=3, status="pending", position=1, archive_id=12),
+                    PrintQueueItem(printer_id=None, status="pending", position=1, archive_id=13),
+                ]
+            )
+            await db.commit()
+
+            result = await db.execute(
+                select(PrintQueueItem.printer_id)
+                .where(PrintQueueItem.status == "printing")
+                .where(PrintQueueItem.printer_id.is_not(None))
+            )
+            busy_printers = {pid for (pid,) in result.all() if pid is not None}
+
+        assert busy_printers == {1, 2}
+
+        await engine.dispose()
+
+    @pytest.mark.asyncio
+    async def test_seed_query_empty_when_no_printing_items(self):
+        """With only pending items, no printer is considered busy by the query."""
+        from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker, create_async_engine
+
+        import backend.app.models  # noqa: F401
+        from backend.app.core.database import Base
+        from backend.app.models.print_queue import PrintQueueItem
+
+        engine = create_async_engine("sqlite+aiosqlite:///:memory:", echo=False)
+        async with engine.begin() as conn:
+            await conn.run_sync(Base.metadata.create_all)
+        session_maker = async_sessionmaker(engine, class_=AsyncSession, expire_on_commit=False)
+
+        async with session_maker() as db:
+            db.add_all(
+                [
+                    PrintQueueItem(printer_id=1, status="pending", position=1, archive_id=10),
+                    PrintQueueItem(printer_id=2, status="completed", position=1, archive_id=11),
+                    PrintQueueItem(printer_id=3, status="failed", position=1, archive_id=12),
+                    PrintQueueItem(printer_id=4, status="cancelled", position=1, archive_id=13),
+                ]
+            )
+            await db.commit()
+
+            result = await db.execute(
+                select(PrintQueueItem.printer_id)
+                .where(PrintQueueItem.status == "printing")
+                .where(PrintQueueItem.printer_id.is_not(None))
+            )
+            busy_printers = {pid for (pid,) in result.all() if pid is not None}
+
+        assert busy_printers == set()
+
+        await engine.dispose()
+
+    @pytest.mark.asyncio
+    async def test_check_queue_skips_printer_with_existing_printing_item(self, caplog):
+        """Simulate the exact observed bug: a pending item targets a printer that already
+        has another queue item in 'printing' status. The scheduler must NOT dispatch the
+        pending item even if the live MQTT state reports IDLE.
+        """
+        from unittest.mock import AsyncMock, patch
+
+        from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker, create_async_engine
+
+        import backend.app.models  # noqa: F401
+        from backend.app.core.database import Base
+        from backend.app.models.print_queue import PrintQueueItem
+        from backend.app.services.print_scheduler import PrintScheduler
+
+        engine = create_async_engine("sqlite+aiosqlite:///:memory:", echo=False)
+        async with engine.begin() as conn:
+            await conn.run_sync(Base.metadata.create_all)
+        session_maker = async_sessionmaker(engine, class_=AsyncSession, expire_on_commit=False)
+
+        async with session_maker() as db:
+            db.add_all(
+                [
+                    PrintQueueItem(printer_id=1, status="printing", position=1, archive_id=84),
+                    PrintQueueItem(printer_id=1, status="pending", position=2, archive_id=84),
+                ]
+            )
+            await db.commit()
+
+        scheduler = PrintScheduler()
+        start_print_mock = AsyncMock()
+
+        with (
+            patch("backend.app.services.print_scheduler.async_session", session_maker),
+            patch.object(scheduler, "_get_bool_setting", AsyncMock(return_value=False)),
+            patch.object(scheduler, "_is_printer_idle", return_value=True),
+            patch.object(scheduler, "_check_auto_drying", AsyncMock()),
+            patch.object(scheduler, "_start_print", start_print_mock),
+            patch("backend.app.services.print_scheduler.printer_manager") as mock_pm,
+        ):
+            mock_pm.is_connected.return_value = True
+            await scheduler.check_queue()
+
+        start_print_mock.assert_not_called()
+
+        async with session_maker() as db:
+            rows = (await db.execute(select(PrintQueueItem).order_by(PrintQueueItem.position))).scalars().all()
+            statuses = [r.status for r in rows]
+        assert statuses == ["printing", "pending"]
+
+        await engine.dispose()

+ 39 - 28
frontend/src/pages/QueuePage.tsx

@@ -558,38 +558,49 @@ function SortableQueueItem({
           </div>
 
           {/* Progress bar for printing items - TODO: integrate with WebSocket */}
-          {isPrinting && status && (
-            <div className="mt-2 sm:mt-3">
-              <div className="flex items-center justify-between text-xs sm:text-sm">
-                <div className="flex-1 bg-bambu-dark-tertiary rounded-full h-1.5 sm:h-2 mr-3">
-                  <div
-                    className="bg-bambu-green h-1.5 sm:h-2 rounded-full transition-all"
-                    style={{ width: `${status.progress || 0}%` }}
-                  />
+          {isPrinting && status && (() => {
+            // Gate progress/remaining/layer on printer actually running this print.
+            // Between dispatch and RUNNING transition (H2D/P1 MQTT lag), status.progress
+            // is stale from the previous print — showing 100% then snapping back to 0%
+            // once the new print starts. Only trust these fields when state is active.
+            const isActive = status.state === 'RUNNING' || status.state === 'PAUSE';
+            const progress = isActive ? (status.progress || 0) : 0;
+            const remaining = isActive ? status.remaining_time : null;
+            const layerNum = isActive ? status.layer_num : null;
+            const totalLayers = isActive ? status.total_layers : null;
+            return (
+              <div className="mt-2 sm:mt-3">
+                <div className="flex items-center justify-between text-xs sm:text-sm">
+                  <div className="flex-1 bg-bambu-dark-tertiary rounded-full h-1.5 sm:h-2 mr-3">
+                    <div
+                      className="bg-bambu-green h-1.5 sm:h-2 rounded-full transition-all"
+                      style={{ width: `${progress}%` }}
+                    />
+                  </div>
+                  <span className="text-white">{Math.round(progress)}%</span>
                 </div>
-                <span className="text-white">{Math.round(status.progress || 0)}%</span>
-              </div>
-              <div className="flex flex-wrap items-center gap-2 sm:gap-3 mt-1.5 sm:mt-2 text-[10px] sm:text-xs text-bambu-gray">
-                {status.remaining_time != null && status.remaining_time > 0 && (
-                  <>
+                <div className="flex flex-wrap items-center gap-2 sm:gap-3 mt-1.5 sm:mt-2 text-[10px] sm:text-xs text-bambu-gray">
+                  {remaining != null && remaining > 0 && (
+                    <>
+                      <span className="flex items-center gap-1">
+                        <Clock className="w-3 h-3" />
+                        {formatDuration(remaining * 60)}
+                      </span>
+                      <span className="text-bambu-green font-medium" title={t('printers.estimatedCompletion')}>
+                        ETA {formatETA(remaining, timeFormat, t)}
+                      </span>
+                    </>
+                  )}
+                  {layerNum != null && totalLayers != null && totalLayers > 0 && (
                     <span className="flex items-center gap-1">
-                      <Clock className="w-3 h-3" />
-                      {formatDuration(status.remaining_time * 60)}
+                      <Layers className="w-3 h-3" />
+                      {layerNum}/{totalLayers}
                     </span>
-                    <span className="text-bambu-green font-medium" title={t('printers.estimatedCompletion')}>
-                      ETA {formatETA(status.remaining_time, timeFormat, t)}
-                    </span>
-                  </>
-                )}
-                {status.layer_num != null && status.total_layers != null && status.total_layers > 0 && (
-                  <span className="flex items-center gap-1">
-                    <Layers className="w-3 h-3" />
-                    {status.layer_num}/{status.total_layers}
-                  </span>
-                )}
+                  )}
+                </div>
               </div>
-            </div>
-          )}
+            );
+          })()}
 
           {/* Waiting reason for model-based assignments */}
           {item.waiting_reason && item.status === 'pending' && (