"""The queue's per-printer summary says which fact took a printer out of the pass (#3018). ``busy_printers`` holds two opposite things: printers that cannot take work, and printers this pass has claimed *for* work. The old summary called every one of them "not available" and printed printer state read at log time rather than the state the decision was made on. #3018's bundle shows both faults landing at once:: Queue: printer 1 not available — connected=True, state=IDLE, awaiting_plate_clear=False Launching 1 upload(s) (pool 0/4 in flight) Starting queue item 18 That is the first line anyone greps when asking why an item did not go out, and there it is, on the printer that just received one. The dispatch in that trace is correct and these tests pin it as such: a print scheduled for later does not reserve the printer, so an unscheduled item behind it runs while the printer is free. Only the reporting changed. """ import asyncio import logging from contextlib import ExitStack, asynccontextmanager from datetime import datetime, timedelta, timezone from pathlib import Path from types import SimpleNamespace from unittest.mock import AsyncMock, MagicMock, patch import pytest from sqlalchemy.ext.asyncio import async_sessionmaker, create_async_engine import backend.app.models # noqa: F401 - populate Base.metadata import backend.app.services.archive as archive_module import backend.app.services.print_scheduler as scheduler_module from backend.app.core.database import Base from backend.app.models.archive import PrintArchive from backend.app.models.print_queue import PrintQueueItem from backend.app.models.printer import Printer from backend.app.services.print_scheduler import PrintScheduler SCHEDULER_LOGGER = "backend.app.services.print_scheduler" @pytest.fixture async def one_printer(tmp_path): """One printer, and a factory for the queue items a test needs on it.""" 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, expire_on_commit=False) base_dir = tmp_path / "farm" (base_dir / "archives").mkdir(parents=True, exist_ok=True) async with session_maker() as db: printer = Printer( name="Printer", serial_number="SERIAL", ip_address="10.0.0.1", access_code="access-code", model="X1C", ) db.add(printer) await db.flush() printer_id = printer.id await db.commit() async def add_item(*, scheduled_in: timedelta | None = None, status: str = "pending", position: int = 0): async with session_maker() as db: archive_rel = Path("archives") / f"job-{position}.3mf" (base_dir / archive_rel).write_bytes(b"archive payload") archive = PrintArchive( printer_id=printer_id, filename=f"job-{position}.3mf", file_path=str(archive_rel), file_size=15, print_time_seconds=120, status="completed", ) db.add(archive) await db.flush() item = PrintQueueItem( printer_id=printer_id, archive_id=archive.id, status=status, position=position, scheduled_time=(datetime.now(timezone.utc) + scheduled_in) if scheduled_in else None, ) db.add(item) await db.commit() return item.id try: yield SimpleNamespace( session_maker=session_maker, base_dir=base_dir, printer_id=printer_id, add_item=add_item, ) finally: await engine.dispose() @asynccontextmanager async def _scheduler(ctx, *, idle: bool): scheduler = PrintScheduler() def _real_spawn(coro, *, name=None): return asyncio.create_task(coro, name=name) patches = [ patch.object(scheduler_module.settings, "base_dir", ctx.base_dir), patch.object(archive_module.settings, "base_dir", ctx.base_dir), patch.object(archive_module.settings, "archive_dir", ctx.base_dir / "archive"), patch("backend.app.services.print_scheduler.async_session", ctx.session_maker), patch("backend.app.core.database.async_session", ctx.session_maker), patch("backend.app.services.print_scheduler.printer_manager.is_connected", MagicMock(return_value=True)), patch( "backend.app.services.print_scheduler.printer_manager.get_status", MagicMock( return_value=SimpleNamespace(state="IDLE" if idle else "RUNNING", subtask_id=None, gcode_file=None) ), ), patch( "backend.app.services.print_scheduler.printer_manager.is_awaiting_plate_clear", MagicMock(return_value=False), ), patch("backend.app.services.print_scheduler.printer_manager.start_print", MagicMock(return_value=True)), patch("backend.app.services.print_scheduler.printer_manager.set_awaiting_plate_clear", MagicMock()), patch("backend.app.services.print_scheduler.upload_file_async", AsyncMock(return_value=True)), patch("backend.app.services.print_scheduler.delete_file_async", AsyncMock(return_value=True)), patch( "backend.app.services.print_scheduler.get_ftp_retry_settings", AsyncMock(return_value=(False, 0, 0, 1.0)), ), patch("backend.app.services.print_scheduler.cache_3mf_download", MagicMock()), patch("backend.app.services.print_scheduler.spawn_background_task", _real_spawn), patch( "backend.app.services.notification_service.notification_service.on_queue_job_started", AsyncMock(), ), patch( "backend.app.services.notification_service.notification_service.on_queue_job_failed", AsyncMock(), ), patch("backend.app.services.mqtt_relay.mqtt_relay.on_queue_job_started", AsyncMock()), patch.object(scheduler, "_is_printer_idle", MagicMock(return_value=idle)), patch.object(scheduler, "_propagate_owner_to_printer_manager", AsyncMock()), patch.object(scheduler, "_power_off_if_needed", AsyncMock()), patch.object(scheduler, "_preheat_and_soak", AsyncMock()), patch.object(scheduler, "_check_auto_drying", AsyncMock()), patch.object(scheduler, "_watchdog_print_start", AsyncMock()), ] with ExitStack() as stack: for patcher in patches: stack.enter_context(patcher) yield scheduler tasks = [task for (task, _pid) in scheduler._inflight.values()] if tasks: await asyncio.gather(*tasks, return_exceptions=True) def _printer_lines(caplog) -> list[str]: return [r.getMessage() for r in caplog.records if r.getMessage().startswith("Queue: printer")] class TestAPrinterTheQueueIsUsing: """#3018's trace: an item goes out, and the summary must not call that unavailable.""" @pytest.mark.asyncio async def test_a_reserved_printer_is_not_called_unavailable(self, one_printer, caplog): await one_printer.add_item(scheduled_in=timedelta(hours=6), position=0) await one_printer.add_item(position=1) with caplog.at_level(logging.INFO, logger=SCHEDULER_LOGGER): async with _scheduler(one_printer, idle=True) as scheduler: await scheduler.check_queue() lines = _printer_lines(caplog) assert len(lines) == 1, f"expected one line for the one printer, got {lines}" assert "reserved" in lines[0] assert "selected for dispatch in this pass" in lines[0] assert "unavailable" not in lines[0], ( "the printer that just received the item must not be reported as unable to take one" ) @pytest.mark.asyncio async def test_the_scheduled_item_stays_behind_and_the_other_goes(self, one_printer, caplog): """The behaviour #3018 reported as the bug. It is the intended one. A print scheduled for later does not hold the printer until then -- it is skipped as 'scheduled_future' while an unscheduled item uses the idle printer. Pinned here because the report turned on the label, not on this. """ scheduled_id = await one_printer.add_item(scheduled_in=timedelta(hours=6), position=0) queued_id = await one_printer.add_item(position=1) with caplog.at_level(logging.INFO, logger=SCHEDULER_LOGGER): async with _scheduler(one_printer, idle=True) as scheduler: await scheduler.check_queue() assert any("'scheduled_future': 1" in r.getMessage() for r in caplog.records) async with one_printer.session_maker() as db: assert (await db.get(PrintQueueItem, scheduled_id)).status == "pending" assert (await db.get(PrintQueueItem, queued_id)).status != "pending" class TestAPrinterThatCannotTakeWork: """The other half of the set still reports, and now says which fact stopped it.""" @pytest.mark.asyncio async def test_an_unavailable_printer_names_the_reason(self, one_printer, caplog): await one_printer.add_item(position=0) with caplog.at_level(logging.INFO, logger=SCHEDULER_LOGGER): async with _scheduler(one_printer, idle=False) as scheduler: await scheduler.check_queue() lines = _printer_lines(caplog) assert len(lines) == 1, f"expected one line, got {lines}" assert "unavailable" in lines[0] assert "not idle" in lines[0] assert "reserved" not in lines[0] @pytest.mark.asyncio async def test_the_live_fields_are_labelled_as_read_now(self, one_printer, caplog): """They stay, because a bundle reader wants them -- but not as the reason. The old line offered them as the explanation, which is how it came to print state=IDLE under the heading 'not available'. """ await one_printer.add_item(position=0) with caplog.at_level(logging.INFO, logger=SCHEDULER_LOGGER): async with _scheduler(one_printer, idle=False) as scheduler: await scheduler.check_queue() line = _printer_lines(caplog)[0] assert "(now: connected=True" in line assert line.index("not idle") < line.index("now:"), "the recorded reason leads, the live read follows" @pytest.mark.asyncio async def test_two_items_on_one_printer_report_once(self, one_printer, caplog): """One line per printer, not per item it turned away.""" await one_printer.add_item(position=0) await one_printer.add_item(position=1) with caplog.at_level(logging.INFO, logger=SCHEDULER_LOGGER): async with _scheduler(one_printer, idle=False) as scheduler: await scheduler.check_queue() assert len(_printer_lines(caplog)) == 1