| 12345678910111213141516171819202122232425262728293031323334353637383940414243444546474849505152535455565758596061626364656667686970717273747576777879808182838485868788899091929394959697989910010110210310410510610710810911011111211311411511611711811912012112212312412512612712812913013113213313413513613713813914014114214314414514614714814915015115215315415515615715815916016116216316416516616716816917017117217317417517617717817918018118218318418518618718818919019119219319419519619719819920020120220320420520620720820921021121221321421521621721821922022122222322422522622722822923023123223323423523623723823924024124224324424524624724824925025125225325425525625725825926026126226326426526626726826927027127227327427527627727827928028128228328428528628728828929029129229329429529629729829930030130230330430530630730830931031131231331431531631731831932032132232332432532632732832933033133233333433533633733833934034134234334434534634734834935035135235335435535635735835936036136236336436536636736836937037137237337437537637737837938038138238338438538638738838939039139239339439539639739839940040140240340440540640740840941041141241341441541641741841942042142242342442542642742842943043143243343443543643743843944044144244344444544644744844945045145245345445545645745845946046146246346446546646746846947047147247347447547647747847948048148248348448548648748848949049149249349449549649749849950050150250350450550650750850951051151251351451551651751851952052152252352452552652752852953053153253353453553653753853954054154254354454554654754854955055155255355455555655755855956056156256356456556656756856957057157257357457557657757857958058158258358458558658758858959059159259359459559659759859960060160260360460560660760860961061161261361461561661761861962062162262362462562662762862963063163263363463563663763863964064164264364464564664764864965065165265365465565665765865966066166266366466566666766866967067167267367467567667767867968068168268368468568668768868969069169269369469569669769869970070170270370470570670770870971071171271371471571671771871972072172272372472572672772872973073173273373473573673773873974074174274374474574674774874975075175275375475575675775875976076176276376476576676776876977077177277377477577677777877978078178278378478578678778878979079179279379479579679779879980080180280380480580680780880981081181281381481581681781881982082182282382482582682782882983083183283383483583683783883984084184284384484584684784884985085185285385485585685785885986086186286386486586686786886987087187287387487587687787887988088188288388488588688788888989089189289389489589689789889990090190290390490590690790890991091191291391491591691791891992092192292392492592692792892993093193293393493593693793893994094194294394494594694794894995095195295395495595695795895996096196296396496596696796896997097197297397497597697797897998098198298398498598698798898999099199299399499599699799899910001001100210031004100510061007100810091010101110121013101410151016101710181019102010211022102310241025102610271028102910301031103210331034103510361037103810391040104110421043104410451046104710481049105010511052105310541055105610571058105910601061106210631064106510661067106810691070107110721073107410751076107710781079108010811082108310841085108610871088108910901091109210931094109510961097109810991100110111021103110411051106110711081109111011111112111311141115111611171118111911201121112211231124112511261127112811291130113111321133113411351136113711381139114011411142114311441145114611471148114911501151115211531154115511561157115811591160116111621163116411651166116711681169117011711172117311741175117611771178117911801181118211831184118511861187118811891190119111921193119411951196119711981199120012011202120312041205120612071208120912101211121212131214121512161217121812191220122112221223122412251226122712281229123012311232123312341235123612371238123912401241124212431244124512461247124812491250125112521253125412551256125712581259126012611262126312641265126612671268126912701271127212731274127512761277127812791280128112821283128412851286128712881289129012911292129312941295129612971298129913001301130213031304130513061307130813091310131113121313131413151316131713181319132013211322132313241325132613271328132913301331133213331334133513361337133813391340134113421343134413451346134713481349135013511352135313541355135613571358135913601361136213631364136513661367136813691370137113721373137413751376137713781379138013811382138313841385138613871388138913901391139213931394139513961397139813991400140114021403140414051406140714081409141014111412141314141415141614171418141914201421142214231424142514261427142814291430143114321433143414351436143714381439144014411442144314441445144614471448144914501451145214531454145514561457145814591460146114621463146414651466146714681469147014711472147314741475147614771478147914801481148214831484148514861487148814891490149114921493149414951496149714981499150015011502150315041505150615071508150915101511151215131514151515161517151815191520152115221523152415251526152715281529153015311532153315341535153615371538153915401541154215431544154515461547154815491550155115521553155415551556155715581559156015611562156315641565156615671568156915701571157215731574157515761577157815791580158115821583158415851586158715881589159015911592159315941595159615971598159916001601160216031604160516061607160816091610161116121613161416151616161716181619162016211622162316241625162616271628162916301631163216331634163516361637163816391640164116421643164416451646164716481649165016511652165316541655165616571658165916601661166216631664166516661667166816691670167116721673167416751676167716781679168016811682168316841685168616871688168916901691169216931694169516961697169816991700170117021703170417051706170717081709171017111712171317141715171617171718171917201721172217231724172517261727172817291730173117321733173417351736173717381739174017411742174317441745174617471748174917501751175217531754175517561757175817591760176117621763176417651766176717681769177017711772177317741775177617771778177917801781178217831784178517861787178817891790179117921793179417951796179717981799180018011802180318041805180618071808180918101811181218131814181518161817181818191820182118221823182418251826182718281829183018311832183318341835183618371838183918401841184218431844184518461847184818491850185118521853185418551856185718581859186018611862186318641865186618671868186918701871187218731874187518761877187818791880188118821883188418851886188718881889189018911892189318941895189618971898189919001901190219031904190519061907190819091910191119121913191419151916191719181919192019211922192319241925192619271928192919301931193219331934193519361937193819391940194119421943194419451946194719481949195019511952195319541955195619571958195919601961196219631964196519661967196819691970197119721973197419751976197719781979198019811982198319841985198619871988198919901991199219931994199519961997199819992000200120022003200420052006200720082009201020112012201320142015201620172018201920202021202220232024202520262027202820292030203120322033203420352036203720382039204020412042204320442045204620472048204920502051205220532054205520562057205820592060206120622063206420652066206720682069207020712072207320742075207620772078207920802081208220832084208520862087208820892090209120922093209420952096209720982099210021012102210321042105210621072108210921102111211221132114211521162117211821192120212121222123212421252126212721282129213021312132213321342135213621372138213921402141214221432144214521462147214821492150215121522153215421552156215721582159216021612162216321642165216621672168216921702171217221732174217521762177217821792180218121822183218421852186218721882189219021912192219321942195219621972198219922002201220222032204220522062207220822092210221122122213221422152216221722182219222022212222222322242225222622272228222922302231223222332234223522362237223822392240224122422243224422452246224722482249225022512252225322542255225622572258225922602261226222632264226522662267226822692270227122722273227422752276227722782279228022812282228322842285228622872288228922902291229222932294229522962297229822992300230123022303230423052306230723082309231023112312231323142315231623172318231923202321232223232324232523262327232823292330233123322333233423352336233723382339234023412342234323442345234623472348234923502351235223532354235523562357235823592360236123622363236423652366236723682369237023712372237323742375237623772378237923802381238223832384238523862387238823892390239123922393239423952396239723982399240024012402240324042405240624072408240924102411241224132414241524162417241824192420242124222423242424252426242724282429243024312432243324342435243624372438243924402441244224432444244524462447244824492450245124522453245424552456245724582459246024612462246324642465246624672468246924702471247224732474247524762477247824792480248124822483248424852486248724882489249024912492249324942495249624972498249925002501250225032504250525062507250825092510251125122513251425152516251725182519252025212522252325242525252625272528252925302531253225332534253525362537253825392540254125422543254425452546254725482549255025512552255325542555255625572558255925602561256225632564256525662567256825692570257125722573257425752576257725782579258025812582258325842585258625872588258925902591259225932594259525962597259825992600260126022603260426052606260726082609261026112612261326142615261626172618261926202621262226232624262526262627262826292630263126322633263426352636263726382639264026412642264326442645264626472648264926502651265226532654265526562657265826592660266126622663266426652666266726682669267026712672267326742675267626772678267926802681268226832684268526862687268826892690269126922693269426952696269726982699270027012702270327042705270627072708270927102711271227132714271527162717271827192720272127222723272427252726272727282729273027312732273327342735273627372738273927402741274227432744274527462747274827492750275127522753275427552756275727582759276027612762276327642765276627672768276927702771277227732774277527762777277827792780278127822783278427852786278727882789279027912792279327942795279627972798279928002801280228032804280528062807280828092810281128122813281428152816281728182819282028212822282328242825282628272828282928302831283228332834283528362837283828392840284128422843284428452846284728482849285028512852285328542855285628572858285928602861286228632864286528662867286828692870287128722873287428752876287728782879288028812882288328842885288628872888288928902891289228932894289528962897289828992900290129022903290429052906290729082909291029112912291329142915291629172918291929202921292229232924292529262927292829292930293129322933293429352936293729382939294029412942294329442945294629472948294929502951295229532954295529562957295829592960296129622963296429652966296729682969297029712972297329742975297629772978297929802981298229832984298529862987298829892990299129922993299429952996299729982999300030013002300330043005300630073008300930103011301230133014301530163017301830193020302130223023302430253026302730283029303030313032303330343035303630373038303930403041304230433044304530463047304830493050305130523053305430553056305730583059306030613062306330643065306630673068306930703071307230733074307530763077307830793080308130823083308430853086308730883089309030913092309330943095309630973098309931003101310231033104310531063107310831093110311131123113311431153116311731183119312031213122312331243125312631273128312931303131313231333134313531363137313831393140314131423143314431453146314731483149315031513152315331543155315631573158315931603161316231633164316531663167316831693170317131723173317431753176317731783179318031813182318331843185318631873188318931903191319231933194319531963197319831993200320132023203320432053206320732083209321032113212321332143215321632173218321932203221322232233224322532263227322832293230323132323233323432353236323732383239324032413242324332443245324632473248324932503251325232533254325532563257325832593260326132623263326432653266326732683269327032713272327332743275327632773278327932803281328232833284328532863287328832893290329132923293329432953296329732983299330033013302330333043305330633073308330933103311331233133314331533163317331833193320332133223323332433253326332733283329333033313332333333343335333633373338333933403341334233433344334533463347334833493350335133523353335433553356335733583359336033613362336333643365336633673368336933703371337233733374337533763377337833793380338133823383338433853386338733883389339033913392339333943395339633973398339934003401340234033404340534063407340834093410341134123413341434153416341734183419342034213422342334243425342634273428342934303431343234333434343534363437343834393440344134423443344434453446344734483449345034513452345334543455345634573458345934603461346234633464346534663467346834693470347134723473347434753476347734783479348034813482348334843485348634873488348934903491349234933494349534963497349834993500350135023503350435053506350735083509351035113512351335143515351635173518351935203521352235233524352535263527352835293530353135323533353435353536353735383539354035413542354335443545354635473548354935503551355235533554355535563557355835593560356135623563356435653566356735683569357035713572357335743575357635773578357935803581358235833584358535863587358835893590359135923593359435953596359735983599 |
- """Print scheduler service - processes the print queue."""
- import asyncio
- import json
- import logging
- import time
- from datetime import datetime, timezone
- from pathlib import Path
- from sqlalchemy import func, select, update
- from sqlalchemy.ext.asyncio import AsyncSession
- from sqlalchemy.orm import selectinload
- from backend.app.core.config import settings
- from backend.app.core.database import async_session, run_with_retry
- from backend.app.core.tasks import spawn_background_task
- from backend.app.core.websocket import ws_manager
- from backend.app.models.archive import PrintArchive
- from backend.app.models.library import LibraryFile
- from backend.app.models.print_queue import PrintQueueItem
- from backend.app.models.printer import Printer
- from backend.app.models.settings import Settings
- from backend.app.models.smart_plug import SmartPlug
- from backend.app.models.spool_assignment import SpoolAssignment
- from backend.app.models.spoolman_slot_assignment import SpoolmanSlotAssignment
- from backend.app.services.bambu_ftp import (
- UploadCancelled,
- cache_3mf_download,
- delete_file_async,
- get_ftp_retry_settings,
- upload_file_async,
- with_ftp_retry,
- )
- from backend.app.services.filament_deficit import compute_deficit_for_queue_item
- from backend.app.services.notification_service import notification_service
- from backend.app.services.printer_manager import (
- printer_manager,
- supports_airduct,
- supports_chamber_heater,
- supports_chamber_temp,
- supports_drying,
- supports_drying_while_printing,
- )
- from backend.app.services.smart_plug_manager import smart_plug_manager
- from backend.app.utils.filename import derive_remote_filename
- from backend.app.utils.printer_models import normalize_printer_model
- logger = logging.getLogger(__name__)
- # Dispatch-toast progress throttling (#1625 follow-up). Mirrors the legacy
- # background_dispatch.py upload_progress_callback (200 ms time gate + 256 KB
- # byte gate) from before the scheduler unification. Time gate keeps small
- # files from going silent (a single 8 KB chunk fires once and that's it);
- # byte gate caps the broadcast rate on slow LAN where 200 ms covers many
- # chunks. uploaded >= total always emits so the bar closes cleanly even on
- # sub-200 ms files.
- _DISPATCH_PROGRESS_BYTE_STEP = 256 * 1024
- _DISPATCH_PROGRESS_MIN_INTERVAL_SECS = 0.2
- class _UploadProgressBridge:
- """Thread-safe bridge from ``upload_file_async`` to the WS broadcaster.
- ``upload_file_async`` runs the FTP transfer in an executor thread and
- invokes its ``progress_callback`` from that thread, so the callback
- body cannot ``await`` directly. This bridge captures the asyncio loop
- at construction (on the scheduler thread) and uses
- ``run_coroutine_threadsafe`` to hop back. The byte/time throttle
- matches the legacy background_dispatch.py path 1:1 so the toast feels
- identical to the pre-#1625 experience.
- Failures inside the emit are swallowed — progress is a UX nicety, the
- upload itself must not fail because of a WS hiccup.
- """
- def __init__(self, user_id: int | None, queue_item_id: int):
- self._user_id = user_id
- self._queue_item_id = queue_item_id
- try:
- self._loop = asyncio.get_running_loop()
- except RuntimeError:
- self._loop = None
- self._last_emit_bytes = 0
- self._last_emit_monotonic = 0.0
- self._has_emitted = False
- def __call__(self, bytes_transferred: int, total_bytes: int) -> None:
- if self._loop is None or total_bytes <= 0:
- return
- now = time.monotonic()
- # Mirrors legacy bg-dispatch: emit if first call OR upload complete
- # OR 200 ms elapsed OR ≥256 KB transferred since last emit. Two of
- # the four matter most: first-call so the user sees something even
- # for sub-chunk-size files; uploaded >= total so the bar locks at
- # 100% even when the throttle would otherwise eat it.
- should_emit = (
- not self._has_emitted
- or bytes_transferred >= total_bytes
- or now - self._last_emit_monotonic >= _DISPATCH_PROGRESS_MIN_INTERVAL_SECS
- or bytes_transferred - self._last_emit_bytes >= _DISPATCH_PROGRESS_BYTE_STEP
- )
- if not should_emit:
- return
- self._has_emitted = True
- self._last_emit_bytes = bytes_transferred
- self._last_emit_monotonic = now
- try:
- asyncio.run_coroutine_threadsafe(
- ws_manager.send_queue_item_upload_progress(
- user_id=self._user_id,
- queue_item_id=self._queue_item_id,
- bytes_transferred=bytes_transferred,
- total_bytes=total_bytes,
- ),
- self._loop,
- )
- except Exception:
- pass # progress is best-effort, never block the upload
- # Bambu firmware states that mean the project_file has actually been accepted
- # and the printer is now processing / running / paused mid-print. Used by the
- # dispatch watchdog (#1370): a transition into one of these states means the
- # print landed, anything else (e.g. FINISH -> IDLE after the user dismisses
- # a post-print prompt) is NOT a valid "command landed" signal even though the
- # state value did change. SLICING is included because some firmwares park
- # briefly in SLICING between PREPARE and RUNNING while parsing the g-code.
- _ACTIVE_PRINT_STATES: frozenset[str] = frozenset({"PREPARE", "SLICING", "RUNNING", "PAUSE"})
- # How many times the start-watchdog may revert an item to 'pending' before it
- # gives up and fails the row instead (#2555). Each attempt costs a full 3MF
- # re-upload plus the watchdog's wait, so a wedged printer left to retry forever
- # both never recovers and starves the other printers of dispatch slots. Three
- # is chosen to clear the transient causes the watchdog already recovers from —
- # a lost MQTT publish on a half-broken session (#887/#936) is fixed by the
- # force-reconnect on the very next attempt — while still bounding the loop.
- DISPATCH_MAX_ATTEMPTS = 3
- # Filament type equivalence groups — types within the same group are
- # interchangeable on the printer side (Bambu Lab firmware treats them as compatible).
- _FILAMENT_TYPE_GROUPS: list[list[str]] = [
- ["PA-CF", "PA12-CF", "PAHT-CF"],
- ]
- _FILAMENT_EQUIV_MAP: dict[str, str] = {}
- for _group in _FILAMENT_TYPE_GROUPS:
- _canonical = _group[0].upper()
- for _t in _group:
- _FILAMENT_EQUIV_MAP[_t.upper()] = _canonical
- def _canonical_filament_type(ftype: str) -> str:
- """Return canonical type for equivalence matching."""
- upper = ftype.upper()
- return _FILAMENT_EQUIV_MAP.get(upper, upper)
- def _installed_nozzle_diameters(status) -> list[float]:
- """Parse the installed nozzle diameters from a PrinterState (#1899).
- Returns the diameters the printer actually reports (e.g. [0.4] single-nozzle,
- [0.4, 0.6] dual-nozzle), skipping the empty-string defaults that populate a
- NozzleInfo before MQTT fills it in. An empty list means "the printer hasn't
- told us its nozzle hardware" — callers must treat that as unknown, not as a
- mismatch, so we never block a print on missing data.
- """
- diameters: list[float] = []
- for nozzle in getattr(status, "nozzles", None) or []:
- raw = getattr(nozzle, "nozzle_diameter", "") or ""
- try:
- value = float(raw)
- except (TypeError, ValueError):
- continue
- if value > 0:
- diameters.append(value)
- return diameters
- def _nozzle_mismatch_message(sliced_nozzle: float | None, installed: list[float]) -> str | None:
- """Return an actionable error message when the sliced nozzle can't be
- printed on any installed nozzle, else None (#1899).
- Fail-safe: returns None whenever we lack the data to judge — no sliced
- diameter, or the printer reported no nozzles — so a print is only ever
- blocked on a POSITIVE mismatch. On dual-nozzle printers a match against
- EITHER installed nozzle passes (a 0.6 slice is fine if one hotend is 0.6).
- The 0.05 tolerance absorbs float noise while staying well inside the 0.2
- gap between adjacent nozzle sizes (0.2/0.4/0.6/0.8).
- """
- if not sliced_nozzle or not installed:
- return None
- if any(abs(d - sliced_nozzle) < 0.05 for d in installed):
- return None
- installed_str = " / ".join(f"{d:g}mm" for d in installed)
- return (
- f"File sliced for a {sliced_nozzle:g}mm nozzle, but the printer has "
- f"{installed_str} installed. Re-slice for the installed nozzle, or "
- f"install the matching nozzle before printing."
- )
- class PrintScheduler:
- """Background scheduler that processes the print queue."""
- # Built-in drying presets per filament type (from BambuStudio filament profiles)
- # Format: { n3f_temp, n3s_temp, n3f_hours, n3s_hours }
- DEFAULT_DRYING_PRESETS: dict[str, dict[str, int]] = {
- "PLA": {"n3f": 45, "n3s": 45, "n3f_hours": 12, "n3s_hours": 12},
- "PETG": {"n3f": 65, "n3s": 65, "n3f_hours": 12, "n3s_hours": 12},
- "TPU": {"n3f": 65, "n3s": 75, "n3f_hours": 12, "n3s_hours": 18},
- "ABS": {"n3f": 65, "n3s": 80, "n3f_hours": 12, "n3s_hours": 8},
- "ASA": {"n3f": 65, "n3s": 80, "n3f_hours": 12, "n3s_hours": 8},
- "PA": {"n3f": 65, "n3s": 85, "n3f_hours": 12, "n3s_hours": 12},
- "PC": {"n3f": 65, "n3s": 80, "n3f_hours": 12, "n3s_hours": 8},
- "PVA": {"n3f": 65, "n3s": 85, "n3f_hours": 12, "n3s_hours": 18},
- }
- 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)
- self._drying_in_progress: dict[int, float] = {}
- # Defensive in-memory dispatch hold (#1157): a printer that just received
- # a project_file command must not get a second dispatch until either it
- # transitions out of pre_state OR the hard timeout expires. The H2D Pro
- # can take 80–210 s to flip FINISH→PREPARE after project_file, and
- # during that window the DB busy_printers seed is empirically unreliable
- # (multi-plate batches double-/triple-dispatched onto the same printer
- # 30 s apart). Keyed by printer_id; cleared by the watchdog on success
- # or revert.
- # printer_id -> (monotonic_started_at, pre_state, pre_subtask_id)
- self._dispatch_holds: dict[int, tuple[float, str, str | None]] = {}
- # Minimum cooldown between dispatches to the same printer (covers the
- # H2D's project_file digestion window).
- self._dispatch_min_cooldown = 60.0
- # Hard timeout — drop the hold even if we never observed a transition,
- # so a lost MQTT session can't lock a printer out of the queue forever.
- # Matches the watchdog timeout (90 s) plus a safety margin so the
- # watchdog runs first on the unhappy path.
- self._dispatch_max_hold = 180.0
- async def run(self):
- """Main loop - check queue every interval."""
- self._running = True
- logger.info("Print scheduler started")
- while self._running:
- dispatched = False
- try:
- dispatched = await self.check_queue()
- except Exception as e:
- logger.error("Scheduler error: %s", e)
- # 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) -> 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")
- # Get all pending items, ordered by printer and position (or SJF order)
- if sjf_enabled:
- # SJF: group by printer (and target_model for model-based jobs),
- # then items already jumped get top priority (starvation guard),
- # then sort by print_time ascending. Items with no print time go last.
- result = await db.execute(
- select(PrintQueueItem)
- .where(PrintQueueItem.status == "pending")
- .order_by(
- PrintQueueItem.printer_id,
- PrintQueueItem.target_model,
- PrintQueueItem.been_jumped.desc(),
- PrintQueueItem.print_time_seconds.asc().nullslast(),
- PrintQueueItem.position,
- )
- )
- else:
- result = await db.execute(
- select(PrintQueueItem)
- .where(PrintQueueItem.status == "pending")
- .order_by(PrintQueueItem.printer_id, PrintQueueItem.position)
- )
- items = list(result.scalars().all())
- # Read plate-clear setting once per queue check. Default MUST be
- # False to match the schema (SettingsSchema.require_plate_clear
- # defaults False) and the frontend (toggle + card badge both treat a
- # missing value as off). When no settings row exists, a True default
- # here re-enabled the plate-clear gate the UI showed as disabled,
- # blocking dispatch to FINISH-state printers forever with no UI path
- # to clear it (#1865).
- require_plate_clear = await self._get_bool_setting(db, "require_plate_clear", default=False)
- 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 False
- logger.info(
- "Queue check: found %d pending items: %s",
- len(items),
- [(i.id, i.printer_id, i.archive_id, i.library_file_id) for i in items],
- )
- # 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}
- # Defense-in-depth (#1157): augment busy_printers with any printer
- # still in its post-dispatch hold window. Empirically, the DB seed
- # above can miss in-flight items in a multi-plate batch — same-file
- # plates were being dispatched 30 s apart while the H2D was still
- # digesting the first project_file. The hold is keyed in-memory and
- # released by the watchdog on the success path, so it adds a layer
- # that doesn't depend on DB row visibility or completion-callback
- # timing.
- for held_printer_id in list(self._dispatch_holds.keys()):
- if self._printer_in_dispatch_hold(held_printer_id):
- busy_printers.add(held_printer_id)
- # Log skip reasons once per queue check (not per item)
- skip_reasons: dict[str, int] = {}
- # Items selected for dispatch in this pass, one per printer. The
- # loop below only *decides* — the uploads happen afterwards, in
- # parallel (#2555). See _dispatch_selected().
- dispatch_ids: list[int] = []
- # Library rows queued with `cleanup_library_after_dispatch` (the
- # printer-card "upload and print" flow) are CONSUMED by the dispatch
- # that prints them: the row is deleted and the 3MF is unlinked from
- # disk. That was safe only because dispatch was serial. Run two of
- # them against the same row at once and the second DELETE matches no
- # row (StaleDataError), and the winner's unlink can pull the file out
- # from under the loser's in-flight upload.
- #
- # Only the cleanup flag mutates the row. An ordinary library print
- # just reads it, so the common fan-out — one file, many printers,
- # which is exactly the reporter's workload — still goes out fully in
- # parallel. Narrow the guard to the mutating case; do not serialise
- # the case the whole fix exists for.
- dispatch_libs: set[int] = set()
- consumed_libs: set[int] = set()
- def _library_row_conflict(candidate: PrintQueueItem) -> bool:
- """True if dispatching `candidate` now would race another item's cleanup."""
- lib_id = candidate.library_file_id
- if lib_id is None:
- return False
- if candidate.cleanup_library_after_dispatch:
- # We would delete a row someone else in this pass is reading.
- return lib_id in dispatch_libs
- # Someone else in this pass will delete the row out from under us.
- return lib_id in consumed_libs
- def _claim_library_row(candidate: PrintQueueItem) -> None:
- lib_id = candidate.library_file_id
- if lib_id is None:
- return
- dispatch_libs.add(lib_id)
- if candidate.cleanup_library_after_dispatch:
- consumed_libs.add(lib_id)
- for item in items:
- # Check scheduled time first (scheduled_time is stored in UTC from ISO string)
- if item.scheduled_time:
- sched = item.scheduled_time
- 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:
- # Specific printer assignment (existing behavior)
- if item.printer_id in busy_printers:
- continue
- # Check if printer is idle
- printer_idle = self._is_printer_idle(item.printer_id, require_plate_clear)
- printer_connected = printer_manager.is_connected(item.printer_id)
- # If printer not connected, try to power on via smart plug
- if not printer_connected:
- plugs = await self._get_smart_plugs(db, item.printer_id)
- auto_on_plugs = [p for p in plugs if p.auto_on and p.enabled]
- if auto_on_plugs:
- logger.info("Printer %s offline, attempting to power on via smart plug(s)", item.printer_id)
- # Power on using the first auto_on plug (the printer power plug)
- powered_on = await self._power_on_and_wait(auto_on_plugs[0], item.printer_id, db)
- if powered_on:
- # Also turn on any remaining auto_on plugs (e.g., filter)
- for extra_plug in auto_on_plugs[1:]:
- try:
- service = await smart_plug_manager.get_service_for_plug(extra_plug, db)
- await service.turn_on(extra_plug)
- logger.info(
- "Also powered on plug '%s' for printer %s", extra_plug.name, item.printer_id
- )
- except Exception as e:
- logger.warning("Failed to power on extra plug '%s': %s", extra_plug.name, e)
- printer_connected = True
- printer_idle = self._is_printer_idle(item.printer_id, require_plate_clear)
- else:
- logger.warning("Could not power on printer %s via smart plug", item.printer_id)
- busy_printers.add(item.printer_id)
- continue
- else:
- # No plug or auto_on disabled
- busy_printers.add(item.printer_id)
- continue
- # Check if printer is idle (busy with another print)
- if not printer_idle:
- # If printer is drying (not truly busy), handle based on queue_drying_block
- if self._drying_in_progress.get(item.printer_id):
- block_for_drying = await self._get_bool_setting(db, "queue_drying_block")
- if block_for_drying:
- # Drying blocks queue — skip this printer
- busy_printers.add(item.printer_id)
- continue
- else:
- # Print takes priority — stop drying
- await self._stop_drying(item.printer_id)
- # Re-check idle after stopping drying
- printer_idle = self._is_printer_idle(item.printer_id, require_plate_clear)
- if not printer_idle:
- busy_printers.add(item.printer_id)
- continue
- else:
- busy_printers.add(item.printer_id)
- continue
- # Check condition (previous print success)
- if item.require_previous_success:
- if not await self._check_previous_success(db, item):
- item.status = "skipped"
- item.error_message = "Previous print failed or was aborted"
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- logger.info("Skipped queue item %s - previous print failed", item.id)
- # Send notification
- job_name = await self._get_job_name(db, item)
- printer = await self._get_printer(db, item.printer_id)
- await notification_service.on_queue_job_skipped(
- job_name=job_name,
- printer_id=item.printer_id,
- printer_name=printer.name if printer else "Unknown",
- reason="Previous print failed or was aborted",
- db=db,
- )
- continue
- # Compute AMS mapping if not already set
- if not item.ams_mapping:
- computed_mapping = await self._compute_ams_mapping_for_printer(db, item.printer_id, item)
- if computed_mapping:
- item.ams_mapping = json.dumps(computed_mapping)
- logger.info(
- f"Queue item {item.id}: Computed AMS mapping for printer {item.printer_id}: {computed_mapping}"
- )
- await db.commit()
- # Filament-deficit pre-dispatch check (#1496). If the
- # assigned spool can't satisfy any required slot grams,
- # promote the item to manual_start so the user must
- # acknowledge via the ▶ button (which re-checks live).
- if await self._block_on_filament_deficit(db, item):
- continue
- # Hold this item back for the next pass rather than racing
- # another dispatch over the same transient library row. The
- # printer is still marked busy so a later item does not jump
- # its place in this printer's queue.
- if _library_row_conflict(item):
- skip_reasons["library_row_in_use"] = skip_reasons.get("library_row_in_use", 0) + 1
- busy_printers.add(item.printer_id)
- continue
- # Queue the dispatch instead of running it here — see
- # _dispatch_selected(). busy_printers still gets the printer
- # immediately, so nothing else in this pass can target it.
- _claim_library_row(item)
- dispatch_ids.append(item.id)
- busy_printers.add(item.printer_id)
- # SJF starvation guard: mark items that were jumped
- if sjf_enabled and item.print_time_seconds is not None:
- for other in items:
- if (
- other.id != item.id
- and other.status == "pending"
- and other.printer_id == item.printer_id
- and not other.been_jumped
- and other.position < item.position
- and (
- other.print_time_seconds is None
- or other.print_time_seconds > item.print_time_seconds
- )
- ):
- other.been_jumped = True
- await db.commit()
- elif item.target_model:
- # Model-based assignment - find any idle printer of matching model
- # Parse required filament types if present
- required_types = None
- if item.required_filament_types:
- try:
- required_types = json.loads(item.required_filament_types)
- except json.JSONDecodeError:
- pass # Ignore malformed filament types; treat as no constraint
- # Parse filament overrides if present
- filament_overrides = None
- if item.filament_overrides:
- try:
- filament_overrides = json.loads(item.filament_overrides)
- except json.JSONDecodeError:
- pass
- # If overrides exist, use override types for validation instead
- effective_types = required_types
- if filament_overrides:
- override_types = sorted({o["type"] for o in filament_overrides if "type" in o})
- if override_types:
- # Merge: keep original types for non-overridden slots, add override types
- effective_types = sorted(set(required_types or []) | set(override_types))
- printer_id, waiting_reason = await self._find_idle_printer_for_model(
- db,
- item.target_model,
- busy_printers,
- effective_types,
- item.target_location,
- filament_overrides=filament_overrides,
- require_plate_clear=require_plate_clear,
- )
- # Update waiting_reason if changed and send notification when first waiting
- if item.waiting_reason != waiting_reason:
- was_waiting = item.waiting_reason is not None
- item.waiting_reason = waiting_reason
- await db.commit()
- # Send waiting notification only when transitioning to waiting state
- # and the reason requires user action (not just "all printers busy")
- if waiting_reason and not was_waiting and not self._is_busy_only(waiting_reason):
- job_name = await self._get_job_name(db, item)
- await notification_service.on_queue_job_waiting(
- job_name=job_name,
- target_model=item.target_model,
- waiting_reason=waiting_reason,
- db=db,
- )
- if printer_id:
- # Before claiming the printer: hold back rather than race
- # another dispatch over the same transient library row.
- # Checked here so a held item does not get a printer
- # assigned and then sit on it. See _library_row_conflict().
- #
- # No busy_printers.add() here, unlike the fixed-printer
- # branch above: that one protects its printer's own queue
- # ordering, but this item was never assigned to `printer_id`
- # — the matcher merely offered it. Marking it busy would
- # strand an idle printer for the rest of the pass.
- if _library_row_conflict(item):
- skip_reasons["library_row_in_use"] = skip_reasons.get("library_row_in_use", 0) + 1
- continue
- # Check condition (previous print success) before assigning
- if item.require_previous_success:
- if not await self._check_previous_success(db, item):
- item.status = "skipped"
- item.error_message = "Previous print failed or was aborted"
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- logger.info("Skipped queue item %s - previous print failed", item.id)
- # Send notification
- job_name = await self._get_job_name(db, item)
- printer = await self._get_printer(db, printer_id)
- await notification_service.on_queue_job_skipped(
- job_name=job_name,
- printer_id=printer_id,
- printer_name=printer.name if printer else "Unknown",
- reason="Previous print failed or was aborted",
- db=db,
- )
- continue
- # Assign printer and start - clear waiting reason
- item.printer_id = printer_id
- item.waiting_reason = None
- logger.info("Model-based assignment: queue item %s assigned to printer %s", item.id, printer_id)
- # Send assignment notification
- job_name = await self._get_job_name(db, item)
- printer = await self._get_printer(db, printer_id)
- await notification_service.on_queue_job_assigned(
- job_name=job_name,
- printer_id=printer_id,
- printer_name=printer.name if printer else "Unknown",
- target_model=item.target_model,
- db=db,
- )
- # Compute AMS mapping for the assigned printer if not already set
- # This is critical for model-based jobs where mapping wasn't computed upfront
- if not item.ams_mapping:
- computed_mapping = await self._compute_ams_mapping_for_printer(db, printer_id, item)
- if computed_mapping:
- item.ams_mapping = json.dumps(computed_mapping)
- logger.info(
- f"Queue item {item.id}: Computed AMS mapping for printer {printer_id}: {computed_mapping}"
- )
- await db.commit()
- # Filament-deficit pre-dispatch check (#1496).
- if await self._block_on_filament_deficit(db, item):
- continue
- _claim_library_row(item)
- dispatch_ids.append(item.id)
- busy_printers.add(printer_id)
- # SJF starvation guard: mark model-based items that were jumped
- if sjf_enabled and item.print_time_seconds is not None:
- for other in items:
- if (
- other.id != item.id
- and other.status == "pending"
- and other.printer_id is None
- and other.target_model
- and other.target_model.upper() == item.target_model.upper()
- and not other.been_jumped
- and other.position < item.position
- and (
- other.print_time_seconds is None
- or other.print_time_seconds > item.print_time_seconds
- )
- ):
- other.been_jumped = True
- await db.commit()
- # Log the decisions BEFORE dispatching. The dispatch below blocks for
- # as long as the slowest upload takes (minutes on a big 3MF), and a
- # skip summary that only lands after the transfers have finished is
- # useless for working out why an item did not go out.
- 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)
- awaiting = printer_manager.is_awaiting_plate_clear(pid)
- state_name = state.state if state else "NO_STATUS"
- logger.info(
- "Queue: printer %d not available — connected=%s, state=%s, awaiting_plate_clear=%s",
- pid,
- connected,
- state_name,
- awaiting,
- )
- # Read the concurrency limit BEFORE the commit below, not inside
- # _dispatch_selected(). A SELECT on this session after the commit
- # implicitly opens a fresh transaction that nothing then closes, and
- # it would stay open for the whole dispatch — minutes of "idle in
- # transaction" on Postgres (pinned MVCC snapshot, vacuum blocked),
- # and on SQLite a pinned WAL read snapshot that stops the WAL being
- # checkpointed while every dispatch is writing to it.
- upload_limit = max(1, await self._get_int_setting(db, "queue_max_concurrent_uploads", default=4))
- # Selection is done; every decision above is recorded on `db`
- # (model-based printer assignment, computed ams_mapping). Flush it
- # before the dispatch tasks open their own sessions, or they will
- # read a row that still says printer_id=None. This also releases the
- # connection back to the pool for the duration of the dispatch.
- await db.commit()
- if dispatch_ids:
- await self._dispatch_selected(dispatch_ids, upload_limit)
- # 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.
- Dispatch used to happen inline in the selection loop: ``await
- _start_print(db, item)`` for each item in turn. Since ``_start_print``
- performs the FTP upload, that serialized every printer behind every
- other printer's transfer — even though the printers are entirely
- independent machines. A Bambu printer's FTP server sustains ~150 KB/s
- (its own SD write is the bottleneck, not the network), so a 41 MB 3MF
- takes ~4 minutes. The reporter's 19-printer farm therefore needed ~80
- minutes before the last printer received its file, and the queue looked
- like it was starting prints "one by one, very slowly" (#2555).
- Uploads to *different* printers contend for nothing, so they run
- concurrently here, bounded by ``queue_max_concurrent_uploads``. The
- bound exists because the printers are independent but the host is not:
- each in-flight upload holds a thread in the FTP pool, a TLS session and
- a file handle.
- This is awaited before ``check_queue`` returns, which preserves the
- invariant the rest of the scheduler is built on: a pass never overlaps
- with the next one. It matters more than it looks — ``_start_print``
- flips the row pending -> printing only *after* the upload finishes, so
- a pass that returned early while uploads were still in flight would let
- the next pass re-dispatch the very same still-pending rows.
- ``limit`` is read by the caller, on the caller's session, before it
- commits — reading it here would leave that session idle-in-transaction
- for the whole dispatch. This function deliberately takes no session.
- """
- sem = asyncio.Semaphore(limit)
- async def _one(item_id: int) -> None:
- # Its own session: these run concurrently, and an AsyncSession is not
- # safe to share across tasks. It also keeps a slow upload from pinning
- # the caller's session (and, on SQLite, its transaction) open for the
- # duration.
- async with sem, async_session() as item_db:
- item = await item_db.get(PrintQueueItem, item_id)
- if not item:
- logger.info("Queue item %s vanished before dispatch — skipping", item_id)
- return
- await self._start_print(item_db, item)
- logger.info(
- "Dispatching %d queue item(s) with up to %d concurrent upload(s): %s",
- len(item_ids),
- limit,
- item_ids,
- )
- results = await asyncio.gather(*(_one(i) for i in item_ids), return_exceptions=True)
- # gather() with return_exceptions keeps one printer's failure from
- # cancelling its siblings' in-flight uploads. _start_print already
- # handles its own failure modes and marks the item failed; anything
- # arriving here is unexpected, so log it loudly rather than letting
- # gather swallow it.
- for item_id, result in zip(item_ids, results, strict=True):
- if isinstance(result, BaseException):
- logger.error("Queue item %s: dispatch raised %s: %s", item_id, type(result).__name__, result)
- async def _find_idle_printer_for_model(
- self,
- db: AsyncSession,
- model: str,
- exclude_ids: set[int],
- required_filament_types: list[str] | None = None,
- target_location: str | None = None,
- filament_overrides: list[dict] | None = None,
- require_plate_clear: bool = True,
- ) -> tuple[int | None, str | None]:
- """Find an idle, connected printer matching the model with compatible filaments.
- Args:
- db: Database session
- model: Printer model to match (e.g., "X1C", "P1S")
- exclude_ids: Printer IDs to exclude (already busy)
- required_filament_types: Optional list of filament types needed (e.g., ["PLA", "PETG"])
- If provided, only printers with all required types loaded will match.
- target_location: Optional location filter. If provided, only printers in this location are considered.
- filament_overrides: Optional list of override dicts. Each entry may include
- ``force_color_match: true`` to require an exact type+color match
- on the printer for that slot. Without the flag the existing
- colour-preference logic applies.
- Returns:
- Tuple of (printer_id, waiting_reason):
- - (printer_id, None) if a matching printer was found
- - (None, reason) if no printer is available, with explanation
- """
- # Normalize model name and use case-insensitive matching
- normalized_model = normalize_printer_model(model) or model
- query = (
- select(Printer)
- .where(func.lower(Printer.model) == normalized_model.lower())
- .where(Printer.is_active == True) # noqa: E712
- )
- # Add location filter if specified
- if target_location:
- query = query.where(Printer.location == target_location)
- result = await db.execute(query)
- printers = list(result.scalars().all())
- location_suffix = f" in {target_location}" if target_location else ""
- if not printers:
- return None, f"No active {normalized_model} printers{location_suffix} configured"
- # Separate force-matched overrides from preference-only overrides
- force_overrides = [o for o in (filament_overrides or []) if o.get("force_color_match")]
- pref_overrides = [o for o in (filament_overrides or []) if not o.get("force_color_match")]
- # Track reasons for skipping printers
- printers_busy = []
- printers_offline = []
- printers_missing_filament: list[tuple[str, list[str]]] = []
- candidates: list[tuple[int, int]] = [] # (printer_id, color_match_count)
- for printer in printers:
- if printer.id in exclude_ids:
- # Printer is already claimed by another job in this scheduling run.
- # For force-color jobs, still check if the color would match — if not,
- # report it as a color mismatch rather than plain "Busy" so the user
- # knows the job needs a filament change, not just to wait for availability.
- if force_overrides and not pref_overrides:
- missing_colors = self._get_missing_force_color_slots(printer.id, force_overrides)
- if missing_colors:
- printers_missing_filament.append((printer.name, missing_colors))
- continue
- printers_busy.append(printer.name)
- continue
- is_connected = printer_manager.is_connected(printer.id)
- is_idle = self._is_printer_idle(printer.id, require_plate_clear) if is_connected else False
- if not is_connected:
- printers_offline.append(printer.name)
- continue
- if not is_idle:
- # Printer is currently printing. For force-color jobs, check whether the
- # loaded color would satisfy the requirement — if not, surface it as a
- # color-mismatch reason rather than plain "Busy" so the user understands
- # that the job is waiting for a filament change, not just printer availability.
- if force_overrides and not pref_overrides:
- missing_colors = self._get_missing_force_color_slots(printer.id, force_overrides)
- if missing_colors:
- printers_missing_filament.append((printer.name, missing_colors))
- logger.debug(
- "Printer %s (%s) is busy but also has wrong force-color: %s",
- printer.id,
- printer.name,
- missing_colors,
- )
- continue
- printers_busy.append(printer.name)
- continue
- # Validate filament compatibility if required types are specified
- if required_filament_types:
- missing = self._get_missing_filament_types(printer.id, required_filament_types)
- if missing:
- # When force_overrides are present, enrich missing entries with color info
- # so the "Waiting on" message includes "TYPE (color)" instead of just "TYPE"
- if force_overrides:
- force_color_map = {
- (o.get("type") or "").upper(): o.get("color_name") or o.get("color", "?")
- for o in force_overrides
- }
- missing_enriched = [
- f"{t} ({force_color_map[t_upper]})" if (t_upper := t.upper()) in force_color_map else t
- for t in missing
- ]
- printers_missing_filament.append((printer.name, missing_enriched))
- else:
- printers_missing_filament.append((printer.name, missing))
- logger.debug("Skipping printer %s (%s) - missing filaments: %s", printer.id, printer.name, missing)
- continue
- # Force color match: ALL flagged slots must have an exact type+color match
- if force_overrides:
- missing_colors = self._get_missing_force_color_slots(printer.id, force_overrides)
- if missing_colors:
- printers_missing_filament.append((printer.name, missing_colors))
- logger.debug(
- "Skipping printer %s (%s) - missing force-matched colors: %s",
- printer.id,
- printer.name,
- missing_colors,
- )
- continue
- # If preference-only overrides exist, rank by color matches (existing behaviour)
- if pref_overrides:
- color_matches = self._count_override_color_matches(printer.id, pref_overrides)
- if color_matches > 0:
- candidates.append((printer.id, color_matches))
- else:
- override_colors = [f"{o.get('type', '?')} ({o.get('color', '?')})" for o in pref_overrides]
- printers_missing_filament.append((printer.name, override_colors))
- logger.debug("Skipping printer %s (%s) - no matching override colors", printer.id, printer.name)
- continue
- elif force_overrides:
- # Passed all force checks — immediately eligible (no preference ordering needed)
- return printer.id, None
- else:
- # No overrides at all - take first available (existing behavior)
- return printer.id, None
- # If we have candidates from preference override matching, pick the one with most color matches
- if candidates:
- candidates.sort(key=lambda c: c[1], reverse=True)
- return candidates[0][0], None
- # Build waiting reason from what we found
- reasons = []
- if printers_missing_filament:
- # Filament/color mismatch is most actionable - show first
- if force_overrides and not pref_overrides:
- # All mismatches are force-color failures — use descriptive message only;
- # but only if there are no busy printers that DO have the matching color.
- # If a printer has the right color but is busy, surface "Busy" instead so
- # the user knows the job will start automatically once that printer is free.
- if not printers_busy:
- all_missing = sorted({c for _, cols in printers_missing_filament for c in cols})
- return None, f"No matching material/color. Waiting on {', '.join(all_missing)}"
- # else: fall through — printers_busy will be appended below
- else:
- names_and_missing = [
- f"{name} (needs {', '.join(missing)})" for name, missing in printers_missing_filament
- ]
- reasons.append(f"Waiting for filament: {'; '.join(names_and_missing)}")
- if printers_busy:
- reasons.append(f"Busy: {', '.join(printers_busy)}")
- if printers_offline:
- reasons.append(f"Offline: {', '.join(printers_offline)}")
- return None, " | ".join(reasons) if reasons else f"No available {model} printers{location_suffix}"
- @staticmethod
- def _is_busy_only(waiting_reason: str) -> bool:
- """Check if the waiting reason only contains 'Busy' entries.
- When all matching printers are simply busy printing, the queued job
- will start automatically once a printer finishes — no user action
- is required, so we skip the notification.
- """
- parts = [p.strip() for p in waiting_reason.split(" | ")]
- return all(p.startswith("Busy:") for p in parts)
- def _get_missing_force_color_slots(self, printer_id: int, force_overrides: list[dict]) -> list[str]:
- """Return descriptive strings for force_color_match slots not satisfied by the printer.
- Each entry in ``force_overrides`` must have ``type`` and ``color`` fields and is expected
- to carry ``force_color_match: True``. The printer must have **every** such slot loaded
- with an exact type+color match.
- Returns:
- List of ``"TYPE (color)"`` strings for unmatched slots (empty list means all match).
- """
- status = printer_manager.get_status(printer_id)
- if not status:
- return [f"{o.get('type', '?')} ({o.get('color_name') or o.get('color', '?')})" for o in force_overrides]
- # Build set of loaded type+colour pairs from AMS and external spool
- loaded: set[tuple[str, str]] = set()
- for ams_unit in status.raw_data.get("ams", []):
- for tray in ams_unit.get("tray", []):
- tray_type = tray.get("tray_type")
- tray_color = tray.get("tray_color", "")
- if tray_type:
- color_norm = tray_color.replace("#", "").lower()[:6]
- loaded.add((_canonical_filament_type(tray_type), color_norm))
- for vt in status.raw_data.get("vt_tray") or []:
- vt_type = vt.get("tray_type")
- if vt_type:
- color_norm = (vt.get("tray_color", "") or "").replace("#", "").lower()[:6]
- loaded.add((_canonical_filament_type(vt_type), color_norm))
- missing = []
- for o in force_overrides:
- o_type = _canonical_filament_type(o.get("type") or "")
- o_color = (o.get("color") or "").replace("#", "").lower()[:6]
- if (o_type, o_color) not in loaded:
- color_label = o.get("color_name") or o.get("color", "?")
- missing.append(f"{o_type} ({color_label})")
- return missing
- def _get_missing_filament_types(self, printer_id: int, required_types: list[str]) -> list[str]:
- """Get the list of required filament types that are not loaded on the printer.
- Args:
- printer_id: The printer ID
- required_types: List of filament types needed (e.g., ["PLA", "PETG"])
- Returns:
- List of missing filament types (empty if all are loaded)
- """
- status = printer_manager.get_status(printer_id)
- if not status:
- return required_types # Can't determine, assume all missing
- # Collect all filament types loaded on this printer (AMS units + external spool)
- # Use canonical types so equivalence groups (e.g. PA-CF/PA12-CF/PAHT-CF) match.
- loaded_types: set[str] = set()
- # Check AMS units (stored in raw_data["ams"])
- ams_data = status.raw_data.get("ams", [])
- if ams_data:
- for ams_unit in ams_data:
- for tray in ams_unit.get("tray", []):
- tray_type = tray.get("tray_type")
- if tray_type:
- loaded_types.add(_canonical_filament_type(tray_type))
- # Check external spool(s) (virtual tray, stored in raw_data["vt_tray"] as list)
- for vt in status.raw_data.get("vt_tray") or []:
- vt_type = vt.get("tray_type")
- if vt_type:
- loaded_types.add(_canonical_filament_type(vt_type))
- # Find which required types are missing (using canonical type for equivalence)
- missing = []
- for req_type in required_types:
- if _canonical_filament_type(req_type) not in loaded_types:
- missing.append(req_type)
- return missing
- def _count_override_color_matches(self, printer_id: int, overrides: list[dict]) -> int:
- """Count how many filament overrides have an exact color match on the printer.
- Used to prefer printers that already have the desired override colors loaded.
- """
- status = printer_manager.get_status(printer_id)
- if not status:
- return 0
- # Collect loaded filaments' type+color pairs
- loaded: set[tuple[str, str]] = set()
- for ams_unit in status.raw_data.get("ams", []):
- for tray in ams_unit.get("tray", []):
- tray_type = tray.get("tray_type")
- tray_color = tray.get("tray_color", "")
- if tray_type:
- color_norm = tray_color.replace("#", "").lower()[:6]
- loaded.add((tray_type.upper(), color_norm))
- for vt in status.raw_data.get("vt_tray") or []:
- vt_type = vt.get("tray_type")
- if vt_type:
- color_norm = (vt.get("tray_color", "") or "").replace("#", "").lower()[:6]
- loaded.add((vt_type.upper(), color_norm))
- matches = 0
- for o in overrides:
- o_type = (o.get("type") or "").upper()
- o_color = (o.get("color") or "").replace("#", "").lower()[:6]
- if (o_type, o_color) in loaded:
- matches += 1
- return matches
- async def _compute_ams_mapping_for_printer(
- self, db: AsyncSession, printer_id: int, item: PrintQueueItem
- ) -> list[int] | None:
- """Compute AMS mapping for a printer based on filament requirements.
- Called when a queue item has no ams_mapping set — either for model-based
- items after printer assignment, or printer-specific items (e.g. from VP).
- Args:
- db: Database session
- printer_id: The assigned printer ID
- item: The queue item (contains archive_id or library_file_id)
- Returns:
- AMS mapping array or None if no mapping needed/possible
- """
- # Get printer status
- status = printer_manager.get_status(printer_id)
- if not status:
- logger.warning("Cannot compute AMS mapping: printer %s status unavailable", printer_id)
- return None
- # Filament Track Switch (FTS): when installed it routes any AMS slot to
- # either extruder, so the per-nozzle hard filter below must NOT apply.
- # Otherwise a print on one nozzle can't use a spool physically loaded in
- # an AMS on the *other* nozzle, and the matcher falls through to a
- # same-type wrong-colour spool on the target nozzle — the H2C + FTS
- # wrong-filament bug (#2186). Mirrors the frontend skip added for #1162.
- fts_installed = bool(getattr(getattr(status, "fila_switch", None), "installed", False))
- # Get filament requirements from source file
- filament_reqs = await self._get_filament_requirements(db, item)
- if not filament_reqs:
- # When the 3MF can't be read but force-color overrides are present, build a
- # direct mapping from the overrides so the printer uses the correct AMS slot.
- if item.filament_overrides:
- try:
- overrides = json.loads(item.filament_overrides)
- force_overrides = [o for o in overrides if o.get("force_color_match")]
- if force_overrides:
- logger.info(
- "Queue item %s: No filament reqs from 3MF; building AMS mapping from %d "
- "force-color override(s)",
- item.id,
- len(force_overrides),
- )
- return self._build_override_direct_mapping(force_overrides, status)
- except (json.JSONDecodeError, KeyError, TypeError) as e:
- logger.warning("Queue item %s: Force-color fallback mapping failed: %s", item.id, e)
- logger.debug("No filament requirements found for queue item %s", item.id)
- return None
- # Apply filament overrides if present
- if item.filament_overrides:
- try:
- overrides = json.loads(item.filament_overrides)
- override_map = {o["slot_id"]: o for o in overrides}
- for req in filament_reqs:
- if req["slot_id"] in override_map:
- override = override_map[req["slot_id"]]
- req["type"] = override["type"]
- req["color"] = override["color"]
- # Clear tray_info_idx so matching uses type+color instead of
- # the original 3MF's tray_info_idx (which would match the old filament)
- req["tray_info_idx"] = ""
- logger.debug(
- "Queue item %s: Override slot %d -> %s %s",
- item.id,
- req["slot_id"],
- override["type"],
- override["color"],
- )
- except (json.JSONDecodeError, KeyError, TypeError) as e:
- logger.warning("Failed to apply filament overrides for queue item %s: %s", item.id, e)
- # Build loaded filaments from printer status
- loaded_filaments = self._build_loaded_filaments(status)
- if not loaded_filaments:
- logger.debug("No filaments loaded on printer %s", printer_id)
- return None
- # Check if user prefers lowest remaining filament when multiple spools match
- prefer_lowest = await self._get_bool_setting(db, "prefer_lowest_filament")
- # Gate prefer_lowest on the printer's AMS Filament Backup state (#1766).
- # Without backup, the printer will not switch to a second spool when the
- # picked one runs out — so sorting toward the lowest leaves the print
- # at risk of running dry mid-job. None (unknown / A1 family) preserves
- # today's behaviour intentionally.
- if prefer_lowest and status.ams_filament_backup is False:
- logger.info("[prefer-lowest] skipped (AMS Backup OFF on printer %s)", printer_id)
- prefer_lowest = False
- # When the preference is on, surface Bambuddy's inventory-side
- # remaining for each slot that's bound to a tracked spool, so the
- # sort beats the MQTT-only blind spot (#1508). Skip the lookup
- # entirely when the preference is off — no behaviour change for
- # users who haven't opted in.
- inventory_remain_overrides: dict[int, float] | None = None
- if prefer_lowest:
- inventory_remain_overrides = await self._build_inventory_remain_overrides(db, printer_id, loaded_filaments)
- # Compute mapping: match required filaments to available slots
- return self._match_filaments_to_slots(
- filament_reqs, loaded_filaments, prefer_lowest, inventory_remain_overrides, fts_installed
- )
- def _build_override_direct_mapping(self, force_overrides: list[dict], status) -> list[int] | None:
- """Build an AMS mapping directly from force-color overrides without a 3MF.
- Used when ``_get_filament_requirements`` returns nothing (e.g. the 3MF's
- slice_info is missing or unreadable) but ``force_color_match`` overrides
- are present. Each override's ``slot_id``, ``type``, and ``color`` are
- treated as the filament requirement for that slot and matched against the
- current AMS state of the printer.
- Returns the same format as ``_match_filaments_to_slots``, or None when
- the AMS has no loaded filaments.
- """
- loaded = self._build_loaded_filaments(status)
- if not loaded:
- return None
- reqs = [
- {
- "slot_id": o["slot_id"],
- "type": o.get("type", ""),
- "color": o.get("color", ""),
- "tray_info_idx": "",
- }
- for o in force_overrides
- ]
- return self._match_filaments_to_slots(reqs, loaded)
- async def _get_filament_requirements(self, db: AsyncSession, item: PrintQueueItem) -> list[dict] | None:
- """Resolve the queue item's source 3MF and parse the per-slot
- filament requirements out of it. Thin DB-resolver wrapper around
- ``filament_requirements.extract_filament_requirements`` so the VP
- queue-mode write path (#1188) can reuse the same parser at upload
- time.
- """
- from backend.app.services.filament_requirements import extract_filament_requirements
- file_path: Path | None = None
- if item.archive_id:
- result = await db.execute(select(PrintArchive).where(PrintArchive.id == item.archive_id))
- archive = result.scalar_one_or_none()
- if archive:
- file_path = settings.base_dir / archive.file_path
- elif item.library_file_id:
- result = await db.execute(LibraryFile.active().where(LibraryFile.id == item.library_file_id))
- library_file = result.scalar_one_or_none()
- if library_file:
- lib_path = Path(library_file.file_path)
- file_path = lib_path if lib_path.is_absolute() else settings.base_dir / library_file.file_path
- if not file_path or not file_path.exists():
- return None
- filaments = extract_filament_requirements(file_path, plate_id=item.plate_id)
- return filaments if filaments else None
- def _build_loaded_filaments(self, status) -> list[dict]:
- """Build list of loaded filaments from printer status.
- Args:
- status: PrinterState from printer_manager
- Returns:
- List of loaded filament dicts with type, color, ams_id, tray_id, global_tray_id
- """
- filaments = []
- # Get ams_extruder_map for dual-nozzle printers (H2D, H2D Pro)
- ams_extruder_map = status.raw_data.get("ams_extruder_map", {})
- # Parse AMS units from raw_data
- ams_data = status.raw_data.get("ams", [])
- for ams_unit in ams_data:
- ams_id = int(ams_unit.get("id", 0))
- trays = ams_unit.get("tray", [])
- is_ht = len(trays) == 1 # AMS-HT has single tray
- for tray in trays:
- tray_type = tray.get("tray_type")
- if tray_type:
- tray_id = int(tray.get("id", 0))
- tray_color = tray.get("tray_color", "")
- # tray_info_idx identifies the specific spool (e.g., "GFA00", "P4d64437")
- tray_info_idx = tray.get("tray_info_idx", "")
- # Normalize color: remove alpha, add hash
- color = self._normalize_color(tray_color)
- # Calculate global tray ID
- # AMS-HT units have IDs starting at 128 with a single tray
- global_tray_id = ams_id if ams_id >= 128 else ams_id * 4 + tray_id
- filaments.append(
- {
- "type": tray_type,
- "color": color,
- "tray_info_idx": tray_info_idx,
- "ams_id": ams_id,
- "tray_id": tray_id,
- "is_ht": is_ht,
- "is_external": False,
- "global_tray_id": global_tray_id,
- "extruder_id": ams_extruder_map.get(str(ams_id)),
- "remain": tray.get("remain", -1),
- }
- )
- # Check external spool(s) (vt_tray is a list)
- for idx, vt in enumerate(status.raw_data.get("vt_tray") or []):
- if vt.get("tray_type"):
- color = self._normalize_color(vt.get("tray_color", ""))
- tray_id = int(vt.get("id", 254))
- filaments.append(
- {
- "type": vt["tray_type"],
- "color": color,
- "tray_info_idx": vt.get("tray_info_idx", ""),
- "ams_id": -1,
- "tray_id": idx,
- "is_ht": False,
- "is_external": True,
- "global_tray_id": tray_id,
- "extruder_id": (255 - tray_id) if ams_extruder_map else None,
- "remain": vt.get("remain", -1),
- }
- )
- return filaments
- def _normalize_color(self, color: str | None) -> str:
- """Normalize color to #RRGGBB format."""
- if not color:
- return "#808080"
- hex_color = color.replace("#", "")[:6]
- return f"#{hex_color}"
- def _normalize_color_for_compare(self, color: str | None) -> str:
- """Normalize color for comparison (lowercase, no hash)."""
- if not color:
- return ""
- return color.replace("#", "").lower()[:6]
- def _colors_are_similar(self, color1: str | None, color2: str | None, threshold: int = 40) -> bool:
- """Check if two colors are visually similar within a threshold."""
- hex1 = self._normalize_color_for_compare(color1)
- hex2 = self._normalize_color_for_compare(color2)
- if not hex1 or not hex2 or len(hex1) < 6 or len(hex2) < 6:
- return False
- try:
- r1 = int(hex1[0:2], 16)
- g1 = int(hex1[2:4], 16)
- b1 = int(hex1[4:6], 16)
- r2 = int(hex2[0:2], 16)
- g2 = int(hex2[2:4], 16)
- b2 = int(hex2[4:6], 16)
- return abs(r1 - r2) <= threshold and abs(g1 - g2) <= threshold and abs(b1 - b2) <= threshold
- except ValueError:
- return False
- async def _build_inventory_remain_overrides(
- self, db: AsyncSession, printer_id: int, loaded: list[dict]
- ) -> dict[int, float]:
- """Return ``{global_tray_id: remaining_grams}`` for AMS slots the user
- has bound to an inventory spool — Bambuddy-side or Spoolman-side.
- The MQTT ``remain`` field on a tray is the printer firmware's
- RFID-decremented value, which has two limitations the "Prefer Lowest
- Remaining Filament" feature has been ignoring (#1508):
- - it's only meaningful for Bambu RFID spools; everything else reports
- ``-1`` (then clamped to a sentinel), so multiple non-RFID trays
- compare equal and the sort collapses to AMS-slot order — the user
- who's curating inventory weights gets the lower-slot pick instead
- of the lower-remaining pick;
- - even when set, it's the *printer's* counter, not Bambuddy's
- ``label_weight - weight_used`` (internal mode) or Spoolman's
- ``remaining_weight`` (Spoolman mode) — the two diverge any time the
- user re-spools, swaps cardboard, or runs a print outside Bambuddy.
- When the user has bound a spool to a slot, their own inventory
- tracking is authoritative; this helper surfaces that value so the
- sort can prefer it. Slots without a binding are absent from the
- returned map — the caller then falls back to MQTT ``remain`` for
- those, preserving the pre-#1508 behaviour for un-tracked spools.
- Returns an empty map on any failure (no inventory bindings, DB
- error, Spoolman unreachable). A best-effort lookup; "Prefer Lowest"
- is a preference, not a guarantee.
- """
- if not loaded:
- return {}
- # External / virtual-tray slots are tracked separately from AMS — skip
- # them so a VT-loaded spool doesn't accidentally inherit a tracked
- # AMS binding (the tables use ams_id 254/255 for VT, but the cross
- # match is fiddly and out of scope for this fix).
- tracked_slots = [(f["ams_id"], f["tray_id"], f["global_tray_id"]) for f in loaded if not f.get("is_external")]
- if not tracked_slots:
- return {}
- is_spoolman = await self._is_spoolman_mode(db)
- overrides: dict[int, float] = {}
- if is_spoolman:
- result = await db.execute(
- select(SpoolmanSlotAssignment).where(SpoolmanSlotAssignment.printer_id == printer_id)
- )
- assignments = list(result.scalars().all())
- by_slot = {(a.ams_id, a.tray_id): a.spoolman_spool_id for a in assignments}
- from backend.app.services.filament_deficit import _spoolman_remaining_grams
- for ams_id, tray_id, gtid in tracked_slots:
- spoolman_id = by_slot.get((ams_id, tray_id))
- if spoolman_id is None:
- continue
- grams = await _spoolman_remaining_grams(spoolman_id)
- if grams is not None:
- overrides[gtid] = grams
- return overrides
- # Internal inventory mode (default). selectinload matches the pattern
- # used elsewhere (inventory.py, spoolman.py routes) — a single query
- # plus an eager-loaded relationship rather than an explicit join, so
- # the row-attribute shape is exactly what those routes already rely on.
- result = await db.execute(
- select(SpoolAssignment)
- .options(selectinload(SpoolAssignment.spool))
- .where(SpoolAssignment.printer_id == printer_id)
- )
- assignments = list(result.scalars().all())
- by_slot = {(a.ams_id, a.tray_id): a.spool for a in assignments}
- for ams_id, tray_id, gtid in tracked_slots:
- spool = by_slot.get((ams_id, tray_id))
- if spool is None:
- continue
- label = float(spool.label_weight or 0)
- used = float(spool.weight_used or 0)
- overrides[gtid] = max(0.0, label - used)
- return overrides
- @staticmethod
- async def _is_spoolman_mode(db: AsyncSession) -> bool:
- """Mirror of ``filament_deficit._is_spoolman_mode`` — kept private
- here to avoid making this module import-dependent on that private
- helper's signature."""
- try:
- from backend.app.api.routes.settings import get_setting
- v = await get_setting(db, "spoolman_enabled")
- return bool(v) and v.lower() == "true"
- except Exception:
- return False
- @staticmethod
- def _slot_priority(ams_id: int | None, tray_id: int | None) -> int:
- """Deterministic slot-position tie-breaker for the prefer-lowest sort.
- Three bands, matched to the emission order in ``_build_loaded_filaments``
- so a tied sort produces the same physical-position order the pre-#1508
- stable sort did (preserves the regression-free baseline):
- - Regular AMS (``ams_id`` 0..7): ``ams_id * 4 + tray_id`` → 0..31
- - AMS-HT (``ams_id`` >= 128, single tray): ``1000 + (ams_id - 128) * 4``
- - External / VT (``ams_id`` < 0, or ``None``): ``10_000``
- Banding ensures regular AMS < AMS-HT < external on ties, regardless of
- what the raw ``ams_id`` happens to be (in particular, ``ams_id = -1``
- for VT must NOT sort to a negative number or it would beat AMS slot 0).
- """
- if ams_id is None or ams_id < 0:
- return 10_000
- if ams_id >= 128:
- return 1_000 + (ams_id - 128) * 4 + (tray_id or 0)
- return ams_id * 4 + (tray_id or 0)
- @staticmethod
- def _prefer_lowest_sort_key(f: dict, overrides: dict[int, float] | None) -> tuple[int, float, int]:
- """Sort key for the "Prefer Lowest Remaining Filament" preference.
- Two-tier ordering: inventory-tracked spools always sort BEFORE
- non-tracked spools (the user has told us they care about these
- specifically), then ascending by remaining within each tier, then
- ascending by AMS slot position as the deterministic tie-breaker.
- Tiers are flagged by the first tuple element (0 = inventory-tracked,
- 1 = MQTT-only / unknown). Cross-tier value comparisons never run
- because the tier flag dominates — which is what lets us mix grams
- (inventory) and percent (MQTT) without a unit conversion.
- Within the MQTT tier ``remain = -1`` (unknown) is mapped to 101 so
- spools the printer DOES know something about sort ahead of those
- it knows nothing about — preserves pre-#1508 behaviour for the
- no-inventory-binding case.
- Slot tie-breaker via ``_slot_priority`` so regular AMS < AMS-HT <
- external on ties, matching the legacy emission-order stable sort.
- """
- gtid = f.get("global_tray_id")
- slot_order = PrintScheduler._slot_priority(f.get("ams_id"), f.get("tray_id"))
- if overrides and gtid in overrides:
- return (0, overrides[gtid], slot_order)
- remain = f.get("remain", -1)
- return (1, float(remain) if remain is not None and remain >= 0 else 101.0, slot_order)
- def _match_filaments_to_slots(
- self,
- required: list[dict],
- loaded: list[dict],
- prefer_lowest: bool = False,
- inventory_remain_overrides: dict[int, float] | None = None,
- fts_installed: bool = False,
- ) -> list[int] | None:
- """Match required filaments to loaded filaments and build AMS mapping.
- Priority: unique tray_info_idx match > exact color match > similar color match > type-only match
- The tray_info_idx is a filament type identifier stored in the 3MF file when the user
- slices (e.g., "GFA00" for generic PLA, "P4d64437" for custom presets). If the same
- tray_info_idx appears in only ONE available tray, we use that tray. If multiple trays
- have the same tray_info_idx (e.g., two spools of generic PLA), we fall back to color
- matching among those trays.
- Args:
- required: List of required filaments with slot_id, type, color, tray_info_idx
- loaded: List of loaded filaments with type, color, tray_info_idx, global_tray_id
- Returns:
- AMS mapping array (position = slot_id - 1, value = global_tray_id or -1)
- """
- if not required:
- return None
- # Track used trays to avoid duplicate assignment
- used_tray_ids: set[int] = set()
- comparisons = []
- for req in required:
- req_type = (req.get("type") or "").upper()
- req_color = req.get("color", "")
- req_tray_info_idx = req.get("tray_info_idx", "")
- # Find best match: unique tray_info_idx > exact color > similar color > type-only
- idx_match = None
- exact_match = None
- similar_match = None
- type_only_match = None
- # Get available trays (not already used)
- available = [f for f in loaded if f["global_tray_id"] not in used_tray_ids]
- # Nozzle-aware filtering: restrict to trays on the correct nozzle.
- # Hard filter — cross-nozzle assignment causes print failures
- # ("position of left hotend is abnormal"), so never fall back.
- # Skipped when an FTS is installed: it routes any AMS slot to either
- # extruder, so restricting to one nozzle would wrongly exclude the
- # correct spool sitting in the other nozzle's AMS (#2186).
- req_nozzle_id = req.get("nozzle_id")
- if req_nozzle_id is not None and not fts_installed:
- available = [f for f in available if f.get("extruder_id") == req_nozzle_id]
- # Sort by remaining filament (ascending) so lowest-remain spool wins .find().
- # Inventory-tracked spools sort before MQTT-only ones (#1508); see
- # _prefer_lowest_sort_key for the full rationale.
- if prefer_lowest:
- available.sort(key=lambda f: self._prefer_lowest_sort_key(f, inventory_remain_overrides))
- # INFO-level decision trace for "Prefer Lowest Filament" #1766.
- # One line per filament req so a bug report can be diagnosed
- # without enabling debug logging: shows what the matcher saw
- # (req shape + sorted candidate trays with their remain values
- # and any inventory override that was applied). Mirrored by
- # the picked-match log at the bottom of the loop.
- logger.info(
- "[prefer-lowest] req slot=%s type=%r color=%r tii=%r nozzle=%s; available (sorted lowest-first): %s",
- req.get("slot_id"),
- req_type,
- req_color,
- req_tray_info_idx,
- req_nozzle_id,
- [
- {
- "gtid": f.get("global_tray_id"),
- "type": f.get("type"),
- "color": f.get("color"),
- "tii": f.get("tray_info_idx"),
- "remain": f.get("remain"),
- "inv_g": (
- inventory_remain_overrides.get(f.get("global_tray_id"))
- if inventory_remain_overrides
- else None
- ),
- }
- for f in available
- ],
- )
- # Check if tray_info_idx is unique among available trays
- if req_tray_info_idx:
- idx_matches = [f for f in available if f.get("tray_info_idx") == req_tray_info_idx]
- if len(idx_matches) == 1:
- # Unique tray_info_idx - use it as definitive match
- idx_match = idx_matches[0]
- logger.debug(
- f"Matched filament slot {req.get('slot_id')} by unique tray_info_idx={req_tray_info_idx} "
- f"-> tray {idx_match['global_tray_id']}"
- )
- elif len(idx_matches) > 1:
- # Multiple trays with same tray_info_idx - use color matching among them
- logger.debug(
- f"Non-unique tray_info_idx={req_tray_info_idx} found in {len(idx_matches)} trays, "
- f"using color matching among trays: {[f['global_tray_id'] for f in idx_matches]}"
- )
- if prefer_lowest:
- idx_matches.sort(key=lambda f: self._prefer_lowest_sort_key(f, inventory_remain_overrides))
- # Use color matching within this subset
- for f in idx_matches:
- f_color = f.get("color", "")
- if self._normalize_color_for_compare(f_color) == self._normalize_color_for_compare(req_color):
- if not exact_match:
- exact_match = f
- elif self._colors_are_similar(f_color, req_color):
- if not similar_match:
- similar_match = f
- elif not type_only_match:
- type_only_match = f
- # If no idx_match yet, do standard type/color matching on all available trays
- if not idx_match and not exact_match and not similar_match and not type_only_match:
- for f in available:
- f_type = (f.get("type") or "").upper()
- if _canonical_filament_type(f_type) != _canonical_filament_type(req_type):
- continue
- # Type matches - check color
- f_color = f.get("color", "")
- if self._normalize_color_for_compare(f_color) == self._normalize_color_for_compare(req_color):
- if not exact_match:
- exact_match = f
- elif self._colors_are_similar(f_color, req_color):
- if not similar_match:
- similar_match = f
- elif not type_only_match:
- type_only_match = f
- match = idx_match or exact_match or similar_match or type_only_match
- if match:
- used_tray_ids.add(match["global_tray_id"])
- comparisons.append({"slot_id": req.get("slot_id", 0), "global_tray_id": match["global_tray_id"]})
- else:
- comparisons.append({"slot_id": req.get("slot_id", 0), "global_tray_id": -1})
- if prefer_lowest:
- # Pair with the "available (sorted)" log above so the reporter
- # bundle shows BOTH what the matcher saw AND which match bucket
- # won — fast triage when "Prefer Lowest Filament" picks the
- # wrong slot (#1766).
- if match:
- bucket = (
- "idx"
- if idx_match is not None
- else "exact_color"
- if exact_match is not None
- else "similar_color"
- if similar_match is not None
- else "type_only"
- )
- logger.info(
- "[prefer-lowest] picked gtid=%s via %s for req slot=%s",
- match["global_tray_id"],
- bucket,
- req.get("slot_id"),
- )
- else:
- logger.info(
- "[prefer-lowest] NO MATCH for req slot=%s (type=%r color=%r tii=%r)",
- req.get("slot_id"),
- req_type,
- req_color,
- req_tray_info_idx,
- )
- # Build mapping array
- if not comparisons:
- return None
- max_slot_id = max(c["slot_id"] for c in comparisons)
- if max_slot_id <= 0:
- return None
- mapping = [-1] * max_slot_id
- for c in comparisons:
- slot_id = c["slot_id"]
- if slot_id and slot_id > 0:
- mapping[slot_id - 1] = c["global_tray_id"]
- return mapping
- def _mark_printer_dispatched(
- self,
- printer_id: int,
- pre_state: str | None,
- pre_subtask_id: str | None,
- ) -> None:
- """Record that a print command was just sent to ``printer_id``.
- Held until either the watchdog observes a state/subtask transition
- (success path) or the hard timeout expires. See ``_dispatch_holds``.
- """
- if not pre_state:
- # No pre_state means we can't detect a transition — fall back to a
- # pure time-based hold using empty string as a sentinel that won't
- # match any real printer state.
- pre_state = ""
- self._dispatch_holds[printer_id] = (time.monotonic(), pre_state, pre_subtask_id)
- def _release_dispatch_hold(self, printer_id: int) -> None:
- """Drop the dispatch hold for ``printer_id`` (called by the watchdog)."""
- self._dispatch_holds.pop(printer_id, None)
- def _printer_in_dispatch_hold(self, printer_id: int) -> bool:
- """True if ``printer_id`` is still inside its post-dispatch hold window.
- Returns False (and clears the hold) once any of these are true:
- - hard timeout (``_dispatch_max_hold``) has elapsed
- - the printer has transitioned out of pre_state and we're past the
- minimum cooldown
- - the printer's subtask_id has advanced past pre_subtask_id and we're
- past the minimum cooldown
- Otherwise the printer is held — caller should treat it as busy.
- """
- entry = self._dispatch_holds.get(printer_id)
- if not entry:
- return False
- started_at, pre_state, pre_subtask_id = entry
- elapsed = time.monotonic() - started_at
- if elapsed >= self._dispatch_max_hold:
- self._dispatch_holds.pop(printer_id, None)
- return False
- # Without a pre_state we can't detect a transition — fall back to the
- # min cooldown alone, then drop the hold.
- if not pre_state:
- if elapsed >= self._dispatch_min_cooldown:
- self._dispatch_holds.pop(printer_id, None)
- return False
- return True
- status = printer_manager.get_status(printer_id)
- current_state = getattr(status, "state", None) if status else None
- current_subtask_id = getattr(status, "subtask_id", None) if status else None
- transitioned = (current_state is not None and current_state != pre_state) or (
- pre_subtask_id is not None and current_subtask_id is not None and current_subtask_id != pre_subtask_id
- )
- if transitioned and elapsed >= self._dispatch_min_cooldown:
- self._dispatch_holds.pop(printer_id, None)
- return False
- return True
- def _is_printer_idle(self, printer_id: int, require_plate_clear: bool = True) -> 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
- # Plate-clear gate: if the printer finished/failed a previous print and the user
- # hasn't acknowledged the plate was cleared, the queue must not dispatch the next
- # job — even if the printer currently reports IDLE. After Auto Off cycles the
- # printer, it boots back into IDLE with no memory of the previous finish; without
- # the persisted awaiting flag we'd bypass the confirmation prompt (#961).
- if require_plate_clear and printer_manager.is_awaiting_plate_clear(printer_id):
- logger.debug(
- "Printer %d: not idle — awaiting plate-clear acknowledgment (state=%s)",
- printer_id,
- state.state,
- )
- return False
- idle = state.state in ("IDLE", "FINISH", "FAILED")
- if not idle:
- logger.debug("Printer %d: not idle — state=%s", printer_id, state.state)
- return idle
- async def _get_setting(self, db: AsyncSession, key: str) -> str | None:
- """Read a setting value from the database."""
- result = await db.execute(select(Settings).where(Settings.key == key))
- setting = result.scalar_one_or_none()
- return setting.value if setting else None
- async def _get_bool_setting(self, db: AsyncSession, key: str, default: bool = False) -> bool:
- """Read a boolean setting from the database."""
- result = await db.execute(select(Settings).where(Settings.key == key))
- setting = result.scalar_one_or_none()
- if setting:
- return setting.value.lower() == "true"
- return default
- async def _get_int_setting(self, db: AsyncSession, key: str, default: int) -> int:
- """Read an int setting; falls back to default on missing/unparseable rows."""
- result = await db.execute(select(Settings).where(Settings.key == key))
- setting = result.scalar_one_or_none()
- if setting and setting.value:
- try:
- return int(setting.value)
- except ValueError:
- pass
- return default
- async def _get_drying_presets(self, db: AsyncSession) -> dict[str, dict[str, int]]:
- """Get drying presets (user-configured or built-in defaults)."""
- result = await db.execute(select(Settings).where(Settings.key == "drying_presets"))
- setting = result.scalar_one_or_none()
- if setting and setting.value:
- try:
- presets = json.loads(setting.value)
- if isinstance(presets, dict) and presets:
- return presets
- except json.JSONDecodeError:
- pass
- return self.DEFAULT_DRYING_PRESETS
- async def _get_humidity_thresholds(self, db: AsyncSession) -> dict[str, int]:
- """Per-filament humidity thresholds (#1605).
- Returns the user-configured overrides map keyed by normalized filament
- type (uppercase base, e.g. ``PLA``, ``ASA``) plus a ``default`` key for
- unknown / unmapped types. Empty / unset → empty dict, in which case
- callers fall back to ``ams_humidity_fair``.
- """
- result = await db.execute(select(Settings).where(Settings.key == "ams_humidity_thresholds"))
- setting = result.scalar_one_or_none()
- if not setting or not setting.value:
- return {}
- try:
- data = json.loads(setting.value)
- except json.JSONDecodeError:
- return {}
- if not isinstance(data, dict):
- return {}
- out: dict[str, int] = {}
- for key, value in data.items():
- try:
- out[str(key).upper() if key != "default" else "default"] = int(value)
- except (TypeError, ValueError):
- continue
- return out
- @staticmethod
- def resolve_humidity_threshold(trays: list[dict], thresholds: dict[str, int], fallback: int) -> int:
- """Resolve the effective humidity threshold for an AMS unit (#1605).
- For mixed filament types loaded into one AMS, returns the most
- restrictive (lowest) threshold across all loaded tray types — matches
- the conservative-params strategy already used for drying temp/hours.
- Empty / unloaded trays contribute no constraint. Unknown types use the
- ``default`` key, falling through to ``fallback`` (= ``ams_humidity_fair``)
- when no per-type map is configured at all.
- """
- default = thresholds.get("default", fallback)
- if not thresholds:
- return fallback
- candidates: list[int] = []
- for tray in trays:
- tray_type = str(tray.get("tray_type") or "").strip()
- if not tray_type:
- continue
- base_type = tray_type.split()[0].upper()
- candidates.append(thresholds.get(base_type, default))
- if not candidates:
- return default
- return min(candidates)
- def _get_conservative_drying_params(
- self, trays: list[dict], module_type: str, presets: dict[str, dict[str, int]]
- ) -> tuple[int, int, str] | None:
- """Get the most conservative drying params for mixed filament types in an AMS unit.
- Returns (temp, duration_hours, filament_type) or None if no drying-eligible filaments.
- """
- temp_key = module_type if module_type in ("n3f", "n3s") else "n3f"
- hours_key = f"{temp_key}_hours"
- min_temp = None
- max_hours = None
- filament_type = ""
- for tray in trays:
- tray_type = tray.get("tray_type", "")
- if not tray_type:
- continue
- # Normalize filament type for preset lookup (e.g., "PLA Basic" -> "PLA")
- base_type = tray_type.split()[0].upper()
- preset = presets.get(base_type)
- if not preset:
- continue
- temp = preset.get(temp_key, 55)
- hours = preset.get(hours_key, 12)
- # Conservative: lowest temp, longest duration
- if min_temp is None or temp < min_temp:
- min_temp = temp
- if max_hours is None or hours > max_hours:
- max_hours = hours
- if not filament_type:
- filament_type = base_type
- if min_temp is None:
- return None
- return (min_temp, max_hours or 12, filament_type)
- async def _check_auto_drying(
- self,
- db: AsyncSession,
- queue_items: list[PrintQueueItem],
- busy_printers: set[int],
- *,
- require_plate_clear: bool = True,
- ):
- """Start drying on idle printers based on humidity.
- Three modes (can all be enabled independently):
- - queue_drying_enabled: Dry between scheduled queue prints
- - ambient_drying_enabled: Dry any idle printer when humidity is high, regardless of queue
- - print_drying_enabled: Also evaluate printers that are currently printing,
- when model+firmware supports "Print While Drying" (gated by
- supports_drying_while_printing). Drying temperature is capped at
- max(40, preset_temp - 5) to protect spools mid-print.
- """
- queue_drying_enabled = await self._get_bool_setting(db, "queue_drying_enabled")
- ambient_drying_enabled = await self._get_bool_setting(db, "ambient_drying_enabled")
- print_drying_enabled = await self._get_bool_setting(db, "print_drying_enabled")
- if not queue_drying_enabled and not ambient_drying_enabled:
- # Stop active drying on all printers if both features disabled
- if self._drying_in_progress:
- for pid in list(self._drying_in_progress):
- logger.info("Auto-drying: printer %d — stopping, auto-drying disabled", pid)
- await self._stop_drying(pid)
- return
- # Update drying state from printer status (handles backend restart)
- self._sync_drying_state()
- # Find printers with scheduled items (for queue drying mode)
- printers_with_scheduled: set[int] = set()
- printers_with_items: set[int] = set()
- for item in queue_items:
- if item.printer_id:
- printers_with_items.add(item.printer_id)
- if item.scheduled_time and not item.manual_start:
- printers_with_scheduled.add(item.printer_id)
- # If only queue mode is on and no printers have scheduled items, stop drying
- # (but skip this short-circuit when print_drying_enabled is on — busy printers
- # may still be eligible for mid-print drying regardless of queue state).
- if not ambient_drying_enabled and not printers_with_scheduled and not print_drying_enabled:
- for pid in list(self._drying_in_progress):
- logger.info("Auto-drying: printer %d — stopping, no scheduled prints in queue", pid)
- await self._stop_drying(pid)
- return
- # Get humidity threshold (global fallback)
- result = await db.execute(select(Settings).where(Settings.key == "ams_humidity_fair"))
- setting = result.scalar_one_or_none()
- global_humidity_threshold = int(setting.value) if setting else 60
- # Per-filament humidity threshold overrides (#1605). Empty → fall back
- # to the global threshold for every AMS unit.
- per_type_thresholds = await self._get_humidity_thresholds(db)
- # Get drying presets
- presets = await self._get_drying_presets(db)
- # Determine if drying should be skipped for printers with pending items
- block_for_drying = await self._get_bool_setting(db, "queue_drying_block")
- # Get all active printers
- all_printers = await db.execute(select(Printer).where(Printer.is_active.is_(True)))
- for printer in all_printers.scalars():
- pid = printer.id
- # Resolve model+firmware up front — needed to decide whether this printer
- # qualifies for mid-print drying (busy printer on capable hardware).
- state = printer_manager.get_status(pid)
- if not state:
- logger.debug("Auto-drying: printer %d skipped — no state", pid)
- continue
- model = printer_manager.get_model(pid)
- firmware = state.firmware_version
- mid_print = (
- pid in busy_printers and print_drying_enabled and supports_drying_while_printing(model, firmware)
- )
- if pid in busy_printers and not mid_print:
- logger.debug("Auto-drying: printer %d skipped — busy", pid)
- continue
- if not mid_print:
- # In queue-only mode, only dry printers that have scheduled prints
- if not ambient_drying_enabled and pid not in printers_with_scheduled:
- if self._drying_in_progress.get(pid):
- logger.info("Auto-drying: printer %d — stopping, no scheduled prints for this printer", pid)
- await self._stop_drying(pid)
- logger.debug("Auto-drying: printer %d skipped — no scheduled prints", pid)
- continue
- # When block mode is on, don't START new drying on printers with pending items.
- # But allow already-drying printers through so humidity auto-stop logic still runs.
- if block_for_drying and pid in printers_with_items and not self._drying_in_progress.get(pid):
- logger.debug("Auto-drying: printer %d skipped — has pending items (block mode)", pid)
- continue
- if not printer_manager.is_connected(pid):
- logger.debug("Auto-drying: printer %d skipped — not connected", pid)
- continue
- if not mid_print and not self._is_printer_idle(pid, require_plate_clear):
- logger.debug("Auto-drying: printer %d skipped — not idle", pid)
- continue
- # Check drying capability. For mid-print path, supports_drying_while_printing
- # was already verified when computing mid_print above.
- if not mid_print and not supports_drying(model, firmware):
- logger.debug("Auto-drying: printer %d skipped — model %s does not support drying", pid, model)
- continue
- # Check each AMS unit from raw_data
- ams_list = state.raw_data.get("ams", [])
- logger.debug("Auto-drying: printer %d — checking %d AMS units", pid, len(ams_list))
- for ams_data in ams_list:
- module_type = str(ams_data.get("module_type") or "")
- ams_id = int(ams_data.get("id", 0))
- # Only n3f/n3s support drying
- if module_type not in ("n3f", "n3s"):
- logger.debug("Auto-drying: printer %d AMS %d skipped — module_type=%s", pid, ams_id, module_type)
- continue
- # Resolve per-filament humidity threshold for this AMS unit (#1605).
- # Most-restrictive of all loaded tray types; falls back to the
- # global threshold when no overrides are configured.
- trays = ams_data.get("tray", []) or []
- humidity_threshold = self.resolve_humidity_threshold(
- trays, per_type_thresholds, global_humidity_threshold
- )
- dry_time = int(ams_data.get("dry_time") or 0)
- # Read humidity — prefer humidity_raw (actual %) over humidity (index 1-5)
- humidity = None
- h_raw = ams_data.get("humidity_raw")
- if h_raw is not None:
- try:
- humidity = int(h_raw)
- except (ValueError, TypeError):
- pass
- if humidity is None:
- h_idx = ams_data.get("humidity")
- if h_idx is not None:
- try:
- humidity = int(h_idx)
- except (ValueError, TypeError):
- pass
- # Already drying — let it run to its configured duration (#1892).
- #
- # We deliberately do NOT stop drying from a humidity re-check here.
- # Relative humidity drops steeply in heated air, so the AMS sensor
- # reads ~15-20% within minutes of the dryer starting even while the
- # filament is still saturated. A humidity-based early-stop therefore
- # always fires at the minimum-time floor, truncating both user-started
- # manual cycles and Bambuddy's own preset-duration dries to ~30 min.
- # The firmware stops when the configured duration elapses; scheduling
- # stops (print takes priority, queue no longer needs drying) are
- # handled separately via _stop_drying().
- if dry_time > 0:
- if pid not in self._drying_in_progress:
- # Drying we didn't start (manual or from before restart) —
- # track it so scheduling stops still apply; never auto-stop it.
- self._drying_in_progress[pid] = time.monotonic()
- logger.debug(
- "Auto-drying: printer %d AMS %d — drying (%dm left, humidity %s%%), letting it run",
- pid,
- ams_id,
- dry_time,
- humidity,
- )
- continue
- # Humidity below threshold — no need to start drying
- if humidity is None or humidity <= humidity_threshold:
- logger.debug(
- "Auto-drying: printer %d AMS %d skipped — humidity %s <= threshold %d",
- pid,
- ams_id,
- humidity,
- humidity_threshold,
- )
- continue
- # Check cannot-dry reasons (power constraints etc.)
- sf_reasons = ams_data.get("dry_sf_reason", [])
- if sf_reasons:
- logger.debug(
- "Auto-drying: printer %d AMS %d skipped — cannot dry reasons: %s",
- pid,
- ams_id,
- sf_reasons,
- )
- continue
- # Get conservative drying params for mixed filaments
- params = self._get_conservative_drying_params(trays, module_type, presets)
- if not params:
- logger.debug(
- "Auto-drying: printer %d AMS %d skipped — no drying-eligible filaments in trays", pid, ams_id
- )
- continue
- temp, duration_hours, filament_type = params
- # Mid-print drying: cap drying temperature to protect spools (Bambu warns
- # "drying temperature must not exceed the filament's softening temperature"
- # for Print While Drying). Floor at 40 degC — below that the dryer is
- # ineffective and firmware will reject anyway.
- if mid_print:
- temp = max(40, temp - 5)
- # Start drying
- logger.info(
- "Auto-drying: printer %d AMS %d — humidity %d%% > threshold %d%%, "
- "starting %s drying at %d°C for %dh%s",
- pid,
- ams_id,
- humidity,
- humidity_threshold,
- filament_type,
- temp,
- duration_hours,
- " (mid-print)" if mid_print else "",
- )
- success = printer_manager.send_drying_command(
- pid, ams_id, temp, duration_hours, mode=1, filament=filament_type
- )
- if success:
- self._drying_in_progress[pid] = time.monotonic()
- def _sync_drying_state(self):
- """Sync in-memory drying state with actual printer status.
- Handles backend restart — if a printer is drying but we don't know about it,
- update our state. If we think it's drying but it's not, clear it.
- """
- to_remove = []
- for pid in self._drying_in_progress:
- state = printer_manager.get_status(pid)
- if not state:
- to_remove.append(pid)
- continue
- # Check if any AMS unit is still drying
- ams_list = state.raw_data.get("ams", [])
- any_drying = any(int(a.get("dry_time") or 0) > 0 for a in ams_list)
- if not any_drying:
- to_remove.append(pid)
- for pid in to_remove:
- self._drying_in_progress.pop(pid, None)
- async def _stop_drying(self, printer_id: int):
- """Stop all active drying on a printer (print takes priority)."""
- state = printer_manager.get_status(printer_id)
- if not state:
- self._drying_in_progress.pop(printer_id, None)
- return
- ams_list = state.raw_data.get("ams", [])
- for ams_data in ams_list:
- dry_time = int(ams_data.get("dry_time") or 0)
- if dry_time > 0:
- ams_id = int(ams_data.get("id", 0))
- logger.info(
- "Auto-drying: stopping drying on printer %d AMS %d — print takes priority",
- printer_id,
- ams_id,
- )
- printer_manager.send_drying_command(printer_id, ams_id, 0, 0, mode=0)
- self._drying_in_progress.pop(printer_id, None)
- async def _get_smart_plugs(self, db: AsyncSession, printer_id: int) -> list[SmartPlug]:
- """Get all smart plugs associated with a printer."""
- result = await db.execute(select(SmartPlug).where(SmartPlug.printer_id == printer_id))
- return list(result.scalars().all())
- # Bundled defaults for preheat_filament_targets (#1468). Values are the
- # chamber-temperature recommendations BambuStudio ships for the matching
- # filament profile; users can override via Settings → Workflow → Preheat
- # card. "default" applies when a loaded tray's normalised type isn't in
- # the map (rare — Bambu RFID-tagged spools always carry a known type).
- DEFAULT_PREHEAT_FILAMENT_TARGETS: dict[str, int] = {
- "PLA": 0,
- "PETG": 0,
- "PETG-CF": 40,
- "ABS": 45,
- "ASA": 45,
- "PA": 50,
- "PA-CF": 55,
- "PC": 50,
- "PC-FR": 50,
- "TPU": 0,
- "PVA": 0,
- "default": 0,
- }
- async def _get_preheat_filament_targets(self, db: AsyncSession) -> dict[str, int]:
- """Parse the user-configured filament→chamber-target map, falling back
- to DEFAULT_PREHEAT_FILAMENT_TARGETS on missing / malformed JSON. Keys
- are uppercased and the 'default' fallback is always present in the
- returned dict so the resolution loop can index it unconditionally."""
- raw = await self._get_setting(db, "preheat_filament_targets")
- if not raw:
- return dict(self.DEFAULT_PREHEAT_FILAMENT_TARGETS)
- try:
- parsed = json.loads(raw)
- if not isinstance(parsed, dict):
- raise ValueError("not an object")
- except (json.JSONDecodeError, ValueError) as exc:
- logger.warning("preheat_filament_targets unparseable, using defaults: %s", exc)
- return dict(self.DEFAULT_PREHEAT_FILAMENT_TARGETS)
- # Coerce values to int; drop unparseable rows so a stray string
- # doesn't crash the loop.
- out: dict[str, int] = {}
- for key, value in parsed.items():
- try:
- out[str(key).upper()] = int(value)
- except (TypeError, ValueError):
- continue
- if "DEFAULT" not in out:
- out["DEFAULT"] = self.DEFAULT_PREHEAT_FILAMENT_TARGETS["default"]
- return out
- @staticmethod
- def _normalize_filament_type(tray_type: str) -> str:
- """Reduce the printer's tray_type to a preset-lookup key. Mirrors the
- existing drying-preset normalisation (split-at-space, upper-case) so
- the two maps share vocabulary — "PLA Basic" → "PLA", "PA-CF" stays
- "PA-CF" (no space to split on)."""
- return tray_type.split()[0].upper() if tray_type else ""
- def _derive_chamber_target(
- self,
- printer: Printer,
- targets: dict[str, int],
- ) -> int:
- """Look up the chamber target for each loaded AMS tray and return the
- max. Returns 0 when no AMS data is available (e.g. external-spool
- prints) or when every loaded slot maps to 0 — the chamber phase then
- short-circuits in the main loop.
- Reads from `printer_manager.get_status(...).raw_data['ams']`, which is
- the same source the dispatcher uses for AMS slot mapping. Empty / RFID-
- less slots have empty `tray_type` and contribute nothing."""
- state = printer_manager.get_status(printer.id)
- if state is None:
- return 0
- ams_list = (state.raw_data or {}).get("ams") if state.raw_data else None
- # Older Bambu firmware nests AMS as {"ams": {"ams": [...]}} — try both.
- if isinstance(ams_list, dict):
- ams_list = ams_list.get("ams") or []
- if not isinstance(ams_list, list):
- return 0
- best = 0
- for ams in ams_list:
- for tray in (ams.get("tray") or []) if isinstance(ams, dict) else []:
- normalised = self._normalize_filament_type(tray.get("tray_type") or "")
- if not normalised:
- continue
- target = targets.get(normalised, targets.get("DEFAULT", 0))
- if target > best:
- best = target
- return best
- async def _preheat_and_soak(
- self,
- db: AsyncSession,
- item: PrintQueueItem,
- printer: Printer,
- archive: PrintArchive | None,
- ) -> None:
- """Run the per-printer preheat + heat-soak stage before FTP upload (#1468).
- Resolution order:
- 1. `item.preheat_override` — 'off' skips entirely; 'inherit' falls back
- to the global `preheat_enabled` setting; 'on' forces the stage on
- even if the global is off.
- 2. Chamber target — `item.preheat_chamber_target_override` if non-null;
- else max of `preheat_filament_targets[normalize(t.tray_type)]`
- across loaded AMS slots; else 0 (skips chamber phase, keeps bed
- phase + soak timer).
- 3. Three hardware tiers branch the wait loop:
- - Chamber heater (H2C/H2D/H2DPro/H2S/X2D/X1E via supports_chamber_heater):
- send M141 to the resolved target, then wait for the chamber sensor
- to reach it (or the max-wait timeout to elapse).
- - Chamber sensor only (X1C/P2S via supports_chamber_temp ∧ ¬supports_chamber_heater):
- no M141; the bed is the only heat source, so we wait for the chamber
- sensor to rise via bed radiation OR fall through on timeout.
- - No chamber sensor (P1S/P1P/A1/A1 Mini): no way to verify chamber
- temperature; the function just heats the bed and holds for the
- configured soak duration.
- The bed target comes from the archive's parsed metadata
- (`bed_temperature`); if missing the preheat stage logs and returns
- without dispatching anything, rather than guessing at a default that
- might wreck filament setup.
- Failures are logged but never re-raised — preheat is best-effort. A
- printer that goes offline mid-soak, a refused gcode command, or a
- missing temperature reading must not turn into a failed queue item; the
- normal upload + start path runs immediately after this method returns.
- """
- override = (getattr(item, "preheat_override", None) or "inherit").lower()
- if override == "off":
- return
- if override == "inherit":
- enabled = await self._get_bool_setting(db, "preheat_enabled", default=False)
- if not enabled:
- return
- # override == "on" forces the stage on regardless of the global setting.
- max_wait = await self._get_int_setting(db, "preheat_max_wait_seconds", default=900)
- soak_seconds = await self._get_int_setting(db, "preheat_soak_seconds", default=300)
- # Chamber target resolution:
- # 1. Explicit per-item override beats everything (user knows best).
- # 2. Otherwise derive from loaded AMS filament types via the per-
- # filament target map. PLA-only print derives 0 → chamber phase
- # auto-skips without the user touching anything.
- explicit_target = getattr(item, "preheat_chamber_target_override", None)
- if explicit_target is not None and explicit_target > 0:
- chamber_target = int(explicit_target)
- chamber_source = "item-override"
- elif explicit_target == 0:
- chamber_target = 0 # explicit 0 means "no chamber, even if filament wants it"
- chamber_source = "item-override-zero"
- else:
- targets = await self._get_preheat_filament_targets(db)
- chamber_target = self._derive_chamber_target(printer, targets)
- chamber_source = "filament-map"
- bed_target = int(archive.bed_temperature) if archive and archive.bed_temperature else 0
- if bed_target <= 0:
- logger.info(
- "Queue item %s: preheat skipped — archive has no bed_temperature metadata",
- item.id,
- )
- return
- client = printer_manager.get_client(printer.id)
- if client is None:
- logger.warning("Queue item %s: preheat skipped — printer client unavailable", item.id)
- return
- model = printer.model or ""
- has_heater = supports_chamber_heater(model)
- has_sensor = supports_chamber_temp(model)
- do_chamber = chamber_target > 0 and (has_heater or has_sensor)
- logger.info(
- "Queue item %s: preheat starting — bed=%d°C chamber_target=%d°C (source=%s override=%s "
- "model=%s has_heater=%s has_sensor=%s) max_wait=%ds soak=%ds",
- item.id,
- bed_target,
- chamber_target if do_chamber else 0,
- chamber_source,
- override,
- model,
- has_heater,
- has_sensor,
- max_wait,
- soak_seconds,
- )
- # Dispatch heaters. set_bed_temperature / set_chamber_temperature already
- # cache the target locally so the polling reads below see consistent
- # state (firmware MQTT echoes lag by ~1s).
- try:
- client.set_bed_temperature(bed_target)
- except Exception as exc:
- logger.warning("Queue item %s: preheat bed M140 failed: %s", item.id, exc)
- return
- # Airduct mode (#1468 follow-up). Models with the cooling/heating flap
- # (H2C/H2D/H2D Pro/H2S/X2D/P2S) keep the flap whatever the user last
- # left it on, regardless of M141. Default cooling actively vents the
- # chamber, so a `chamber_target > 0` print with the flap stuck in
- # cooling never converges — the heater fights the open exhaust. We
- # flip the flap BEFORE M141 to "heating" when the preheat wants
- # chamber heat, and back to "cooling" when it doesn't (PLA-only print
- # on an H2D that was previously running ABS would otherwise stay in
- # heating mode and overheat PLA). The current-state read keeps the
- # command idempotent — no MQTT chatter when the flap is already where
- # we want it.
- if supports_airduct(model):
- desired_airduct = "heating" if chamber_target > 0 else "cooling"
- desired_id = 1 if desired_airduct == "heating" else 0
- current_state = printer_manager.get_status(printer.id)
- current_airduct = getattr(current_state, "airduct_mode", None) if current_state else None
- if current_airduct != desired_id:
- try:
- client.set_airduct_mode(desired_airduct)
- except Exception as exc:
- logger.warning(
- "Queue item %s: preheat airduct %s mode failed: %s",
- item.id,
- desired_airduct,
- exc,
- )
- if do_chamber and has_heater:
- try:
- client.set_chamber_temperature(chamber_target)
- except Exception as exc:
- logger.warning("Queue item %s: preheat chamber M141 failed: %s", item.id, exc)
- # Wait for convergence. Bed warm-up is fast (~5 min from cold); chamber
- # via M141 takes a few minutes; chamber via bed radiation can take 20+.
- # Poll every 3s — frequent enough for responsive logging without
- # spamming the MQTT state stream. The "converged" predicate is:
- # bed reached target (within 2°C tolerance for floating-point + heater hysteresis),
- # AND
- # chamber phase satisfied (no chamber phase, no sensor, or sensor reached target).
- BED_TOLERANCE = 2.0
- CHAMBER_TOLERANCE = 2.0
- POLL_INTERVAL = 3.0
- deadline = asyncio.get_event_loop().time() + max_wait
- while True:
- state = printer_manager.get_status(printer.id)
- if state is None:
- logger.warning("Queue item %s: preheat lost state during wait", item.id)
- break
- temps = state.temperatures or {}
- bed_now = float(temps.get("bed", 0) or 0)
- chamber_now = float(temps.get("chamber", 0) or 0)
- bed_ok = bed_now >= bed_target - BED_TOLERANCE
- if not do_chamber:
- chamber_ok = True # phase disabled or model has neither sensor nor heater
- elif not has_sensor:
- chamber_ok = True # P1S etc — can't read, rely on soak timer only
- else:
- chamber_ok = chamber_now >= chamber_target - CHAMBER_TOLERANCE
- if bed_ok and chamber_ok:
- logger.info(
- "Queue item %s: preheat target reached (bed=%.1f chamber=%.1f) — entering soak",
- item.id,
- bed_now,
- chamber_now,
- )
- break
- if asyncio.get_event_loop().time() >= deadline:
- logger.info(
- "Queue item %s: preheat max_wait reached (bed=%.1f/%d chamber=%.1f/%d) — falling through to soak",
- item.id,
- bed_now,
- bed_target,
- chamber_now,
- chamber_target if do_chamber else 0,
- )
- break
- await asyncio.sleep(POLL_INTERVAL)
- if soak_seconds > 0:
- logger.info("Queue item %s: preheat soak — holding for %ds", item.id, soak_seconds)
- await asyncio.sleep(soak_seconds)
- logger.info("Queue item %s: preheat complete — proceeding to upload", item.id)
- async def _power_on_and_wait(self, plug: SmartPlug, printer_id: int, db: AsyncSession) -> bool:
- """Turn on smart plug and wait for printer to connect.
- Returns True if printer connected successfully within timeout.
- """
- # Get the appropriate service for the plug type (Tasmota or Home Assistant)
- service = await smart_plug_manager.get_service_for_plug(plug, db)
- # Check current plug state
- status = await service.get_status(plug)
- if not status.get("reachable"):
- logger.warning("Smart plug '%s' is not reachable", plug.name)
- return False
- # Turn on if not already on
- if status.get("state") != "ON":
- success = await service.turn_on(plug)
- if not success:
- logger.warning("Failed to turn on smart plug '%s'", plug.name)
- return False
- logger.info("Powered on smart plug '%s' for printer %s", plug.name, printer_id)
- # Get printer from database for connection
- result = await db.execute(select(Printer).where(Printer.id == printer_id))
- printer = result.scalar_one_or_none()
- if not printer:
- logger.error("Printer %s not found in database", printer_id)
- return False
- # Wait for printer to boot (give it some time before trying to connect)
- logger.info("Waiting 30s for printer %s to boot...", printer_id)
- await asyncio.sleep(30)
- # Try to connect to the printer periodically
- elapsed = 30 # Already waited 30s
- while elapsed < self._power_on_wait_time:
- # Try to connect
- logger.info("Attempting to connect to printer %s...", printer_id)
- try:
- connected = await printer_manager.connect_printer(printer)
- if connected:
- logger.info("Printer %s connected after %ss", printer_id, elapsed)
- # Give it a moment to stabilize and get status
- await asyncio.sleep(5)
- return True
- except Exception as e:
- logger.debug("Connection attempt failed: %s", e)
- await asyncio.sleep(self._power_on_check_interval)
- elapsed += self._power_on_check_interval
- logger.debug("Waiting for printer %s to connect... (%ss)", printer_id, elapsed)
- logger.warning("Printer %s did not connect within %ss after power on", printer_id, self._power_on_wait_time)
- return False
- async def _check_previous_success(self, db: AsyncSession, item: PrintQueueItem) -> bool:
- """Check if the previous print on this printer succeeded.
- A user-cancelled predecessor is treated as neutral — `cancelled` is a
- deliberate action, not a failure, so subsequent items should still
- dispatch (#1667). `skipped` is excluded from the lookback entirely:
- a skip isn't an actual print attempt, so it must not gate downstream
- items — counting it as a failed predecessor was the cascade bug that
- let a single cancellation block 18 items over 3 days for the reporter.
- Only `failed` and `aborted` — real print-attempt failures — block.
- Failures with `gate_acknowledged=True` (set by the per-printer Resume
- action — #1818) are also excluded from the lookback so the user can
- clear the gate after fixing the physical issue without having to
- re-queue every downstream job.
- """
- result = await db.execute(
- select(PrintQueueItem)
- .where(PrintQueueItem.printer_id == item.printer_id)
- .where(PrintQueueItem.id != item.id)
- .where(PrintQueueItem.status.in_(["completed", "failed", "cancelled", "aborted"]))
- .where(PrintQueueItem.gate_acknowledged == False) # noqa: E712
- .order_by(PrintQueueItem.completed_at.desc())
- .limit(1)
- )
- prev_item = result.scalar_one_or_none()
- # If no previous item, assume success (first in queue)
- if not prev_item:
- return True
- return prev_item.status in ("completed", "cancelled")
- async def _power_off_if_needed(self, db: AsyncSession, item: PrintQueueItem):
- """Schedule power-off if the queue item enabled auto_off_after.
- Delegates to the smart-plug manager so the off honours each plug's
- configured strategy (time delay or temperature threshold), is cancelled
- if the printer starts printing again, and never cuts power on a loaded
- print (#1890). Previously this hardcoded a 50°C / 600s cooldown wait and
- powered off on the timeout regardless of print state.
- """
- if not item.auto_off_after:
- return
- try:
- await smart_plug_manager.schedule_off_after_queue_job(item.printer_id, db)
- except Exception as e:
- logger.warning("Auto-off: Failed to schedule power-off for printer %s: %s", item.printer_id, e)
- async def _get_job_name(self, db: AsyncSession, item: PrintQueueItem) -> str:
- """Get a human-readable name for a queue item."""
- if item.archive_id:
- result = await db.execute(select(PrintArchive).where(PrintArchive.id == item.archive_id))
- archive = result.scalar_one_or_none()
- if archive:
- return archive.filename.replace(".gcode.3mf", "").replace(".3mf", "")
- if item.library_file_id:
- result = await db.execute(LibraryFile.active().where(LibraryFile.id == item.library_file_id))
- library_file = result.scalar_one_or_none()
- if library_file:
- return library_file.filename.replace(".gcode.3mf", "").replace(".3mf", "")
- return f"Job #{item.id}"
- async def _get_printer(self, db: AsyncSession, printer_id: int) -> Printer | None:
- """Get printer by ID."""
- result = await db.execute(select(Printer).where(Printer.id == printer_id))
- return result.scalar_one_or_none()
- async def _notify_dispatch_gave_up(
- self,
- queue_item_id: int,
- printer_id: int,
- created_by_id: int | None,
- ) -> None:
- """Tell the user the queue item was failed after exhausting its dispatch retries.
- Called from the watchdog, which is a background task with no session of
- its own — hence the fresh one here. Best-effort throughout: the row is
- already marked failed and that is the load-bearing part; a notification
- provider being down must not resurrect the retry loop we just stopped.
- """
- try:
- async with async_session() as db:
- item = await db.get(PrintQueueItem, queue_item_id)
- if not item:
- return
- job_name = await self._get_job_name(db, item)
- printer = await self._get_printer(db, printer_id)
- await notification_service.on_queue_job_failed(
- job_name=job_name,
- printer_id=printer_id,
- printer_name=printer.name if printer else "Unknown",
- reason="Printer accepted the file but never started printing",
- db=db,
- )
- except Exception as e:
- logger.warning("Queue item %s: give-up notification failed: %s", queue_item_id, e)
- try:
- await ws_manager.send_queue_item_failed(
- user_id=created_by_id,
- queue_item_id=queue_item_id,
- printer_id=printer_id,
- reason="never_started",
- )
- except Exception:
- pass # toast is best-effort
- async def _block_on_filament_deficit(
- self,
- db: AsyncSession,
- item: PrintQueueItem,
- ) -> bool:
- """Promote the item to manual_start when the assigned spool is short (#1496).
- Returns True when this dispatch attempt was blocked, False when the
- item is clear to start. A previously-flagged item whose spool has
- since been swapped to one with enough material clears the flag here
- so the next scheduler tick dispatches it.
- """
- # User has explicitly acknowledged the deficit ("Print Anyway") —
- # don't re-flag, don't even compute. Without this short-circuit the
- # scheduler bounces between "user said anyway" (route clears
- # manual_start) and "scheduler re-blocked" (this method re-flags it
- # on identical spool state) (#1698-followup).
- if item.skip_filament_check:
- # #1762 diagnostic: surface the short-circuit at INFO so a
- # future "Print Anyway didn't work" report (e.g. issue #1762
- # comment 3) has actionable evidence in the support bundle
- # without needing DEBUG enabled.
- logger.info(
- "Queue item %s honouring user's Print Anyway acknowledgement — skipping deficit check",
- item.id,
- )
- return False
- try:
- deficit = await compute_deficit_for_queue_item(db, item)
- except Exception as e:
- # Never let a flaky deficit check wedge the queue — log and let
- # dispatch proceed. The PrintModal-side check still runs on the
- # manual paths.
- logger.warning("Filament deficit check failed for item %s: %s", item.id, e)
- return False
- if deficit:
- item.filament_short = True
- item.manual_start = True
- await db.commit()
- job_name = await self._get_job_name(db, item)
- printer = await self._get_printer(db, item.printer_id) if item.printer_id else None
- logger.info(
- "Queue item %s blocked on filament deficit (%d slot(s)) — promoted to manual_start",
- item.id,
- len(deficit),
- )
- try:
- await notification_service.on_queue_job_waiting(
- job_name=job_name,
- target_model=(printer.model if printer else "") or "",
- waiting_reason="filament_short",
- db=db,
- )
- except Exception as e:
- logger.debug("filament_short notification failed for item %s: %s", item.id, e)
- return True
- # No deficit — clear any stale flag from a previous tick.
- if item.filament_short:
- item.filament_short = False
- await db.commit()
- return False
- async def _propagate_owner_to_printer_manager(self, db: AsyncSession, item: PrintQueueItem) -> None:
- """Hand the queue item's owner to printer_manager so the
- print-complete callback can credit the user in PrintLogEntry (#1670).
- No-ops when the item has no `created_by_id` or the referenced user
- row is missing (e.g. user deleted between queue-add and dispatch —
- in that case the print log row falls back to the existing un-credited
- behaviour rather than crashing the dispatch).
- """
- if not item.created_by_id:
- return
- from backend.app.models.user import User
- owner = await db.get(User, item.created_by_id)
- if owner:
- printer_manager.set_current_print_user(item.printer_id, owner.id, owner.username)
- async def _start_print(self, db: AsyncSession, item: PrintQueueItem):
- """Upload file and start print for a queue item.
- Supports two sources:
- - archive_id: Print from an existing archive
- - library_file_id: Print from a library file (file manager)
- """
- logger.info("Starting queue item %s", item.id)
- # Get printer first (needed for both paths)
- result = await db.execute(select(Printer).where(Printer.id == item.printer_id))
- printer = result.scalar_one_or_none()
- if not printer:
- item.status = "failed"
- item.error_message = "Printer not found"
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- logger.error("Queue item %s: Printer %s not found", item.id, item.printer_id)
- await self._power_off_if_needed(db, item)
- return
- # Check printer is connected
- if not printer_manager.is_connected(item.printer_id):
- item.status = "failed"
- item.error_message = "Printer not connected"
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- logger.error("Queue item %s: Printer %s not connected", item.id, item.printer_id)
- await self._power_off_if_needed(db, item)
- return
- # Cancel-while-dispatching race (#1853): the scheduler's snapshot of
- # `items` was taken at the top of check_queue, but the user can /cancel
- # any pending row in the gap before we reach this point. Re-read the
- # row and bail out cleanly instead of starting an FTP upload for a row
- # that's already cancelled. The atomic CAS at the pending→printing
- # transition (below, before start_print) is the load-bearing guard;
- # this is the early-exit optimisation that avoids wasted FTP I/O.
- await db.refresh(item)
- if item.status != "pending":
- logger.info(
- "Queue item %s no longer pending (status=%s) — aborting dispatch",
- item.id,
- item.status,
- )
- return
- # Determine source: archive or library file
- archive = None
- library_file = None
- file_path = None
- filename = None
- cleanup_disk_paths: list[Path] = []
- if item.archive_id:
- # Print from archive
- result = await db.execute(select(PrintArchive).where(PrintArchive.id == item.archive_id))
- archive = result.scalar_one_or_none()
- if not archive:
- item.status = "failed"
- item.error_message = "Archive not found"
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- logger.error("Queue item %s: Archive %s not found", item.id, item.archive_id)
- await self._power_off_if_needed(db, item)
- return
- file_path = settings.base_dir / archive.file_path
- filename = archive.filename
- elif item.library_file_id:
- # Print from library file (file manager)
- result = await db.execute(LibraryFile.active().where(LibraryFile.id == item.library_file_id))
- library_file = result.scalar_one_or_none()
- if not library_file:
- item.status = "failed"
- item.error_message = "Library file not found"
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- logger.error("Queue item %s: Library file %s not found", item.id, item.library_file_id)
- await self._power_off_if_needed(db, item)
- return
- # Library files store absolute paths
- lib_path = Path(library_file.file_path)
- file_path = lib_path if lib_path.is_absolute() else settings.base_dir / library_file.file_path
- filename = library_file.filename
- # Create archive from library file so usage tracking has access to the 3MF
- queue_item_id = item.id
- try:
- from backend.app.services.archive import ArchiveService
- archive_service = ArchiveService(db)
- archive = await archive_service.archive_print(
- printer_id=item.printer_id,
- source_file=file_path,
- original_filename=filename,
- created_by_id=item.created_by_id,
- project_id=item.project_id,
- )
- if archive:
- item.archive_id = archive.id
- if item.cleanup_library_after_dispatch and not library_file.is_external:
- item.library_file_id = None
- cleanup_disk_paths.append(file_path)
- if library_file.thumbnail_path:
- thumb_path = Path(library_file.thumbnail_path)
- if not thumb_path.is_absolute():
- thumb_path = settings.base_dir / library_file.thumbnail_path
- cleanup_disk_paths.append(thumb_path)
- await db.delete(library_file)
- file_path = settings.base_dir / archive.file_path
- filename = archive.filename
- # Commit, not flush — flush opens the SQLite write
- # transaction (item.archive_id update + library_file
- # delete) and would hold the WAL writer lock through the
- # FTP upload below, causing "database is locked" cascades
- # for sensor history + concurrent cancels (#1853).
- await db.commit()
- logger.info(
- "Queue item %s: Created archive %s from library file %s",
- item.id,
- archive.id,
- item.library_file_id,
- )
- except Exception as e:
- logger.warning(
- "Queue item %s: Failed to create archive from library file: %s",
- queue_item_id,
- e,
- exc_info=True,
- )
- await db.rollback()
- item = await db.get(PrintQueueItem, queue_item_id)
- if item:
- item.status = "failed"
- item.error_message = "Failed to create archive from library file"
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- await self._power_off_if_needed(db, item)
- return
- if not archive:
- item.status = "failed"
- item.error_message = "Failed to create archive from library file"
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- logger.error("Queue item %s: Archive creation from library file returned no archive", item.id)
- await self._power_off_if_needed(db, item)
- return
- else:
- # Neither archive nor library file specified
- item.status = "failed"
- item.error_message = "No source file specified"
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- logger.error("Queue item %s: No archive_id or library_file_id specified", item.id)
- await self._power_off_if_needed(db, item)
- return
- # Check file exists on disk
- if not file_path.exists():
- item.status = "failed"
- item.error_message = "Source file not found on disk"
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- logger.error("Queue item %s: File not found: %s", item.id, file_path)
- await self._power_off_if_needed(db, item)
- return
- # Nozzle-diameter mismatch guard (#1899). A file sliced for one nozzle
- # size dispatched to a printer with a different nozzle installed is
- # rejected by the firmware with a cryptic HMS ("Failed to get AMS mapping
- # table" 0700_8012, or "nozzle diameter … not consistent" 0500_4038) that
- # gives the user no idea what went wrong. Catch it here, before we spend
- # time preheating and uploading, and fail with an actionable message.
- # Fail-safe by construction: only a POSITIVE mismatch blocks — when the
- # slice carries no nozzle diameter (archive.nozzle_diameter is None) or
- # the printer hasn't reported its nozzles yet, we fall through and let the
- # print proceed exactly as before. On dual-nozzle printers (H2D) a match
- # against EITHER installed nozzle passes, so a 0.6 slice is fine as long
- # as one of the two hotends is a 0.6.
- sliced_nozzle = archive.nozzle_diameter if archive else None
- if sliced_nozzle:
- installed = _installed_nozzle_diameters(printer_manager.get_status(item.printer_id))
- mismatch_msg = _nozzle_mismatch_message(sliced_nozzle, installed)
- if mismatch_msg:
- item.status = "failed"
- item.error_message = mismatch_msg
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- logger.warning("Queue item %s: nozzle mismatch — %s", item.id, mismatch_msg)
- await notification_service.on_queue_job_failed(
- job_name=filename.replace(".gcode.3mf", "").replace(".3mf", ""),
- printer_id=printer.id,
- printer_name=printer.name,
- reason=mismatch_msg,
- db=db,
- )
- try:
- await ws_manager.send_queue_item_failed(
- user_id=item.created_by_id,
- queue_item_id=item.id,
- printer_id=item.printer_id,
- reason="nozzle_mismatch",
- )
- except Exception:
- pass
- await self._power_off_if_needed(db, item)
- return
- # Preheat / heat-soak (#1468) — fires before upload so the printer's
- # bed (and chamber, if applicable) is at temperature when the firmware
- # starts the actual print routine. Best-effort: any failure logs and
- # falls through to the normal upload+start path rather than turning a
- # configuration issue into a failed queue item.
- await self._preheat_and_soak(db, item, printer, archive)
- # G-code injection for auto-print systems (#422)
- injected_path = None
- if item.gcode_injection:
- try:
- snippets_raw = await self._get_setting(db, "gcode_snippets")
- if snippets_raw:
- snippets = json.loads(snippets_raw)
- model_snippets = snippets.get(printer.model, {})
- start_gc = (model_snippets.get("start_gcode") or "").strip()
- end_gc = (model_snippets.get("end_gcode") or "").strip()
- if start_gc or end_gc:
- from backend.app.utils.threemf_tools import inject_gcode_into_3mf
- injected_path = inject_gcode_into_3mf(
- file_path, item.plate_id or 1, start_gc or None, end_gc or None
- )
- if injected_path:
- file_path = injected_path
- logger.info("Queue item %s: G-code injected for model %s", item.id, printer.model)
- else:
- logger.warning(
- "Queue item %s: G-code injection returned no result, using original", item.id
- )
- except Exception as e:
- logger.warning("Queue item %s: G-code injection failed, using original: %s", item.id, e)
- # Upload to root directory (not /cache/) - the start_print command references
- # files by name only (ftp://{filename}), so they must be in the root
- remote_filename = derive_remote_filename(filename)
- remote_path = f"/{remote_filename}"
- # Get FTP retry settings
- ftp_retry_enabled, ftp_retry_count, ftp_retry_delay, ftp_timeout = await get_ftp_retry_settings()
- logger.info(
- f"Queue item {item.id}: FTP upload starting - printer={printer.name} ({printer.model}), "
- f"ip={printer.ip_address}, file={remote_filename}, local_path={file_path}, "
- f"retry_enabled={ftp_retry_enabled}, retry_count={ftp_retry_count}, timeout={ftp_timeout}"
- )
- # Delete existing file if present (avoids 553 error on overwrite)
- try:
- logger.debug("Queue item %s: Deleting existing file %s if present...", item.id, remote_path)
- delete_result = await delete_file_async(
- printer.ip_address,
- printer.access_code,
- remote_path,
- socket_timeout=ftp_timeout,
- printer_model=printer.model,
- )
- logger.debug("Queue item %s: Delete result: %s", item.id, delete_result)
- except Exception as e:
- logger.debug("Queue item %s: Delete failed (may not exist): %s", item.id, e)
- # Dispatch toast — announce the upload start with the total byte
- # count so the frontend can render an honest progress bar.
- toast_uid = item.created_by_id
- toast_file_name = filename.replace(".gcode.3mf", "").replace(".3mf", "")
- try:
- total_bytes = file_path.stat().st_size
- except OSError:
- total_bytes = 0
- try:
- await ws_manager.send_queue_item_uploading(
- user_id=toast_uid,
- queue_item_id=item.id,
- printer_id=item.printer_id,
- printer_name=printer.name,
- file_name=toast_file_name,
- total_bytes=total_bytes,
- )
- except Exception:
- pass # toast is best-effort
- progress_bridge = _UploadProgressBridge(toast_uid, item.id)
- # A deadline expiry gets its own message: "check your SD card" is the
- # wrong advice for a link that was simply too slow to finish (#2529).
- upload_error: str | None = None
- try:
- if ftp_retry_enabled:
- uploaded = await with_ftp_retry(
- upload_file_async,
- printer.ip_address,
- printer.access_code,
- file_path,
- remote_path,
- socket_timeout=ftp_timeout,
- printer_model=printer.model,
- progress_callback=progress_bridge,
- max_retries=ftp_retry_count,
- retry_delay=ftp_retry_delay,
- operation_name=f"Upload print to {printer.name}",
- )
- else:
- uploaded = await upload_file_async(
- printer.ip_address,
- printer.access_code,
- file_path,
- remote_path,
- socket_timeout=ftp_timeout,
- printer_model=printer.model,
- progress_callback=progress_bridge,
- )
- except UploadCancelled as e:
- uploaded = False
- upload_error = (
- "Upload was too slow to finish and was cancelled. The printer's connection could not sustain "
- "the transfer — check its Wi-Fi signal, or move it closer to the access point."
- )
- logger.error("Queue item %s: upload deadline exceeded: %s", item.id, e)
- except Exception as e:
- uploaded = False
- logger.error("Queue item %s: FTP error: %s (type: %s)", item.id, e, type(e).__name__)
- # Clean up injected temp file after upload attempt
- if injected_path and injected_path.exists():
- injected_path.unlink(missing_ok=True)
- if not uploaded:
- error_msg = upload_error or (
- "Failed to upload file to printer. Check if SD card is inserted and properly formatted (FAT32/exFAT). "
- "See server logs for detailed diagnostics."
- )
- item.status = "failed"
- item.error_message = error_msg
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- logger.error(
- f"Queue item {item.id}: FTP upload failed - printer={printer.name}, model={printer.model}, "
- f"ip={printer.ip_address}. Check logs above for storage diagnostics and specific error codes."
- )
- # Send failure notification
- await notification_service.on_queue_job_failed(
- job_name=filename.replace(".gcode.3mf", "").replace(".3mf", ""),
- printer_id=printer.id,
- printer_name=printer.name,
- reason="Failed to upload file to printer",
- db=db,
- )
- try:
- await ws_manager.send_queue_item_failed(
- user_id=toast_uid,
- queue_item_id=item.id,
- printer_id=item.printer_id,
- reason="upload_failed",
- )
- except Exception:
- pass
- await self._power_off_if_needed(db, item)
- return
- # Parse AMS mapping if stored
- ams_mapping = None
- if item.ams_mapping:
- try:
- ams_mapping = json.loads(item.ams_mapping)
- except json.JSONDecodeError:
- logger.warning("Queue item %s: Invalid AMS mapping JSON, ignoring", item.id)
- # Register as expected print so we don't create a duplicate archive
- # Only applicable for archive-based prints
- if archive:
- from backend.app.main import register_expected_print
- register_expected_print(
- item.printer_id,
- remote_filename,
- archive.id,
- ams_mapping=ams_mapping,
- created_by_id=item.created_by_id,
- plate_id=item.plate_id,
- )
- # Propagate the queue item's owner into printer_manager so the
- # print-complete callback can credit the user in the PrintLogEntry
- # (#1670). `created_by_id` is set either at queue-add time (UI-added
- # items) or when the user clicks the manual-start button.
- await self._propagate_owner_to_printer_manager(db, item)
- # IMPORTANT: Set status to "printing" BEFORE sending the print command.
- # This prevents phantom reprints if the backend crashes/restarts after the
- # print command is sent but before the status update is committed.
- # If we crash after this commit but before start_print(), the item will be
- # in "printing" status without actually printing - but that's safer than
- # accidentally reprinting the same file hours later.
- #
- # Atomic CAS (#1853): a user pressing /cancel mid-dispatch (between the
- # initial pending read at the top of check_queue and this point) flips
- # the row to "cancelled" in a separate session. Without the WHERE
- # status='pending' clause, the unconditional update here would silently
- # overwrite that cancellation and we'd ship the MQTT start_print below
- # — printer obeys, user sees "I pressed cancel and the print started".
- # rowcount==0 means the user won the race; bail out, best-effort delete
- # the file we just uploaded, do NOT send start_print.
- now_utc = datetime.now(timezone.utc)
- cas = await db.execute(
- update(PrintQueueItem)
- .where(PrintQueueItem.id == item.id)
- .where(PrintQueueItem.status == "pending")
- .values(status="printing", started_at=now_utc)
- )
- await db.commit()
- if cas.rowcount == 0:
- logger.info(
- "Queue item %s no longer pending at print-command time "
- "(cancelled or removed mid-dispatch) — aborting before MQTT send (#1853)",
- item.id,
- )
- try:
- await delete_file_async(
- printer.ip_address,
- printer.access_code,
- remote_path,
- socket_timeout=ftp_timeout,
- printer_model=printer.model,
- )
- except Exception as cleanup_err:
- logger.debug(
- "Queue item %s: best-effort cleanup of uploaded file failed: %s",
- item.id,
- cleanup_err,
- )
- try:
- await ws_manager.send_queue_item_failed(
- user_id=toast_uid,
- queue_item_id=item.id,
- printer_id=item.printer_id,
- reason="cancelled_mid_dispatch",
- )
- except Exception:
- pass
- return
- # Sync the in-memory item so subsequent code that reads item.status /
- # item.started_at sees the values we just persisted.
- item.status = "printing"
- item.started_at = now_utc
- for cleanup_path in cleanup_disk_paths:
- try:
- if cleanup_path.exists():
- cleanup_path.unlink()
- except OSError as cleanup_err:
- logger.warning(
- "TRANSIENT_LIBRARY_FILE_ORPHAN %s",
- json.dumps(
- {
- "queue_item_id": item.id,
- "path": str(cleanup_path),
- "error": str(cleanup_err),
- },
- sort_keys=True,
- ),
- )
- # Clear the awaiting-plate-clear flag now that we're starting a new print
- printer_manager.set_awaiting_plate_clear(item.printer_id, False)
- logger.info("Queue item %s: Status set to 'printing', sending print command...", item.id)
- # Capture state before dispatch so the watchdog can detect whether the
- # printer actually transitioned (#967). Also capture subtask_id so the
- # watchdog can recognise "command landed but state hasn't flipped yet"
- # on slow H2D transitions (#1078).
- pre_status = printer_manager.get_status(item.printer_id)
- pre_state = getattr(pre_status, "state", None) if pre_status else None
- pre_subtask_id = getattr(pre_status, "subtask_id", None) if pre_status else None
- pre_gcode_file = getattr(pre_status, "gcode_file", None) if pre_status else None
- # #1721: respect the user's explicit timelapse choice. The #1397
- # force-on at dispatch was removed because it caused per-layer nozzle
- # parking on slicer profiles with Timelapse Type = Smooth. Finish-photo
- # capture is now driven by the stg_cur=22 transition in bambu_mqtt.py
- # ("Filament unloading", toolhead parked, bed not yet dropped) with a
- # FINISH-state fallback — no need to force a video.
- effective_timelapse = bool(item.timelapse)
- # Start the print with AMS mapping, plate_id and print options.
- # nozzle_mapping rides through verbatim — JSON string captured from
- # Bambu Studio's project_file on VP intake (#1780); the MQTT layer
- # parses + injects it only for dual-nozzle models so a null on every
- # other model is a transparent pass-through.
- started = printer_manager.start_print(
- item.printer_id,
- remote_filename,
- plate_id=item.plate_id or 1,
- ams_mapping=ams_mapping,
- bed_levelling=item.bed_levelling,
- flow_cali=item.flow_cali,
- vibration_cali=item.vibration_cali,
- layer_inspect=item.layer_inspect,
- timelapse=effective_timelapse,
- use_ams=item.use_ams,
- nozzle_offset_cali=item.nozzle_offset_cali,
- nozzle_mapping=item.nozzle_mapping,
- )
- if started:
- logger.info("Queue item %s: Print started successfully - %s", item.id, filename)
- # No dispatch-toast event here: the legacy bg-dispatch path kept
- # status='processing' from upload start until the printer acked
- # (or timed out). The frontend derives "Awaiting printer…" purely
- # from upload_progress_pct >= 99.9; an explicit 'dispatched' WS
- # event would push the status chip out of 'PROCESSING' prematurely
- # — which is exactly what the screenshot at #1625-followup
- # complained about.
- # Register the local 3MF in the cover-cache so /cover skips FTP
- # (#1166 follow-up). file_path was resolved earlier from either the
- # archive or the library file row.
- if file_path is not None:
- cache_3mf_download(item.printer_id, remote_filename, file_path)
- # Hold the printer against further dispatches until the watchdog
- # confirms the printer transitioned (or until the hard timeout).
- # Prevents multi-plate batches from triple-dispatching onto the
- # same H2D Pro while it digests the first project_file (#1157).
- self._mark_printer_dispatched(item.printer_id, pre_state, pre_subtask_id)
- # Watchdog: if the printer never transitions out of pre_state AND
- # never advances subtask_id, the MQTT publish was accepted locally but
- # didn't reach the printer (half-broken session — same shape as
- # #887/#936). Revert the queue item so the next dispatch can pick it
- # up instead of leaving it stuck in "printing" (#967). subtask_id
- # check avoids false reverts on slow H2D FINISH→PREPARE transitions
- # that would otherwise cause the item to re-dispatch as a reprint
- # of the just-finished job (#1078).
- if pre_state:
- spawn_background_task(
- self._watchdog_print_start(
- item.id,
- item.printer_id,
- pre_state,
- pre_subtask_id,
- pre_gcode_file,
- created_by_id=toast_uid,
- ),
- name=f"watchdog-print-start-{item.id}",
- )
- # Get estimated time for notification.
- #
- # This used to fall back to `library_file.print_time_seconds`, a column
- # LibraryFile does not have — the print time it knows about lives in
- # `file_metadata`. So a library print whose archive carried no parseable
- # print time (a plain .gcode, or a 3MF the parser could not read) raised
- # AttributeError right here, *after* the printer had already been sent
- # the job: the started-notification never fired, and the exception
- # unwound the whole queue pass, so every other printer still waiting to
- # be dispatched on that tick silently missed its turn.
- #
- # The queue item caches the print time at creation ("Cached from
- # archive/library"), which is the value this was reaching for.
- estimated_time = None
- if archive and archive.print_time_seconds:
- estimated_time = archive.print_time_seconds
- elif item.print_time_seconds:
- estimated_time = item.print_time_seconds
- # Send job started notification
- await notification_service.on_queue_job_started(
- job_name=filename.replace(".gcode.3mf", "").replace(".3mf", ""),
- printer_id=printer.id,
- printer_name=printer.name,
- db=db,
- estimated_time=estimated_time,
- )
- # MQTT relay - publish queue job started
- try:
- from backend.app.services.mqtt_relay import mqtt_relay
- await mqtt_relay.on_queue_job_started(
- job_id=item.id,
- filename=filename,
- printer_id=printer.id,
- printer_name=printer.name,
- printer_serial=printer.serial_number,
- )
- except Exception:
- pass # Don't fail if MQTT fails
- else:
- # Clean up uploaded file from SD card to prevent phantom prints
- try:
- await delete_file_async(
- printer.ip_address,
- printer.access_code,
- remote_path,
- printer_model=printer.model,
- )
- except Exception:
- pass # Best-effort — don't fail the error handler
- # Print command failed - revert status
- item.status = "failed"
- item.error_message = "Failed to send print command to printer"
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- logger.error(
- f"Queue item {item.id}: Failed to start print on {printer.name} ({printer.model}) - "
- f"printer_manager.start_print() returned False. "
- f"This may indicate: printer not connected, MQTT error, unsupported model configuration, or firmware issue. "
- f"Check printer status and backend logs for details."
- )
- # Send failure notification
- await notification_service.on_queue_job_failed(
- job_name=filename.replace(".gcode.3mf", "").replace(".3mf", ""),
- printer_id=printer.id,
- printer_name=printer.name,
- reason="Failed to send print command to printer - check printer connection and status",
- db=db,
- )
- try:
- await ws_manager.send_queue_item_failed(
- user_id=toast_uid,
- queue_item_id=item.id,
- printer_id=item.printer_id,
- reason="start_command_failed",
- )
- except Exception:
- pass
- await self._power_off_if_needed(db, item)
- @staticmethod
- async def _watchdog_print_start(
- queue_item_id: int,
- printer_id: int,
- pre_state: str,
- pre_subtask_id: str | None = None,
- pre_gcode_file: str | None = None,
- timeout: float = 90.0,
- phase_b_timeout: float = 180.0,
- poll_interval: float = 3.0,
- created_by_id: int | None = None,
- ) -> None:
- """Revert a queue item if the printer never acknowledges the start command.
- Bambuddy optimistically marks the queue item as "printing" right after the
- MQTT project_file publish succeeds locally. The watchdog runs in two phases:
- Phase A (up to ``timeout``): wait for either an active-state transition
- or a ``subtask_id`` advance past ``pre_subtask_id``. State alone is the
- primary signal; subtask_id advance handles the H2D case where state can
- sit at FINISH for ~50 s after the printer accepted ``project_file``
- before flipping to PREPARE (#1078). If neither happens, the MQTT publish
- was lost on a half-broken session (#887/#936) — revert and force
- reconnect (the #967 recovery path).
- Phase B (up to ``phase_b_timeout``, only if Phase A exited on subtask_id
- alone): keep watching for the active-state transition. subtask_id alone
- proves the file landed but not that the printer started — and a printer
- that accepts the command but stays at IDLE/FINISH indefinitely (e.g.
- cloud+LAN re-auth dance after a power cycle on old firmware, #1678)
- used to leave the queue item stuck in 'printing' forever because the
- old watchdog returned success as soon as subtask_id advanced. If Phase
- B times out, revert the queue item so the user can retry without
- restarting Bambuddy. Skip ``force_reconnect`` here: the file landed and
- a forced reconnect mid-parse triggers 0500_4003 (#1150).
- Phase A timeout raised from 45 s → 90 s as belt-and-braces for slow
- transitions that also don't emit an early subtask_id tick.
- """
- last_status = None
- landed_on_subtask = False
- deadline = time.monotonic() + timeout
- while time.monotonic() < deadline:
- await asyncio.sleep(poll_interval)
- status = printer_manager.get_status(printer_id)
- if not status:
- # Printer disconnected — don't mess with the DB. Drop the
- # in-memory dispatch hold too so a fresh dispatch can retry
- # once the printer comes back; the hard timeout would
- # otherwise hold the printer unnecessarily.
- scheduler._release_dispatch_hold(printer_id)
- return
- last_status = status
- if status.state in _ACTIVE_PRINT_STATES:
- # Printer is actively processing the job — release the
- # post-dispatch hold so the next pending item for this printer
- # can be evaluated normally. We do NOT accept arbitrary state
- # transitions: a printer going FINISH -> IDLE (user dismissed
- # the post-print prompt without accepting our project_file)
- # would otherwise look like "command landed" and leave the
- # queue item stuck in 'printing' forever (#1370).
- scheduler._release_dispatch_hold(printer_id)
- try:
- await ws_manager.send_queue_item_acked(
- user_id=created_by_id,
- queue_item_id=queue_item_id,
- printer_id=printer_id,
- )
- except Exception:
- pass
- return
- if pre_subtask_id is not None and status.subtask_id is not None and status.subtask_id != pre_subtask_id:
- # Phase A exit — printer accepted the file (subtask_id flipped
- # to our submission id). Don't return yet: the printer may
- # have accepted the command but never actually start (e.g.
- # cloud+LAN re-auth dance after a power cycle, #1678). Phase
- # B watches for the active-state transition.
- landed_on_subtask = True
- break
- if landed_on_subtask:
- phase_b_deadline = time.monotonic() + phase_b_timeout
- while time.monotonic() < phase_b_deadline:
- await asyncio.sleep(poll_interval)
- status = printer_manager.get_status(printer_id)
- if not status:
- scheduler._release_dispatch_hold(printer_id)
- return
- last_status = status
- if status.state in _ACTIVE_PRINT_STATES:
- scheduler._release_dispatch_hold(printer_id)
- try:
- await ws_manager.send_queue_item_acked(
- user_id=created_by_id,
- queue_item_id=queue_item_id,
- printer_id=printer_id,
- )
- except Exception:
- pass
- return
- # No active-state transition. Revert the item so the scheduler can retry.
- # Drop the in-memory hold so the retry isn't blocked by it.
- scheduler._release_dispatch_hold(printer_id)
- # Four outcomes from the revert attempt, each routed differently:
- # "reverted": row flipped from printing -> pending, run recovery
- # "gave_up": same, but the retry budget is spent — row failed
- # rather than pending, so it stops going round again
- # "already_moved_on": item.status != 'printing' (completed/cancelled by
- # on_print_complete or user). Skip recovery entirely
- # — the print clearly landed somewhere even if the
- # watchdog didn't see the active-state transition.
- # "revert_failed": SQLite contention exhausted retries. Still run
- # recovery so the MQTT session gets a fresh client_id
- # on the half-broken-session path.
- #
- # The retry budget (#2555): reverting to 'pending' hands the item straight
- # back to the next queue pass, which re-uploads the whole 3MF and waits out
- # the watchdog again. For a printer that is genuinely wedged that loop never
- # ends — the reporter had one printer "since this morning still not launch"
- # — and each lap also consumes an upload slot that the other printers in the
- # farm are waiting on. Retrying is right; retrying forever is not.
- async def _do_revert(db):
- item = await db.get(PrintQueueItem, queue_item_id)
- if not item or item.status != "printing":
- return "already_moved_on"
- item.dispatch_attempts = (item.dispatch_attempts or 0) + 1
- item.started_at = None
- if item.dispatch_attempts >= DISPATCH_MAX_ATTEMPTS:
- item.status = "failed"
- item.error_message = (
- f"The printer accepted the file but never started printing, after "
- f"{item.dispatch_attempts} attempts. Check the printer's screen for a "
- f"prompt or error, confirm its SD card is readable, and start the job again."
- )
- item.completed_at = datetime.now(timezone.utc)
- await db.commit()
- return "gave_up"
- item.status = "pending"
- await db.commit()
- return "reverted"
- try:
- revert_outcome = await run_with_retry(_do_revert, label=f"watchdog revert item={queue_item_id}")
- except Exception as e:
- logger.warning(
- "Queue item %s: failed to revert to 'pending' (printer %d): %s — "
- "scheduler may keep treating this item as in-flight",
- queue_item_id,
- printer_id,
- e,
- )
- revert_outcome = "revert_failed"
- if revert_outcome == "already_moved_on":
- # Preserves the pre-#1370 early-return: if on_print_complete (or any
- # other path) already moved the item past 'printing', don't run the
- # MQTT session-recovery logic below — a forced reconnect on a healthy
- # session breaks ongoing prints on the same printer.
- return
- total_timeout = timeout + (phase_b_timeout if landed_on_subtask else 0.0)
- if revert_outcome == "gave_up":
- logger.error(
- "Queue item %s: printer %d never started the print after %d dispatch "
- "attempts (last one waited %.0fs) — marking the item failed instead of "
- "re-uploading it again (#2555)",
- queue_item_id,
- printer_id,
- DISPATCH_MAX_ATTEMPTS,
- total_timeout,
- )
- await scheduler._notify_dispatch_gave_up(queue_item_id, printer_id, created_by_id)
- elif revert_outcome == "reverted":
- if landed_on_subtask:
- logger.warning(
- "Queue item %s: printer %d accepted project_file (subtask_id "
- "advanced) but never transitioned to an active state within "
- "%.0fs — printer wedged post-acceptance; reverted to 'pending' "
- "for retry (#1678)",
- queue_item_id,
- printer_id,
- total_timeout,
- )
- else:
- logger.warning(
- "Queue item %s: printer %d did not respond to print command within "
- "%.0fs (state still %s, subtask_id still %s) — reverted to 'pending' "
- "for retry (#967)",
- queue_item_id,
- printer_id,
- timeout,
- pre_state,
- pre_subtask_id,
- )
- # Phase B was entered iff subtask_id advanced, which means the
- # project_file landed on the printer. A forced reconnect at this point
- # would interrupt the printer's parse and trigger 0500_4003 (#1150) —
- # skip the recovery entirely.
- if landed_on_subtask:
- return
- # Phase A timeout path: if the printer's gcode_file changed since
- # pre-dispatch, the project_file command landed and the printer is
- # parsing — a forced reconnect mid-parse triggers 0500_4003 (#1150).
- # If gcode_file is unchanged, the publish was silently swallowed
- # (#887/#936) and force_reconnect recovery is what we want.
- client = printer_manager.get_client(printer_id)
- current_gcode_file = getattr(last_status, "gcode_file", None) if last_status else None
- publish_landed = current_gcode_file is not None and current_gcode_file != pre_gcode_file
- if publish_landed:
- logger.warning(
- "Queue item %s: gcode_file changed to %r (was %r) — printer "
- "received the command and is parsing slowly. Skipping forced "
- "MQTT reconnect to avoid 0500_4003 mid-parse (#1150).",
- queue_item_id,
- current_gcode_file,
- pre_gcode_file,
- )
- elif client and hasattr(client, "force_reconnect_stale_session"):
- client.force_reconnect_stale_session(
- f"queue print command unacknowledged after {timeout:.0f}s "
- f"(state still {pre_state}, gcode_file {current_gcode_file!r})"
- )
- # Global scheduler instance
- scheduler = PrintScheduler()
|