usage_tracker.py 83 KB

1234567891011121314151617181920212223242526272829303132333435363738394041424344454647484950515253545556575859606162636465666768697071727374757677787980818283848586878889909192939495969798991001011021031041051061071081091101111121131141151161171181191201211221231241251261271281291301311321331341351361371381391401411421431441451461471481491501511521531541551561571581591601611621631641651661671681691701711721731741751761771781791801811821831841851861871881891901911921931941951961971981992002012022032042052062072082092102112122132142152162172182192202212222232242252262272282292302312322332342352362372382392402412422432442452462472482492502512522532542552562572582592602612622632642652662672682692702712722732742752762772782792802812822832842852862872882892902912922932942952962972982993003013023033043053063073083093103113123133143153163173183193203213223233243253263273283293303313323333343353363373383393403413423433443453463473483493503513523533543553563573583593603613623633643653663673683693703713723733743753763773783793803813823833843853863873883893903913923933943953963973983994004014024034044054064074084094104114124134144154164174184194204214224234244254264274284294304314324334344354364374384394404414424434444454464474484494504514524534544554564574584594604614624634644654664674684694704714724734744754764774784794804814824834844854864874884894904914924934944954964974984995005015025035045055065075085095105115125135145155165175185195205215225235245255265275285295305315325335345355365375385395405415425435445455465475485495505515525535545555565575585595605615625635645655665675685695705715725735745755765775785795805815825835845855865875885895905915925935945955965975985996006016026036046056066076086096106116126136146156166176186196206216226236246256266276286296306316326336346356366376386396406416426436446456466476486496506516526536546556566576586596606616626636646656666676686696706716726736746756766776786796806816826836846856866876886896906916926936946956966976986997007017027037047057067077087097107117127137147157167177187197207217227237247257267277287297307317327337347357367377387397407417427437447457467477487497507517527537547557567577587597607617627637647657667677687697707717727737747757767777787797807817827837847857867877887897907917927937947957967977987998008018028038048058068078088098108118128138148158168178188198208218228238248258268278288298308318328338348358368378388398408418428438448458468478488498508518528538548558568578588598608618628638648658668678688698708718728738748758768778788798808818828838848858868878888898908918928938948958968978988999009019029039049059069079089099109119129139149159169179189199209219229239249259269279289299309319329339349359369379389399409419429439449459469479489499509519529539549559569579589599609619629639649659669679689699709719729739749759769779789799809819829839849859869879889899909919929939949959969979989991000100110021003100410051006100710081009101010111012101310141015101610171018101910201021102210231024102510261027102810291030103110321033103410351036103710381039104010411042104310441045104610471048104910501051105210531054105510561057105810591060106110621063106410651066106710681069107010711072107310741075107610771078107910801081108210831084108510861087108810891090109110921093109410951096109710981099110011011102110311041105110611071108110911101111111211131114111511161117111811191120112111221123112411251126112711281129113011311132113311341135113611371138113911401141114211431144114511461147114811491150115111521153115411551156115711581159116011611162116311641165116611671168116911701171117211731174117511761177117811791180118111821183118411851186118711881189119011911192119311941195119611971198119912001201120212031204120512061207120812091210121112121213121412151216121712181219122012211222122312241225122612271228122912301231123212331234123512361237123812391240124112421243124412451246124712481249125012511252125312541255125612571258125912601261126212631264126512661267126812691270127112721273127412751276127712781279128012811282128312841285128612871288128912901291129212931294129512961297129812991300130113021303130413051306130713081309131013111312131313141315131613171318131913201321132213231324132513261327132813291330133113321333133413351336133713381339134013411342134313441345134613471348134913501351135213531354135513561357135813591360136113621363136413651366136713681369137013711372137313741375137613771378137913801381138213831384138513861387138813891390139113921393139413951396139713981399140014011402140314041405140614071408140914101411141214131414141514161417141814191420142114221423142414251426142714281429143014311432143314341435143614371438143914401441144214431444144514461447144814491450145114521453145414551456145714581459146014611462146314641465146614671468146914701471147214731474147514761477147814791480148114821483148414851486148714881489149014911492149314941495149614971498149915001501150215031504150515061507150815091510151115121513151415151516151715181519152015211522152315241525152615271528152915301531153215331534153515361537153815391540154115421543154415451546154715481549155015511552155315541555155615571558155915601561156215631564156515661567156815691570157115721573157415751576157715781579158015811582158315841585158615871588158915901591159215931594159515961597159815991600160116021603160416051606160716081609161016111612161316141615161616171618161916201621162216231624162516261627162816291630163116321633163416351636163716381639164016411642164316441645164616471648164916501651165216531654165516561657165816591660166116621663166416651666166716681669167016711672167316741675167616771678167916801681168216831684168516861687168816891690169116921693169416951696169716981699170017011702170317041705170617071708170917101711171217131714171517161717171817191720172117221723172417251726172717281729173017311732173317341735173617371738173917401741174217431744174517461747174817491750175117521753175417551756175717581759176017611762176317641765176617671768176917701771177217731774177517761777177817791780178117821783178417851786178717881789179017911792179317941795179617971798179918001801180218031804180518061807180818091810181118121813181418151816181718181819182018211822182318241825182618271828182918301831183218331834183518361837183818391840184118421843184418451846184718481849185018511852185318541855185618571858185918601861186218631864186518661867186818691870187118721873187418751876187718781879188018811882188318841885188618871888188918901891189218931894189518961897189818991900190119021903190419051906190719081909191019111912191319141915191619171918191919201921192219231924192519261927192819291930193119321933193419351936193719381939194019411942194319441945194619471948194919501951195219531954195519561957195819591960196119621963196419651966196719681969197019711972
  1. """Automatic filament consumption tracking.
  2. Captures AMS tray remain% at print start, then computes consumption
  3. deltas at print complete to update spool weight_used and last_used.
  4. Primary tracking uses 3MF slicer estimates (precise per-filament data).
  5. AMS remain% delta is the fallback for trays not covered by 3MF data.
  6. """
  7. import asyncio
  8. import json
  9. import logging
  10. import re
  11. from dataclasses import dataclass, field
  12. from datetime import datetime, timezone
  13. from sqlalchemy import select
  14. from sqlalchemy.ext.asyncio import AsyncSession
  15. from backend.app.models.spool import Spool
  16. from backend.app.models.spool_assignment import SpoolAssignment
  17. from backend.app.models.spool_usage_history import SpoolUsageHistory
  18. logger = logging.getLogger(__name__)
  19. def _decode_mqtt_mapping(mapping_raw: list | None) -> list[int] | None:
  20. """Decode MQTT mapping field (snow-encoded) to bambuddy global tray IDs.
  21. The printer's MQTT mapping field is an array indexed by slicer filament slot
  22. (0-based). Each value uses snow encoding: ams_hw_id * 256 + local_slot.
  23. 65535 means unmapped.
  24. Returns a list of bambuddy global tray IDs (or -1 for unmapped), or None if
  25. no valid mappings found.
  26. """
  27. if not isinstance(mapping_raw, list) or not mapping_raw:
  28. return None
  29. result = []
  30. for value in mapping_raw:
  31. if not isinstance(value, int) or value >= 65535:
  32. result.append(-1)
  33. continue
  34. ams_hw_id = value >> 8
  35. slot = value & 0xFF
  36. if 0 <= ams_hw_id <= 3:
  37. # Regular AMS: sequential global ID
  38. result.append(ams_hw_id * 4 + (slot & 0x03))
  39. elif 128 <= ams_hw_id <= 135:
  40. # AMS-HT: global ID is the hardware ID (one slot per unit)
  41. result.append(ams_hw_id)
  42. elif ams_hw_id in (254, 255):
  43. # External spool
  44. result.append(254 if slot != 255 else 255)
  45. else:
  46. result.append(-1)
  47. # Only return if at least one valid mapping exists
  48. if all(v < 0 for v in result):
  49. return None
  50. return result
  51. def _spool_color_to_hex(rgba: str | None) -> str | None:
  52. """Normalise a ``Spool.rgba`` value (``RRGGBBAA`` hex, no ``#``) to the
  53. ``#RRGGBB`` form archives store in ``filament_color``.
  54. Alpha is dropped — the archive colour list and the Color Distribution
  55. graph treat filament colour as opaque. Returns ``None`` for a missing or
  56. too-short value so the caller can fall back to the 3MF colour.
  57. """
  58. if not rgba:
  59. return None
  60. h = rgba.strip().lstrip("#")
  61. if len(h) < 6:
  62. return None
  63. return "#" + h[:6].upper()
  64. def _archive_colors_from_spools(filament_usage: list[dict], results: list[dict]) -> list[str] | None:
  65. """Slot-ordered, de-duplicated hex colours for an archive's ``filament_color``,
  66. taken from the inventory spools that actually fed the print (#1494).
  67. The slicer's 3MF carries its own ``filament_colour`` per slot — a value
  68. picked independently of the colour the user curates on the matched
  69. inventory spool. So an archive printed from a ``#000000`` inventory spool
  70. would otherwise show the slicer's near-black ``#161616``. Once usage
  71. tracking has resolved the used slots to spools, the spool colours are the
  72. authoritative source and replace the 3MF values.
  73. Returns ``None`` — leave the 3MF colour untouched — unless *every* slot
  74. with non-zero usage was matched to a spool that carries a colour. A
  75. partial rewrite would silently drop the unmatched slots' colours from the
  76. archive (and the Color Distribution graph), so it is all-or-nothing.
  77. """
  78. used_slots = {u["slot_id"] for u in filament_usage if u.get("used_g", 0) > 0 and u.get("slot_id") is not None}
  79. if not used_slots:
  80. return None
  81. slot_color: dict[int, str] = {}
  82. for r in results:
  83. slot_id = r.get("slot_id")
  84. color = r.get("color")
  85. if slot_id is not None and color:
  86. slot_color.setdefault(slot_id, color)
  87. if not used_slots.issubset(slot_color):
  88. return None
  89. ordered: list[str] = []
  90. for slot_id in sorted(used_slots):
  91. color = slot_color[slot_id]
  92. if color not in ordered:
  93. ordered.append(color)
  94. return ordered
  95. def _archive_types_from_spools(filament_usage: list[dict], results: list[dict]) -> list[str] | None:
  96. """Slot-ordered, de-duplicated materials for an archive's ``filament_type``,
  97. taken from the inventory spools that actually fed the print (#2563).
  98. The slicer's 3MF records the filament type it was *sliced for*. When the
  99. user manually maps a slot to a differently-typed loaded spool in the Print
  100. dialog — a PLA slice routed to the only loaded PETG slot — that sliced type
  101. misclassifies the run in the archive card, the Print Log and the material
  102. statistics, even though the deduction correctly hit the PETG spool. Once
  103. usage tracking has resolved every used slot to an inventory spool, the
  104. spool's declared material is the authoritative record of what was consumed,
  105. the same reasoning that already adopts the spool colour (#1494).
  106. Returns ``None`` — leave the 3MF type untouched — unless *every* slot with
  107. non-zero usage was matched to a spool that carries a material. All-or-
  108. nothing, exactly like ``_archive_colors_from_spools``: a partial rewrite
  109. would silently drop the unmatched slots' types from the archive (and the
  110. material stats).
  111. """
  112. used_slots = {u["slot_id"] for u in filament_usage if u.get("used_g", 0) > 0 and u.get("slot_id") is not None}
  113. if not used_slots:
  114. return None
  115. slot_material: dict[int, str] = {}
  116. for r in results:
  117. slot_id = r.get("slot_id")
  118. material = (r.get("material") or "").strip()
  119. if slot_id is not None and material:
  120. slot_material.setdefault(slot_id, material)
  121. if not used_slots.issubset(slot_material):
  122. return None
  123. ordered: list[str] = []
  124. for slot_id in sorted(used_slots):
  125. material = slot_material[slot_id]
  126. if material not in ordered:
  127. ordered.append(material)
  128. return ordered
  129. def _match_slots_by_color(
  130. filament_usage: list[dict],
  131. ams_raw: dict | list | None,
  132. ) -> list[int] | None:
  133. """Match 3MF filament slots to AMS trays by color.
  134. Fallback mapping for printers that don't provide the MQTT mapping field
  135. or request topic subscription (e.g. A1, A1 Mini, P1S, P2S).
  136. Compares the 3MF slicer filament color (per slot) against each AMS tray's
  137. color to find a unique match. Only returns a mapping if every used slot
  138. matches exactly one tray (no ambiguity).
  139. Args:
  140. filament_usage: List of 3MF slot dicts with 'slot_id', 'color', 'type'
  141. ams_raw: raw_data["ams"] dict or list from printer state
  142. Returns:
  143. List of global tray IDs indexed by slicer slot (0-based), or None.
  144. """
  145. if not filament_usage or not ams_raw:
  146. return None
  147. ams_data = ams_raw.get("ams", []) if isinstance(ams_raw, dict) else ams_raw if isinstance(ams_raw, list) else []
  148. if not ams_data:
  149. return None
  150. # Build map of normalized color → list of global tray IDs
  151. color_to_trays: dict[str, list[int]] = {}
  152. for ams_unit in ams_data:
  153. ams_id = int(ams_unit.get("id", 0))
  154. for tray in ams_unit.get("tray", []):
  155. tray_id = int(tray.get("id", 0))
  156. tray_color = tray.get("tray_color", "")
  157. tray_type = tray.get("tray_type", "")
  158. if not tray_color or not tray_type:
  159. continue
  160. # Normalize AMS color: strip alpha (last 2 chars), lowercase
  161. norm = tray_color[:6].lower() if len(tray_color) >= 6 else tray_color.lower()
  162. if ams_id >= 128:
  163. global_id = ams_id # AMS-HT
  164. else:
  165. global_id = ams_id * 4 + tray_id
  166. color_to_trays.setdefault(norm, []).append(global_id)
  167. if not color_to_trays:
  168. return None
  169. # Find max slot_id to size the result array
  170. max_slot = max(u.get("slot_id", 0) for u in filament_usage)
  171. if max_slot <= 0:
  172. return None
  173. result = [-1] * max_slot
  174. used_trays: set[int] = set()
  175. for usage in filament_usage:
  176. slot_id = usage.get("slot_id", 0)
  177. if slot_id <= 0:
  178. continue
  179. slot_color = usage.get("color", "").lstrip("#").lower()
  180. if len(slot_color) < 6:
  181. return None # Can't match without a valid color
  182. slot_color = slot_color[:6] # Strip alpha if present
  183. candidates = color_to_trays.get(slot_color, [])
  184. # Filter out trays already claimed by another slot
  185. available = [t for t in candidates if t not in used_trays]
  186. if len(available) != 1:
  187. # Ambiguous (multiple trays with same color) or no match
  188. return None
  189. result[slot_id - 1] = available[0]
  190. used_trays.add(available[0])
  191. # Only return if at least one valid mapping exists
  192. if all(v < 0 for v in result):
  193. return None
  194. logger.info("[UsageTracker] Color-matched slot_to_tray: %s", result)
  195. return result
  196. @dataclass
  197. class PrintSession:
  198. printer_id: int
  199. print_name: str
  200. started_at: datetime
  201. tray_remain_start: dict[tuple[int, int], int] = field(default_factory=dict)
  202. # tray_now at print start (correct value, unlike at completion where it's 255)
  203. tray_now_at_start: int = -1
  204. # Snapshot of spool assignments at print start: {(ams_id, tray_id): spool_id}
  205. # Prevents usage loss when on_ams_change unlinks a spool mid-print
  206. spool_assignments: dict[tuple[int, int], int] = field(default_factory=dict)
  207. # AMS mapping from print command (captured at start, needed when auto-archive is off)
  208. ams_mapping: list[int] | None = None
  209. # Queue item's plate_id when this print is a multi-plate 3MF dispatched for a
  210. # single plate (#1697). None for non-queue prints — the file's first/only plate
  211. # is the default and the 3MF parser already returns the full file in that case.
  212. plate_id: int | None = None
  213. # Module-level storage, keyed by printer_id. Mirrored to the
  214. # ``active_print_sessions`` table so a restart mid-print doesn't lose the
  215. # context — see ``persist_session`` / ``restore_session``.
  216. _active_sessions: dict[int, PrintSession] = {}
  217. # Serialises the read-modify-write on the persisted tray-change log, per printer.
  218. _tray_change_locks: dict[int, asyncio.Lock] = {}
  219. def _tray_key_to_str(key: tuple[int, int]) -> str:
  220. return f"{key[0]}-{key[1]}"
  221. def _tray_key_from_str(key: str) -> tuple[int, int] | None:
  222. ams_str, _, tray_str = key.partition("-")
  223. try:
  224. return int(ams_str), int(tray_str)
  225. except ValueError:
  226. return None
  227. def _tray_map_to_json(mapping: dict[tuple[int, int], int]) -> dict[str, int]:
  228. return {_tray_key_to_str(k): v for k, v in mapping.items()}
  229. def _tray_map_from_json(mapping: dict | None) -> dict[tuple[int, int], int]:
  230. result: dict[tuple[int, int], int] = {}
  231. for raw_key, value in (mapping or {}).items():
  232. key = _tray_key_from_str(str(raw_key))
  233. if key is not None and isinstance(value, int):
  234. result[key] = value
  235. return result
  236. async def persist_session(
  237. db: AsyncSession,
  238. session: PrintSession,
  239. tray_change_log: list | None = None,
  240. ) -> None:
  241. """Mirror ``session`` into ``active_print_sessions`` for restart recovery.
  242. Overwrites any existing row for the printer: a printer runs one print at a
  243. time, and a row left behind by a completion we never saw must not outlive
  244. the next print start.
  245. """
  246. from backend.app.models.active_print_session import ActivePrintSession
  247. row = await db.get(ActivePrintSession, session.printer_id)
  248. if row is None:
  249. row = ActivePrintSession(printer_id=session.printer_id)
  250. db.add(row)
  251. row.print_name = session.print_name or ""
  252. row.started_at = session.started_at.replace(tzinfo=None)
  253. row.tray_now_at_start = session.tray_now_at_start
  254. row.plate_id = session.plate_id
  255. row.ams_mapping = list(session.ams_mapping) if session.ams_mapping else None
  256. row.spool_assignments = _tray_map_to_json(session.spool_assignments) or None
  257. row.tray_remain_start = _tray_map_to_json(session.tray_remain_start) or None
  258. row.tray_change_log = [list(entry) for entry in (tray_change_log or [])] or None
  259. await db.commit()
  260. async def record_tray_change(db: AsyncSession, printer_id: int, tray_global: int, layer_num: int) -> None:
  261. """Append one tray change to the persisted log.
  262. No-op when no print-start row exists — a tray change outside a tracked
  263. print has nothing to attribute.
  264. """
  265. from backend.app.models.active_print_session import ActivePrintSession
  266. # Read-modify-write on a JSON column: two changes close together (a runout
  267. # parks the extruder and the backup tray loads moments later) would
  268. # otherwise race and drop a segment boundary.
  269. async with _tray_change_locks.setdefault(printer_id, asyncio.Lock()):
  270. row = await db.get(ActivePrintSession, printer_id)
  271. if row is None:
  272. return
  273. log = [list(entry) for entry in (row.tray_change_log or [])]
  274. entry = [tray_global, layer_num]
  275. if log and log[-1] == entry:
  276. # print-start seeds the log from PrinterState, which may already
  277. # hold a change this callback is also reporting.
  278. return
  279. log.append(entry)
  280. row.tray_change_log = log
  281. await db.commit()
  282. async def get_persisted_print_name(db: AsyncSession, printer_id: int) -> str | None:
  283. """Print name on the persisted row, for identity-checking a restored session."""
  284. from backend.app.models.active_print_session import ActivePrintSession
  285. row = await db.get(ActivePrintSession, printer_id)
  286. return row.print_name if row is not None else None
  287. async def restore_session(db: AsyncSession, printer_id: int, register_active: bool = True) -> list[list[int]] | None:
  288. """Rebuild the in-memory session for ``printer_id`` from the persisted row.
  289. Returns the persisted tray-change log so the caller can put it back on
  290. ``PrinterState``, or None when there is nothing to restore.
  291. ``register_active=False`` returns the log without publishing the session to
  292. ``_active_sessions`` — for Spoolman users, who need the tray-change log
  293. restored but whose remain%-sync must not be suppressed by it (see
  294. ``on_print_start``).
  295. """
  296. from backend.app.models.active_print_session import ActivePrintSession
  297. row = await db.get(ActivePrintSession, printer_id)
  298. if row is None:
  299. return None
  300. started_at = row.started_at
  301. if started_at.tzinfo is None:
  302. started_at = started_at.replace(tzinfo=timezone.utc)
  303. session = PrintSession(
  304. printer_id=printer_id,
  305. print_name=row.print_name or "",
  306. started_at=started_at,
  307. tray_remain_start=_tray_map_from_json(row.tray_remain_start),
  308. tray_now_at_start=row.tray_now_at_start,
  309. spool_assignments=_tray_map_from_json(row.spool_assignments),
  310. ams_mapping=list(row.ams_mapping) if row.ams_mapping else None,
  311. plate_id=row.plate_id,
  312. )
  313. if register_active:
  314. _active_sessions[printer_id] = session
  315. log = [list(entry) for entry in (row.tray_change_log or [])]
  316. logger.info(
  317. "[UsageTracker] Restored print session for printer %d: plate_id=%s, ams_mapping=%s, "
  318. "%d assignments, tray_change_log=%s",
  319. printer_id,
  320. row.plate_id,
  321. row.ams_mapping,
  322. len(row.spool_assignments or {}),
  323. log,
  324. )
  325. return log
  326. async def clear_persisted_session(db: AsyncSession, printer_id: int) -> None:
  327. """Drop the persisted print-start row once the print is closed out."""
  328. from backend.app.models.active_print_session import ActivePrintSession
  329. row = await db.get(ActivePrintSession, printer_id)
  330. if row is not None:
  331. await db.delete(row)
  332. await db.commit()
  333. async def discard_session(db: AsyncSession, printer_id: int) -> None:
  334. """Forget a printer's print-start context, in memory and on disk.
  335. The completion path calls this for every print, including the ones whose
  336. usage Spoolman owns: the context is captured for both backends, but only
  337. the internal tracker's ``on_print_complete`` consumes (and pops) it.
  338. """
  339. _active_sessions.pop(printer_id, None)
  340. _tray_change_locks.pop(printer_id, None)
  341. await clear_persisted_session(db, printer_id)
  342. def _to_epoch_seconds(value: datetime | None) -> float | None:
  343. """Convert datetime to epoch seconds, assuming UTC for naive values."""
  344. if value is None:
  345. return None
  346. dt = value
  347. if dt.tzinfo is None:
  348. dt = dt.replace(tzinfo=timezone.utc)
  349. return dt.timestamp()
  350. async def _resolve_spool_id_for_tray(
  351. printer_id: int,
  352. ams_id: int,
  353. tray_id: int,
  354. db: AsyncSession,
  355. spool_assignments_snapshot: dict[tuple[int, int], int] | None = None,
  356. print_started_at: datetime | None = None,
  357. ) -> int | None:
  358. """Resolve spool ID for a tray with safe support for mid-print reassignment.
  359. Resolution order:
  360. 1. If snapshot exists and live assignment changed *during this print*, use live spool.
  361. 2. Otherwise use snapshot spool when available.
  362. 3. Fall back to live assignment.
  363. """
  364. key = (ams_id, tray_id)
  365. snapshot_spool_id = spool_assignments_snapshot.get(key) if spool_assignments_snapshot else None
  366. # Backward-compatible fast path: if we have a snapshot but no print-start
  367. # timestamp, preserve legacy behavior and avoid extra DB lookups.
  368. if snapshot_spool_id is not None and print_started_at is None:
  369. return snapshot_spool_id
  370. result = await db.execute(
  371. select(SpoolAssignment).where(
  372. SpoolAssignment.printer_id == printer_id,
  373. SpoolAssignment.ams_id == ams_id,
  374. SpoolAssignment.tray_id == tray_id,
  375. )
  376. )
  377. live_assignment = result.scalar_one_or_none()
  378. if snapshot_spool_id is not None:
  379. if live_assignment and live_assignment.spool_id != snapshot_spool_id:
  380. live_created_ts = _to_epoch_seconds(getattr(live_assignment, "created_at", None))
  381. started_ts = _to_epoch_seconds(print_started_at)
  382. if live_created_ts is not None and started_ts is not None and live_created_ts >= started_ts:
  383. logger.info(
  384. "[UsageTracker] Assignment changed during print for printer %d AMS%d-T%d: snapshot spool %d -> live spool %d",
  385. printer_id,
  386. ams_id,
  387. tray_id,
  388. snapshot_spool_id,
  389. live_assignment.spool_id,
  390. )
  391. return live_assignment.spool_id
  392. return snapshot_spool_id
  393. if live_assignment:
  394. return live_assignment.spool_id
  395. return None
  396. async def on_print_start(
  397. printer_id: int,
  398. data: dict,
  399. printer_manager,
  400. db: AsyncSession | None = None,
  401. spoolman_owns_usage: bool = False,
  402. ) -> None:
  403. """Capture AMS tray remain% and spool assignments at print start.
  404. The capture runs for both inventory backends — the persisted row carries
  405. the tray-change log, which is the only record of which spool fed which
  406. layers when AMS Filament Backup swaps trays, and Spoolman's own durable
  407. row (#1820) does not hold it.
  408. ``spoolman_owns_usage`` keeps the in-memory session out of
  409. ``_active_sessions`` when Spoolman is writing the usage. That dict doubles
  410. as ``on_ams_change``'s "a print is running, so skip the remain%-based
  411. weight sync because the internal tracker will deduct precisely" flag
  412. (#880); registering a session the internal tracker will never complete
  413. would suppress a sync those users still need.
  414. """
  415. state = printer_manager.get_status(printer_id)
  416. if not state or not state.raw_data:
  417. logger.debug("[UsageTracker] No state for printer %d, skipping", printer_id)
  418. return
  419. ams_raw = state.raw_data.get("ams", [])
  420. ams_data = ams_raw.get("ams", []) if isinstance(ams_raw, dict) else ams_raw if isinstance(ams_raw, list) else []
  421. tray_remain_start: dict[tuple[int, int], int] = {}
  422. skipped_invalid: list[str] = []
  423. for ams_unit in ams_data:
  424. ams_id = int(ams_unit.get("id", 0))
  425. for tray in ams_unit.get("tray", []):
  426. tray_id = int(tray.get("id", 0))
  427. remain = tray.get("remain", -1)
  428. if isinstance(remain, int) and 0 <= remain <= 100:
  429. tray_remain_start[(ams_id, tray_id)] = remain
  430. else:
  431. skipped_invalid.append(f"AMS{ams_id}-T{tray_id}(remain={remain})")
  432. # Also capture VT (external) tray remain% — these are separate from AMS units
  433. vt_tray_raw = state.raw_data.get("vt_tray") or []
  434. if isinstance(vt_tray_raw, dict):
  435. vt_tray_raw = [vt_tray_raw]
  436. for vt in vt_tray_raw:
  437. if not isinstance(vt, dict):
  438. continue
  439. vt_id = int(vt.get("id", 254))
  440. # VT tray id 254 → (ams_id=255, tray_id=0), id 255 → (ams_id=255, tray_id=1)
  441. vt_tray_id = vt_id - 254
  442. remain = vt.get("remain", -1)
  443. if isinstance(remain, int) and 0 <= remain <= 100:
  444. tray_remain_start[(255, vt_tray_id)] = remain
  445. else:
  446. skipped_invalid.append(f"VT{vt_id}(remain={remain})")
  447. if skipped_invalid:
  448. logger.info(
  449. "[UsageTracker] Skipped trays with invalid remain%% for printer %d: %s",
  450. printer_id,
  451. ", ".join(skipped_invalid),
  452. )
  453. if not ams_data and not vt_tray_raw:
  454. logger.debug("[UsageTracker] No AMS or VT tray data for printer %d, skipping", printer_id)
  455. return
  456. print_name = data.get("subtask_name", "") or data.get("filename", "unknown")
  457. # Capture tray_now at print start (reliable, unlike at completion where it's 255)
  458. tray_now_at_start = state.tray_now if state else -1
  459. # --- Diagnostic logging: dump mapping-related MQTT fields at print start ---
  460. # This helps us understand what each printer model reports for slot-to-tray mapping.
  461. mapping_field = state.raw_data.get("mapping")
  462. logger.info(
  463. "[UsageTracker] PRINT START printer %d: mapping=%s, tray_now=%d, last_loaded_tray=%s",
  464. printer_id,
  465. mapping_field,
  466. tray_now_at_start,
  467. getattr(state, "last_loaded_tray", "N/A"),
  468. )
  469. # Log all raw_data keys containing "map" or "ams" for discovery
  470. map_keys = {k: state.raw_data[k] for k in state.raw_data if "map" in k.lower()}
  471. if map_keys:
  472. logger.info("[UsageTracker] PRINT START printer %d: mapping-related keys: %s", printer_id, map_keys)
  473. # Log per-tray summary: tray_now, tray_tar, tray_type, tray_color for each slot
  474. for ams_unit in ams_data:
  475. ams_id = int(ams_unit.get("id", 0))
  476. tray_summary = []
  477. for tray in ams_unit.get("tray", []):
  478. tray_summary.append(
  479. f"T{tray.get('id', '?')}(type={tray.get('tray_type', '')}, "
  480. f"color={tray.get('tray_color', '')}, "
  481. f"now={ams_raw.get('tray_now', '?') if isinstance(ams_raw, dict) else '?'}, "
  482. f"tar={ams_raw.get('tray_tar', '?') if isinstance(ams_raw, dict) else '?'})"
  483. )
  484. logger.info("[UsageTracker] PRINT START printer %d AMS %d: %s", printer_id, ams_id, ", ".join(tray_summary))
  485. # Snapshot spool assignments so usage isn't lost if on_ams_change unlinks mid-print
  486. spool_assignments: dict[tuple[int, int], int] = {}
  487. if db:
  488. assign_result = await db.execute(select(SpoolAssignment).where(SpoolAssignment.printer_id == printer_id))
  489. for assignment in assign_result.scalars().all():
  490. spool_assignments[(assignment.ams_id, assignment.tray_id)] = assignment.spool_id
  491. if spool_assignments:
  492. logger.info(
  493. "[UsageTracker] Snapshotted %d spool assignments for printer %d: %s",
  494. len(spool_assignments),
  495. printer_id,
  496. {f"{k[0]}-{k[1]}": v for k, v in spool_assignments.items()},
  497. )
  498. # Capture the queue item's plate_id so 3MF parsing at completion is scoped to
  499. # the plate that actually ran, not the whole multi-plate file (#1697).
  500. plate_id: int | None = None
  501. if db:
  502. from backend.app.models.print_queue import PrintQueueItem
  503. queue_result = await db.execute(
  504. select(PrintQueueItem)
  505. .where(PrintQueueItem.printer_id == printer_id)
  506. .where(PrintQueueItem.status == "printing")
  507. )
  508. queue_item = queue_result.scalars().first()
  509. if queue_item is not None:
  510. plate_id = queue_item.plate_id
  511. # Always create session (even without valid remain data) so print_name
  512. # is available at completion for 3MF-based tracking
  513. session = PrintSession(
  514. printer_id=printer_id,
  515. print_name=print_name,
  516. started_at=datetime.now(timezone.utc),
  517. tray_remain_start=tray_remain_start,
  518. tray_now_at_start=tray_now_at_start,
  519. spool_assignments=spool_assignments,
  520. ams_mapping=data.get("ams_mapping"),
  521. plate_id=plate_id,
  522. )
  523. if spoolman_owns_usage:
  524. _active_sessions.pop(printer_id, None)
  525. else:
  526. _active_sessions[printer_id] = session
  527. # Mirror to the DB so a restart mid-print doesn't lose the context. The
  528. # tray-change log has already been cleared and seeded with the starting
  529. # tray by bambu_mqtt before this callback fires.
  530. if db:
  531. try:
  532. await persist_session(db, session, getattr(state, "tray_change_log", None))
  533. except Exception:
  534. logger.exception("[UsageTracker] Failed to persist print session for printer %d", printer_id)
  535. if tray_remain_start:
  536. logger.info(
  537. "[UsageTracker] Captured start remain%% for printer %d (%d trays): %s",
  538. printer_id,
  539. len(tray_remain_start),
  540. {f"{k[0]}-{k[1]}": v for k, v in tray_remain_start.items()},
  541. )
  542. else:
  543. logger.debug("[UsageTracker] No valid remain%% for printer %d, 3MF fallback available", printer_id)
  544. async def on_print_complete(
  545. printer_id: int,
  546. data: dict,
  547. printer_manager,
  548. db: AsyncSession,
  549. archive_id: int | None = None,
  550. ams_mapping: list[int] | None = None,
  551. ) -> list[dict]:
  552. """Compute consumption deltas and update spool weight_used/last_used.
  553. Uses two tracking strategies in priority order:
  554. 1. 3MF per-filament estimates (primary) — precise slicer data for all spools
  555. 2. AMS remain% delta (fallback) — only for trays not already handled by 3MF
  556. Returns a list of dicts describing what was logged (for WebSocket broadcast).
  557. """
  558. from sqlalchemy import select
  559. from backend.app.api.routes.settings import get_setting
  560. from backend.app.models.spool_usage_history import SpoolUsageHistory
  561. session = _active_sessions.pop(printer_id, None)
  562. if session is None:
  563. # Restart mid-print: the in-memory session is gone but the print-start
  564. # row survived. Without this the completion path loses the plate, the
  565. # dispatched mapping and the assignment snapshot, and attributes the
  566. # whole print to whichever tray happened to finish it.
  567. try:
  568. await restore_session(db, printer_id)
  569. except Exception:
  570. logger.exception("[UsageTracker] Failed to restore print session for printer %d", printer_id)
  571. session = _active_sessions.pop(printer_id, None)
  572. status = data.get("status", "completed")
  573. results = []
  574. handled_trays: set[tuple[int, int]] = set()
  575. # Fetch default filament cost from settings for fallback
  576. default_cost_str = await get_setting(db, "default_filament_cost")
  577. default_filament_cost = float(default_cost_str) if default_cost_str else 0.0
  578. # Fall back to ams_mapping captured at print start (needed when auto-archive is off
  579. # and the caller can't retrieve the mapping from _print_ams_mappings without archive_id)
  580. if not ams_mapping and session and session.ams_mapping:
  581. ams_mapping = session.ams_mapping
  582. logger.info(
  583. "[UsageTracker] on_print_complete: printer=%d, archive=%s, session=%s, ams_mapping=%s",
  584. printer_id,
  585. archive_id,
  586. "yes" if session else "no",
  587. ams_mapping,
  588. )
  589. # --- Diagnostic logging: dump mapping-related MQTT fields at print completion ---
  590. state = printer_manager.get_status(printer_id)
  591. if state and state.raw_data:
  592. logger.info(
  593. "[UsageTracker] PRINT COMPLETE printer %d: mapping=%s, tray_now=%s, last_loaded_tray=%s",
  594. printer_id,
  595. state.raw_data.get("mapping"),
  596. state.tray_now,
  597. getattr(state, "last_loaded_tray", "N/A"),
  598. )
  599. # --- Path 1 (PRIMARY): 3MF per-filament estimates ---
  600. print_name = (
  601. (session.print_name if session else None) or data.get("subtask_name", "") or data.get("filename", "unknown")
  602. )
  603. # When auto-archive is disabled (archive_id=None), try to find a 3MF by filename
  604. # from the library or previous archives so we can still track filament usage.
  605. threemf_path = None
  606. if not archive_id:
  607. from backend.app.core.config import settings as app_settings
  608. search_filename = data.get("filename") or data.get("subtask_name") or (session.print_name if session else "")
  609. if search_filename:
  610. threemf_path = await _find_3mf_by_filename(
  611. printer_id,
  612. search_filename,
  613. db,
  614. app_settings.base_dir,
  615. print_name=data.get("subtask_name") or (session.print_name if session else None),
  616. )
  617. if archive_id or threemf_path:
  618. threemf_results = await _track_from_3mf(
  619. printer_id,
  620. archive_id,
  621. status,
  622. print_name,
  623. handled_trays,
  624. printer_manager,
  625. db,
  626. ams_mapping=ams_mapping,
  627. tray_now_at_start=session.tray_now_at_start if session else -1,
  628. last_progress=data.get("last_progress", 0.0),
  629. last_layer_num=data.get("last_layer_num", 0),
  630. default_filament_cost=default_filament_cost,
  631. spool_assignments=session.spool_assignments if session else None,
  632. print_started_at=session.started_at if session else None,
  633. threemf_path=threemf_path,
  634. plate_id=session.plate_id if session else None,
  635. )
  636. results.extend(threemf_results)
  637. # --- Path 2 (FALLBACK): AMS remain% delta (only for trays not handled by 3MF) ---
  638. if session and session.tray_remain_start:
  639. state = printer_manager.get_status(printer_id)
  640. if state and state.raw_data:
  641. ams_raw = state.raw_data.get("ams", [])
  642. ams_data = (
  643. ams_raw.get("ams", []) if isinstance(ams_raw, dict) else ams_raw if isinstance(ams_raw, list) else []
  644. )
  645. # Build set of trays actually involved in this print (#1269).
  646. # Without this guard, swapping a spool in an UNUSED slot mid-print
  647. # makes that slot's remain% drop to 0, which the fallback below
  648. # would otherwise charge to the originally-assigned spool.
  649. def _global_to_ams_key(global_tray_id: int) -> tuple[int, int]:
  650. if global_tray_id >= 254:
  651. return (255, global_tray_id - 254)
  652. if global_tray_id >= 128:
  653. return (global_tray_id, 0)
  654. return (global_tray_id // 4, global_tray_id % 4)
  655. print_used_keys: set[tuple[int, int]] = set()
  656. if ams_mapping:
  657. for gid in ams_mapping:
  658. if isinstance(gid, int) and gid >= 0:
  659. print_used_keys.add(_global_to_ams_key(gid))
  660. for change in getattr(state, "tray_change_log", None) or []:
  661. if isinstance(change, (tuple, list)) and len(change) >= 1:
  662. gid = change[0]
  663. if isinstance(gid, int) and gid >= 0:
  664. print_used_keys.add(_global_to_ams_key(gid))
  665. # 255 is not a slot: it is what ``tray_now`` reads at rest, before
  666. # the printer has reported one and while nothing is loaded, and an
  667. # unparseable reading falls back to it too. Mapped as a tray id it
  668. # becomes (255, 1), and if it were the only evidence every real
  669. # slot would be excluded and the fallback would charge nothing at
  670. # all (#1820). The external spool reports 254 when in use.
  671. if session.tray_now_at_start is not None and 0 <= session.tray_now_at_start <= 254:
  672. print_used_keys.add(_global_to_ams_key(session.tray_now_at_start))
  673. # Collect all trays to check: AMS trays + VT (external) trays
  674. # Each entry: (ams_id_for_assignment, tray_id_for_assignment, current_remain, label)
  675. trays_to_check: list[tuple[int, int, int, str]] = []
  676. for ams_unit in ams_data:
  677. ams_id = int(ams_unit.get("id", 0))
  678. for tray in ams_unit.get("tray", []):
  679. tray_id = int(tray.get("id", 0))
  680. remain = tray.get("remain", -1)
  681. trays_to_check.append((ams_id, tray_id, remain, f"AMS{ams_id}-T{tray_id}"))
  682. # VT (external) trays — same remain% delta logic
  683. vt_tray_raw = state.raw_data.get("vt_tray") or []
  684. if isinstance(vt_tray_raw, dict):
  685. vt_tray_raw = [vt_tray_raw]
  686. for vt in vt_tray_raw:
  687. if not isinstance(vt, dict):
  688. continue
  689. vt_id = int(vt.get("id", 254))
  690. vt_tray_id = vt_id - 254 # 254→0, 255→1
  691. remain = vt.get("remain", -1)
  692. trays_to_check.append((255, vt_tray_id, remain, f"VT{vt_id}"))
  693. for assign_ams_id, assign_tray_id, current_remain, tray_label in trays_to_check:
  694. key = (assign_ams_id, assign_tray_id)
  695. if key in handled_trays:
  696. continue # Already tracked via 3MF
  697. if key not in session.tray_remain_start:
  698. # No usable remain% when the print began, so there is no delta
  699. # to charge. Said out loud for the same reason as the branches
  700. # below: a slot the print used, holding a spool the operator
  701. # assigned, otherwise vanished from the accounting without a
  702. # word. Common on non-RFID spools, which report remain = -1
  703. # until a remaining amount is set by hand.
  704. if not print_used_keys or key in print_used_keys:
  705. logger.info(
  706. "[UsageTracker] %s: no valid remain%% at print start, nothing to charge for printer %d",
  707. tray_label,
  708. printer_id,
  709. )
  710. continue
  711. # Skip trays the print never touched. Only enforce when we have
  712. # evidence of which trays the print used; if print_used_keys is
  713. # empty (no mapping, no change log, no tray_now_at_start) keep
  714. # the legacy behavior of scanning every tray.
  715. if print_used_keys and key not in print_used_keys:
  716. logger.info(
  717. "[UsageTracker] %s: not in print mapping/tray_change_log — skipping fallback for printer %d",
  718. tray_label,
  719. printer_id,
  720. )
  721. continue
  722. if not isinstance(current_remain, int) or current_remain < 0 or current_remain > 100:
  723. logger.info(
  724. "[UsageTracker] %s: invalid remain%% at completion (%s), skipping fallback for printer %d",
  725. tray_label,
  726. current_remain,
  727. printer_id,
  728. )
  729. continue
  730. start_remain = session.tray_remain_start[key]
  731. delta_pct = start_remain - current_remain
  732. if delta_pct <= 0:
  733. # Not necessarily "nothing was printed". A fresh spool sits
  734. # at 100% for the first tens of grams, and the AMS estimate
  735. # drifts upward on its own, so a real print can end with the
  736. # same or a higher reading than it started with. Said out
  737. # loud because the alternative -- charging nothing, silently
  738. # -- is indistinguishable from having nothing to charge, and
  739. # the operator has no other way to find the prints that went
  740. # uncounted (#1820).
  741. logger.info(
  742. "[UsageTracker] %s: remain%% did not fall over the print (%d%% -> %d%%), "
  743. "nothing charged for printer %d",
  744. tray_label,
  745. start_remain,
  746. current_remain,
  747. printer_id,
  748. )
  749. continue
  750. spool_id = await _resolve_spool_id_for_tray(
  751. printer_id=printer_id,
  752. ams_id=assign_ams_id,
  753. tray_id=assign_tray_id,
  754. db=db,
  755. spool_assignments_snapshot=session.spool_assignments,
  756. print_started_at=session.started_at,
  757. )
  758. if spool_id is None:
  759. logger.info(
  760. "[UsageTracker] %s: no spool assigned, skipping fallback for printer %d",
  761. tray_label,
  762. printer_id,
  763. )
  764. continue
  765. # Load spool
  766. spool_result = await db.execute(select(Spool).where(Spool.id == spool_id))
  767. spool = spool_result.scalar_one_or_none()
  768. if not spool:
  769. continue
  770. # Compute weight consumed
  771. weight_grams = (delta_pct / 100.0) * spool.label_weight
  772. # Update spool
  773. spool.weight_used = (spool.weight_used or 0) + weight_grams
  774. spool.last_used = datetime.now(timezone.utc)
  775. # Calculate cost for this usage
  776. cost = None
  777. cost_per_kg = spool.cost_per_kg if spool.cost_per_kg is not None else default_filament_cost
  778. if cost_per_kg > 0:
  779. cost = round((weight_grams / 1000.0) * cost_per_kg, 2)
  780. # Insert usage history record
  781. history = SpoolUsageHistory(
  782. spool_id=spool.id,
  783. printer_id=printer_id,
  784. print_name=session.print_name,
  785. weight_used=round(weight_grams, 1),
  786. percent_used=delta_pct,
  787. status=status,
  788. cost=cost,
  789. archive_id=archive_id,
  790. )
  791. db.add(history)
  792. handled_trays.add(key)
  793. results.append(
  794. {
  795. "spool_id": spool.id,
  796. "weight_used": round(weight_grams, 1),
  797. "percent_used": delta_pct,
  798. "ams_id": assign_ams_id,
  799. "tray_id": assign_tray_id,
  800. "material": spool.material,
  801. "cost": cost,
  802. # AMS remain%-delta fallback has no 3MF slot — slot_id
  803. # stays None so it is excluded from the colour rewrite.
  804. "slot_id": None,
  805. "color": _spool_color_to_hex(spool.rgba),
  806. }
  807. )
  808. logger.info(
  809. "[UsageTracker] Spool %d consumed %.1fg (%d%%) on printer %d %s (AMS fallback, %s)",
  810. spool.id,
  811. weight_grams,
  812. delta_pct,
  813. printer_id,
  814. tray_label,
  815. status,
  816. )
  817. if results:
  818. await db.commit()
  819. # --- Update PrintArchive.cost from THIS print session only ---
  820. #
  821. # Cover any filament weight that wasn't tracked by an inventory spool with
  822. # the global default rate (#1344). Without this, a multi-color print where
  823. # only some AMS trays are mapped to inventory spools would record only the
  824. # mapped slots' share — e.g. $0.01 for a 110g print when 3 of 4 trays had
  825. # no spool record. The initial cost set by archive.py (total grams *
  826. # primary cost_per_kg) is fine on its own, but this block overwrites it,
  827. # so the overwrite must reconstruct the whole-print cost.
  828. if archive_id and results:
  829. from sqlalchemy import func, select
  830. from backend.app.models.archive import PrintArchive
  831. from backend.app.models.print_log import PrintLogEntry
  832. archive_result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
  833. archive = archive_result.scalar_one_or_none()
  834. if archive:
  835. total_cost = sum(r.get("cost", 0) or 0 for r in results)
  836. tracked_grams = sum(r.get("weight_used", 0) or 0 for r in results)
  837. archive_grams = archive.filament_used_grams or 0
  838. untracked_grams = max(0.0, archive_grams - tracked_grams)
  839. if untracked_grams > 0 and default_filament_cost > 0:
  840. total_cost += (untracked_grams / 1000.0) * default_filament_cost
  841. if total_cost > 0:
  842. # Only overwrite archive.cost on the first run. Reprint actuals
  843. # live in PrintLogEntry; the archive card keeps the first run's
  844. # cost so a failed reprint doesn't visually clobber a successful
  845. # 100 g/$X print with a 10 g/$X/10 partial (#1378).
  846. _existing_runs_result = await db.execute(
  847. select(func.count(PrintLogEntry.id)).where(PrintLogEntry.archive_id == archive_id)
  848. )
  849. _existing_runs = _existing_runs_result.scalar()
  850. if not _existing_runs:
  851. archive.cost = round(total_cost, 2)
  852. await db.commit()
  853. return results
  854. # A running print's ``filename`` is the path the printer is executing, and on a
  855. # sliced job that is always ``…/Metadata/plate_<N>.gcode``. Its stem names the
  856. # *plate*, not the model, and every Bambu print in existence has one — so it
  857. # identifies nothing and must never be used to match a 3MF. It reached the
  858. # matcher for real on H2-series and P2S prints, where the file goes to internal
  859. # eMMC, no 3MF can be fetched, and the archive keeps the gcode path as its
  860. # filename: `plate_1` then matched an unrelated `lid_plate_1.gcode.3mf` and that
  861. # print's filament figures were read off a different model entirely.
  862. _GENERIC_PLATE_STEM = re.compile(r"^plate_?\d+$", re.IGNORECASE)
  863. def _like_escape(value: str) -> str:
  864. """Escape LIKE metacharacters so a stem matches literally.
  865. ``_`` is a single-character wildcard, and model names are full of them.
  866. """
  867. return value.replace("\\", "\\\\").replace("%", "\\%").replace("_", "\\_")
  868. def _threemf_search_stem(*candidates: str | None) -> str | None:
  869. """First candidate that names a model, or None if none of them do.
  870. Candidates are tried in order and the generic plate name is skipped rather
  871. than accepted, so a print that only has one falls through to "no match"
  872. instead of matching everything.
  873. """
  874. for raw in candidates:
  875. if not raw:
  876. continue
  877. stem = raw.split("/")[-1].strip()
  878. for suffix in (".gcode.3mf", ".gcode", ".3mf"):
  879. if stem.lower().endswith(suffix):
  880. stem = stem[: -len(suffix)]
  881. break
  882. # Stripped only to judge the stem, never to change it: a real archive
  883. # here is named "…Face Down .gcode.3mf", and a stem trimmed to
  884. # "…Face Down" no longer matches the file it came from.
  885. probe = stem.strip()
  886. if probe and not _GENERIC_PLATE_STEM.match(probe):
  887. return stem
  888. return None
  889. def _stem_matches(column, stem: str):
  890. """Filter matching *stem* at a filename boundary rather than anywhere.
  891. ``ilike("%<stem>.%")`` also matched a *suffix* of a longer name, which is how
  892. `plate_1` reached `lid_plate_1.gcode.3mf`. A name is either the whole
  893. basename or the basename after a directory separator.
  894. """
  895. escaped = _like_escape(stem)
  896. return column.ilike(f"{escaped}.%", escape="\\") | column.ilike(f"%/{escaped}.%", escape="\\")
  897. def _expected_plate_for_print(plate_id: int | None, gcode_file: str | None) -> int | None:
  898. """The plate a running print is on, from whatever was recorded about it.
  899. ``plate_id`` is the reliable source, and the archives that need a donor 3MF
  900. have none: the no-3MF fallback row is created before any 3MF is read, so
  901. the column is never filled. The gcode path the printer echoed is the other
  902. source, exact on the firmwares that echo ``Metadata/plate_N.gcode``. Some
  903. P1S builds echo only the 3MF filename, and then the plate is simply not
  904. knowable at print start (#2957).
  905. """
  906. from backend.app.services.printer_manager import parse_plate_id
  907. if plate_id is not None:
  908. return plate_id
  909. return parse_plate_id(gcode_file)
  910. def _donor_3mf_conflicts(candidate, expected_plate: int | None) -> str | None:
  911. """Why *candidate* cannot be this print's 3MF, or None if nothing rules it out.
  912. A same-name 3MF is not the same print. Bambu Studio writes the printer-side
  913. filename from the project's ``Title`` metadata, so every plate of a project
  914. arrives under one name however the user renamed the file on disk, and a
  915. donor chosen on the name alone hands one plate's slicer estimates to another
  916. plate's print. A reporter's single-filament job was charged against three
  917. spools that way, and nothing about the deduction said it was a guess
  918. (#2957).
  919. The plate is the one thing that can settle this. It is the same comparison
  920. #1204 already makes against a freshly downloaded 3MF, so a single-plate
  921. export is known to carry its original index rather than a renumbered 1.
  922. Filament *count* deliberately is not checked, however tempting: the slicer's
  923. ``ams_mapping`` is indexed by the project's filament slot -- see
  924. ``slot_to_tray[slot_id - 1]`` below -- not by the plate's, so a real
  925. single-filament print reports ``[0, -1, -1, -1]`` and its length says
  926. nothing about how many filaments the plate uses.
  927. """
  928. from backend.app.services.archive import plate_indexes_in_3mf
  929. if expected_plate is None:
  930. return None
  931. plates = plate_indexes_in_3mf(candidate)
  932. if not plates or any(plate is None for plate in plates):
  933. # Nothing was read, or not all of it was, and neither is evidence about
  934. # the plate. Refusing here would drop the fallback for every 3MF variant
  935. # this parser does not understand; downstream reports that honestly as
  936. # "no filament usage data".
  937. return None
  938. if len(plates) == 1 and plates[0] != expected_plate:
  939. return f"it holds plate {plates[0]}, this print is plate {expected_plate}"
  940. if expected_plate not in plates:
  941. # An all-plates export is a good donor precisely when it carries the
  942. # plate that is running. Without this the plate is looked for
  943. # downstream, found missing, and the whole file's filaments are summed
  944. # onto one plate's print.
  945. return f"it has no plate {expected_plate}"
  946. return None
  947. async def _resolve_3mf_fallback(archive, db: AsyncSession, base_dir):
  948. """Try to find a 3MF file from library or a previous archive when the current archive has none.
  949. This handles fallback archives (FTP download failed) where the 3MF may already exist
  950. locally from a library upload or a previous successful print of the same file.
  951. A name match alone does not make a candidate this print's file, so every
  952. candidate is put through :func:`_donor_3mf_conflicts` before it is handed
  953. back (#2957).
  954. """
  955. from pathlib import Path
  956. from backend.app.models.archive import PrintArchive
  957. from backend.app.models.library import LibraryFile
  958. # Derive search name from archive filename (e.g. "benchy.3mf" or "benchy.gcode.3mf"),
  959. # falling back to the print name when the filename is only a plate path.
  960. search_base = _threemf_search_stem(archive.filename, archive.print_name)
  961. if not search_base:
  962. return None
  963. print_data = (getattr(archive, "extra_data", None) or {}).get("_print_data") or {}
  964. expected_plate = _expected_plate_for_print(
  965. getattr(archive, "plate_id", None),
  966. archive.filename or print_data.get("filename"),
  967. )
  968. if expected_plate is None:
  969. # Worth saying out loud. On the firmwares that echo only the 3MF
  970. # filename there is nothing to check a donor against, so whatever is
  971. # accepted below is accepted on its name alone -- which is how the
  972. # reporter's spools were debited for another plate's filament. The
  973. # deduction being silent was half the bug (#2957).
  974. logger.warning(
  975. "[UsageTracker] 3MF fallback: archive %s does not know its plate (%r), so a same-named "
  976. "3MF can only be matched on its name",
  977. archive.id,
  978. archive.filename,
  979. )
  980. # 1. Try library files matching the name (match base name at file boundary)
  981. try:
  982. lib_result = await db.execute(
  983. LibraryFile.active()
  984. .where(_stem_matches(LibraryFile.file_path, search_base))
  985. .where(LibraryFile.file_path.ilike("%.3mf"))
  986. .order_by(LibraryFile.created_at.desc())
  987. .limit(3)
  988. )
  989. for lib_file in lib_result.scalars().all():
  990. lib_path = Path(lib_file.file_path)
  991. candidate = lib_path if lib_path.is_absolute() else base_dir / lib_file.file_path
  992. if candidate.exists() and candidate.suffix == ".3mf":
  993. conflict = _donor_3mf_conflicts(candidate, expected_plate)
  994. if conflict:
  995. logger.warning(
  996. "[UsageTracker] 3MF fallback: not using library file %s for archive %s — %s",
  997. candidate,
  998. archive.id,
  999. conflict,
  1000. )
  1001. continue
  1002. logger.info(
  1003. "[UsageTracker] 3MF fallback: found library file %s for archive %s (expected plate=%s)",
  1004. candidate,
  1005. archive.id,
  1006. expected_plate,
  1007. )
  1008. return candidate
  1009. except Exception as e:
  1010. logger.debug("[UsageTracker] 3MF fallback: library lookup failed: %s", e)
  1011. # 2. Try previous archives with the same filename that have a valid file_path
  1012. try:
  1013. prev_result = await db.execute(
  1014. select(PrintArchive)
  1015. .where(PrintArchive.id != archive.id)
  1016. .where(PrintArchive.printer_id == archive.printer_id)
  1017. .where(PrintArchive.file_path != "")
  1018. .where(PrintArchive.file_path.isnot(None))
  1019. .where(_stem_matches(PrintArchive.filename, search_base))
  1020. .order_by(PrintArchive.created_at.desc())
  1021. .limit(3)
  1022. )
  1023. for prev_archive in prev_result.scalars().all():
  1024. candidate = base_dir / prev_archive.file_path
  1025. if candidate.exists() and candidate.suffix == ".3mf":
  1026. conflict = _donor_3mf_conflicts(candidate, expected_plate)
  1027. if conflict:
  1028. logger.warning(
  1029. "[UsageTracker] 3MF fallback: not using archive %s's file for archive %s — %s",
  1030. prev_archive.id,
  1031. archive.id,
  1032. conflict,
  1033. )
  1034. continue
  1035. logger.info(
  1036. "[UsageTracker] 3MF fallback: found previous archive %s file for archive %s (expected plate=%s)",
  1037. prev_archive.id,
  1038. archive.id,
  1039. expected_plate,
  1040. )
  1041. return candidate
  1042. except Exception as e:
  1043. logger.debug("[UsageTracker] 3MF fallback: previous archive lookup failed: %s", e)
  1044. return None
  1045. async def _find_3mf_by_filename(
  1046. printer_id: int,
  1047. filename: str,
  1048. db: AsyncSession,
  1049. base_dir,
  1050. print_name: str | None = None,
  1051. ):
  1052. """Find a 3MF file by filename from library or previous archives.
  1053. Used when auto-archive is disabled and there's no archive_id, but we still
  1054. need the 3MF slicer data for filament usage tracking.
  1055. ``print_name`` is the model name to fall back to when ``filename`` is the
  1056. printer's plate path, which names no model at all -- and when it is that
  1057. plate path, it is also what keeps a same-named file for a different plate
  1058. from being adopted (#2957); see :func:`_donor_3mf_conflicts`.
  1059. """
  1060. from pathlib import Path
  1061. from backend.app.models.archive import PrintArchive
  1062. from backend.app.models.library import LibraryFile
  1063. search_base = _threemf_search_stem(filename, print_name)
  1064. if not search_base:
  1065. return None
  1066. expected_plate = _expected_plate_for_print(None, filename)
  1067. # 1. Try library files matching the name
  1068. try:
  1069. lib_result = await db.execute(
  1070. LibraryFile.active()
  1071. .where(_stem_matches(LibraryFile.file_path, search_base))
  1072. .where(LibraryFile.file_path.ilike("%.3mf"))
  1073. .order_by(LibraryFile.created_at.desc())
  1074. .limit(3)
  1075. )
  1076. for lib_file in lib_result.scalars().all():
  1077. lib_path = Path(lib_file.file_path)
  1078. candidate = lib_path if lib_path.is_absolute() else base_dir / lib_file.file_path
  1079. if candidate.exists() and candidate.suffix == ".3mf":
  1080. conflict = _donor_3mf_conflicts(candidate, expected_plate)
  1081. if conflict:
  1082. logger.warning(
  1083. "[UsageTracker] 3MF (no-archive): not using library file %s for '%s' — %s",
  1084. candidate,
  1085. filename,
  1086. conflict,
  1087. )
  1088. continue
  1089. logger.info("[UsageTracker] 3MF (no-archive): found library file %s for '%s'", candidate, filename)
  1090. return candidate
  1091. except Exception as e:
  1092. logger.debug("[UsageTracker] 3MF (no-archive): library lookup failed: %s", e)
  1093. # 2. Try previous archives with a valid 3MF file_path
  1094. try:
  1095. prev_result = await db.execute(
  1096. select(PrintArchive)
  1097. .where(PrintArchive.printer_id == printer_id)
  1098. .where(PrintArchive.file_path != "")
  1099. .where(PrintArchive.file_path.isnot(None))
  1100. .where(_stem_matches(PrintArchive.filename, search_base))
  1101. .order_by(PrintArchive.created_at.desc())
  1102. .limit(3)
  1103. )
  1104. for prev_archive in prev_result.scalars().all():
  1105. candidate = base_dir / prev_archive.file_path
  1106. if candidate.exists() and candidate.suffix == ".3mf":
  1107. conflict = _donor_3mf_conflicts(candidate, expected_plate)
  1108. if conflict:
  1109. logger.warning(
  1110. "[UsageTracker] 3MF (no-archive): not using archive %s's file for '%s' — %s",
  1111. prev_archive.id,
  1112. filename,
  1113. conflict,
  1114. )
  1115. continue
  1116. logger.info(
  1117. "[UsageTracker] 3MF (no-archive): found previous archive %s file for '%s'",
  1118. prev_archive.id,
  1119. filename,
  1120. )
  1121. return candidate
  1122. except Exception as e:
  1123. logger.debug("[UsageTracker] 3MF (no-archive): previous archive lookup failed: %s", e)
  1124. return None
  1125. async def _track_from_3mf(
  1126. printer_id: int,
  1127. archive_id: int | None,
  1128. status: str,
  1129. print_name: str,
  1130. handled_trays: set[tuple[int, int]],
  1131. printer_manager,
  1132. db: AsyncSession,
  1133. ams_mapping: list[int] | None = None,
  1134. tray_now_at_start: int = -1,
  1135. last_progress: float = 0.0,
  1136. last_layer_num: int = 0,
  1137. default_filament_cost: float = 0.0,
  1138. spool_assignments: dict[tuple[int, int], int] | None = None,
  1139. print_started_at: datetime | None = None,
  1140. threemf_path=None,
  1141. plate_id: int | None = None,
  1142. ) -> list[dict]:
  1143. """Track usage from 3MF per-filament slicer data (primary path).
  1144. Uses slicer-estimated filament weight for all spools (BL and non-BL).
  1145. For partial prints (failed/aborted), tries per-layer gcode data first,
  1146. then falls back to linear scaling by progress.
  1147. When archive_id is None (auto-archive disabled), a pre-resolved threemf_path
  1148. can be provided to still track filament usage from slicer data.
  1149. When ``plate_id`` is set (queue prints of a single plate from a multi-plate
  1150. 3MF), only that plate's filaments contribute. Without it the 3MF parser sums
  1151. every plate, which is correct for direct/library Print flows that always
  1152. target the first or only plate (#1697).
  1153. Slot-to-tray mapping priority:
  1154. 1. Stored ams_mapping from print command (reprints/direct prints)
  1155. 2. MQTT mapping field from printer state (universal, all print sources)
  1156. 3. Queue item ams_mapping (for queue-initiated prints)
  1157. 4. tray_now from printer state (for single-filament non-queue prints)
  1158. 5. Position-based default using sorted available tray IDs (handles external spools)
  1159. 6. Default mapping: slot_id - 1 = global_tray_id (last resort)
  1160. """
  1161. from pathlib import Path
  1162. from backend.app.core.config import settings as app_settings
  1163. from backend.app.models.archive import PrintArchive
  1164. from backend.app.models.print_queue import PrintQueueItem
  1165. from backend.app.utils.threemf_tools import extract_filament_usage_from_3mf
  1166. file_path: Path | None = threemf_path
  1167. archive: PrintArchive | None = None
  1168. if file_path is None and archive_id:
  1169. result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
  1170. archive = result.scalar_one_or_none()
  1171. if not archive:
  1172. logger.info("[UsageTracker] 3MF: archive %s not found, skipping", archive_id)
  1173. return []
  1174. # Try archive's own file_path first
  1175. if archive.file_path:
  1176. candidate = app_settings.base_dir / archive.file_path
  1177. if candidate.exists():
  1178. file_path = candidate
  1179. # Fallback: find 3MF from library or a previous archive with the same filename
  1180. if file_path is None:
  1181. file_path = await _resolve_3mf_fallback(archive, db, app_settings.base_dir)
  1182. if file_path is None:
  1183. logger.info("[UsageTracker] 3MF: no file available for archive %s, skipping", archive_id)
  1184. return []
  1185. # The queue item carries both the plate and the dispatched mapping; look it
  1186. # up at most once. ``.first()`` rather than ``.scalar_one_or_none()``
  1187. # because a batch dispatches one archive as several queue items, and
  1188. # raising there would cost the print all of its usage tracking.
  1189. _queue_item_lookup: list = []
  1190. async def _dispatch_queue_item():
  1191. if not _queue_item_lookup:
  1192. if not archive_id:
  1193. _queue_item_lookup.append(None)
  1194. else:
  1195. queue_result = await db.execute(
  1196. select(PrintQueueItem)
  1197. .where(PrintQueueItem.archive_id == archive_id)
  1198. .where(PrintQueueItem.status.in_(["printing", "completed", "failed"]))
  1199. )
  1200. _queue_item_lookup.append(queue_result.scalars().first())
  1201. return _queue_item_lookup[0]
  1202. # The caller's plate_id comes from the in-memory session, which a restart
  1203. # mid-print destroys. Both the archive and the queue item recorded the
  1204. # plate at dispatch — without falling back to them the parser sums every
  1205. # plate of a multi-plate file and charges the lot to one spool.
  1206. if plate_id is None:
  1207. if archive is not None and archive.plate_id is not None:
  1208. plate_id = archive.plate_id
  1209. logger.info("[UsageTracker] 3MF: plate_id=%s recovered from archive %s", plate_id, archive_id)
  1210. else:
  1211. plate_queue_item = await _dispatch_queue_item()
  1212. if plate_queue_item is not None and plate_queue_item.plate_id is not None:
  1213. plate_id = plate_queue_item.plate_id
  1214. logger.info(
  1215. "[UsageTracker] 3MF: plate_id=%s recovered from queue item %s",
  1216. plate_id,
  1217. plate_queue_item.id,
  1218. )
  1219. filament_usage = extract_filament_usage_from_3mf(file_path, plate_id)
  1220. if not filament_usage and plate_id is not None:
  1221. # The plate isn't in this file. That happens when the archive's own 3MF
  1222. # is gone and `_resolve_3mf_fallback` substituted a same-named file from
  1223. # the library that was sliced with different plates. Summing the whole
  1224. # file is wrong for a single-plate run, but it is closer than recording
  1225. # nothing at all — and unlike the silent whole-file sum this replaces,
  1226. # it says so.
  1227. filament_usage = extract_filament_usage_from_3mf(file_path, None)
  1228. if filament_usage:
  1229. logger.warning(
  1230. "[UsageTracker] 3MF: plate %s not present in %s — falling back to the whole-file total",
  1231. plate_id,
  1232. file_path,
  1233. )
  1234. plate_id = None
  1235. if not filament_usage:
  1236. logger.info("[UsageTracker] 3MF: no filament usage data in %s", file_path)
  1237. return []
  1238. logger.info("[UsageTracker] 3MF: archive %s, plate_id=%s, filament_usage=%s", archive_id, plate_id, filament_usage)
  1239. # --- Resolve slot-to-tray mapping ---
  1240. mapping_source = None
  1241. # 1. Use stored ams_mapping from the print command (reprints/direct prints)
  1242. slot_to_tray = ams_mapping
  1243. if slot_to_tray:
  1244. mapping_source = "print_cmd"
  1245. # 2. Try queue item ams_mapping (queue-initiated prints store the exact mapping)
  1246. #
  1247. # Ranked above the live MQTT field on purpose: `mapping` reports the tray
  1248. # the printer is feeding from *now*, and AMS filament backup rewrites it to
  1249. # the substitute tray when a spool runs dry. Read at completion it names
  1250. # the tray that finished the print, not the one the slicer assigned — the
  1251. # queue item's copy is the mapping the print was actually dispatched with.
  1252. if not slot_to_tray and archive_id:
  1253. queue_item = await _dispatch_queue_item()
  1254. if queue_item and queue_item.ams_mapping:
  1255. try:
  1256. slot_to_tray = json.loads(queue_item.ams_mapping)
  1257. mapping_source = "queue"
  1258. except (json.JSONDecodeError, TypeError):
  1259. pass
  1260. # 3. Try MQTT mapping field from printer state (universal, all print sources)
  1261. if not slot_to_tray:
  1262. state = printer_manager.get_status(printer_id)
  1263. raw_data = getattr(state, "raw_data", None) if state else None
  1264. if raw_data:
  1265. mqtt_mapping = raw_data.get("mapping")
  1266. decoded = _decode_mqtt_mapping(mqtt_mapping)
  1267. if decoded:
  1268. slot_to_tray = decoded
  1269. mapping_source = "mqtt"
  1270. # 4. Color-match 3MF filament slots to AMS trays (for printers without mapping field)
  1271. if not slot_to_tray:
  1272. state = printer_manager.get_status(printer_id)
  1273. raw_data = getattr(state, "raw_data", None) if state else None
  1274. if raw_data:
  1275. matched = _match_slots_by_color(filament_usage, raw_data.get("ams"))
  1276. if matched:
  1277. slot_to_tray = matched
  1278. mapping_source = "color_match"
  1279. logger.info(
  1280. "[UsageTracker] 3MF: slot_to_tray=%s (source: %s)",
  1281. slot_to_tray,
  1282. mapping_source or "none",
  1283. )
  1284. # 5. For single-filament non-queue prints, use tray_now from printer state
  1285. # Priority: tray_change_log (multi-tray split) > tray_now_at_start > current tray_now
  1286. # > last_loaded_tray > vt_tray check
  1287. #
  1288. # tray_change_log evidence wins over slot_to_tray when present: if the
  1289. # printer fed from multiple trays mid-print (AMS auto-fallback when one
  1290. # spool runs out, #957), the slicer's mapping captured at print start
  1291. # is stale and needs to be replaced with per-layer split attribution.
  1292. nonzero_slots = [u for u in filament_usage if u.get("used_g", 0) > 0]
  1293. tray_now_override: int | None = None
  1294. tray_changes: list[tuple[int, int]] = [] # [(global_tray_id, layer_num), ...]
  1295. state = printer_manager.get_status(printer_id) if len(nonzero_slots) == 1 else None
  1296. if state is not None:
  1297. tray_changes = getattr(state, "tray_change_log", []) or []
  1298. elif len(nonzero_slots) > 1:
  1299. # Multi-material print: every filament change moves tray_now, so the
  1300. # log can't be read as "this slot moved to that tray" and splitting
  1301. # would attribute worse than the mapping does. Say so rather than
  1302. # silently dropping the evidence — a runout mid-print on a
  1303. # multi-material job still lands entirely on the mapped tray.
  1304. _multi_state = printer_manager.get_status(printer_id)
  1305. if len(getattr(_multi_state, "tray_change_log", []) or []) > 1:
  1306. logger.warning(
  1307. "[UsageTracker] 3MF: %d tray changes observed but %d filament slots used — "
  1308. "splitting needs a single slot, attributing by mapping alone (printer %d, archive %s)",
  1309. len(_multi_state.tray_change_log),
  1310. len(nonzero_slots),
  1311. printer_id,
  1312. archive_id,
  1313. )
  1314. if len(tray_changes) > 1:
  1315. # Multi-tray usage detected — splitting takes over regardless of slot_to_tray.
  1316. logger.info("[UsageTracker] 3MF: tray change log: %s (will split weight)", tray_changes)
  1317. elif not slot_to_tray and len(nonzero_slots) == 1:
  1318. if 0 <= tray_now_at_start <= 254:
  1319. tray_now_override = tray_now_at_start
  1320. logger.info("[UsageTracker] 3MF: using tray_now_at_start=%d (single-filament fallback)", tray_now_at_start)
  1321. elif state and 0 <= state.tray_now <= 254:
  1322. tray_now_override = state.tray_now
  1323. logger.info("[UsageTracker] 3MF: using current tray_now=%d", state.tray_now)
  1324. elif state and 0 <= state.last_loaded_tray <= 253:
  1325. tray_now_override = state.last_loaded_tray
  1326. logger.info("[UsageTracker] 3MF: using last_loaded_tray=%d (post-retract fallback)", state.last_loaded_tray)
  1327. elif state and state.tray_now == 255:
  1328. # 255 = "no filament" on legacy printers, but valid 2nd external spool on H2-series
  1329. vt_tray = state.raw_data.get("vt_tray") or []
  1330. if any(int(vt.get("id", 0)) == 255 for vt in vt_tray if isinstance(vt, dict)):
  1331. tray_now_override = state.tray_now
  1332. logger.info("[UsageTracker] 3MF: using tray_now=255 (H2-series external spool)")
  1333. if tray_now_override is None:
  1334. logger.info(
  1335. "[UsageTracker] 3MF: no valid tray_now (at_start=%d, current=%s, last_loaded=%s)",
  1336. tray_now_at_start,
  1337. state.tray_now if state else "N/A",
  1338. state.last_loaded_tray if state else "N/A",
  1339. )
  1340. # Scale factor for partial prints (failed/aborted)
  1341. if status == "completed":
  1342. scale = 1.0
  1343. else:
  1344. state = printer_manager.get_status(printer_id)
  1345. progress = state.progress if state else 0
  1346. # Firmware resets progress to 0 on cancel — use last valid progress captured during print
  1347. if progress <= 0 and last_progress > 0:
  1348. progress = last_progress
  1349. logger.info("[UsageTracker] 3MF: using last_progress=%.1f (firmware reset current to 0)", last_progress)
  1350. scale = max(0.0, min(progress / 100.0, 1.0))
  1351. # Per-layer gcode accuracy for partial prints
  1352. layer_grams: dict[int, float] | None = None
  1353. if status != "completed":
  1354. state = printer_manager.get_status(printer_id)
  1355. current_layer = state.layer_num if state else 0
  1356. # Firmware resets layer_num to 0 on cancel — use last valid layer captured during print
  1357. if current_layer <= 0 and last_layer_num > 0:
  1358. current_layer = last_layer_num
  1359. logger.info("[UsageTracker] 3MF: using last_layer_num=%d (firmware reset current to 0)", last_layer_num)
  1360. if current_layer > 0:
  1361. try:
  1362. from backend.app.utils.threemf_tools import (
  1363. extract_filament_properties_from_3mf,
  1364. extract_layer_filament_usage_from_3mf,
  1365. get_cumulative_usage_at_layer,
  1366. mm_to_grams,
  1367. )
  1368. layer_usage = extract_layer_filament_usage_from_3mf(file_path, plate_id)
  1369. if layer_usage:
  1370. cumulative_mm = get_cumulative_usage_at_layer(layer_usage, current_layer)
  1371. filament_props = extract_filament_properties_from_3mf(file_path)
  1372. layer_grams = {}
  1373. for filament_id, mm_used in cumulative_mm.items():
  1374. slot_id = filament_id + 1 # 0-based to 1-based
  1375. props = filament_props.get(slot_id, {})
  1376. density = props.get("density", 1.24)
  1377. diameter = props.get("diameter", 1.75)
  1378. layer_grams[slot_id] = mm_to_grams(mm_used, diameter, density)
  1379. except Exception:
  1380. pass # Fall back to linear scaling
  1381. results = []
  1382. # Trays this print drew from that no longer have an assignment to charge.
  1383. # Collected rather than acted on inline so one notification covers the whole
  1384. # print instead of one per slot (#2812).
  1385. unassigned_global_trays: list[int] = []
  1386. for usage in filament_usage:
  1387. slot_id = usage.get("slot_id", 0)
  1388. used_g = usage.get("used_g", 0)
  1389. if used_g <= 0:
  1390. continue
  1391. # --- Mid-print tray switch: split weight across trays ---
  1392. # Split math is shared with the Spoolman writer via
  1393. # ``utils.tray_split.compute_tray_split_grams`` (#1793) — both
  1394. # inventory backends must attribute segments identically or a
  1395. # user running dual-mode sees divergent totals.
  1396. if len(tray_changes) > 1:
  1397. # Compute total weight for this slot (same logic as normal path)
  1398. if layer_grams and slot_id in layer_grams:
  1399. total_weight = layer_grams[slot_id]
  1400. else:
  1401. total_weight = used_g * scale
  1402. if total_weight <= 0:
  1403. continue
  1404. # Extract per-layer gcode for segment splitting
  1405. split_layer_usage = None
  1406. split_props: dict = {}
  1407. try:
  1408. from backend.app.utils.threemf_tools import (
  1409. extract_filament_properties_from_3mf,
  1410. extract_layer_filament_usage_from_3mf,
  1411. )
  1412. split_layer_usage = extract_layer_filament_usage_from_3mf(file_path, plate_id)
  1413. filament_props = extract_filament_properties_from_3mf(file_path)
  1414. split_props = filament_props.get(slot_id, {})
  1415. except Exception:
  1416. pass # Fall back to linear splitting
  1417. from backend.app.utils.tray_split import compute_tray_split_grams
  1418. segments = compute_tray_split_grams(
  1419. tray_changes=tray_changes,
  1420. total_weight=total_weight,
  1421. slot_id=slot_id,
  1422. layer_usage=split_layer_usage,
  1423. density=split_props.get("density", 1.24),
  1424. diameter=split_props.get("diameter", 1.75),
  1425. total_layers=(state.total_layers if state else 0) or 0,
  1426. last_layer_num=last_layer_num,
  1427. )
  1428. for seg_idx, tray_global, segment_grams in segments:
  1429. if segment_grams <= 0:
  1430. continue
  1431. # Convert global tray ID to (ams_id, tray_id)
  1432. if tray_global >= 254:
  1433. seg_ams_id = 255
  1434. seg_tray_id = tray_global - 254
  1435. elif tray_global >= 128:
  1436. seg_ams_id = tray_global
  1437. seg_tray_id = 0
  1438. else:
  1439. seg_ams_id = tray_global // 4
  1440. seg_tray_id = tray_global % 4
  1441. seg_key = (seg_ams_id, seg_tray_id)
  1442. if seg_key in handled_trays:
  1443. continue
  1444. seg_start_layer = tray_changes[seg_idx][1]
  1445. is_last = seg_idx + 1 >= len(tray_changes)
  1446. logger.info(
  1447. "[UsageTracker] 3MF split: segment %d tray=%d (AMS%d-T%d) layers %d-%s -> %.1fg",
  1448. seg_idx,
  1449. tray_global,
  1450. seg_ams_id,
  1451. seg_tray_id,
  1452. seg_start_layer,
  1453. tray_changes[seg_idx + 1][1] if not is_last else "end",
  1454. segment_grams,
  1455. )
  1456. seg_spool_id = await _resolve_spool_id_for_tray(
  1457. printer_id=printer_id,
  1458. ams_id=seg_ams_id,
  1459. tray_id=seg_tray_id,
  1460. db=db,
  1461. spool_assignments_snapshot=spool_assignments,
  1462. print_started_at=print_started_at,
  1463. )
  1464. if seg_spool_id is None:
  1465. logger.info(
  1466. "[UsageTracker] 3MF split: no spool at printer %d AMS%d-T%d, skipping segment",
  1467. printer_id,
  1468. seg_ams_id,
  1469. seg_tray_id,
  1470. )
  1471. continue
  1472. spool_result = await db.execute(select(Spool).where(Spool.id == seg_spool_id))
  1473. spool = spool_result.scalar_one_or_none()
  1474. if not spool:
  1475. continue
  1476. spool.weight_used = (spool.weight_used or 0) + segment_grams
  1477. spool.last_used = datetime.now(timezone.utc)
  1478. percent = round(segment_grams / (spool.label_weight or 1000) * 100)
  1479. cost = None
  1480. cost_per_kg = spool.cost_per_kg if spool.cost_per_kg is not None else default_filament_cost
  1481. if cost_per_kg > 0:
  1482. cost = round((segment_grams / 1000.0) * cost_per_kg, 2)
  1483. history = SpoolUsageHistory(
  1484. spool_id=spool.id,
  1485. printer_id=printer_id,
  1486. print_name=print_name,
  1487. weight_used=round(segment_grams, 1),
  1488. percent_used=percent,
  1489. status=status,
  1490. cost=cost,
  1491. archive_id=archive_id,
  1492. )
  1493. db.add(history)
  1494. handled_trays.add(seg_key)
  1495. results.append(
  1496. {
  1497. "spool_id": spool.id,
  1498. "weight_used": round(segment_grams, 1),
  1499. "percent_used": percent,
  1500. "ams_id": seg_ams_id,
  1501. "tray_id": seg_tray_id,
  1502. "material": spool.material,
  1503. "cost": cost,
  1504. "slot_id": slot_id,
  1505. "color": _spool_color_to_hex(spool.rgba),
  1506. }
  1507. )
  1508. logger.info(
  1509. "[UsageTracker] Spool %d consumed %.1fg (3MF split seg%d) on printer %d AMS%d-T%d (%s)",
  1510. spool.id,
  1511. segment_grams,
  1512. seg_idx,
  1513. printer_id,
  1514. seg_ams_id,
  1515. seg_tray_id,
  1516. status,
  1517. )
  1518. continue # Skip normal single-tray processing for this slot
  1519. # Map 3MF slot_id to physical (ams_id, tray_id) using resolved mapping
  1520. if tray_now_override is not None:
  1521. # Single-filament non-queue print: use actual tray from printer state
  1522. global_tray_id = tray_now_override
  1523. else:
  1524. # Explicit mapping (print command, MQTT, queue, color match)
  1525. global_tray_id = None
  1526. if slot_to_tray and slot_id <= len(slot_to_tray):
  1527. mapped = slot_to_tray[slot_id - 1]
  1528. if isinstance(mapped, int) and mapped >= 0:
  1529. global_tray_id = mapped
  1530. # Position-based default: sort available tray IDs so external spools (254/255)
  1531. # naturally follow standard AMS trays, matching slicer slot numbering.
  1532. #
  1533. # Filter out AMS slots that have no spool loaded (empty `tray_type`) —
  1534. # BambuStudio/OrcaSlicer compact the slot list when assigning filaments
  1535. # and don't expose empty AMS slots to the user, so the slicer's 3MF
  1536. # slot N maps to the Nth *loaded* tray, not the Nth physical position.
  1537. # Without this filter a "3 AMS slots loaded + 1 empty + external"
  1538. # layout routes the slicer's 4th filament to the empty AMS slot
  1539. # instead of the external (#1607), and the external's spool usage
  1540. # never gets recorded. vt_tray entries are already filtered the
  1541. # same way inside `build_ams_tray_lookup` (line 174 checks
  1542. # `tray_type`), so this just mirrors that for the AMS side.
  1543. if global_tray_id is None:
  1544. _state = printer_manager.get_status(printer_id)
  1545. _raw = getattr(_state, "raw_data", None) if _state else None
  1546. if _raw:
  1547. from backend.app.services.spoolman_tracking import build_ams_tray_lookup
  1548. _lookup = build_ams_tray_lookup(_raw)
  1549. available_trays = sorted(gid for gid, info in _lookup.items() if info.get("tray_type"))
  1550. if slot_id <= len(available_trays):
  1551. global_tray_id = available_trays[slot_id - 1]
  1552. # Final fallback: slot_id - 1 (legacy, works for pure AMS without external spools)
  1553. if global_tray_id is None:
  1554. global_tray_id = slot_id - 1
  1555. if global_tray_id >= 254:
  1556. # External spool: ams_id=255 (sentinel), tray_id=slot index (0 or 1)
  1557. ams_id = 255
  1558. tray_id = global_tray_id - 254
  1559. elif global_tray_id >= 128:
  1560. ams_id = global_tray_id
  1561. tray_id = 0
  1562. else:
  1563. ams_id = global_tray_id // 4
  1564. tray_id = global_tray_id % 4
  1565. logger.info(
  1566. "[UsageTracker] 3MF: slot_id=%d -> global_tray=%d -> AMS%d-T%d (used_g=%.1f, tray_now_override=%s)",
  1567. slot_id,
  1568. global_tray_id,
  1569. ams_id,
  1570. tray_id,
  1571. used_g,
  1572. tray_now_override,
  1573. )
  1574. key = (ams_id, tray_id)
  1575. if key in handled_trays:
  1576. continue
  1577. spool_id = await _resolve_spool_id_for_tray(
  1578. printer_id=printer_id,
  1579. ams_id=ams_id,
  1580. tray_id=tray_id,
  1581. db=db,
  1582. spool_assignments_snapshot=spool_assignments,
  1583. print_started_at=print_started_at,
  1584. )
  1585. if spool_id is None:
  1586. # WARNING, not INFO: everything upstream of this line succeeded --
  1587. # the 3MF was found, the grams were read, the tray resolved -- and
  1588. # the print will still report success while this filament is never
  1589. # deducted. At INFO it was invisible under the default log level and
  1590. # absent from the reasoning in support bundles (#2812).
  1591. logger.warning(
  1592. "[UsageTracker] 3MF: no spool assignment at printer %d AMS%d-T%d — %.1fg not deducted",
  1593. printer_id,
  1594. ams_id,
  1595. tray_id,
  1596. used_g,
  1597. )
  1598. unassigned_global_trays.append(global_tray_id)
  1599. continue
  1600. # Load spool
  1601. spool_result = await db.execute(select(Spool).where(Spool.id == spool_id))
  1602. spool = spool_result.scalar_one_or_none()
  1603. if not spool:
  1604. continue
  1605. # Use per-layer grams if available, otherwise linear scale
  1606. if layer_grams and slot_id in layer_grams:
  1607. weight_grams = layer_grams[slot_id]
  1608. else:
  1609. weight_grams = used_g * scale
  1610. if weight_grams <= 0:
  1611. continue
  1612. # Update spool
  1613. spool.weight_used = (spool.weight_used or 0) + weight_grams
  1614. spool.last_used = datetime.now(timezone.utc)
  1615. percent = round(weight_grams / (spool.label_weight or 1000) * 100)
  1616. # Calculate cost for this usage
  1617. cost = None
  1618. cost_per_kg = spool.cost_per_kg if spool.cost_per_kg is not None else default_filament_cost
  1619. if cost_per_kg > 0:
  1620. cost = round((weight_grams / 1000.0) * cost_per_kg, 2)
  1621. # Insert usage history record
  1622. history = SpoolUsageHistory(
  1623. spool_id=spool.id,
  1624. printer_id=printer_id,
  1625. print_name=print_name,
  1626. weight_used=round(weight_grams, 1),
  1627. percent_used=percent,
  1628. status=status,
  1629. cost=cost,
  1630. archive_id=archive_id,
  1631. )
  1632. db.add(history)
  1633. handled_trays.add(key)
  1634. results.append(
  1635. {
  1636. "spool_id": spool.id,
  1637. "weight_used": round(weight_grams, 1),
  1638. "percent_used": percent,
  1639. "ams_id": ams_id,
  1640. "tray_id": tray_id,
  1641. "material": spool.material,
  1642. "cost": cost,
  1643. "slot_id": slot_id,
  1644. "color": _spool_color_to_hex(spool.rgba),
  1645. }
  1646. )
  1647. # Determine mapping source for debug logging
  1648. if tray_now_override is not None:
  1649. map_src = ", tray_now"
  1650. elif mapping_source:
  1651. map_src = f", {mapping_source}_map"
  1652. else:
  1653. map_src = ""
  1654. logger.info(
  1655. "[UsageTracker] Spool %d consumed %.1fg (3MF%s%s) on printer %d AMS%d-T%d (%s)",
  1656. spool.id,
  1657. weight_grams,
  1658. " per-layer" if (layer_grams and slot_id in layer_grams) else (f" scaled {scale:.0%}" if scale < 1 else ""),
  1659. map_src,
  1660. printer_id,
  1661. ams_id,
  1662. tray_id,
  1663. status,
  1664. )
  1665. # --- Adopt the matched inventory spools' colours for the archive (#1494) ---
  1666. # The archive's filament_color was set from the slicer's 3MF at creation
  1667. # time; now that every used slot has been resolved to an inventory spool,
  1668. # the curated spool colour is authoritative. Committed by the caller's
  1669. # `if results: await db.commit()`.
  1670. if archive is not None:
  1671. spool_colors = _archive_colors_from_spools(filament_usage, results)
  1672. if spool_colors:
  1673. joined = ",".join(spool_colors)
  1674. if joined != archive.filament_color:
  1675. logger.info(
  1676. "[UsageTracker] 3MF: archive %s filament_color %r -> %r (from inventory spools)",
  1677. archive_id,
  1678. archive.filament_color,
  1679. joined,
  1680. )
  1681. archive.filament_color = joined
  1682. # Adopt the matched spools' materials too (#2563) — a slot mapped to a
  1683. # differently-typed spool than it was sliced for otherwise records the
  1684. # sliced type in the archive, Print Log and material stats.
  1685. spool_types = _archive_types_from_spools(filament_usage, results)
  1686. if spool_types:
  1687. joined_types = ",".join(spool_types)
  1688. if joined_types != archive.filament_type:
  1689. logger.info(
  1690. "[UsageTracker] 3MF: archive %s filament_type %r -> %r (from inventory spools)",
  1691. archive_id,
  1692. archive.filament_type,
  1693. joined_types,
  1694. )
  1695. archive.filament_type = joined_types
  1696. if unassigned_global_trays:
  1697. from backend.app.services.spool_assignment_notifications import (
  1698. notify_missing_spool_assignments_on_print_complete,
  1699. )
  1700. await notify_missing_spool_assignments_on_print_complete(printer_id, unassigned_global_trays, db, logger)
  1701. return results