diff --git a/CHANGELOG.md b/CHANGELOG.md index 4ff21a802..51231554e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,6 +13,7 @@ All notable changes to Bambuddy will be documented in this file. - **Prints on a multi-printer farm started one by one, up to an hour apart (#2555, reporter @Maxtrim3D)** — Start a batch across several printers and they trickle out one at a time; the more printers, the worse it gets. Not a misconfiguration, and nothing in the wiki could have helped: the scheduler awaited each dispatch inline in its selection loop, and a dispatch includes the FTP upload. So every printer queued behind every other printer's transfer, even though they are entirely independent machines. **The arithmetic is the whole bug report.** A Bambu printer's FTP server sustains around 150 KB/s — its own SD-card write is the bottleneck, not the network — so the reporter's 41 MB `.3mf` took **254 seconds per printer**, straight from his logs (`40978500 bytes in 254.1s, 157 KB/s`). Nineteen printers in series is roughly **80 minutes** before the last one starts, which is exactly the "up to 1 hour" he reported, and exactly why it got worse the more printers he selected — the delay is linear in fleet size. The logs show the next upload beginning **131 ms** after the previous one finished, back to back, forever. **Uploads to different printers now run concurrently**, capped by a new **Settings → Workflow → Queue & Dispatch → Concurrent Uploads** value (default 4, up to 16; set it to 1 for the old strictly-serial behaviour if your network or host cannot take parallel transfers). Selection is unchanged and still sequential — only the transfers overlap — so every existing gate (busy printers, plate-clear, filament deficit, shortest-job-first, staggered start) behaves exactly as before, and a queue pass still finishes all of its uploads before the next one begins, which is what stops the same still-`pending` row being dispatched twice. FTP work also moves off asyncio's shared default executor onto its own pool: that executor is sized `min(32, cpu_count + 4)` — six threads on a 2-core NAS — and is shared with everything else in the app, so parallel uploads would have parked one thread each, for minutes at a time, and starved unrelated work. - **A printer that accepted a file but never started printing was retried forever (#2555)** — Surfaced by the same reporter: "I have a printer who, since the morning, still not launch." When a printer takes the file (its `subtask_id` advances) but never actually begins, the start-watchdog waits 270 seconds, reverts the queue item to `pending`, and the next pass re-uploads the entire file and waits it out again — with **no attempt limit**. For a genuinely wedged printer that loop never terminates, and on a farm each lap also consumes an upload slot the other printers are queueing for, so one stuck machine dragged out everybody else's start times. Retrying is right; retrying forever is not. Attempts are now counted on the queue item: the transient causes the watchdog already recovers from (a publish lost on a half-broken MQTT session is fixed by the forced reconnect on the very next try) still get their retries, but after **three** the item is failed with a message pointing at the printer — check its screen for a prompt or error, and check the SD card — rather than being handed back to the queue a fourth time. - **A queued library print with no readable print time crashed the dispatch — and took the rest of that queue pass down with it (#2555)** — Found while reviewing the above. Starting a print from a library file read `library_file.print_time_seconds`, a column `LibraryFile` does not have (its print time lives in the file's parsed metadata). It only fired when the archive carried no print time of its own — a plain `.gcode`, or a 3MF the parser could not read — and it fired *after* the job had already been sent to the printer, so the print itself ran but the "print started" notification was lost. Worse, the error unwound the whole queue pass: every other printer still waiting to be dispatched on that tick silently missed its turn and had to wait for the next one. It now uses the print time the queue item already caches. The concurrent-dispatch change above independently contains this class of failure — one printer's dispatch blowing up can no longer cancel its siblings' in-flight uploads. +- **Every job on a busy farm waited up to 30 seconds after a printer freed up before it was sent (#2555, reporter @Maxtrim3D)** — With the parallel-upload fix in, the reporter still saw prints take "several long minutes" to leave the queue, sometimes going out together and sometimes in dribs. The scheduler's main loop did its work and then slept a **fixed 30 seconds** before looking again, unconditionally. That interval is dead air: a printer that finished a job one second after a pass ended sat idle for the next 29 before its follow-on print was even considered, and a batch fanning out across a fleet — where printers free up a few seconds apart as their current jobs end — dispatched in 30-second steps regardless of how fast the machines were actually becoming available. On nineteen printers that is minutes of nobody-is-uploading time stacked on top of the transfers. The loop now **re-checks within a few seconds whenever the previous pass actually dispatched something**, and only falls back to the 30-second idle sleep when a pass sent nothing. So a draining batch keeps moving at the speed the printers free up, not at the speed of a fixed timer. This cannot become a busy-loop: the fast tick fires *only* after a productive pass, and a pass is productive only while there is ready work to send — the moment the remaining items are all behind printers that are genuinely busy printing (or behind a wedged head-of-line job holding its printer in the post-dispatch cooldown), the pass dispatches nothing and the loop reverts to the slow interval. Selection, the concurrency cap, and the finish-all-uploads-before-the-next-pass invariant are all untouched; only the gap between passes shrinks when shrinking it helps. **Tests.** 2 new cases: a pass that dispatches three items reports that it did (so the caller re-ticks fast), and an empty queue reports that it did not (so it sleeps normally). The existing concurrent-dispatch suite — parallel fan-out, the cap, the serial escape hatch, one-failure-doesn't-cancel-siblings, and the uploads-finish-before-return invariant — passes unchanged against the new return value. - **Debug logging was unusable on a large fleet, and the support bundle only shipped a fraction of what was on disk (#2555)** — We asked the reporter to turn on debug logging and send a support bundle. The bundle came back holding **4 minutes 49 seconds** of history — barely one upload — for a problem that takes an hour to unfold. Two causes, both fixed. The state dumps in the MQTT push_status handler fired whenever their field was *present* in a frame, and a full frame carries every field, so they fired on **every frame** regardless of whether anything had changed; several said "updated" or "when X changes" in their own comment while doing nothing of the sort. On one printer that is ~1.5 lines/s and invisible. On nineteen it is ~100 lines/s: **27,727 of the bundle's 29,830 lines** were these dumps, and they rolled the 5 MB log over in under five minutes. They now log transitions only — every change is still recorded, the steady-state repetition is not. Separately, the bundle shipped only the live `bambuddy.log` and ignored the three rotated backups sitting next to it, even though its own byte budget was four times larger than the file it was reading; it now spans the rotation, oldest first, spending the budget on the most recent history. - **Filament Override vanished for a multi-plate selection in Any [model] mode — but only on the second visit (#2552, reporter @bondjw07)** — Open a sliced multi-plate `.gcode.3mf`, pick **Any [model]**, tick two plates, and the whole Filament Override section is gone. Tick one plate and it comes back. The reporter tied it to having queued or printed the file before, which is the real clue, but not the cause: what actually mattered was that the dialog had been opened once already, so the plates data was still in the cache. The filament requirements are fetched under a key that carries the selected plate, and that key is `null` as soon as two plates are ticked. On the first open the plates are not yet known, so for one render the modal cannot tell it is a multi-plate file and fetches the requirements for the whole file — the union of every plate's filaments — which the override panel then rendered from. On the next open the plates are already cached, the modal knows it is multi-plate from the first render, the whole-file fetch therefore never happens, and the panel had nothing to render. So the section's visibility was decided by a cache race, and the case that "worked" was showing you filaments from plates you had not selected. **Both halves are now wrong-free**: a multi-plate selection in model mode renders one **Filament Override — Plate N** panel per selected plate, each fetched for that plate and listing only the slots that plate actually prints, identical on a cold and a warm cache. A slot's chosen filament and its Force color match tick are shared across plates that print that slot — slot ids are global to the file, so slot 3 is the same filament wherever it appears — and each queued plate is sent only the overrides for its own slots, so a colour forced for plate 2 no longer holds plate 1 back (the API narrows them per plate as of #2551, and the modal no longer sends them wide in the first place). Measured on the old code: warm cache, two plates → zero override panels; cold cache → one panel listing both plates' filaments. Now: two panels, one slot each, either way. **Four further holes in the same per-plate machinery closed while reviewing it**: a manual tray pick on one plate survived a change of printer, and a global tray id names a different spool on a different machine — so the job went out on a tray nobody chose; a plate whose filaments could not be read (or had simply not loaded yet) was indistinguishable from a plate needing none, and was queued with no mapping and no forced colours, to print in whatever happened to be loaded — the Print button now waits for every selected plate to answer and says which one could not be read; the "not enough filament left" check still weighed the whole file's filaments against a mapping the plates no longer use, so it either failed to warn at all or warned about trays the print would not touch — it now follows what each plate actually dispatches, and sums the demand per tray, because 60 g left does not cover two plates of 40 g even though it covers either one of them; and the per-printer tray editor still appeared for a multi-plate fan-out, collecting tray choices that were then discarded. - **Queueing several plates of one file mapped them all through the first plate's filaments — and hid the panel that would have shown you (#2551, reporter @bondjw07)** — Select one plate and the Filament Mapping panel appears; select a second and it vanishes, and in **Any [model]** mode it never appears at all. Both were deliberate, and one of them was covering a wrong-tray dispatch. **Why the panel hid.** It maps one set of 3MF slots onto one printer's AMS trays, so it needed a single plate and a single printer; `selectedPlates.size <= 1` hid it the moment you ticked a second plate. In model mode there is no printer selected, so there are no trays to map onto — that one is legitimate, and the scheduler computes the mapping per plate when it picks the printer. **What the hidden panel was hiding.** The modal kept posting an `ams_mapping` anyway. With two plates selected the modal has no single plate to ask about, so it falls back to the whole file's filament list — the **union of every plate** — and matched against that. Tray assignment is stateful: a tray claimed by one slot is not offered to the next. So for a file where plate 1 prints red on slot 1 and plate 2 prints red on slot 2, slot 1 took the only red spool and slot 2 fell through to a type-only match on **black** — and that one mapping, `[red, black]`, was sent with *both* plates. The scheduler uses a stored mapping verbatim and only computes its own when the item has none, so plate 2 printed in the wrong colour, decided by a panel the user was never shown. Measured, not deduced: driving the old modal with a real cache posts `ams_mapping: [0, 1]` for both plates. (It reproduces only with a realistic React Query cache — the test harness's `gcTime: 0` evicts the union and makes the modal look innocent, which is why this hid for so long.) **Now each plate maps itself.** Select several plates on one printer and you get one mapping panel **per plate**, named after it, each showing and mapping only the slots its own plate prints, each with its own tray overrides — pin plate 2's red to a different spool and plate 1 is untouched. Each queue item carries its own plate's mapping. Fanning several plates across several printers would be a panel per plate per printer; those items are queued with **no** mapping instead, and the scheduler maps each plate against the printer it actually dispatches to, which it already does correctly. **One matcher, not three.** The tray-matching logic existed twice (once in the hook, once in `computeAmsMapping`) and this needed a third caller, so it is now extracted once and both paths delegate to it — the per-plate panel and the per-printer fan-out cannot drift apart. Its 62 existing tests pass against the extraction unchanged. **Tests.** 3 on the matcher, pinning the exact divergence: each plate alone maps to the red tray, the union starves the second slot onto black, and a manual override on one plate does not leak into another. 4 on the modal: one panel per selected plate; each plate posts the mapping for its own slots (`[0]` and `[-1, 0]`, not the union's `[0, 1]`); a multi-printer fan-out posts none; a model-assigned job posts none. Mutation-verified against a production-like cache — the per-plate test fails with exactly the old `[0, 1]`, and removing the multi-printer guard leaks printer 1's trays onto printer 2. diff --git a/backend/app/services/print_scheduler.py b/backend/app/services/print_scheduler.py index 837199075..86b3bbe3b 100644 --- a/backend/app/services/print_scheduler.py +++ b/backend/app/services/print_scheduler.py @@ -217,6 +217,17 @@ class PrintScheduler: def __init__(self): self._running = False self._check_interval = 30 # seconds + # After a pass that actually dispatched something, loop again almost + # immediately instead of sleeping the full interval (#2555). A dispatch + # changes printer state — a batch launch fans out over several passes as + # printers free up, a wedged head-of-line job reverts to pending, an + # upload slot opens — and the next batch of ready work should not have to + # wait 30 s behind an idle sleep. When a pass dispatches nothing (all + # pending items are behind printers that are genuinely busy printing), + # there is nothing to react to, so we fall back to the normal interval; + # that also means this can never tight-loop, since fast ticks only + # continue while dispatches keep happening and the queue is draining. + self._fast_check_interval = 3 # seconds self._power_on_wait_time = 180 # seconds to wait for printer after power on (3 min) self._power_on_check_interval = 10 # seconds between connection checks # Track which printers are currently auto-drying (printer_id -> start timestamp) @@ -246,20 +257,27 @@ class PrintScheduler: logger.info("Print scheduler started") while self._running: + dispatched = False try: - await self.check_queue() + dispatched = await self.check_queue() except Exception as e: logger.error("Scheduler error: %s", e) - await asyncio.sleep(self._check_interval) + # Re-check quickly after a productive pass so a draining batch does + # not stall behind the idle interval; otherwise sleep normally (#2555). + await asyncio.sleep(self._fast_check_interval if dispatched else self._check_interval) def stop(self): """Stop the scheduler.""" self._running = False logger.info("Print scheduler stopped") - async def check_queue(self): - """Check for prints ready to start.""" + async def check_queue(self) -> bool: + """Check for prints ready to start. + + Returns True if this pass dispatched at least one item, so the caller + can loop again quickly instead of sleeping the full interval (#2555). + """ async with async_session() as db: # Check if shortest-job-first scheduling is enabled sjf_enabled = await self._get_bool_setting(db, "queue_shortest_first") @@ -300,7 +318,7 @@ class PrintScheduler: if not items: # No pending items — still check auto-drying on idle printers await self._check_auto_drying(db, [], set(), require_plate_clear=require_plate_clear) - return + return False logger.info( "Queue check: found %d pending items: %s", @@ -710,6 +728,8 @@ class PrintScheduler: # Auto-drying: start drying on idle printers that have no pending queue items await self._check_auto_drying(db, items, busy_printers, require_plate_clear=require_plate_clear) + return bool(dispatch_ids) + async def _dispatch_selected(self, item_ids: list[int], limit: int) -> None: """Upload and start every item selected by this queue pass, in parallel. diff --git a/backend/tests/unit/test_scheduler_concurrent_dispatch.py b/backend/tests/unit/test_scheduler_concurrent_dispatch.py index 409195e37..cf6894293 100644 --- a/backend/tests/unit/test_scheduler_concurrent_dispatch.py +++ b/backend/tests/unit/test_scheduler_concurrent_dispatch.py @@ -177,7 +177,7 @@ async def _run_check_queue(ctx, upload, job_started=None): with ExitStack() as stack: for patcher in patches: stack.enter_context(patcher) - await scheduler.check_queue() + return await scheduler.check_queue() async def _statuses(ctx): @@ -269,6 +269,30 @@ async def test_one_failing_upload_does_not_cancel_the_others(farm): ) +@pytest.mark.asyncio +async def test_check_queue_reports_it_dispatched(farm): + """A productive pass returns True so ``run()`` re-checks quickly (#2555). + + The fast re-tick is what stops a draining batch from stalling 30 s behind + the idle sleep every time a printer frees up. + """ + ctx = await farm(3, max_concurrent=3) + + dispatched = await _run_check_queue(ctx, _UploadRecorder()) + + assert dispatched is True, "check_queue dispatched 3 items but did not report it" + + +@pytest.mark.asyncio +async def test_check_queue_reports_nothing_dispatched_when_empty(farm): + """An empty queue returns False so ``run()`` falls back to the idle interval.""" + ctx = await farm(0, max_concurrent=3) + + dispatched = await _run_check_queue(ctx, _UploadRecorder()) + + assert dispatched is False, "an empty pass must not trigger a fast re-tick" + + @pytest.mark.asyncio async def test_check_queue_awaits_its_dispatches_before_returning(farm): """The pass must not return while uploads are still in flight.