mirror of
https://github.com/maziggy/bambuddy.git
synced 2026-10-04 05:01:37 +02:00
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.
This commit is contained in:
maziggy
@@ -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] = {}
|
||||
|
||||
@@ -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()
|
||||
|
||||
@@ -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' && (
|
||||
|
||||
File diff suppressed because one or more lines are too long
Reference in New Issue
Block a user