main.py 96 KB

12345678910111213141516171819202122232425262728293031323334353637383940414243444546474849505152535455565758596061626364656667686970717273747576777879808182838485868788899091929394959697989910010110210310410510610710810911011111211311411511611711811912012112212312412512612712812913013113213313413513613713813914014114214314414514614714814915015115215315415515615715815916016116216316416516616716816917017117217317417517617717817918018118218318418518618718818919019119219319419519619719819920020120220320420520620720820921021121221321421521621721821922022122222322422522622722822923023123223323423523623723823924024124224324424524624724824925025125225325425525625725825926026126226326426526626726826927027127227327427527627727827928028128228328428528628728828929029129229329429529629729829930030130230330430530630730830931031131231331431531631731831932032132232332432532632732832933033133233333433533633733833934034134234334434534634734834935035135235335435535635735835936036136236336436536636736836937037137237337437537637737837938038138238338438538638738838939039139239339439539639739839940040140240340440540640740840941041141241341441541641741841942042142242342442542642742842943043143243343443543643743843944044144244344444544644744844945045145245345445545645745845946046146246346446546646746846947047147247347447547647747847948048148248348448548648748848949049149249349449549649749849950050150250350450550650750850951051151251351451551651751851952052152252352452552652752852953053153253353453553653753853954054154254354454554654754854955055155255355455555655755855956056156256356456556656756856957057157257357457557657757857958058158258358458558658758858959059159259359459559659759859960060160260360460560660760860961061161261361461561661761861962062162262362462562662762862963063163263363463563663763863964064164264364464564664764864965065165265365465565665765865966066166266366466566666766866967067167267367467567667767867968068168268368468568668768868969069169269369469569669769869970070170270370470570670770870971071171271371471571671771871972072172272372472572672772872973073173273373473573673773873974074174274374474574674774874975075175275375475575675775875976076176276376476576676776876977077177277377477577677777877978078178278378478578678778878979079179279379479579679779879980080180280380480580680780880981081181281381481581681781881982082182282382482582682782882983083183283383483583683783883984084184284384484584684784884985085185285385485585685785885986086186286386486586686786886987087187287387487587687787887988088188288388488588688788888989089189289389489589689789889990090190290390490590690790890991091191291391491591691791891992092192292392492592692792892993093193293393493593693793893994094194294394494594694794894995095195295395495595695795895996096196296396496596696796896997097197297397497597697797897998098198298398498598698798898999099199299399499599699799899910001001100210031004100510061007100810091010101110121013101410151016101710181019102010211022102310241025102610271028102910301031103210331034103510361037103810391040104110421043104410451046104710481049105010511052105310541055105610571058105910601061106210631064106510661067106810691070107110721073107410751076107710781079108010811082108310841085108610871088108910901091109210931094109510961097109810991100110111021103110411051106110711081109111011111112111311141115111611171118111911201121112211231124112511261127112811291130113111321133113411351136113711381139114011411142114311441145114611471148114911501151115211531154115511561157115811591160116111621163116411651166116711681169117011711172117311741175117611771178117911801181118211831184118511861187118811891190119111921193119411951196119711981199120012011202120312041205120612071208120912101211121212131214121512161217121812191220122112221223122412251226122712281229123012311232123312341235123612371238123912401241124212431244124512461247124812491250125112521253125412551256125712581259126012611262126312641265126612671268126912701271127212731274127512761277127812791280128112821283128412851286128712881289129012911292129312941295129612971298129913001301130213031304130513061307130813091310131113121313131413151316131713181319132013211322132313241325132613271328132913301331133213331334133513361337133813391340134113421343134413451346134713481349135013511352135313541355135613571358135913601361136213631364136513661367136813691370137113721373137413751376137713781379138013811382138313841385138613871388138913901391139213931394139513961397139813991400140114021403140414051406140714081409141014111412141314141415141614171418141914201421142214231424142514261427142814291430143114321433143414351436143714381439144014411442144314441445144614471448144914501451145214531454145514561457145814591460146114621463146414651466146714681469147014711472147314741475147614771478147914801481148214831484148514861487148814891490149114921493149414951496149714981499150015011502150315041505150615071508150915101511151215131514151515161517151815191520152115221523152415251526152715281529153015311532153315341535153615371538153915401541154215431544154515461547154815491550155115521553155415551556155715581559156015611562156315641565156615671568156915701571157215731574157515761577157815791580158115821583158415851586158715881589159015911592159315941595159615971598159916001601160216031604160516061607160816091610161116121613161416151616161716181619162016211622162316241625162616271628162916301631163216331634163516361637163816391640164116421643164416451646164716481649165016511652165316541655165616571658165916601661166216631664166516661667166816691670167116721673167416751676167716781679168016811682168316841685168616871688168916901691169216931694169516961697169816991700170117021703170417051706170717081709171017111712171317141715171617171718171917201721172217231724172517261727172817291730173117321733173417351736173717381739174017411742174317441745174617471748174917501751175217531754175517561757175817591760176117621763176417651766176717681769177017711772177317741775177617771778177917801781178217831784178517861787178817891790179117921793179417951796179717981799180018011802180318041805180618071808180918101811181218131814181518161817181818191820182118221823182418251826182718281829183018311832183318341835183618371838183918401841184218431844184518461847184818491850185118521853185418551856185718581859186018611862186318641865186618671868186918701871187218731874187518761877187818791880188118821883188418851886188718881889189018911892189318941895189618971898189919001901190219031904190519061907190819091910191119121913191419151916191719181919192019211922192319241925192619271928192919301931193219331934193519361937193819391940194119421943194419451946194719481949195019511952195319541955195619571958195919601961196219631964196519661967196819691970197119721973197419751976197719781979198019811982198319841985198619871988198919901991199219931994199519961997199819992000200120022003200420052006200720082009201020112012201320142015201620172018201920202021202220232024202520262027202820292030203120322033203420352036203720382039204020412042204320442045204620472048204920502051205220532054205520562057205820592060206120622063206420652066206720682069207020712072207320742075207620772078207920802081208220832084208520862087208820892090209120922093209420952096209720982099210021012102210321042105210621072108210921102111211221132114211521162117211821192120212121222123212421252126212721282129213021312132213321342135
  1. import asyncio
  2. import logging
  3. from contextlib import asynccontextmanager
  4. from datetime import UTC, datetime, timedelta
  5. from logging.handlers import RotatingFileHandler
  6. from fastapi import FastAPI
  7. # Import settings first for logging configuration
  8. from backend.app.core.config import APP_VERSION, settings as app_settings
  9. # Configure logging based on settings
  10. # DEBUG=true -> DEBUG level, else use LOG_LEVEL setting
  11. log_level_str = "DEBUG" if app_settings.debug else app_settings.log_level.upper()
  12. log_level = getattr(logging, log_level_str, logging.INFO)
  13. log_format = "%(asctime)s %(levelname)s [%(name)s] %(message)s"
  14. # Create root logger
  15. root_logger = logging.getLogger()
  16. root_logger.setLevel(log_level)
  17. # Console handler - always enabled
  18. console_handler = logging.StreamHandler()
  19. console_handler.setLevel(log_level)
  20. console_handler.setFormatter(logging.Formatter(log_format))
  21. root_logger.addHandler(console_handler)
  22. # File handler - only in production or if explicitly enabled
  23. if app_settings.log_to_file:
  24. log_file = app_settings.log_dir / "bambuddy.log"
  25. file_handler = RotatingFileHandler(
  26. log_file,
  27. maxBytes=5 * 1024 * 1024, # 5MB
  28. backupCount=3,
  29. encoding="utf-8",
  30. )
  31. file_handler.setLevel(log_level)
  32. file_handler.setFormatter(logging.Formatter(log_format))
  33. root_logger.addHandler(file_handler)
  34. logging.info(f"Logging to file: {log_file}")
  35. # Reduce noise from third-party libraries in production
  36. if not app_settings.debug:
  37. logging.getLogger("sqlalchemy.engine").setLevel(logging.WARNING)
  38. logging.getLogger("httpcore").setLevel(logging.WARNING)
  39. logging.getLogger("httpx").setLevel(logging.WARNING)
  40. logging.info(f"Bambuddy starting - debug={app_settings.debug}, log_level={log_level_str}")
  41. from fastapi.responses import FileResponse
  42. from fastapi.staticfiles import StaticFiles
  43. from sqlalchemy import delete, or_, select
  44. from backend.app.api.routes import (
  45. ams_history,
  46. api_keys,
  47. archives,
  48. auth,
  49. camera,
  50. cloud,
  51. discovery,
  52. external_links,
  53. filaments,
  54. firmware,
  55. kprofiles,
  56. library,
  57. maintenance,
  58. notification_templates,
  59. notifications,
  60. pending_uploads,
  61. print_queue,
  62. printers,
  63. projects,
  64. settings as settings_routes,
  65. smart_plugs,
  66. spoolman,
  67. support,
  68. system,
  69. updates,
  70. users,
  71. webhook,
  72. websocket,
  73. )
  74. from backend.app.api.routes.maintenance import _get_printer_maintenance_internal, ensure_default_types
  75. from backend.app.api.routes.support import init_debug_logging
  76. from backend.app.core.database import async_session, init_db
  77. from backend.app.core.websocket import ws_manager
  78. from backend.app.models.smart_plug import SmartPlug
  79. from backend.app.services.archive import ArchiveService
  80. from backend.app.services.bambu_ftp import download_file_async, get_ftp_retry_settings, with_ftp_retry
  81. from backend.app.services.bambu_mqtt import PrinterState
  82. from backend.app.services.homeassistant import homeassistant_service
  83. from backend.app.services.mqtt_relay import mqtt_relay
  84. from backend.app.services.notification_service import notification_service
  85. from backend.app.services.print_scheduler import scheduler as print_scheduler
  86. from backend.app.services.printer_manager import (
  87. init_printer_connections,
  88. printer_manager,
  89. printer_state_to_dict,
  90. )
  91. from backend.app.services.smart_plug_manager import smart_plug_manager
  92. from backend.app.services.spoolman import close_spoolman_client, get_spoolman_client, init_spoolman_client
  93. from backend.app.services.tasmota import tasmota_service
  94. from backend.app.services.telemetry import start_telemetry_loop
  95. # Track active prints: {(printer_id, filename): archive_id}
  96. _active_prints: dict[tuple[int, str], int] = {}
  97. # Track expected prints from reprint/scheduled (skip auto-archiving for these)
  98. # {(printer_id, filename): archive_id}
  99. _expected_prints: dict[tuple[int, str], int] = {}
  100. # Track starting energy for prints: {archive_id: starting_kwh}
  101. _print_energy_start: dict[int, float] = {}
  102. # Track reprints to add costs on completion: {archive_id}
  103. _reprint_archives: set[int] = set()
  104. async def _get_plug_energy(plug, db) -> dict | None:
  105. """Get energy from plug regardless of type (Tasmota or Home Assistant).
  106. For HA plugs, configures the service with current settings from DB.
  107. """
  108. if plug.plug_type == "homeassistant":
  109. from backend.app.api.routes.settings import get_setting
  110. ha_url = await get_setting(db, "ha_url") or ""
  111. ha_token = await get_setting(db, "ha_token") or ""
  112. homeassistant_service.configure(ha_url, ha_token)
  113. return await homeassistant_service.get_energy(plug)
  114. else:
  115. return await tasmota_service.get_energy(plug)
  116. def register_expected_print(printer_id: int, filename: str, archive_id: int):
  117. """Register an expected print from reprint/scheduled so we don't create duplicate archives."""
  118. # Store with multiple filename variations to catch different naming patterns
  119. _expected_prints[(printer_id, filename)] = archive_id
  120. # Also store without .3mf extension if present
  121. if filename.endswith(".3mf"):
  122. base = filename[:-4]
  123. _expected_prints[(printer_id, base)] = archive_id
  124. _expected_prints[(printer_id, f"{base}.gcode")] = archive_id
  125. logging.getLogger(__name__).info(
  126. f"Registered expected print: printer={printer_id}, file={filename}, archive={archive_id}"
  127. )
  128. _last_status_broadcast: dict[int, str] = {}
  129. _nozzle_count_updated: set[int] = set() # Track printers where we've updated nozzle_count
  130. async def _report_spoolman_usage(printer_id: int, archive_id: int, logger):
  131. """Report filament usage to Spoolman after print completion.
  132. This finds the spool by RFID tag_uid from current AMS state and reports
  133. the filament_used_grams from the archive metadata.
  134. """
  135. async with async_session() as db:
  136. from backend.app.api.routes.settings import get_setting
  137. from backend.app.models.archive import PrintArchive
  138. # Check if Spoolman is enabled
  139. spoolman_enabled = await get_setting(db, "spoolman_enabled")
  140. if not spoolman_enabled or spoolman_enabled.lower() != "true":
  141. return
  142. # Get Spoolman URL
  143. spoolman_url = await get_setting(db, "spoolman_url")
  144. if not spoolman_url:
  145. return
  146. # Get or create Spoolman client
  147. client = await get_spoolman_client()
  148. if not client:
  149. client = await init_spoolman_client(spoolman_url)
  150. # Check if Spoolman is reachable
  151. if not await client.health_check():
  152. logger.warning("Spoolman not reachable for usage reporting")
  153. return
  154. # Get archive to find filament usage
  155. result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
  156. archive = result.scalar_one_or_none()
  157. if not archive or not archive.filament_used_grams:
  158. logger.debug(f"No filament usage data for archive {archive_id}")
  159. return
  160. filament_used = archive.filament_used_grams
  161. logger.info(f"[SPOOLMAN] Archive {archive_id} used {filament_used}g of filament")
  162. # Get current AMS state from printer to find the active spool
  163. state = printer_manager.get_status(printer_id)
  164. if not state or not state.raw_data:
  165. logger.debug("No printer state available for usage reporting")
  166. return
  167. ams_data = state.raw_data.get("ams")
  168. if not ams_data:
  169. logger.debug("No AMS data available for usage reporting")
  170. return
  171. # Find spools with RFID tags in Spoolman and report usage
  172. # For now, we report usage to the first spool found with a matching tag
  173. # TODO: In future, track which specific trays were used during the print
  174. spools_updated = 0
  175. for ams_unit in ams_data:
  176. trays = ams_unit.get("tray", [])
  177. for tray_data in trays:
  178. tag_uid = tray_data.get("tag_uid")
  179. if not tag_uid:
  180. continue
  181. # Find spool in Spoolman by tag
  182. spool = await client.find_spool_by_tag(tag_uid)
  183. if spool:
  184. # Report usage to Spoolman
  185. result = await client.use_spool(spool["id"], filament_used)
  186. if result:
  187. logger.info(
  188. f"[SPOOLMAN] Reported {filament_used}g usage to spool {spool['id']} (tag: {tag_uid})"
  189. )
  190. spools_updated += 1
  191. # Only report to one spool for single-material prints
  192. # Multi-material prints would need more sophisticated tracking
  193. return
  194. if spools_updated == 0:
  195. logger.debug(f"No matching Spoolman spools found for printer {printer_id}")
  196. async def on_printer_status_change(printer_id: int, state: PrinterState):
  197. """Handle printer status changes - broadcast via WebSocket."""
  198. # Only broadcast if something meaningful changed (reduce WebSocket spam)
  199. # Include rounded temperatures to detect meaningful temp changes (within 1 degree)
  200. temps = state.temperatures or {}
  201. nozzle_temp = round(temps.get("nozzle", 0))
  202. bed_temp = round(temps.get("bed", 0))
  203. nozzle_2_temp = round(temps.get("nozzle_2", 0)) if "nozzle_2" in temps else ""
  204. chamber_temp = round(temps.get("chamber", 0)) if "chamber" in temps else ""
  205. # Auto-detect dual-nozzle printers from MQTT temperature data
  206. if "nozzle_2" in temps and printer_id not in _nozzle_count_updated:
  207. _nozzle_count_updated.add(printer_id)
  208. # Update nozzle_count in database
  209. async with async_session() as db:
  210. from backend.app.models.printer import Printer
  211. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  212. printer = result.scalar_one_or_none()
  213. if printer and printer.nozzle_count != 2:
  214. printer.nozzle_count = 2
  215. await db.commit()
  216. logging.getLogger(__name__).info(
  217. f"Auto-detected dual-nozzle printer {printer_id}, updated nozzle_count=2"
  218. )
  219. # Include target temps for heating phase detection
  220. bed_target = round(temps.get("bed_target", 0))
  221. nozzle_target = round(temps.get("nozzle_target", 0))
  222. status_key = (
  223. f"{state.connected}:{state.state}:{state.progress}:{state.layer_num}:"
  224. f"{nozzle_temp}:{bed_temp}:{nozzle_2_temp}:{chamber_temp}:"
  225. f"{state.stg_cur}:{bed_target}:{nozzle_target}:"
  226. f"{state.cooling_fan_speed}:{state.big_fan1_speed}:{state.big_fan2_speed}:"
  227. f"{state.chamber_light}:{state.active_extruder}"
  228. )
  229. # MQTT relay - publish status (before dedup check - always publish to MQTT)
  230. try:
  231. printer_info = printer_manager.get_printer(printer_id)
  232. if printer_info:
  233. await mqtt_relay.on_printer_status(printer_id, state, printer_info.name, printer_info.serial_number)
  234. except Exception:
  235. pass # Don't fail status callback if MQTT fails
  236. if _last_status_broadcast.get(printer_id) == status_key:
  237. return # No change, skip WebSocket broadcast
  238. _last_status_broadcast[printer_id] = status_key
  239. await ws_manager.send_printer_status(
  240. printer_id,
  241. printer_state_to_dict(state, printer_id, printer_manager.get_model(printer_id)),
  242. )
  243. async def on_ams_change(printer_id: int, ams_data: list):
  244. """Handle AMS data changes - sync to Spoolman if enabled and auto mode."""
  245. import logging
  246. logger = logging.getLogger(__name__)
  247. # MQTT relay - publish AMS change
  248. try:
  249. printer_info = printer_manager.get_printer(printer_id)
  250. if printer_info:
  251. await mqtt_relay.on_ams_change(printer_id, printer_info.name, printer_info.serial_number, ams_data)
  252. except Exception:
  253. pass # Don't fail AMS callback if MQTT fails
  254. # Broadcast AMS change via WebSocket (bypasses status_key deduplication)
  255. # This ensures frontend gets immediate updates when AMS slots are configured
  256. try:
  257. state = printer_manager.get_status(printer_id)
  258. if state:
  259. logger.info(f"[Printer {printer_id}] Broadcasting AMS change via WebSocket")
  260. await ws_manager.send_printer_status(
  261. printer_id,
  262. printer_state_to_dict(state, printer_id, printer_manager.get_model(printer_id)),
  263. )
  264. except Exception as e:
  265. logger.warning(f"Failed to broadcast AMS change for printer {printer_id}: {e}")
  266. try:
  267. async with async_session() as db:
  268. from backend.app.api.routes.settings import get_setting
  269. from backend.app.models.printer import Printer
  270. # Check if Spoolman is enabled
  271. spoolman_enabled = await get_setting(db, "spoolman_enabled")
  272. if not spoolman_enabled or spoolman_enabled.lower() != "true":
  273. return
  274. # Check sync mode
  275. sync_mode = await get_setting(db, "spoolman_sync_mode")
  276. if sync_mode and sync_mode != "auto":
  277. return # Only sync on auto mode
  278. # Get Spoolman URL
  279. spoolman_url = await get_setting(db, "spoolman_url")
  280. if not spoolman_url:
  281. return
  282. # Get or create Spoolman client
  283. client = await get_spoolman_client()
  284. if not client:
  285. client = await init_spoolman_client(spoolman_url)
  286. # Check if Spoolman is reachable
  287. if not await client.health_check():
  288. logger.warning(f"Spoolman not reachable at {spoolman_url}")
  289. return
  290. # Get printer name for location
  291. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  292. printer = result.scalar_one_or_none()
  293. printer_name = printer.name if printer else f"Printer {printer_id}"
  294. # Sync each AMS tray
  295. synced = 0
  296. for ams_unit in ams_data:
  297. ams_id = int(ams_unit.get("id", 0))
  298. trays = ams_unit.get("tray", [])
  299. for tray_data in trays:
  300. tray = client.parse_ams_tray(ams_id, tray_data)
  301. if not tray:
  302. continue # Empty tray
  303. try:
  304. result = await client.sync_ams_tray(tray, printer_name)
  305. if result:
  306. synced += 1
  307. except Exception as e:
  308. logger.error(f"Error syncing AMS {ams_id} tray {tray.tray_id}: {e}")
  309. if synced > 0:
  310. logger.info(f"Auto-synced {synced} AMS trays to Spoolman for printer {printer_id}")
  311. except Exception as e:
  312. import logging
  313. logging.getLogger(__name__).warning(f"Spoolman AMS sync failed: {e}")
  314. async def _send_print_start_notification(
  315. printer_id: int,
  316. data: dict,
  317. archive_data: dict | None = None,
  318. logger=None,
  319. ):
  320. """Helper to send print start notification with optional archive data."""
  321. if logger is None:
  322. import logging
  323. logger = logging.getLogger(__name__)
  324. try:
  325. async with async_session() as db:
  326. from backend.app.models.printer import Printer
  327. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  328. printer = result.scalar_one_or_none()
  329. printer_name = printer.name if printer else f"Printer {printer_id}"
  330. await notification_service.on_print_start(printer_id, printer_name, data, db, archive_data=archive_data)
  331. except Exception as e:
  332. logger.warning(f"Notification on_print_start failed: {e}")
  333. def _load_objects_from_archive(archive, printer_id: int, logger) -> None:
  334. """Extract printable objects from an archive's 3MF file and store in printer state."""
  335. try:
  336. from backend.app.services.archive import extract_printable_objects_from_3mf
  337. file_path = app_settings.base_dir / archive.file_path
  338. if file_path.exists() and str(file_path).endswith(".3mf"):
  339. with open(file_path, "rb") as f:
  340. threemf_data = f.read()
  341. # Extract with positions for UI overlay
  342. printable_objects, bbox_all = extract_printable_objects_from_3mf(threemf_data, include_positions=True)
  343. if printable_objects:
  344. client = printer_manager.get_client(printer_id)
  345. if client:
  346. client.state.printable_objects = printable_objects
  347. client.state.printable_objects_bbox_all = bbox_all
  348. client.state.skipped_objects = []
  349. logger.info(f"Loaded {len(printable_objects)} printable objects for printer {printer_id}")
  350. except Exception as e:
  351. logger.debug(f"Failed to extract printable objects from archive: {e}")
  352. async def on_print_start(printer_id: int, data: dict):
  353. """Handle print start - archive the 3MF file immediately."""
  354. import logging
  355. logger = logging.getLogger(__name__)
  356. logger.info(f"[CALLBACK] on_print_start called for printer {printer_id}, data keys: {list(data.keys())}")
  357. await ws_manager.send_print_start(printer_id, data)
  358. # MQTT relay - publish print start
  359. try:
  360. printer_info = printer_manager.get_printer(printer_id)
  361. if printer_info:
  362. await mqtt_relay.on_print_start(
  363. printer_id,
  364. printer_info.name,
  365. printer_info.serial_number,
  366. data.get("filename", ""),
  367. data.get("subtask_name", ""),
  368. )
  369. except Exception:
  370. pass # Don't fail print start callback if MQTT fails
  371. # Track if notification was sent (to avoid sending twice)
  372. notification_sent = False
  373. # Smart plug automation: turn on plug when print starts
  374. try:
  375. async with async_session() as db:
  376. await smart_plug_manager.on_print_start(printer_id, db)
  377. except Exception as e:
  378. logger.warning(f"Smart plug on_print_start failed: {e}")
  379. async with async_session() as db:
  380. from backend.app.models.printer import Printer
  381. from backend.app.services.bambu_ftp import list_files_async
  382. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  383. printer = result.scalar_one_or_none()
  384. if not printer or not printer.auto_archive:
  385. # Send notification without archive data (auto-archive disabled)
  386. logger.info(
  387. f"[CALLBACK] Skipping archive - printer: {printer is not None}, auto_archive: {printer.auto_archive if printer else 'N/A'}"
  388. )
  389. if not notification_sent:
  390. await _send_print_start_notification(printer_id, data, logger=logger)
  391. return
  392. # Get the filename and subtask_name
  393. filename = data.get("filename", "")
  394. subtask_name = data.get("subtask_name", "")
  395. logger.info(f"[CALLBACK] Print start detected - filename: {filename}, subtask: {subtask_name}")
  396. if not filename and not subtask_name:
  397. # Send notification without archive data (no filename)
  398. logger.info("[CALLBACK] Skipping archive - no filename or subtask_name")
  399. if not notification_sent:
  400. await _send_print_start_notification(printer_id, data, logger=logger)
  401. return
  402. # Check if this is an expected print from reprint/scheduled
  403. # Build list of possible keys to check
  404. expected_keys = []
  405. if subtask_name:
  406. expected_keys.append((printer_id, subtask_name))
  407. expected_keys.append((printer_id, f"{subtask_name}.3mf"))
  408. expected_keys.append((printer_id, f"{subtask_name}.gcode.3mf"))
  409. if filename:
  410. fname = filename.split("/")[-1] if "/" in filename else filename
  411. expected_keys.append((printer_id, fname))
  412. # Strip extensions to match
  413. base = fname.replace(".gcode", "").replace(".3mf", "")
  414. expected_keys.append((printer_id, base))
  415. expected_keys.append((printer_id, f"{base}.3mf"))
  416. expected_archive_id = None
  417. for key in expected_keys:
  418. expected_archive_id = _expected_prints.pop(key, None)
  419. if expected_archive_id:
  420. # Clean up other possible keys for this print
  421. for other_key in expected_keys:
  422. _expected_prints.pop(other_key, None)
  423. break
  424. if expected_archive_id:
  425. # This is a reprint/scheduled print - use existing archive, don't create new one
  426. logger.info(f"Using expected archive {expected_archive_id} for print (skipping duplicate)")
  427. from backend.app.models.archive import PrintArchive
  428. result = await db.execute(select(PrintArchive).where(PrintArchive.id == expected_archive_id))
  429. archive = result.scalar_one_or_none()
  430. if archive:
  431. # Update archive status to printing
  432. archive.status = "printing"
  433. archive.started_at = datetime.now()
  434. await db.commit()
  435. # Track as active print
  436. _active_prints[(printer_id, archive.filename)] = archive.id
  437. if subtask_name:
  438. _active_prints[(printer_id, f"{subtask_name}.3mf")] = archive.id
  439. # Mark as reprint so we add cost on completion
  440. _reprint_archives.add(archive.id)
  441. logger.info(f"Marked archive {archive.id} as reprint for cost addition on completion")
  442. # Set up energy tracking
  443. try:
  444. plug_result = await db.execute(select(SmartPlug).where(SmartPlug.printer_id == printer_id))
  445. plug = plug_result.scalar_one_or_none()
  446. logger.info(
  447. f"[ENERGY] Print start - archive {archive.id}, printer {printer_id}, plug found: {plug is not None}"
  448. )
  449. if plug:
  450. energy = await _get_plug_energy(plug, db)
  451. logger.info(f"[ENERGY] Energy response from plug: {energy}")
  452. if energy and energy.get("total") is not None:
  453. _print_energy_start[archive.id] = energy["total"]
  454. logger.info(
  455. f"[ENERGY] Recorded starting energy for archive {archive.id}: {energy['total']} kWh"
  456. )
  457. else:
  458. logger.warning(f"[ENERGY] No 'total' in energy response for archive {archive.id}")
  459. else:
  460. logger.info(f"[ENERGY] No smart plug found for printer {printer_id}")
  461. except Exception as e:
  462. logger.warning(f"Failed to record starting energy: {e}")
  463. await ws_manager.send_archive_updated(
  464. {
  465. "id": archive.id,
  466. "status": "printing",
  467. }
  468. )
  469. # Send notification with archive data (reprint/scheduled)
  470. if not notification_sent:
  471. archive_data = {"print_time_seconds": archive.print_time_seconds}
  472. await _send_print_start_notification(printer_id, data, archive_data, logger)
  473. # Extract printable objects from the archived 3MF file
  474. _load_objects_from_archive(archive, printer_id, logger)
  475. return # Skip creating a new archive
  476. # Check if there's already a "printing" archive for this printer/file
  477. # This prevents duplicates when backend restarts during an active print
  478. from backend.app.models.archive import PrintArchive
  479. check_name = subtask_name or filename.split("/")[-1].replace(".gcode", "").replace(".3mf", "")
  480. existing = await db.execute(
  481. select(PrintArchive)
  482. .where(PrintArchive.printer_id == printer_id)
  483. .where(PrintArchive.status == "printing")
  484. .where(PrintArchive.print_name.ilike(f"%{check_name}%"))
  485. .order_by(PrintArchive.created_at.desc())
  486. .limit(1)
  487. )
  488. existing_archive = existing.scalar_one_or_none()
  489. if existing_archive:
  490. # Check if archive is stale (older than 4 hours) - likely a failed/cancelled print
  491. # that didn't get properly updated
  492. archive_age = datetime.now(UTC) - existing_archive.created_at.replace(tzinfo=UTC)
  493. if archive_age.total_seconds() > 4 * 60 * 60: # 4 hours
  494. logger.warning(
  495. f"Found stale 'printing' archive {existing_archive.id} (age: {archive_age}), "
  496. f"marking as cancelled and creating new archive"
  497. )
  498. existing_archive.status = "cancelled"
  499. existing_archive.failure_reason = "Stale - print likely cancelled or failed without status update"
  500. await db.commit()
  501. # Fall through to create new archive (don't return)
  502. existing_archive = None # Clear so we don't use stale archive
  503. else:
  504. logger.info(
  505. f"Skipping duplicate - already have printing archive {existing_archive.id} for {check_name}"
  506. )
  507. # Track this as the active print
  508. _active_prints[(printer_id, existing_archive.filename)] = existing_archive.id
  509. # Also set up energy tracking if not already tracked
  510. if existing_archive.id not in _print_energy_start:
  511. try:
  512. plug_result = await db.execute(select(SmartPlug).where(SmartPlug.printer_id == printer_id))
  513. plug = plug_result.scalar_one_or_none()
  514. if plug:
  515. energy = await _get_plug_energy(plug, db)
  516. if energy and energy.get("total") is not None:
  517. _print_energy_start[existing_archive.id] = energy["total"]
  518. logger.info(
  519. f"Recorded starting energy for existing archive {existing_archive.id}: {energy['total']} kWh"
  520. )
  521. except Exception as e:
  522. logger.warning(f"Failed to record starting energy for existing archive: {e}")
  523. # Send notification with archive data (existing archive)
  524. if not notification_sent:
  525. archive_data = {"print_time_seconds": existing_archive.print_time_seconds}
  526. await _send_print_start_notification(printer_id, data, archive_data, logger)
  527. # Extract printable objects from the archived 3MF file
  528. _load_objects_from_archive(existing_archive, printer_id, logger)
  529. return
  530. # Build list of possible 3MF filenames to try
  531. possible_names = []
  532. # Bambu printers typically store files as "Name.gcode.3mf"
  533. # The subtask_name is usually the best source for the filename
  534. if subtask_name:
  535. # Try common Bambu naming patterns
  536. possible_names.append(f"{subtask_name}.gcode.3mf")
  537. possible_names.append(f"{subtask_name}.3mf")
  538. # Try original filename with .3mf extension
  539. if filename:
  540. # Extract just the filename part, not the full path
  541. fname = filename.split("/")[-1] if "/" in filename else filename
  542. if fname.endswith(".3mf"):
  543. possible_names.append(fname)
  544. elif fname.endswith(".gcode"):
  545. base = fname.rsplit(".", 1)[0]
  546. possible_names.append(f"{base}.gcode.3mf")
  547. possible_names.append(f"{base}.3mf")
  548. else:
  549. possible_names.append(f"{fname}.gcode.3mf")
  550. possible_names.append(f"{fname}.3mf")
  551. # Remove duplicates while preserving order
  552. seen = set()
  553. possible_names = [x for x in possible_names if not (x in seen or seen.add(x))]
  554. logger.info(f"Trying filenames: {possible_names}")
  555. # Try to find and download the 3MF file
  556. temp_path = None
  557. downloaded_filename = None
  558. # Get FTP retry settings
  559. ftp_retry_enabled, ftp_retry_count, ftp_retry_delay, ftp_timeout = await get_ftp_retry_settings()
  560. for try_filename in possible_names:
  561. if not try_filename.endswith(".3mf"):
  562. continue
  563. remote_paths = [
  564. f"/cache/{try_filename}",
  565. f"/model/{try_filename}",
  566. f"/{try_filename}",
  567. ]
  568. temp_path = app_settings.archive_dir / "temp" / try_filename
  569. temp_path.parent.mkdir(parents=True, exist_ok=True)
  570. for remote_path in remote_paths:
  571. logger.debug(f"Trying FTP download: {remote_path}")
  572. try:
  573. if ftp_retry_enabled:
  574. downloaded = await with_ftp_retry(
  575. download_file_async,
  576. printer.ip_address,
  577. printer.access_code,
  578. remote_path,
  579. temp_path,
  580. socket_timeout=ftp_timeout,
  581. printer_model=printer.model,
  582. max_retries=ftp_retry_count,
  583. retry_delay=ftp_retry_delay,
  584. operation_name=f"Download 3MF from {remote_path}",
  585. )
  586. else:
  587. downloaded = await download_file_async(
  588. printer.ip_address,
  589. printer.access_code,
  590. remote_path,
  591. temp_path,
  592. socket_timeout=ftp_timeout,
  593. printer_model=printer.model,
  594. )
  595. if downloaded:
  596. downloaded_filename = try_filename
  597. logger.info(f"Downloaded: {remote_path}")
  598. break
  599. except Exception as e:
  600. logger.debug(f"FTP download failed for {remote_path}: {e}")
  601. if downloaded_filename:
  602. break
  603. # If still not found, try listing /cache to find matching file
  604. if not downloaded_filename and (filename or subtask_name):
  605. search_term = (subtask_name or filename).lower().replace(".gcode", "").replace(".3mf", "")
  606. logger.info(f"Direct FTP download failed, listing /cache to find '{search_term}'")
  607. try:
  608. cache_files = await list_files_async(printer.ip_address, printer.access_code, "/cache")
  609. threemf_files = [f.get("name") for f in cache_files if f.get("name", "").endswith(".3mf")]
  610. logger.info(
  611. f"Found {len(threemf_files)} 3MF files in /cache: {threemf_files[:5]}{'...' if len(threemf_files) > 5 else ''}"
  612. )
  613. for f in cache_files:
  614. if f.get("is_directory"):
  615. continue
  616. fname = f.get("name", "")
  617. if fname.endswith(".3mf") and search_term in fname.lower():
  618. logger.info(f"Found matching file: {fname}")
  619. temp_path = app_settings.archive_dir / "temp" / fname
  620. temp_path.parent.mkdir(parents=True, exist_ok=True)
  621. if ftp_retry_enabled:
  622. downloaded = await with_ftp_retry(
  623. download_file_async,
  624. printer.ip_address,
  625. printer.access_code,
  626. f"/cache/{fname}",
  627. temp_path,
  628. max_retries=ftp_retry_count,
  629. retry_delay=ftp_retry_delay,
  630. operation_name=f"Download 3MF from /cache/{fname}",
  631. )
  632. else:
  633. downloaded = await download_file_async(
  634. printer.ip_address,
  635. printer.access_code,
  636. f"/cache/{fname}",
  637. temp_path,
  638. )
  639. if downloaded:
  640. downloaded_filename = fname
  641. logger.info(f"Found and downloaded from cache: {fname}")
  642. break
  643. except Exception as e:
  644. logger.warning(f"Failed to list cache: {e}")
  645. if not downloaded_filename or not temp_path:
  646. logger.warning(f"Could not find 3MF file for print: {filename or subtask_name}")
  647. # Create a fallback archive without 3MF data so the print is still tracked
  648. # This commonly happens with P1S/A1 printers where FTP has file size limitations
  649. try:
  650. from backend.app.models.archive import PrintArchive
  651. # Derive print name from subtask_name or filename
  652. print_name = subtask_name or filename
  653. if print_name:
  654. # Clean up the name (remove extensions, path parts)
  655. print_name = print_name.split("/")[-1]
  656. print_name = print_name.replace(".gcode.3mf", "").replace(".gcode", "").replace(".3mf", "")
  657. else:
  658. print_name = "Unknown Print"
  659. # Create minimal archive entry
  660. fallback_archive = PrintArchive(
  661. printer_id=printer_id,
  662. filename=filename or f"{print_name}.3mf",
  663. file_path="", # Empty - no 3MF file available
  664. file_size=0,
  665. print_name=print_name,
  666. status="printing",
  667. started_at=datetime.now(),
  668. extra_data={"no_3mf_available": True, "original_subtask": subtask_name, "_print_data": data},
  669. )
  670. db.add(fallback_archive)
  671. await db.commit()
  672. await db.refresh(fallback_archive)
  673. logger.info(f"Created fallback archive {fallback_archive.id} for {print_name} (no 3MF available)")
  674. # Track as active print
  675. _active_prints[(printer_id, fallback_archive.filename)] = fallback_archive.id
  676. if filename:
  677. _active_prints[(printer_id, filename)] = fallback_archive.id
  678. if subtask_name:
  679. _active_prints[(printer_id, f"{subtask_name}.3mf")] = fallback_archive.id
  680. _active_prints[(printer_id, subtask_name)] = fallback_archive.id
  681. # Record starting energy if smart plug available
  682. try:
  683. plug_result = await db.execute(select(SmartPlug).where(SmartPlug.printer_id == printer_id))
  684. plug = plug_result.scalar_one_or_none()
  685. if plug:
  686. energy = await _get_plug_energy(plug, db)
  687. if energy and energy.get("total") is not None:
  688. _print_energy_start[fallback_archive.id] = energy["total"]
  689. logger.info(
  690. f"[ENERGY] Recorded starting energy for fallback archive {fallback_archive.id}: {energy['total']} kWh"
  691. )
  692. except Exception as e:
  693. logger.warning(f"Failed to record starting energy for fallback: {e}")
  694. # Send WebSocket notification
  695. await ws_manager.send_archive_created(
  696. {
  697. "id": fallback_archive.id,
  698. "printer_id": fallback_archive.printer_id,
  699. "filename": fallback_archive.filename,
  700. "print_name": fallback_archive.print_name,
  701. "status": fallback_archive.status,
  702. }
  703. )
  704. # MQTT relay - publish archive created
  705. try:
  706. await mqtt_relay.on_archive_created(
  707. archive_id=fallback_archive.id,
  708. print_name=fallback_archive.print_name,
  709. printer_name=printer.name,
  710. status=fallback_archive.status,
  711. )
  712. except Exception:
  713. pass # Don't fail if MQTT fails
  714. # Send notification without archive data (file not found)
  715. if not notification_sent:
  716. await _send_print_start_notification(printer_id, data, logger=logger)
  717. return
  718. except Exception as e:
  719. logger.error(f"Failed to create fallback archive: {e}")
  720. # Send notification without archive data (file not found)
  721. if not notification_sent:
  722. await _send_print_start_notification(printer_id, data, logger=logger)
  723. return
  724. try:
  725. # Archive the file with status "printing"
  726. service = ArchiveService(db)
  727. archive = await service.archive_print(
  728. printer_id=printer_id,
  729. source_file=temp_path,
  730. print_data={**data, "status": "printing"},
  731. )
  732. if archive:
  733. # Track this active print (use both original filename and downloaded filename)
  734. _active_prints[(printer_id, downloaded_filename)] = archive.id
  735. if filename and filename != downloaded_filename:
  736. _active_prints[(printer_id, filename)] = archive.id
  737. if subtask_name:
  738. _active_prints[(printer_id, f"{subtask_name}.3mf")] = archive.id
  739. logger.info(f"Created archive {archive.id} for {downloaded_filename}")
  740. # Record starting energy from smart plug if available
  741. try:
  742. plug_result = await db.execute(select(SmartPlug).where(SmartPlug.printer_id == printer_id))
  743. plug = plug_result.scalar_one_or_none()
  744. logger.info(
  745. f"[ENERGY] Auto-archive print start - archive {archive.id}, printer {printer_id}, plug found: {plug is not None}"
  746. )
  747. if plug:
  748. energy = await _get_plug_energy(plug, db)
  749. logger.info(f"[ENERGY] Auto-archive energy response: {energy}")
  750. if energy and energy.get("total") is not None:
  751. _print_energy_start[archive.id] = energy["total"]
  752. logger.info(
  753. f"[ENERGY] Recorded starting energy for archive {archive.id}: {energy['total']} kWh"
  754. )
  755. else:
  756. logger.warning(f"[ENERGY] No 'total' in energy response for archive {archive.id}")
  757. else:
  758. logger.info(f"[ENERGY] No smart plug found for printer {printer_id}")
  759. except Exception as e:
  760. logger.warning(f"Failed to record starting energy: {e}")
  761. await ws_manager.send_archive_created(
  762. {
  763. "id": archive.id,
  764. "printer_id": archive.printer_id,
  765. "filename": archive.filename,
  766. "print_name": archive.print_name,
  767. "status": archive.status,
  768. }
  769. )
  770. # MQTT relay - publish archive created
  771. try:
  772. await mqtt_relay.on_archive_created(
  773. archive_id=archive.id,
  774. print_name=archive.print_name,
  775. printer_name=printer.name,
  776. status=archive.status,
  777. )
  778. except Exception:
  779. pass # Don't fail if MQTT fails
  780. # Send notification with archive data (new archive created)
  781. if not notification_sent:
  782. archive_data = {"print_time_seconds": archive.print_time_seconds}
  783. await _send_print_start_notification(printer_id, data, archive_data, logger)
  784. notification_sent = True
  785. # Extract printable objects for skip object functionality
  786. try:
  787. from backend.app.services.archive import extract_printable_objects_from_3mf
  788. with open(temp_path, "rb") as f:
  789. threemf_data = f.read()
  790. # Extract with positions for UI overlay
  791. printable_objects, bbox_all = extract_printable_objects_from_3mf(
  792. threemf_data, include_positions=True
  793. )
  794. if printable_objects:
  795. # Store objects in printer state
  796. client = printer_manager.get_client(printer_id)
  797. if client:
  798. client.state.printable_objects = printable_objects
  799. client.state.printable_objects_bbox_all = bbox_all
  800. client.state.skipped_objects = [] # Reset skipped objects for new print
  801. logger.info(f"Loaded {len(printable_objects)} printable objects for printer {printer_id}")
  802. except Exception as e:
  803. logger.debug(f"Failed to extract printable objects: {e}")
  804. finally:
  805. if temp_path and temp_path.exists():
  806. temp_path.unlink()
  807. async def _scan_for_timelapse_with_retries(archive_id: int):
  808. """
  809. Scan for timelapse with retries.
  810. The printer encodes the timelapse quickly after print completion.
  811. We just need a short delay then grab the most recent file.
  812. Since we KNOW timelapse was active (from MQTT ipcam data), the most recent
  813. file in /timelapse is our target. Retries handle FTP connection issues.
  814. """
  815. import logging
  816. logger = logging.getLogger(__name__)
  817. # Short delays - printer usually finishes encoding within seconds
  818. retry_delays = [5, 10, 20]
  819. for attempt, delay in enumerate(retry_delays, 1):
  820. logger.info(
  821. f"[TIMELAPSE] Attempt {attempt}/{len(retry_delays)}: waiting {delay}s before scanning for archive {archive_id}"
  822. )
  823. await asyncio.sleep(delay)
  824. try:
  825. async with async_session() as db:
  826. from backend.app.models.printer import Printer
  827. from backend.app.services.bambu_ftp import download_file_bytes_async, list_files_async
  828. # Get archive (ArchiveService from module-level import)
  829. service = ArchiveService(db)
  830. archive = await service.get_archive(archive_id)
  831. if not archive:
  832. logger.warning(f"[TIMELAPSE] Archive {archive_id} not found, stopping retries")
  833. return
  834. if archive.timelapse_path:
  835. logger.info(f"[TIMELAPSE] Archive {archive_id} already has timelapse attached, stopping retries")
  836. return
  837. if not archive.printer_id:
  838. logger.warning(f"[TIMELAPSE] Archive {archive_id} has no printer, stopping retries")
  839. return
  840. # Get printer
  841. result = await db.execute(select(Printer).where(Printer.id == archive.printer_id))
  842. printer = result.scalar_one_or_none()
  843. if not printer:
  844. logger.warning(f"[TIMELAPSE] Printer not found for archive {archive_id}, stopping retries")
  845. return
  846. # Scan timelapse directory on printer
  847. # H2D may store in different locations than X1C
  848. files = []
  849. found_path = None
  850. for timelapse_path in ["/timelapse", "/timelapse/video", "/record", "/recording"]:
  851. try:
  852. found_files = await list_files_async(printer.ip_address, printer.access_code, timelapse_path)
  853. if found_files:
  854. files = found_files
  855. found_path = timelapse_path
  856. logger.info(f"[TIMELAPSE] Attempt {attempt}: Found {len(files)} files in {timelapse_path}")
  857. break
  858. except Exception as e:
  859. logger.debug(f"[TIMELAPSE] Path {timelapse_path} failed: {e}")
  860. continue
  861. if not files:
  862. logger.info(f"[TIMELAPSE] Attempt {attempt}: No timelapse files found on printer, will retry")
  863. continue
  864. mp4_files = [f for f in files if not f.get("is_directory") and f.get("name", "").endswith(".mp4")]
  865. # Log ALL mp4 files found for debugging
  866. logger.info(f"[TIMELAPSE] Attempt {attempt}: Found {len(mp4_files)} MP4 files in {found_path}")
  867. for f in mp4_files[:5]: # Log first 5
  868. logger.info(f"[TIMELAPSE] - {f.get('name')}, mtime={f.get('mtime')}")
  869. if not mp4_files:
  870. logger.info(f"[TIMELAPSE] Attempt {attempt}: No MP4 files found, will retry")
  871. continue
  872. # Sort by mtime descending to get most recent file
  873. mp4_files_with_mtime = [f for f in mp4_files if f.get("mtime")]
  874. if not mp4_files_with_mtime:
  875. logger.info(f"[TIMELAPSE] Attempt {attempt}: No MP4 files with mtime found, will retry")
  876. continue
  877. mp4_files_with_mtime.sort(key=lambda x: x.get("mtime"), reverse=True)
  878. most_recent = mp4_files_with_mtime[0]
  879. file_name = most_recent.get("name")
  880. logger.info(f"[TIMELAPSE] Attempt {attempt}: Most recent file: {file_name}")
  881. # Since we KNOW timelapse was active (from MQTT), just grab the most recent file
  882. remote_path = most_recent.get("path") or f"/timelapse/{file_name}"
  883. logger.info(f"[TIMELAPSE] Downloading {file_name} for archive {archive_id}")
  884. timelapse_data = await download_file_bytes_async(printer.ip_address, printer.access_code, remote_path)
  885. if timelapse_data:
  886. success = await service.attach_timelapse(archive_id, timelapse_data, file_name)
  887. if success:
  888. logger.info(f"[TIMELAPSE] Successfully attached timelapse to archive {archive_id}")
  889. await ws_manager.send_archive_updated({"id": archive_id, "timelapse_attached": True})
  890. return # Success!
  891. else:
  892. logger.warning(f"[TIMELAPSE] Failed to attach timelapse to archive {archive_id}")
  893. else:
  894. logger.warning(f"[TIMELAPSE] Attempt {attempt}: Failed to download, will retry")
  895. except Exception as e:
  896. logger.warning(f"[TIMELAPSE] Attempt {attempt} failed with error: {e}")
  897. logger.warning(f"[TIMELAPSE] All {len(retry_delays)} attempts exhausted for archive {archive_id}, giving up")
  898. async def on_print_complete(printer_id: int, data: dict):
  899. """Handle print completion - update the archive status."""
  900. import logging
  901. import time
  902. logger = logging.getLogger(__name__)
  903. start_time = time.time()
  904. def log_timing(section: str):
  905. elapsed = time.time() - start_time
  906. logger.info(f"[TIMING] {section}: {elapsed:.3f}s elapsed")
  907. logger.info(f"[CALLBACK] on_print_complete started for printer {printer_id}")
  908. try:
  909. ws_data = {
  910. "status": data.get("status"),
  911. "filename": data.get("filename"),
  912. "subtask_name": data.get("subtask_name"),
  913. "timelapse_was_active": data.get("timelapse_was_active"),
  914. }
  915. await ws_manager.send_print_complete(printer_id, ws_data)
  916. log_timing("WebSocket send_print_complete")
  917. except Exception as e:
  918. logger.warning(f"[CALLBACK] WebSocket send_print_complete failed: {e}")
  919. # MQTT relay - publish print complete
  920. try:
  921. printer_info = printer_manager.get_printer(printer_id)
  922. if printer_info:
  923. await mqtt_relay.on_print_complete(
  924. printer_id,
  925. printer_info.name,
  926. printer_info.serial_number,
  927. data.get("filename", ""),
  928. data.get("subtask_name", ""),
  929. data.get("status", "completed"),
  930. )
  931. except Exception:
  932. pass # Don't fail print complete callback if MQTT fails
  933. filename = data.get("filename", "")
  934. subtask_name = data.get("subtask_name", "")
  935. if not filename and not subtask_name:
  936. logger.warning("Print complete without filename or subtask_name")
  937. return
  938. logger.info(f"Print complete - filename: {filename}, subtask: {subtask_name}, status: {data.get('status')}")
  939. # Build list of possible keys to try (matching how they were registered in on_print_start)
  940. possible_keys = []
  941. # Try subtask_name variations first (most reliable for matching)
  942. if subtask_name:
  943. possible_keys.append((printer_id, f"{subtask_name}.3mf"))
  944. possible_keys.append((printer_id, f"{subtask_name}.gcode.3mf"))
  945. possible_keys.append((printer_id, subtask_name))
  946. # Try filename variations
  947. if filename:
  948. # Extract just the filename if it's a path
  949. fname = filename.split("/")[-1] if "/" in filename else filename
  950. if fname.endswith(".3mf"):
  951. possible_keys.append((printer_id, fname))
  952. elif fname.endswith(".gcode"):
  953. base_name = fname.rsplit(".", 1)[0]
  954. possible_keys.append((printer_id, f"{base_name}.gcode.3mf"))
  955. possible_keys.append((printer_id, f"{base_name}.3mf"))
  956. possible_keys.append((printer_id, fname))
  957. else:
  958. possible_keys.append((printer_id, f"{fname}.gcode.3mf"))
  959. possible_keys.append((printer_id, f"{fname}.3mf"))
  960. possible_keys.append((printer_id, fname))
  961. # Also try full path versions
  962. if filename.endswith(".3mf"):
  963. possible_keys.append((printer_id, filename))
  964. elif filename.endswith(".gcode"):
  965. base_name = filename.rsplit(".", 1)[0]
  966. possible_keys.append((printer_id, f"{base_name}.3mf"))
  967. possible_keys.append((printer_id, filename))
  968. else:
  969. possible_keys.append((printer_id, f"{filename}.3mf"))
  970. possible_keys.append((printer_id, filename))
  971. # Find the archive for this print
  972. logger.info(f"Looking for archive in _active_prints, keys to try: {possible_keys[:5]}...")
  973. logger.info(f"Current _active_prints: {list(_active_prints.keys())}")
  974. archive_id = None
  975. for key in possible_keys:
  976. archive_id = _active_prints.pop(key, None)
  977. if archive_id:
  978. logger.info(f"Found archive {archive_id} with key {key}")
  979. # Also clean up any other keys pointing to this archive
  980. keys_to_remove = [k for k, v in _active_prints.items() if v == archive_id]
  981. for k in keys_to_remove:
  982. _active_prints.pop(k, None)
  983. break
  984. if not archive_id:
  985. # Try to find by filename or subtask_name if not tracked (for prints started before app)
  986. async with async_session() as db:
  987. from backend.app.models.archive import PrintArchive
  988. # Try matching by subtask_name (stored as print_name) first
  989. if subtask_name:
  990. result = await db.execute(
  991. select(PrintArchive)
  992. .where(PrintArchive.printer_id == printer_id)
  993. .where(PrintArchive.status == "printing")
  994. .where(
  995. or_(
  996. PrintArchive.print_name.ilike(f"%{subtask_name}%"),
  997. PrintArchive.filename.ilike(f"%{subtask_name}%"),
  998. )
  999. )
  1000. .order_by(PrintArchive.created_at.desc())
  1001. .limit(1)
  1002. )
  1003. archive = result.scalar_one_or_none()
  1004. if archive:
  1005. archive_id = archive.id
  1006. logger.info(f"Found archive {archive_id} by subtask_name match: {subtask_name}")
  1007. # Also try by filename
  1008. if not archive_id and filename:
  1009. result = await db.execute(
  1010. select(PrintArchive)
  1011. .where(PrintArchive.printer_id == printer_id)
  1012. .where(PrintArchive.filename == filename)
  1013. .where(PrintArchive.status == "printing")
  1014. .order_by(PrintArchive.created_at.desc())
  1015. .limit(1)
  1016. )
  1017. archive = result.scalar_one_or_none()
  1018. if archive:
  1019. archive_id = archive.id
  1020. if not archive_id:
  1021. logger.warning(f"Could not find archive for print complete: filename={filename}, subtask={subtask_name}")
  1022. return
  1023. log_timing("Archive lookup")
  1024. # Update archive status
  1025. logger.info(f"[ARCHIVE] Updating archive {archive_id} status...")
  1026. try:
  1027. async with async_session() as db:
  1028. service = ArchiveService(db)
  1029. status = data.get("status", "completed")
  1030. # Auto-detect failure reason
  1031. failure_reason = None
  1032. if status == "aborted":
  1033. failure_reason = "User cancelled"
  1034. logger.info("[ARCHIVE] Print was aborted by user, setting failure_reason='User cancelled'")
  1035. elif status == "failed":
  1036. # Try to determine failure reason from HMS errors
  1037. hms_errors = data.get("hms_errors", [])
  1038. if hms_errors:
  1039. logger.info(f"[ARCHIVE] HMS errors at failure: {hms_errors}")
  1040. # Map known HMS error modules to failure reasons
  1041. # Module 0x07 = Filament, 0x0C = MC (Motion Controller), etc.
  1042. for err in hms_errors:
  1043. module = err.get("module", 0)
  1044. if module == 0x07: # Filament module
  1045. failure_reason = "Filament runout"
  1046. break
  1047. elif module == 0x0C: # Motion controller
  1048. failure_reason = "Layer shift"
  1049. break
  1050. elif module == 0x05: # Nozzle/extruder
  1051. failure_reason = "Clogged nozzle"
  1052. break
  1053. if failure_reason:
  1054. logger.info(f"[ARCHIVE] Detected failure_reason from HMS: {failure_reason}")
  1055. else:
  1056. logger.info("[ARCHIVE] No HMS errors available to determine failure reason")
  1057. await service.update_archive_status(
  1058. archive_id,
  1059. status=status,
  1060. completed_at=datetime.now() if status in ("completed", "failed", "aborted") else None,
  1061. failure_reason=failure_reason,
  1062. )
  1063. logger.info(f"[ARCHIVE] Archive {archive_id} status updated to {status}, failure_reason={failure_reason}")
  1064. # Add cost for reprints (first prints have cost set in archive_print())
  1065. if status == "completed" and archive_id in _reprint_archives:
  1066. _reprint_archives.discard(archive_id)
  1067. try:
  1068. await service.add_reprint_cost(archive_id)
  1069. logger.info(f"[ARCHIVE] Added reprint cost for archive {archive_id}")
  1070. except Exception as e:
  1071. logger.warning(f"[ARCHIVE] Failed to add reprint cost for archive {archive_id}: {e}")
  1072. await ws_manager.send_archive_updated(
  1073. {
  1074. "id": archive_id,
  1075. "status": status,
  1076. }
  1077. )
  1078. logger.info(f"[ARCHIVE] WebSocket notification sent for archive {archive_id}")
  1079. # MQTT relay - publish archive updated
  1080. try:
  1081. await mqtt_relay.on_archive_updated(
  1082. archive_id=archive_id,
  1083. print_name=filename or subtask_name,
  1084. status=status,
  1085. )
  1086. except Exception:
  1087. pass # Don't fail if MQTT fails
  1088. except Exception as e:
  1089. logger.error(f"[ARCHIVE] Failed to update archive {archive_id} status: {e}", exc_info=True)
  1090. # Continue with other operations even if archive update fails
  1091. log_timing("Archive status update")
  1092. # Report filament usage to Spoolman if print completed successfully
  1093. if data.get("status") == "completed":
  1094. try:
  1095. await _report_spoolman_usage(printer_id, archive_id, logger)
  1096. log_timing("Spoolman usage report")
  1097. except Exception as e:
  1098. logger.warning(f"Spoolman usage reporting failed: {e}")
  1099. # Run slow operations as background tasks to avoid blocking the event loop
  1100. # These operations can take 5-10+ seconds and would freeze the UI if awaited
  1101. starting_kwh = _print_energy_start.pop(archive_id, None)
  1102. async def _background_energy_calculation():
  1103. """Calculate and save energy usage in background."""
  1104. try:
  1105. logger.info(f"[ENERGY-BG] Starting energy calculation for archive {archive_id}")
  1106. async with async_session() as db:
  1107. plug_result = await db.execute(select(SmartPlug).where(SmartPlug.printer_id == printer_id))
  1108. plug = plug_result.scalar_one_or_none()
  1109. if plug:
  1110. energy = await _get_plug_energy(plug, db)
  1111. logger.info(f"[ENERGY-BG] Energy response: {energy}")
  1112. energy_used = None
  1113. if starting_kwh is not None and energy and energy.get("total") is not None:
  1114. ending_kwh = energy["total"]
  1115. energy_used = round(ending_kwh - starting_kwh, 4)
  1116. logger.info(f"[ENERGY-BG] Per-print energy: {energy_used} kWh")
  1117. if energy_used is not None and energy_used >= 0:
  1118. from backend.app.api.routes.settings import get_setting
  1119. energy_cost_per_kwh = await get_setting(db, "energy_cost_per_kwh")
  1120. cost_per_kwh = float(energy_cost_per_kwh) if energy_cost_per_kwh else 0.15
  1121. energy_cost = round(energy_used * cost_per_kwh, 2)
  1122. from backend.app.models.archive import PrintArchive
  1123. result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
  1124. archive = result.scalar_one_or_none()
  1125. if archive:
  1126. archive.energy_kwh = energy_used
  1127. archive.energy_cost = energy_cost
  1128. await db.commit()
  1129. logger.info(f"[ENERGY-BG] Saved: {energy_used} kWh, cost={energy_cost}")
  1130. else:
  1131. logger.info(f"[ENERGY-BG] No smart plug for printer {printer_id}")
  1132. except Exception as e:
  1133. logger.warning(f"[ENERGY-BG] Failed: {e}")
  1134. async def _background_finish_photo() -> str | None:
  1135. """Capture finish photo in background. Returns photo filename if captured."""
  1136. try:
  1137. logger.info(f"[PHOTO-BG] Starting finish photo capture for archive {archive_id}")
  1138. from backend.app.api.routes.camera import _active_chamber_streams, _active_streams, get_buffered_frame
  1139. async with async_session() as db:
  1140. from backend.app.api.routes.settings import get_setting
  1141. capture_enabled = await get_setting(db, "capture_finish_photo")
  1142. if capture_enabled is None or capture_enabled.lower() == "true":
  1143. from backend.app.models.printer import Printer
  1144. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  1145. printer = result.scalar_one_or_none()
  1146. if printer and archive_id:
  1147. from backend.app.models.archive import PrintArchive
  1148. result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
  1149. archive = result.scalar_one_or_none()
  1150. if archive:
  1151. import uuid
  1152. from datetime import datetime
  1153. from pathlib import Path
  1154. archive_dir = app_settings.base_dir / Path(archive.file_path).parent
  1155. photo_filename = None
  1156. # Check if camera stream is active - use buffered frame to avoid freeze
  1157. # Check both RTSP streams (_active_streams) and chamber image streams (_active_chamber_streams)
  1158. active_for_printer = [k for k in _active_streams if k.startswith(f"{printer_id}-")]
  1159. active_chamber_for_printer = [
  1160. k for k in _active_chamber_streams if k.startswith(f"{printer_id}-")
  1161. ]
  1162. buffered_frame = get_buffered_frame(printer_id)
  1163. if (active_for_printer or active_chamber_for_printer) and buffered_frame:
  1164. # Use frame from active stream
  1165. logger.info("[PHOTO-BG] Using buffered frame from active stream")
  1166. photos_dir = archive_dir / "photos"
  1167. photos_dir.mkdir(parents=True, exist_ok=True)
  1168. timestamp = datetime.now().strftime("%Y%m%d_%H%M%S")
  1169. photo_filename = f"finish_{timestamp}_{uuid.uuid4().hex[:8]}.jpg"
  1170. photo_path = photos_dir / photo_filename
  1171. await asyncio.to_thread(photo_path.write_bytes, buffered_frame)
  1172. logger.info(f"[PHOTO-BG] Saved buffered frame: {photo_filename}")
  1173. else:
  1174. # No active stream - capture new frame
  1175. from backend.app.services.camera import capture_finish_photo
  1176. photo_filename = await capture_finish_photo(
  1177. printer_id=printer_id,
  1178. ip_address=printer.ip_address,
  1179. access_code=printer.access_code,
  1180. model=printer.model,
  1181. archive_dir=archive_dir,
  1182. )
  1183. if photo_filename:
  1184. photos = archive.photos or []
  1185. photos.append(photo_filename)
  1186. archive.photos = photos
  1187. await db.commit()
  1188. logger.info(f"[PHOTO-BG] Saved: {photo_filename}")
  1189. return photo_filename
  1190. return None
  1191. except Exception as e:
  1192. logger.warning(f"[PHOTO-BG] Failed: {e}")
  1193. return None
  1194. asyncio.create_task(_background_energy_calculation())
  1195. # Photo capture task - result will be used by notifications
  1196. photo_task = asyncio.create_task(_background_finish_photo())
  1197. log_timing("Background tasks scheduled (energy, photo)")
  1198. # Also run smart plug, notifications, and maintenance as background tasks
  1199. print_status = data.get("status", "completed")
  1200. async def _background_smart_plug():
  1201. """Handle smart plug automation in background."""
  1202. try:
  1203. logger.info(f"[AUTO-OFF-BG] Starting smart plug automation for printer {printer_id}")
  1204. async with async_session() as db:
  1205. await smart_plug_manager.on_print_complete(printer_id, print_status, db)
  1206. logger.info("[AUTO-OFF-BG] Completed")
  1207. except Exception as e:
  1208. logger.warning(f"[AUTO-OFF-BG] Failed: {e}")
  1209. async def _background_notifications(finish_photo_filename: str | None = None):
  1210. """Send print complete notifications in background."""
  1211. try:
  1212. logger.info(f"[NOTIFY-BG] Starting notifications for printer {printer_id}, photo={finish_photo_filename}")
  1213. async with async_session() as db:
  1214. from backend.app.models.archive import PrintArchive
  1215. from backend.app.models.printer import Printer
  1216. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  1217. printer = result.scalar_one_or_none()
  1218. printer_name = printer.name if printer else f"Printer {printer_id}"
  1219. archive_data = None
  1220. if archive_id:
  1221. archive_result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
  1222. archive = archive_result.scalar_one_or_none()
  1223. if archive:
  1224. archive_data = {
  1225. "print_time_seconds": archive.print_time_seconds,
  1226. "actual_filament_grams": archive.filament_used_grams,
  1227. "failure_reason": archive.failure_reason,
  1228. }
  1229. # Add finish photo URL if available
  1230. if finish_photo_filename:
  1231. from backend.app.api.routes.settings import get_setting
  1232. external_url = await get_setting(db, "external_url")
  1233. if external_url:
  1234. external_url = external_url.rstrip("/")
  1235. archive_data["finish_photo_url"] = (
  1236. f"{external_url}/api/v1/archives/{archive_id}/photos/{finish_photo_filename}"
  1237. )
  1238. else:
  1239. # Fallback to relative URL (won't work for external services)
  1240. archive_data["finish_photo_url"] = (
  1241. f"/api/v1/archives/{archive_id}/photos/{finish_photo_filename}"
  1242. )
  1243. await notification_service.on_print_complete(
  1244. printer_id, printer_name, print_status, data, db, archive_data=archive_data
  1245. )
  1246. logger.info("[NOTIFY-BG] Completed")
  1247. except Exception as e:
  1248. logger.warning(f"[NOTIFY-BG] Failed: {e}")
  1249. async def _background_maintenance_check():
  1250. """Check for maintenance due in background."""
  1251. if print_status != "completed":
  1252. return
  1253. try:
  1254. logger.info(f"[MAINT-BG] Starting maintenance check for printer {printer_id}")
  1255. async with async_session() as db:
  1256. from backend.app.models.printer import Printer
  1257. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  1258. printer = result.scalar_one_or_none()
  1259. printer_name = printer.name if printer else f"Printer {printer_id}"
  1260. await ensure_default_types(db)
  1261. overview = await _get_printer_maintenance_internal(printer_id, db, commit=True)
  1262. items_needing_attention = [
  1263. {"name": item.maintenance_type_name, "is_due": item.is_due, "is_warning": item.is_warning}
  1264. for item in overview.maintenance_items
  1265. if item.enabled and (item.is_due or item.is_warning)
  1266. ]
  1267. if items_needing_attention:
  1268. await notification_service.on_maintenance_due(printer_id, printer_name, items_needing_attention, db)
  1269. logger.info(f"[MAINT-BG] Sent notification: {len(items_needing_attention)} items need attention")
  1270. # MQTT relay - publish maintenance alerts
  1271. for item in items_needing_attention:
  1272. try:
  1273. await mqtt_relay.on_maintenance_alert(
  1274. printer_id=printer_id,
  1275. printer_name=printer_name,
  1276. maintenance_type=item["name"],
  1277. current_value=0, # Not easily available here
  1278. threshold=0, # Not easily available here
  1279. )
  1280. except Exception:
  1281. pass # Don't fail if MQTT fails
  1282. else:
  1283. logger.info("[MAINT-BG] Completed (no items need attention)")
  1284. except Exception as e:
  1285. logger.warning(f"[MAINT-BG] Failed: {e}")
  1286. asyncio.create_task(_background_smart_plug())
  1287. asyncio.create_task(_background_maintenance_check())
  1288. # Notification task waits for photo capture to complete first
  1289. async def _photo_then_notify():
  1290. """Wait for photo capture, then send notification with photo URL."""
  1291. try:
  1292. finish_photo = await photo_task
  1293. logger.info(f"[PHOTO-NOTIFY] Photo task returned: {finish_photo}")
  1294. await _background_notifications(finish_photo)
  1295. except Exception as e:
  1296. logger.warning(f"[PHOTO-NOTIFY] Failed: {e}")
  1297. # Still try to send notification without photo
  1298. await _background_notifications(None)
  1299. asyncio.create_task(_photo_then_notify())
  1300. log_timing("All background tasks scheduled")
  1301. # Auto-scan for timelapse if recording was active during the print
  1302. if archive_id and data.get("timelapse_was_active") and data.get("status") == "completed":
  1303. logger.info(f"[TIMELAPSE] Timelapse was active during print, scheduling auto-scan for archive {archive_id}")
  1304. # Schedule timelapse scan as background task with retries
  1305. # The printer needs time to encode the video after print completion
  1306. asyncio.create_task(_scan_for_timelapse_with_retries(archive_id))
  1307. log_timing("Timelapse scan scheduled")
  1308. # Update queue item if this was a scheduled print
  1309. try:
  1310. async with async_session() as db:
  1311. from backend.app.models.print_queue import PrintQueueItem
  1312. # Note: SmartPlug is already imported at module level (line 56)
  1313. # Do NOT import it here as it would shadow the module-level import
  1314. # and cause "cannot access local variable" errors earlier in this function
  1315. result = await db.execute(
  1316. select(PrintQueueItem)
  1317. .where(PrintQueueItem.printer_id == printer_id)
  1318. .where(PrintQueueItem.status == "printing")
  1319. )
  1320. queue_item = result.scalar_one_or_none()
  1321. if queue_item:
  1322. status = data.get("status", "completed")
  1323. queue_item.status = status
  1324. queue_item.completed_at = datetime.now()
  1325. await db.commit()
  1326. logger.info(f"Updated queue item {queue_item.id} status to {status}")
  1327. # MQTT relay - publish queue job completed
  1328. try:
  1329. printer_info = printer_manager.get_printer(printer_id)
  1330. await mqtt_relay.on_queue_job_completed(
  1331. job_id=queue_item.id,
  1332. filename=filename or subtask_name,
  1333. printer_id=printer_id,
  1334. printer_name=printer_info.name if printer_info else "Unknown",
  1335. status=status,
  1336. )
  1337. except Exception:
  1338. pass # Don't fail if MQTT fails
  1339. # Handle auto_off_after - power off printer if requested (after cooldown)
  1340. if queue_item.auto_off_after:
  1341. result = await db.execute(select(SmartPlug).where(SmartPlug.printer_id == printer_id))
  1342. plug = result.scalar_one_or_none()
  1343. if plug and plug.enabled:
  1344. logger.info(f"Auto-off requested for printer {printer_id}, waiting for cooldown...")
  1345. async def cooldown_and_poweroff(pid: int, plug_id: int):
  1346. # Wait for nozzle to cool down
  1347. await printer_manager.wait_for_cooldown(pid, target_temp=50.0, timeout=600)
  1348. # Re-fetch plug in new session
  1349. async with async_session() as new_db:
  1350. result = await new_db.execute(select(SmartPlug).where(SmartPlug.id == plug_id))
  1351. p = result.scalar_one_or_none()
  1352. if p and p.enabled:
  1353. success = await tasmota_service.turn_off(p)
  1354. if success:
  1355. logger.info(f"Powered off printer {pid} via smart plug '{p.name}'")
  1356. else:
  1357. logger.warning(f"Failed to power off printer {pid} via smart plug")
  1358. asyncio.create_task(cooldown_and_poweroff(printer_id, plug.id))
  1359. except Exception as e:
  1360. import logging
  1361. logging.getLogger(__name__).warning(f"Queue item update failed: {e}")
  1362. log_timing("Queue item update")
  1363. logger.info(f"[CALLBACK] on_print_complete finished for printer {printer_id}, archive {archive_id}")
  1364. # AMS sensor history recording
  1365. _ams_history_task: asyncio.Task | None = None
  1366. AMS_HISTORY_INTERVAL = 300 # Record every 5 minutes
  1367. AMS_HISTORY_RETENTION_DAYS = 30 # Keep data for 30 days
  1368. _ams_cleanup_counter = 0 # Track recordings to trigger periodic cleanup
  1369. _ams_alarm_cooldown: dict[str, datetime] = {} # Track alarm cooldowns (printer_id:ams_id:type -> last_alarm_time)
  1370. AMS_ALARM_COOLDOWN_MINUTES = 60 # Don't send same alarm more than once per hour
  1371. async def record_ams_history():
  1372. """Background task to record AMS humidity and temperature data."""
  1373. import logging
  1374. logger = logging.getLogger(__name__)
  1375. # Wait a short time for MQTT connections to establish on startup
  1376. await asyncio.sleep(10)
  1377. while True:
  1378. try:
  1379. from backend.app.models.ams_history import AMSSensorHistory
  1380. from backend.app.models.printer import Printer
  1381. from backend.app.models.settings import Settings
  1382. async with async_session() as db:
  1383. # Get all active printers
  1384. result = await db.execute(select(Printer).where(Printer.is_active.is_(True)))
  1385. printers = result.scalars().all()
  1386. # Get alarm thresholds from settings
  1387. humidity_threshold = 60.0 # Default: fair threshold
  1388. temp_threshold = 35.0 # Default: fair threshold
  1389. result = await db.execute(select(Settings).where(Settings.key == "ams_humidity_fair"))
  1390. setting = result.scalar_one_or_none()
  1391. if setting:
  1392. try:
  1393. humidity_threshold = float(setting.value)
  1394. except (ValueError, TypeError):
  1395. pass
  1396. result = await db.execute(select(Settings).where(Settings.key == "ams_temp_fair"))
  1397. setting = result.scalar_one_or_none()
  1398. if setting:
  1399. try:
  1400. temp_threshold = float(setting.value)
  1401. except (ValueError, TypeError):
  1402. pass
  1403. recorded_count = 0
  1404. for printer in printers:
  1405. # Get current state from printer manager
  1406. state = printer_manager.get_status(printer.id)
  1407. if not state or not state.connected or not state.raw_data:
  1408. continue # Skip disconnected printers - don't use stale data
  1409. raw_data = state.raw_data
  1410. if "ams" not in raw_data or not isinstance(raw_data["ams"], list):
  1411. continue
  1412. # Record data for each AMS unit
  1413. for ams_data in raw_data["ams"]:
  1414. ams_id = int(ams_data.get("id", 0))
  1415. # Get humidity (prefer humidity_raw)
  1416. humidity_raw = ams_data.get("humidity_raw")
  1417. humidity_idx = ams_data.get("humidity")
  1418. humidity = None
  1419. if humidity_raw is not None:
  1420. try:
  1421. humidity = float(humidity_raw)
  1422. except (ValueError, TypeError):
  1423. pass
  1424. if humidity is None and humidity_idx is not None:
  1425. try:
  1426. humidity = float(humidity_idx)
  1427. except (ValueError, TypeError):
  1428. pass
  1429. # Get temperature
  1430. temperature = None
  1431. temp_str = ams_data.get("temp")
  1432. if temp_str is not None:
  1433. try:
  1434. temperature = float(temp_str)
  1435. except (ValueError, TypeError):
  1436. pass
  1437. # Skip if no data
  1438. if humidity is None and temperature is None:
  1439. continue
  1440. # Record the data point
  1441. history = AMSSensorHistory(
  1442. printer_id=printer.id,
  1443. ams_id=ams_id,
  1444. humidity=humidity,
  1445. humidity_raw=float(humidity_raw) if humidity_raw else None,
  1446. temperature=temperature,
  1447. )
  1448. db.add(history)
  1449. recorded_count += 1
  1450. # Generate AMS label and determine if it's AMS-HT (A, B, C, D or HT-A for AMS-Lite/Hub)
  1451. is_ams_ht = ams_id >= 128
  1452. if is_ams_ht:
  1453. ams_label = f"HT-{chr(65 + (ams_id - 128))}"
  1454. else:
  1455. ams_label = f"AMS-{chr(65 + ams_id)}"
  1456. # Check humidity alarm (only if above threshold)
  1457. if humidity is not None and humidity > humidity_threshold:
  1458. cooldown_key = f"{printer.id}:{ams_id}:humidity"
  1459. last_alarm = _ams_alarm_cooldown.get(cooldown_key)
  1460. now = datetime.now()
  1461. if (
  1462. last_alarm is None
  1463. or (now - last_alarm).total_seconds() >= AMS_ALARM_COOLDOWN_MINUTES * 60
  1464. ):
  1465. _ams_alarm_cooldown[cooldown_key] = now
  1466. logger.info(
  1467. f"Sending humidity alarm for {printer.name} {ams_label}: {humidity}% > {humidity_threshold}%"
  1468. )
  1469. try:
  1470. # Call different notification method based on AMS type
  1471. if is_ams_ht:
  1472. await notification_service.on_ams_ht_humidity_high(
  1473. printer.id, printer.name, ams_label, humidity, humidity_threshold, db
  1474. )
  1475. else:
  1476. await notification_service.on_ams_humidity_high(
  1477. printer.id, printer.name, ams_label, humidity, humidity_threshold, db
  1478. )
  1479. except Exception as e:
  1480. logger.warning(f"Failed to send humidity alarm: {e}")
  1481. # Check temperature alarm (only if above threshold)
  1482. if temperature is not None and temperature > temp_threshold:
  1483. cooldown_key = f"{printer.id}:{ams_id}:temperature"
  1484. last_alarm = _ams_alarm_cooldown.get(cooldown_key)
  1485. now = datetime.now()
  1486. if (
  1487. last_alarm is None
  1488. or (now - last_alarm).total_seconds() >= AMS_ALARM_COOLDOWN_MINUTES * 60
  1489. ):
  1490. _ams_alarm_cooldown[cooldown_key] = now
  1491. logger.info(
  1492. f"Sending temperature alarm for {printer.name} {ams_label}: {temperature}°C > {temp_threshold}°C"
  1493. )
  1494. try:
  1495. # Call different notification method based on AMS type
  1496. if is_ams_ht:
  1497. await notification_service.on_ams_ht_temperature_high(
  1498. printer.id, printer.name, ams_label, temperature, temp_threshold, db
  1499. )
  1500. else:
  1501. await notification_service.on_ams_temperature_high(
  1502. printer.id, printer.name, ams_label, temperature, temp_threshold, db
  1503. )
  1504. except Exception as e:
  1505. logger.warning(f"Failed to send temperature alarm: {e}")
  1506. await db.commit()
  1507. if recorded_count > 0:
  1508. logger.info(f"Recorded {recorded_count} AMS sensor history entries")
  1509. # Periodic cleanup of old data (every ~288 recordings = ~24 hours at 5min interval)
  1510. global _ams_cleanup_counter
  1511. _ams_cleanup_counter += 1
  1512. if _ams_cleanup_counter >= 288:
  1513. _ams_cleanup_counter = 0
  1514. # Get retention days from settings
  1515. from backend.app.models.settings import Settings
  1516. result = await db.execute(select(Settings).where(Settings.key == "ams_history_retention_days"))
  1517. setting = result.scalar_one_or_none()
  1518. retention_days = int(setting.value) if setting else AMS_HISTORY_RETENTION_DAYS
  1519. cutoff = datetime.now() - timedelta(days=retention_days)
  1520. result = await db.execute(delete(AMSSensorHistory).where(AMSSensorHistory.recorded_at < cutoff))
  1521. await db.commit()
  1522. if result.rowcount > 0:
  1523. logger.info(
  1524. f"Cleaned up {result.rowcount} old AMS sensor history entries (older than {retention_days} days)"
  1525. )
  1526. # Wait until next recording interval
  1527. await asyncio.sleep(AMS_HISTORY_INTERVAL)
  1528. except asyncio.CancelledError:
  1529. break
  1530. except Exception as e:
  1531. logger.warning(f"AMS history recording failed: {e}")
  1532. await asyncio.sleep(60) # Wait a bit before retrying
  1533. def start_ams_history_recording():
  1534. """Start the AMS history recording background task."""
  1535. global _ams_history_task
  1536. if _ams_history_task is None:
  1537. _ams_history_task = asyncio.create_task(record_ams_history())
  1538. logging.getLogger(__name__).info("AMS history recording started")
  1539. def stop_ams_history_recording():
  1540. """Stop the AMS history recording background task."""
  1541. global _ams_history_task
  1542. if _ams_history_task:
  1543. _ams_history_task.cancel()
  1544. _ams_history_task = None
  1545. logging.getLogger(__name__).info("AMS history recording stopped")
  1546. # Printer runtime tracking
  1547. _runtime_tracking_task: asyncio.Task | None = None
  1548. RUNTIME_TRACKING_INTERVAL = 30 # Update every 30 seconds
  1549. async def track_printer_runtime():
  1550. """Background task to track printer active runtime (RUNNING/PAUSE states)."""
  1551. import logging
  1552. logger = logging.getLogger(__name__)
  1553. # Wait for MQTT connections to establish on startup
  1554. await asyncio.sleep(15)
  1555. while True:
  1556. try:
  1557. from backend.app.models.printer import Printer
  1558. async with async_session() as db:
  1559. # Get all active printers
  1560. result = await db.execute(select(Printer).where(Printer.is_active.is_(True)))
  1561. printers = result.scalars().all()
  1562. now = datetime.now()
  1563. updated_count = 0
  1564. needs_commit = False
  1565. for printer in printers:
  1566. # Get current state from printer manager
  1567. state = printer_manager.get_status(printer.id)
  1568. if not state:
  1569. logger.debug(f"[{printer.name}] Runtime tracking: no state available")
  1570. continue
  1571. if not state.connected:
  1572. logger.debug(f"[{printer.name}] Runtime tracking: not connected")
  1573. continue
  1574. # Check if printer is in an active state (RUNNING or PAUSE)
  1575. if state.state in ("RUNNING", "PAUSE"):
  1576. # Calculate time since last update
  1577. if printer.last_runtime_update:
  1578. elapsed = (now - printer.last_runtime_update).total_seconds()
  1579. if elapsed > 0:
  1580. printer.runtime_seconds += int(elapsed)
  1581. updated_count += 1
  1582. needs_commit = True
  1583. logger.debug(
  1584. f"[{printer.name}] Runtime tracking: added {int(elapsed)}s, "
  1585. f"total={printer.runtime_seconds}s ({printer.runtime_seconds / 3600:.2f}h)"
  1586. )
  1587. else:
  1588. # First time seeing printer active - need to commit to save timestamp
  1589. needs_commit = True
  1590. logger.debug(f"[{printer.name}] Runtime tracking: first active detection")
  1591. printer.last_runtime_update = now
  1592. else:
  1593. # Printer is idle/offline - clear last_runtime_update
  1594. if printer.last_runtime_update is not None:
  1595. logger.debug(
  1596. f"[{printer.name}] Runtime tracking: state={state.state}, clearing last_runtime_update"
  1597. )
  1598. printer.last_runtime_update = None
  1599. needs_commit = True
  1600. if needs_commit:
  1601. await db.commit()
  1602. if updated_count > 0:
  1603. logger.debug(f"Updated runtime for {updated_count} printer(s)")
  1604. except asyncio.CancelledError:
  1605. logger.info("Runtime tracking cancelled")
  1606. break
  1607. except Exception as e:
  1608. logger.warning(f"Runtime tracking failed: {e}")
  1609. await asyncio.sleep(RUNTIME_TRACKING_INTERVAL)
  1610. def start_runtime_tracking():
  1611. """Start the printer runtime tracking background task."""
  1612. global _runtime_tracking_task
  1613. if _runtime_tracking_task is None:
  1614. _runtime_tracking_task = asyncio.create_task(track_printer_runtime())
  1615. logging.getLogger(__name__).info("Printer runtime tracking started")
  1616. def stop_runtime_tracking():
  1617. """Stop the printer runtime tracking background task."""
  1618. global _runtime_tracking_task
  1619. if _runtime_tracking_task:
  1620. _runtime_tracking_task.cancel()
  1621. _runtime_tracking_task = None
  1622. logging.getLogger(__name__).info("Printer runtime tracking stopped")
  1623. @asynccontextmanager
  1624. async def lifespan(app: FastAPI):
  1625. # Startup
  1626. await init_db()
  1627. # Restore debug logging state from previous session
  1628. await init_debug_logging()
  1629. # Set up printer manager callbacks
  1630. loop = asyncio.get_event_loop()
  1631. printer_manager.set_event_loop(loop)
  1632. printer_manager.set_status_change_callback(on_printer_status_change)
  1633. printer_manager.set_print_start_callback(on_print_start)
  1634. printer_manager.set_print_complete_callback(on_print_complete)
  1635. printer_manager.set_ams_change_callback(on_ams_change)
  1636. # Initialize MQTT relay from settings
  1637. async with async_session() as db:
  1638. from backend.app.api.routes.settings import get_setting
  1639. mqtt_settings = {
  1640. "mqtt_enabled": (await get_setting(db, "mqtt_enabled") or "false") == "true",
  1641. "mqtt_broker": await get_setting(db, "mqtt_broker") or "",
  1642. "mqtt_port": int(await get_setting(db, "mqtt_port") or "1883"),
  1643. "mqtt_username": await get_setting(db, "mqtt_username") or "",
  1644. "mqtt_password": await get_setting(db, "mqtt_password") or "",
  1645. "mqtt_topic_prefix": await get_setting(db, "mqtt_topic_prefix") or "bambuddy",
  1646. "mqtt_use_tls": (await get_setting(db, "mqtt_use_tls") or "false") == "true",
  1647. }
  1648. await mqtt_relay.configure(mqtt_settings)
  1649. # Connect to all active printers
  1650. async with async_session() as db:
  1651. await init_printer_connections(db)
  1652. # Auto-connect to Spoolman if enabled
  1653. async with async_session() as db:
  1654. from backend.app.api.routes.settings import get_setting
  1655. spoolman_enabled = await get_setting(db, "spoolman_enabled")
  1656. spoolman_url = await get_setting(db, "spoolman_url")
  1657. if spoolman_enabled and spoolman_enabled.lower() == "true" and spoolman_url:
  1658. try:
  1659. client = await init_spoolman_client(spoolman_url)
  1660. if await client.health_check():
  1661. logging.info(f"Auto-connected to Spoolman at {spoolman_url}")
  1662. # Ensure the 'tag' extra field exists for RFID/UUID storage
  1663. await client.ensure_tag_extra_field()
  1664. else:
  1665. logging.warning(f"Spoolman at {spoolman_url} is not reachable")
  1666. except Exception as e:
  1667. logging.warning(f"Failed to auto-connect to Spoolman: {e}")
  1668. # Start the print scheduler
  1669. asyncio.create_task(print_scheduler.run())
  1670. # Start the smart plug scheduler for time-based on/off
  1671. smart_plug_manager.start_scheduler()
  1672. # Resume any pending auto-offs that were interrupted by restart
  1673. await smart_plug_manager.resume_pending_auto_offs()
  1674. # Start the notification digest scheduler
  1675. notification_service.start_digest_scheduler()
  1676. # Start AMS history recording
  1677. start_ams_history_recording()
  1678. # Start printer runtime tracking
  1679. start_runtime_tracking()
  1680. # Start anonymous telemetry (opt-out via settings)
  1681. asyncio.create_task(start_telemetry_loop(async_session))
  1682. # Initialize virtual printer manager
  1683. from backend.app.services.virtual_printer import virtual_printer_manager
  1684. virtual_printer_manager.set_session_factory(async_session)
  1685. # Auto-start virtual printer if enabled
  1686. async with async_session() as db:
  1687. from backend.app.api.routes.settings import get_setting
  1688. vp_enabled = await get_setting(db, "virtual_printer_enabled")
  1689. if vp_enabled and vp_enabled.lower() == "true":
  1690. vp_access_code = await get_setting(db, "virtual_printer_access_code") or ""
  1691. vp_mode = await get_setting(db, "virtual_printer_mode") or "immediate"
  1692. vp_model = await get_setting(db, "virtual_printer_model") or ""
  1693. if vp_access_code:
  1694. try:
  1695. await virtual_printer_manager.configure(
  1696. enabled=True,
  1697. access_code=vp_access_code,
  1698. mode=vp_mode,
  1699. model=vp_model,
  1700. )
  1701. logging.info(f"Virtual printer started (model={vp_model or 'default'})")
  1702. except Exception as e:
  1703. logging.warning(f"Failed to start virtual printer: {e}")
  1704. yield
  1705. # Shutdown
  1706. print_scheduler.stop()
  1707. smart_plug_manager.stop_scheduler()
  1708. notification_service.stop_digest_scheduler()
  1709. stop_ams_history_recording()
  1710. stop_runtime_tracking()
  1711. printer_manager.disconnect_all()
  1712. await close_spoolman_client()
  1713. # Stop virtual printer if running
  1714. if virtual_printer_manager.is_enabled:
  1715. await virtual_printer_manager.configure(enabled=False)
  1716. app = FastAPI(
  1717. title=app_settings.app_name,
  1718. description="Archive and manage Bambu Lab 3MF files",
  1719. version=APP_VERSION,
  1720. lifespan=lifespan,
  1721. )
  1722. # API routes
  1723. app.include_router(auth.router, prefix=app_settings.api_prefix)
  1724. app.include_router(users.router, prefix=app_settings.api_prefix)
  1725. app.include_router(printers.router, prefix=app_settings.api_prefix)
  1726. app.include_router(archives.router, prefix=app_settings.api_prefix)
  1727. app.include_router(filaments.router, prefix=app_settings.api_prefix)
  1728. app.include_router(settings_routes.router, prefix=app_settings.api_prefix)
  1729. app.include_router(cloud.router, prefix=app_settings.api_prefix)
  1730. app.include_router(smart_plugs.router, prefix=app_settings.api_prefix)
  1731. app.include_router(print_queue.router, prefix=app_settings.api_prefix)
  1732. app.include_router(kprofiles.router, prefix=app_settings.api_prefix)
  1733. app.include_router(notifications.router, prefix=app_settings.api_prefix)
  1734. app.include_router(notification_templates.router, prefix=app_settings.api_prefix)
  1735. app.include_router(spoolman.router, prefix=app_settings.api_prefix)
  1736. app.include_router(updates.router, prefix=app_settings.api_prefix)
  1737. app.include_router(maintenance.router, prefix=app_settings.api_prefix)
  1738. app.include_router(camera.router, prefix=app_settings.api_prefix)
  1739. app.include_router(external_links.router, prefix=app_settings.api_prefix)
  1740. app.include_router(projects.router, prefix=app_settings.api_prefix)
  1741. app.include_router(library.router, prefix=app_settings.api_prefix)
  1742. app.include_router(api_keys.router, prefix=app_settings.api_prefix)
  1743. app.include_router(webhook.router, prefix=app_settings.api_prefix)
  1744. app.include_router(ams_history.router, prefix=app_settings.api_prefix)
  1745. app.include_router(system.router, prefix=app_settings.api_prefix)
  1746. app.include_router(support.router, prefix=app_settings.api_prefix)
  1747. app.include_router(websocket.router, prefix=app_settings.api_prefix)
  1748. app.include_router(discovery.router, prefix=app_settings.api_prefix)
  1749. app.include_router(pending_uploads.router, prefix=app_settings.api_prefix)
  1750. app.include_router(firmware.router, prefix=app_settings.api_prefix)
  1751. # Serve static files (React build)
  1752. if app_settings.static_dir.exists() and any(app_settings.static_dir.iterdir()):
  1753. app.mount(
  1754. "/assets",
  1755. StaticFiles(directory=app_settings.static_dir / "assets"),
  1756. name="assets",
  1757. )
  1758. if (app_settings.static_dir / "img").exists():
  1759. app.mount(
  1760. "/img",
  1761. StaticFiles(directory=app_settings.static_dir / "img"),
  1762. name="img",
  1763. )
  1764. if (app_settings.static_dir / "icons").exists():
  1765. app.mount(
  1766. "/icons",
  1767. StaticFiles(directory=app_settings.static_dir / "icons"),
  1768. name="icons",
  1769. )
  1770. @app.get("/")
  1771. async def serve_frontend():
  1772. """Serve the React frontend."""
  1773. index_file = app_settings.static_dir / "index.html"
  1774. if index_file.exists():
  1775. return FileResponse(index_file)
  1776. return {
  1777. "message": "Bambuddy API",
  1778. "docs": "/docs",
  1779. "frontend": "Build and place React app in /static directory",
  1780. }
  1781. @app.get("/health")
  1782. async def health_check():
  1783. """Health check endpoint."""
  1784. return {"status": "healthy"}
  1785. @app.get("/manifest.json")
  1786. async def serve_manifest():
  1787. """Serve PWA manifest."""
  1788. manifest_file = app_settings.static_dir / "manifest.json"
  1789. if manifest_file.exists():
  1790. return FileResponse(manifest_file, media_type="application/manifest+json")
  1791. return {"error": "Manifest not found"}
  1792. @app.get("/sw.js")
  1793. async def serve_service_worker():
  1794. """Serve service worker."""
  1795. sw_file = app_settings.static_dir / "sw.js"
  1796. if sw_file.exists():
  1797. return FileResponse(sw_file, media_type="application/javascript")
  1798. return {"error": "Service worker not found"}
  1799. # Catch-all route for React Router (must be last)
  1800. @app.get("/{full_path:path}")
  1801. async def serve_spa(full_path: str):
  1802. """Serve React app for client-side routing."""
  1803. # Don't intercept API routes - raise proper 404 so FastAPI can handle redirects
  1804. if full_path.startswith("api/"):
  1805. from fastapi import HTTPException
  1806. raise HTTPException(status_code=404, detail="Not found")
  1807. index_file = app_settings.static_dir / "index.html"
  1808. if index_file.exists():
  1809. return FileResponse(index_file)
  1810. return {"error": "Frontend not built"}