main.py 71 KB

1234567891011121314151617181920212223242526272829303132333435363738394041424344454647484950515253545556575859606162636465666768697071727374757677787980818283848586878889909192939495969798991001011021031041051061071081091101111121131141151161171181191201211221231241251261271281291301311321331341351361371381391401411421431441451461471481491501511521531541551561571581591601611621631641651661671681691701711721731741751761771781791801811821831841851861871881891901911921931941951961971981992002012022032042052062072082092102112122132142152162172182192202212222232242252262272282292302312322332342352362372382392402412422432442452462472482492502512522532542552562572582592602612622632642652662672682692702712722732742752762772782792802812822832842852862872882892902912922932942952962972982993003013023033043053063073083093103113123133143153163173183193203213223233243253263273283293303313323333343353363373383393403413423433443453463473483493503513523533543553563573583593603613623633643653663673683693703713723733743753763773783793803813823833843853863873883893903913923933943953963973983994004014024034044054064074084094104114124134144154164174184194204214224234244254264274284294304314324334344354364374384394404414424434444454464474484494504514524534544554564574584594604614624634644654664674684694704714724734744754764774784794804814824834844854864874884894904914924934944954964974984995005015025035045055065075085095105115125135145155165175185195205215225235245255265275285295305315325335345355365375385395405415425435445455465475485495505515525535545555565575585595605615625635645655665675685695705715725735745755765775785795805815825835845855865875885895905915925935945955965975985996006016026036046056066076086096106116126136146156166176186196206216226236246256266276286296306316326336346356366376386396406416426436446456466476486496506516526536546556566576586596606616626636646656666676686696706716726736746756766776786796806816826836846856866876886896906916926936946956966976986997007017027037047057067077087097107117127137147157167177187197207217227237247257267277287297307317327337347357367377387397407417427437447457467477487497507517527537547557567577587597607617627637647657667677687697707717727737747757767777787797807817827837847857867877887897907917927937947957967977987998008018028038048058068078088098108118128138148158168178188198208218228238248258268278288298308318328338348358368378388398408418428438448458468478488498508518528538548558568578588598608618628638648658668678688698708718728738748758768778788798808818828838848858868878888898908918928938948958968978988999009019029039049059069079089099109119129139149159169179189199209219229239249259269279289299309319329339349359369379389399409419429439449459469479489499509519529539549559569579589599609619629639649659669679689699709719729739749759769779789799809819829839849859869879889899909919929939949959969979989991000100110021003100410051006100710081009101010111012101310141015101610171018101910201021102210231024102510261027102810291030103110321033103410351036103710381039104010411042104310441045104610471048104910501051105210531054105510561057105810591060106110621063106410651066106710681069107010711072107310741075107610771078107910801081108210831084108510861087108810891090109110921093109410951096109710981099110011011102110311041105110611071108110911101111111211131114111511161117111811191120112111221123112411251126112711281129113011311132113311341135113611371138113911401141114211431144114511461147114811491150115111521153115411551156115711581159116011611162116311641165116611671168116911701171117211731174117511761177117811791180118111821183118411851186118711881189119011911192119311941195119611971198119912001201120212031204120512061207120812091210121112121213121412151216121712181219122012211222122312241225122612271228122912301231123212331234123512361237123812391240124112421243124412451246124712481249125012511252125312541255125612571258125912601261126212631264126512661267126812691270127112721273127412751276127712781279128012811282128312841285128612871288128912901291129212931294129512961297129812991300130113021303130413051306130713081309131013111312131313141315131613171318131913201321132213231324132513261327132813291330133113321333133413351336133713381339134013411342134313441345134613471348134913501351135213531354135513561357135813591360136113621363136413651366136713681369137013711372137313741375137613771378137913801381138213831384138513861387138813891390139113921393139413951396139713981399140014011402140314041405140614071408140914101411141214131414141514161417141814191420142114221423142414251426142714281429143014311432143314341435143614371438143914401441144214431444144514461447144814491450145114521453145414551456145714581459146014611462146314641465146614671468146914701471147214731474147514761477147814791480148114821483148414851486148714881489149014911492149314941495149614971498149915001501150215031504150515061507150815091510151115121513151415151516151715181519152015211522152315241525152615271528152915301531153215331534153515361537153815391540154115421543154415451546154715481549155015511552155315541555155615571558155915601561156215631564156515661567156815691570157115721573157415751576157715781579158015811582158315841585158615871588158915901591159215931594159515961597159815991600
  1. import asyncio
  2. import logging
  3. from contextlib import asynccontextmanager
  4. from datetime import 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. camera,
  49. cloud,
  50. external_links,
  51. filaments,
  52. kprofiles,
  53. maintenance,
  54. notification_templates,
  55. notifications,
  56. print_queue,
  57. printers,
  58. projects,
  59. settings as settings_routes,
  60. smart_plugs,
  61. spoolman,
  62. system,
  63. updates,
  64. webhook,
  65. websocket,
  66. )
  67. from backend.app.api.routes.maintenance import _get_printer_maintenance_internal, ensure_default_types
  68. from backend.app.core.database import async_session, init_db
  69. from backend.app.core.websocket import ws_manager
  70. from backend.app.models.smart_plug import SmartPlug
  71. from backend.app.services.archive import ArchiveService
  72. from backend.app.services.bambu_ftp import download_file_async
  73. from backend.app.services.bambu_mqtt import PrinterState
  74. from backend.app.services.notification_service import notification_service
  75. from backend.app.services.print_scheduler import scheduler as print_scheduler
  76. from backend.app.services.printer_manager import (
  77. init_printer_connections,
  78. printer_manager,
  79. printer_state_to_dict,
  80. )
  81. from backend.app.services.smart_plug_manager import smart_plug_manager
  82. from backend.app.services.spoolman import close_spoolman_client, get_spoolman_client, init_spoolman_client
  83. from backend.app.services.tasmota import tasmota_service
  84. from backend.app.services.telemetry import start_telemetry_loop
  85. # Track active prints: {(printer_id, filename): archive_id}
  86. _active_prints: dict[tuple[int, str], int] = {}
  87. # Track expected prints from reprint/scheduled (skip auto-archiving for these)
  88. # {(printer_id, filename): archive_id}
  89. _expected_prints: dict[tuple[int, str], int] = {}
  90. # Track starting energy for prints: {archive_id: starting_kwh}
  91. _print_energy_start: dict[int, float] = {}
  92. def register_expected_print(printer_id: int, filename: str, archive_id: int):
  93. """Register an expected print from reprint/scheduled so we don't create duplicate archives."""
  94. # Store with multiple filename variations to catch different naming patterns
  95. _expected_prints[(printer_id, filename)] = archive_id
  96. # Also store without .3mf extension if present
  97. if filename.endswith(".3mf"):
  98. base = filename[:-4]
  99. _expected_prints[(printer_id, base)] = archive_id
  100. _expected_prints[(printer_id, f"{base}.gcode")] = archive_id
  101. logging.getLogger(__name__).info(
  102. f"Registered expected print: printer={printer_id}, file={filename}, archive={archive_id}"
  103. )
  104. _last_status_broadcast: dict[int, str] = {}
  105. _nozzle_count_updated: set[int] = set() # Track printers where we've updated nozzle_count
  106. async def _report_spoolman_usage(printer_id: int, archive_id: int, logger):
  107. """Report filament usage to Spoolman after print completion.
  108. This finds the spool by RFID tag_uid from current AMS state and reports
  109. the filament_used_grams from the archive metadata.
  110. """
  111. async with async_session() as db:
  112. from backend.app.api.routes.settings import get_setting
  113. from backend.app.models.archive import PrintArchive
  114. # Check if Spoolman is enabled
  115. spoolman_enabled = await get_setting(db, "spoolman_enabled")
  116. if not spoolman_enabled or spoolman_enabled.lower() != "true":
  117. return
  118. # Get Spoolman URL
  119. spoolman_url = await get_setting(db, "spoolman_url")
  120. if not spoolman_url:
  121. return
  122. # Get or create Spoolman client
  123. client = await get_spoolman_client()
  124. if not client:
  125. client = await init_spoolman_client(spoolman_url)
  126. # Check if Spoolman is reachable
  127. if not await client.health_check():
  128. logger.warning("Spoolman not reachable for usage reporting")
  129. return
  130. # Get archive to find filament usage
  131. result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
  132. archive = result.scalar_one_or_none()
  133. if not archive or not archive.filament_used_grams:
  134. logger.debug(f"No filament usage data for archive {archive_id}")
  135. return
  136. filament_used = archive.filament_used_grams
  137. logger.info(f"[SPOOLMAN] Archive {archive_id} used {filament_used}g of filament")
  138. # Get current AMS state from printer to find the active spool
  139. state = printer_manager.get_status(printer_id)
  140. if not state or not state.raw_data:
  141. logger.debug("No printer state available for usage reporting")
  142. return
  143. ams_data = state.raw_data.get("ams")
  144. if not ams_data:
  145. logger.debug("No AMS data available for usage reporting")
  146. return
  147. # Find spools with RFID tags in Spoolman and report usage
  148. # For now, we report usage to the first spool found with a matching tag
  149. # TODO: In future, track which specific trays were used during the print
  150. spools_updated = 0
  151. for ams_unit in ams_data:
  152. trays = ams_unit.get("tray", [])
  153. for tray_data in trays:
  154. tag_uid = tray_data.get("tag_uid")
  155. if not tag_uid:
  156. continue
  157. # Find spool in Spoolman by tag
  158. spool = await client.find_spool_by_tag(tag_uid)
  159. if spool:
  160. # Report usage to Spoolman
  161. result = await client.use_spool(spool["id"], filament_used)
  162. if result:
  163. logger.info(
  164. f"[SPOOLMAN] Reported {filament_used}g usage to spool {spool['id']} (tag: {tag_uid})"
  165. )
  166. spools_updated += 1
  167. # Only report to one spool for single-material prints
  168. # Multi-material prints would need more sophisticated tracking
  169. return
  170. if spools_updated == 0:
  171. logger.debug(f"No matching Spoolman spools found for printer {printer_id}")
  172. async def on_printer_status_change(printer_id: int, state: PrinterState):
  173. """Handle printer status changes - broadcast via WebSocket."""
  174. # Only broadcast if something meaningful changed (reduce WebSocket spam)
  175. # Include rounded temperatures to detect meaningful temp changes (within 1 degree)
  176. temps = state.temperatures or {}
  177. nozzle_temp = round(temps.get("nozzle", 0))
  178. bed_temp = round(temps.get("bed", 0))
  179. nozzle_2_temp = round(temps.get("nozzle_2", 0)) if "nozzle_2" in temps else ""
  180. chamber_temp = round(temps.get("chamber", 0)) if "chamber" in temps else ""
  181. # Auto-detect dual-nozzle printers from MQTT temperature data
  182. if "nozzle_2" in temps and printer_id not in _nozzle_count_updated:
  183. _nozzle_count_updated.add(printer_id)
  184. # Update nozzle_count in database
  185. async with async_session() as db:
  186. from backend.app.models.printer import Printer
  187. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  188. printer = result.scalar_one_or_none()
  189. if printer and printer.nozzle_count != 2:
  190. printer.nozzle_count = 2
  191. await db.commit()
  192. logging.getLogger(__name__).info(
  193. f"Auto-detected dual-nozzle printer {printer_id}, updated nozzle_count=2"
  194. )
  195. status_key = (
  196. f"{state.connected}:{state.state}:{state.progress}:{state.layer_num}:"
  197. f"{nozzle_temp}:{bed_temp}:{nozzle_2_temp}:{chamber_temp}"
  198. )
  199. if _last_status_broadcast.get(printer_id) == status_key:
  200. return # No change, skip broadcast
  201. _last_status_broadcast[printer_id] = status_key
  202. await ws_manager.send_printer_status(
  203. printer_id,
  204. printer_state_to_dict(state, printer_id),
  205. )
  206. async def on_ams_change(printer_id: int, ams_data: list):
  207. """Handle AMS data changes - sync to Spoolman if enabled and auto mode."""
  208. import logging
  209. logger = logging.getLogger(__name__)
  210. try:
  211. async with async_session() as db:
  212. from backend.app.api.routes.settings import get_setting
  213. from backend.app.models.printer import Printer
  214. # Check if Spoolman is enabled
  215. spoolman_enabled = await get_setting(db, "spoolman_enabled")
  216. if not spoolman_enabled or spoolman_enabled.lower() != "true":
  217. return
  218. # Check sync mode
  219. sync_mode = await get_setting(db, "spoolman_sync_mode")
  220. if sync_mode and sync_mode != "auto":
  221. return # Only sync on auto mode
  222. # Get Spoolman URL
  223. spoolman_url = await get_setting(db, "spoolman_url")
  224. if not spoolman_url:
  225. return
  226. # Get or create Spoolman client
  227. client = await get_spoolman_client()
  228. if not client:
  229. client = await init_spoolman_client(spoolman_url)
  230. # Check if Spoolman is reachable
  231. if not await client.health_check():
  232. logger.warning(f"Spoolman not reachable at {spoolman_url}")
  233. return
  234. # Get printer name for location
  235. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  236. printer = result.scalar_one_or_none()
  237. printer_name = printer.name if printer else f"Printer {printer_id}"
  238. # Sync each AMS tray
  239. synced = 0
  240. for ams_unit in ams_data:
  241. ams_id = int(ams_unit.get("id", 0))
  242. trays = ams_unit.get("tray", [])
  243. for tray_data in trays:
  244. tray = client.parse_ams_tray(ams_id, tray_data)
  245. if not tray:
  246. continue # Empty tray
  247. try:
  248. result = await client.sync_ams_tray(tray, printer_name)
  249. if result:
  250. synced += 1
  251. except Exception as e:
  252. logger.error(f"Error syncing AMS {ams_id} tray {tray.tray_id}: {e}")
  253. if synced > 0:
  254. logger.info(f"Auto-synced {synced} AMS trays to Spoolman for printer {printer_id}")
  255. except Exception as e:
  256. import logging
  257. logging.getLogger(__name__).warning(f"Spoolman AMS sync failed: {e}")
  258. async def _send_print_start_notification(
  259. printer_id: int,
  260. data: dict,
  261. archive_data: dict | None = None,
  262. logger=None,
  263. ):
  264. """Helper to send print start notification with optional archive data."""
  265. if logger is None:
  266. import logging
  267. logger = logging.getLogger(__name__)
  268. try:
  269. async with async_session() as db:
  270. from backend.app.models.printer import Printer
  271. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  272. printer = result.scalar_one_or_none()
  273. printer_name = printer.name if printer else f"Printer {printer_id}"
  274. await notification_service.on_print_start(printer_id, printer_name, data, db, archive_data=archive_data)
  275. except Exception as e:
  276. logger.warning(f"Notification on_print_start failed: {e}")
  277. async def on_print_start(printer_id: int, data: dict):
  278. """Handle print start - archive the 3MF file immediately."""
  279. import logging
  280. logger = logging.getLogger(__name__)
  281. logger.info(f"[CALLBACK] on_print_start called for printer {printer_id}, data keys: {list(data.keys())}")
  282. await ws_manager.send_print_start(printer_id, data)
  283. # Track if notification was sent (to avoid sending twice)
  284. notification_sent = False
  285. # Smart plug automation: turn on plug when print starts
  286. try:
  287. async with async_session() as db:
  288. await smart_plug_manager.on_print_start(printer_id, db)
  289. except Exception as e:
  290. logger.warning(f"Smart plug on_print_start failed: {e}")
  291. async with async_session() as db:
  292. from backend.app.models.printer import Printer
  293. from backend.app.services.bambu_ftp import list_files_async
  294. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  295. printer = result.scalar_one_or_none()
  296. if not printer or not printer.auto_archive:
  297. # Send notification without archive data (auto-archive disabled)
  298. logger.info(
  299. f"[CALLBACK] Skipping archive - printer: {printer is not None}, auto_archive: {printer.auto_archive if printer else 'N/A'}"
  300. )
  301. if not notification_sent:
  302. await _send_print_start_notification(printer_id, data, logger=logger)
  303. return
  304. # Get the filename and subtask_name
  305. filename = data.get("filename", "")
  306. subtask_name = data.get("subtask_name", "")
  307. logger.info(f"[CALLBACK] Print start detected - filename: {filename}, subtask: {subtask_name}")
  308. if not filename and not subtask_name:
  309. # Send notification without archive data (no filename)
  310. logger.info("[CALLBACK] Skipping archive - no filename or subtask_name")
  311. if not notification_sent:
  312. await _send_print_start_notification(printer_id, data, logger=logger)
  313. return
  314. # Check if this is an expected print from reprint/scheduled
  315. # Build list of possible keys to check
  316. expected_keys = []
  317. if subtask_name:
  318. expected_keys.append((printer_id, subtask_name))
  319. expected_keys.append((printer_id, f"{subtask_name}.3mf"))
  320. expected_keys.append((printer_id, f"{subtask_name}.gcode.3mf"))
  321. if filename:
  322. fname = filename.split("/")[-1] if "/" in filename else filename
  323. expected_keys.append((printer_id, fname))
  324. # Strip extensions to match
  325. base = fname.replace(".gcode", "").replace(".3mf", "")
  326. expected_keys.append((printer_id, base))
  327. expected_keys.append((printer_id, f"{base}.3mf"))
  328. expected_archive_id = None
  329. for key in expected_keys:
  330. expected_archive_id = _expected_prints.pop(key, None)
  331. if expected_archive_id:
  332. # Clean up other possible keys for this print
  333. for other_key in expected_keys:
  334. _expected_prints.pop(other_key, None)
  335. break
  336. if expected_archive_id:
  337. # This is a reprint/scheduled print - use existing archive, don't create new one
  338. logger.info(f"Using expected archive {expected_archive_id} for print (skipping duplicate)")
  339. from datetime import datetime
  340. from backend.app.models.archive import PrintArchive
  341. result = await db.execute(select(PrintArchive).where(PrintArchive.id == expected_archive_id))
  342. archive = result.scalar_one_or_none()
  343. if archive:
  344. # Update archive status to printing
  345. archive.status = "printing"
  346. archive.started_at = datetime.now()
  347. await db.commit()
  348. # Track as active print
  349. _active_prints[(printer_id, archive.filename)] = archive.id
  350. if subtask_name:
  351. _active_prints[(printer_id, f"{subtask_name}.3mf")] = archive.id
  352. # Set up energy tracking
  353. try:
  354. plug_result = await db.execute(select(SmartPlug).where(SmartPlug.printer_id == printer_id))
  355. plug = plug_result.scalar_one_or_none()
  356. logger.info(
  357. f"[ENERGY] Print start - archive {archive.id}, printer {printer_id}, plug found: {plug is not None}"
  358. )
  359. if plug:
  360. energy = await tasmota_service.get_energy(plug)
  361. logger.info(f"[ENERGY] Energy response from plug: {energy}")
  362. if energy and energy.get("total") is not None:
  363. _print_energy_start[archive.id] = energy["total"]
  364. logger.info(
  365. f"[ENERGY] Recorded starting energy for archive {archive.id}: {energy['total']} kWh"
  366. )
  367. else:
  368. logger.warning(f"[ENERGY] No 'total' in energy response for archive {archive.id}")
  369. else:
  370. logger.info(f"[ENERGY] No smart plug found for printer {printer_id}")
  371. except Exception as e:
  372. logger.warning(f"Failed to record starting energy: {e}")
  373. await ws_manager.send_archive_updated(
  374. {
  375. "id": archive.id,
  376. "status": "printing",
  377. }
  378. )
  379. # Send notification with archive data (reprint/scheduled)
  380. if not notification_sent:
  381. archive_data = {"print_time_seconds": archive.print_time_seconds}
  382. await _send_print_start_notification(printer_id, data, archive_data, logger)
  383. return # Skip creating a new archive
  384. # Check if there's already a "printing" archive for this printer/file
  385. # This prevents duplicates when backend restarts during an active print
  386. from backend.app.models.archive import PrintArchive
  387. check_name = subtask_name or filename.split("/")[-1].replace(".gcode", "").replace(".3mf", "")
  388. existing = await db.execute(
  389. select(PrintArchive)
  390. .where(PrintArchive.printer_id == printer_id)
  391. .where(PrintArchive.status == "printing")
  392. .where(PrintArchive.print_name.ilike(f"%{check_name}%"))
  393. .order_by(PrintArchive.created_at.desc())
  394. .limit(1)
  395. )
  396. existing_archive = existing.scalar_one_or_none()
  397. if existing_archive:
  398. logger.info(f"Skipping duplicate - already have printing archive {existing_archive.id} for {check_name}")
  399. # Track this as the active print
  400. _active_prints[(printer_id, existing_archive.filename)] = existing_archive.id
  401. # Also set up energy tracking if not already tracked
  402. if existing_archive.id not in _print_energy_start:
  403. try:
  404. plug_result = await db.execute(select(SmartPlug).where(SmartPlug.printer_id == printer_id))
  405. plug = plug_result.scalar_one_or_none()
  406. if plug:
  407. energy = await tasmota_service.get_energy(plug)
  408. if energy and energy.get("total") is not None:
  409. _print_energy_start[existing_archive.id] = energy["total"]
  410. logger.info(
  411. f"Recorded starting energy for existing archive {existing_archive.id}: {energy['total']} kWh"
  412. )
  413. except Exception as e:
  414. logger.warning(f"Failed to record starting energy for existing archive: {e}")
  415. # Send notification with archive data (existing archive)
  416. if not notification_sent:
  417. archive_data = {"print_time_seconds": existing_archive.print_time_seconds}
  418. await _send_print_start_notification(printer_id, data, archive_data, logger)
  419. return
  420. # Build list of possible 3MF filenames to try
  421. possible_names = []
  422. # Bambu printers typically store files as "Name.gcode.3mf"
  423. # The subtask_name is usually the best source for the filename
  424. if subtask_name:
  425. # Try common Bambu naming patterns
  426. possible_names.append(f"{subtask_name}.gcode.3mf")
  427. possible_names.append(f"{subtask_name}.3mf")
  428. # Try original filename with .3mf extension
  429. if filename:
  430. # Extract just the filename part, not the full path
  431. fname = filename.split("/")[-1] if "/" in filename else filename
  432. if fname.endswith(".3mf"):
  433. possible_names.append(fname)
  434. elif fname.endswith(".gcode"):
  435. base = fname.rsplit(".", 1)[0]
  436. possible_names.append(f"{base}.gcode.3mf")
  437. possible_names.append(f"{base}.3mf")
  438. else:
  439. possible_names.append(f"{fname}.gcode.3mf")
  440. possible_names.append(f"{fname}.3mf")
  441. # Remove duplicates while preserving order
  442. seen = set()
  443. possible_names = [x for x in possible_names if not (x in seen or seen.add(x))]
  444. logger.info(f"Trying filenames: {possible_names}")
  445. # Try to find and download the 3MF file
  446. temp_path = None
  447. downloaded_filename = None
  448. for try_filename in possible_names:
  449. if not try_filename.endswith(".3mf"):
  450. continue
  451. remote_paths = [
  452. f"/cache/{try_filename}",
  453. f"/model/{try_filename}",
  454. f"/{try_filename}",
  455. ]
  456. temp_path = app_settings.archive_dir / "temp" / try_filename
  457. temp_path.parent.mkdir(parents=True, exist_ok=True)
  458. for remote_path in remote_paths:
  459. logger.debug(f"Trying FTP download: {remote_path}")
  460. try:
  461. if await download_file_async(
  462. printer.ip_address,
  463. printer.access_code,
  464. remote_path,
  465. temp_path,
  466. ):
  467. downloaded_filename = try_filename
  468. logger.info(f"Downloaded: {remote_path}")
  469. break
  470. except Exception as e:
  471. logger.debug(f"FTP download failed for {remote_path}: {e}")
  472. if downloaded_filename:
  473. break
  474. # If still not found, try listing /cache to find matching file
  475. if not downloaded_filename and (filename or subtask_name):
  476. search_term = (subtask_name or filename).lower().replace(".gcode", "").replace(".3mf", "")
  477. try:
  478. cache_files = await list_files_async(printer.ip_address, printer.access_code, "/cache")
  479. for f in cache_files:
  480. if f.get("is_directory"):
  481. continue
  482. fname = f.get("name", "")
  483. if fname.endswith(".3mf") and search_term in fname.lower():
  484. temp_path = app_settings.archive_dir / "temp" / fname
  485. temp_path.parent.mkdir(parents=True, exist_ok=True)
  486. if await download_file_async(
  487. printer.ip_address,
  488. printer.access_code,
  489. f"/cache/{fname}",
  490. temp_path,
  491. ):
  492. downloaded_filename = fname
  493. logger.info(f"Found and downloaded from cache: {fname}")
  494. break
  495. except Exception as e:
  496. logger.warning(f"Failed to list cache: {e}")
  497. if not downloaded_filename or not temp_path:
  498. logger.warning(f"Could not find 3MF file for print: {filename or subtask_name}")
  499. # Send notification without archive data (file not found)
  500. if not notification_sent:
  501. await _send_print_start_notification(printer_id, data, logger=logger)
  502. return
  503. try:
  504. # Archive the file with status "printing"
  505. service = ArchiveService(db)
  506. archive = await service.archive_print(
  507. printer_id=printer_id,
  508. source_file=temp_path,
  509. print_data={**data, "status": "printing"},
  510. )
  511. if archive:
  512. # Track this active print (use both original filename and downloaded filename)
  513. _active_prints[(printer_id, downloaded_filename)] = archive.id
  514. if filename and filename != downloaded_filename:
  515. _active_prints[(printer_id, filename)] = archive.id
  516. if subtask_name:
  517. _active_prints[(printer_id, f"{subtask_name}.3mf")] = archive.id
  518. logger.info(f"Created archive {archive.id} for {downloaded_filename}")
  519. # Record starting energy from smart plug if available
  520. try:
  521. plug_result = await db.execute(select(SmartPlug).where(SmartPlug.printer_id == printer_id))
  522. plug = plug_result.scalar_one_or_none()
  523. logger.info(
  524. f"[ENERGY] Auto-archive print start - archive {archive.id}, printer {printer_id}, plug found: {plug is not None}"
  525. )
  526. if plug:
  527. energy = await tasmota_service.get_energy(plug)
  528. logger.info(f"[ENERGY] Auto-archive energy response: {energy}")
  529. if energy and energy.get("total") is not None:
  530. _print_energy_start[archive.id] = energy["total"]
  531. logger.info(
  532. f"[ENERGY] Recorded starting energy for archive {archive.id}: {energy['total']} kWh"
  533. )
  534. else:
  535. logger.warning(f"[ENERGY] No 'total' in energy response for archive {archive.id}")
  536. else:
  537. logger.info(f"[ENERGY] No smart plug found for printer {printer_id}")
  538. except Exception as e:
  539. logger.warning(f"Failed to record starting energy: {e}")
  540. await ws_manager.send_archive_created(
  541. {
  542. "id": archive.id,
  543. "printer_id": archive.printer_id,
  544. "filename": archive.filename,
  545. "print_name": archive.print_name,
  546. "status": archive.status,
  547. }
  548. )
  549. # Send notification with archive data (new archive created)
  550. if not notification_sent:
  551. archive_data = {"print_time_seconds": archive.print_time_seconds}
  552. await _send_print_start_notification(printer_id, data, archive_data, logger)
  553. notification_sent = True
  554. finally:
  555. if temp_path and temp_path.exists():
  556. temp_path.unlink()
  557. async def _scan_for_timelapse_with_retries(archive_id: int):
  558. """
  559. Scan for timelapse with retries.
  560. The printer encodes the timelapse quickly after print completion.
  561. We just need a short delay then grab the most recent file.
  562. Since we KNOW timelapse was active (from MQTT ipcam data), the most recent
  563. file in /timelapse is our target. Retries handle FTP connection issues.
  564. """
  565. import logging
  566. logger = logging.getLogger(__name__)
  567. # Short delays - printer usually finishes encoding within seconds
  568. retry_delays = [5, 10, 20]
  569. for attempt, delay in enumerate(retry_delays, 1):
  570. logger.info(
  571. f"[TIMELAPSE] Attempt {attempt}/{len(retry_delays)}: waiting {delay}s before scanning for archive {archive_id}"
  572. )
  573. await asyncio.sleep(delay)
  574. try:
  575. async with async_session() as db:
  576. from backend.app.models.printer import Printer
  577. from backend.app.services.bambu_ftp import download_file_bytes_async, list_files_async
  578. # Get archive (ArchiveService from module-level import)
  579. service = ArchiveService(db)
  580. archive = await service.get_archive(archive_id)
  581. if not archive:
  582. logger.warning(f"[TIMELAPSE] Archive {archive_id} not found, stopping retries")
  583. return
  584. if archive.timelapse_path:
  585. logger.info(f"[TIMELAPSE] Archive {archive_id} already has timelapse attached, stopping retries")
  586. return
  587. if not archive.printer_id:
  588. logger.warning(f"[TIMELAPSE] Archive {archive_id} has no printer, stopping retries")
  589. return
  590. # Get printer
  591. result = await db.execute(select(Printer).where(Printer.id == archive.printer_id))
  592. printer = result.scalar_one_or_none()
  593. if not printer:
  594. logger.warning(f"[TIMELAPSE] Printer not found for archive {archive_id}, stopping retries")
  595. return
  596. # Scan timelapse directory on printer
  597. # H2D may store in different locations than X1C
  598. files = []
  599. found_path = None
  600. for timelapse_path in ["/timelapse", "/timelapse/video", "/record", "/recording"]:
  601. try:
  602. found_files = await list_files_async(printer.ip_address, printer.access_code, timelapse_path)
  603. if found_files:
  604. files = found_files
  605. found_path = timelapse_path
  606. logger.info(f"[TIMELAPSE] Attempt {attempt}: Found {len(files)} files in {timelapse_path}")
  607. break
  608. except Exception as e:
  609. logger.debug(f"[TIMELAPSE] Path {timelapse_path} failed: {e}")
  610. continue
  611. if not files:
  612. logger.info(f"[TIMELAPSE] Attempt {attempt}: No timelapse files found on printer, will retry")
  613. continue
  614. mp4_files = [f for f in files if not f.get("is_directory") and f.get("name", "").endswith(".mp4")]
  615. # Log ALL mp4 files found for debugging
  616. logger.info(f"[TIMELAPSE] Attempt {attempt}: Found {len(mp4_files)} MP4 files in {found_path}")
  617. for f in mp4_files[:5]: # Log first 5
  618. logger.info(f"[TIMELAPSE] - {f.get('name')}, mtime={f.get('mtime')}")
  619. if not mp4_files:
  620. logger.info(f"[TIMELAPSE] Attempt {attempt}: No MP4 files found, will retry")
  621. continue
  622. # Sort by mtime descending to get most recent file
  623. mp4_files_with_mtime = [f for f in mp4_files if f.get("mtime")]
  624. if not mp4_files_with_mtime:
  625. logger.info(f"[TIMELAPSE] Attempt {attempt}: No MP4 files with mtime found, will retry")
  626. continue
  627. mp4_files_with_mtime.sort(key=lambda x: x.get("mtime"), reverse=True)
  628. most_recent = mp4_files_with_mtime[0]
  629. file_name = most_recent.get("name")
  630. logger.info(f"[TIMELAPSE] Attempt {attempt}: Most recent file: {file_name}")
  631. # Since we KNOW timelapse was active (from MQTT), just grab the most recent file
  632. remote_path = most_recent.get("path") or f"/timelapse/{file_name}"
  633. logger.info(f"[TIMELAPSE] Downloading {file_name} for archive {archive_id}")
  634. timelapse_data = await download_file_bytes_async(printer.ip_address, printer.access_code, remote_path)
  635. if timelapse_data:
  636. success = await service.attach_timelapse(archive_id, timelapse_data, file_name)
  637. if success:
  638. logger.info(f"[TIMELAPSE] Successfully attached timelapse to archive {archive_id}")
  639. await ws_manager.send_archive_updated({"id": archive_id, "timelapse_attached": True})
  640. return # Success!
  641. else:
  642. logger.warning(f"[TIMELAPSE] Failed to attach timelapse to archive {archive_id}")
  643. else:
  644. logger.warning(f"[TIMELAPSE] Attempt {attempt}: Failed to download, will retry")
  645. except Exception as e:
  646. logger.warning(f"[TIMELAPSE] Attempt {attempt} failed with error: {e}")
  647. logger.warning(f"[TIMELAPSE] All {len(retry_delays)} attempts exhausted for archive {archive_id}, giving up")
  648. async def on_print_complete(printer_id: int, data: dict):
  649. """Handle print completion - update the archive status."""
  650. import logging
  651. import time
  652. logger = logging.getLogger(__name__)
  653. start_time = time.time()
  654. def log_timing(section: str):
  655. elapsed = time.time() - start_time
  656. logger.info(f"[TIMING] {section}: {elapsed:.3f}s elapsed")
  657. logger.info(f"[CALLBACK] on_print_complete started for printer {printer_id}")
  658. try:
  659. ws_data = {
  660. "status": data.get("status"),
  661. "filename": data.get("filename"),
  662. "subtask_name": data.get("subtask_name"),
  663. "timelapse_was_active": data.get("timelapse_was_active"),
  664. }
  665. await ws_manager.send_print_complete(printer_id, ws_data)
  666. log_timing("WebSocket send_print_complete")
  667. except Exception as e:
  668. logger.warning(f"[CALLBACK] WebSocket send_print_complete failed: {e}")
  669. filename = data.get("filename", "")
  670. subtask_name = data.get("subtask_name", "")
  671. if not filename and not subtask_name:
  672. logger.warning("Print complete without filename or subtask_name")
  673. return
  674. logger.info(f"Print complete - filename: {filename}, subtask: {subtask_name}, status: {data.get('status')}")
  675. # Build list of possible keys to try (matching how they were registered in on_print_start)
  676. possible_keys = []
  677. # Try subtask_name variations first (most reliable for matching)
  678. if subtask_name:
  679. possible_keys.append((printer_id, f"{subtask_name}.3mf"))
  680. possible_keys.append((printer_id, f"{subtask_name}.gcode.3mf"))
  681. possible_keys.append((printer_id, subtask_name))
  682. # Try filename variations
  683. if filename:
  684. # Extract just the filename if it's a path
  685. fname = filename.split("/")[-1] if "/" in filename else filename
  686. if fname.endswith(".3mf"):
  687. possible_keys.append((printer_id, fname))
  688. elif fname.endswith(".gcode"):
  689. base_name = fname.rsplit(".", 1)[0]
  690. possible_keys.append((printer_id, f"{base_name}.gcode.3mf"))
  691. possible_keys.append((printer_id, f"{base_name}.3mf"))
  692. possible_keys.append((printer_id, fname))
  693. else:
  694. possible_keys.append((printer_id, f"{fname}.gcode.3mf"))
  695. possible_keys.append((printer_id, f"{fname}.3mf"))
  696. possible_keys.append((printer_id, fname))
  697. # Also try full path versions
  698. if filename.endswith(".3mf"):
  699. possible_keys.append((printer_id, filename))
  700. elif filename.endswith(".gcode"):
  701. base_name = filename.rsplit(".", 1)[0]
  702. possible_keys.append((printer_id, f"{base_name}.3mf"))
  703. possible_keys.append((printer_id, filename))
  704. else:
  705. possible_keys.append((printer_id, f"{filename}.3mf"))
  706. possible_keys.append((printer_id, filename))
  707. # Find the archive for this print
  708. logger.info(f"Looking for archive in _active_prints, keys to try: {possible_keys[:5]}...")
  709. logger.info(f"Current _active_prints: {list(_active_prints.keys())}")
  710. archive_id = None
  711. for key in possible_keys:
  712. archive_id = _active_prints.pop(key, None)
  713. if archive_id:
  714. logger.info(f"Found archive {archive_id} with key {key}")
  715. # Also clean up any other keys pointing to this archive
  716. keys_to_remove = [k for k, v in _active_prints.items() if v == archive_id]
  717. for k in keys_to_remove:
  718. _active_prints.pop(k, None)
  719. break
  720. if not archive_id:
  721. # Try to find by filename or subtask_name if not tracked (for prints started before app)
  722. async with async_session() as db:
  723. from backend.app.models.archive import PrintArchive
  724. # Try matching by subtask_name (stored as print_name) first
  725. if subtask_name:
  726. result = await db.execute(
  727. select(PrintArchive)
  728. .where(PrintArchive.printer_id == printer_id)
  729. .where(PrintArchive.status == "printing")
  730. .where(
  731. or_(
  732. PrintArchive.print_name.ilike(f"%{subtask_name}%"),
  733. PrintArchive.filename.ilike(f"%{subtask_name}%"),
  734. )
  735. )
  736. .order_by(PrintArchive.created_at.desc())
  737. .limit(1)
  738. )
  739. archive = result.scalar_one_or_none()
  740. if archive:
  741. archive_id = archive.id
  742. logger.info(f"Found archive {archive_id} by subtask_name match: {subtask_name}")
  743. # Also try by filename
  744. if not archive_id and filename:
  745. result = await db.execute(
  746. select(PrintArchive)
  747. .where(PrintArchive.printer_id == printer_id)
  748. .where(PrintArchive.filename == filename)
  749. .where(PrintArchive.status == "printing")
  750. .order_by(PrintArchive.created_at.desc())
  751. .limit(1)
  752. )
  753. archive = result.scalar_one_or_none()
  754. if archive:
  755. archive_id = archive.id
  756. if not archive_id:
  757. logger.warning(f"Could not find archive for print complete: filename={filename}, subtask={subtask_name}")
  758. return
  759. log_timing("Archive lookup")
  760. # Update archive status
  761. logger.info(f"[ARCHIVE] Updating archive {archive_id} status...")
  762. try:
  763. async with async_session() as db:
  764. service = ArchiveService(db)
  765. status = data.get("status", "completed")
  766. # Auto-detect failure reason
  767. failure_reason = None
  768. if status == "aborted":
  769. failure_reason = "User cancelled"
  770. logger.info("[ARCHIVE] Print was aborted by user, setting failure_reason='User cancelled'")
  771. elif status == "failed":
  772. # Try to determine failure reason from HMS errors
  773. hms_errors = data.get("hms_errors", [])
  774. if hms_errors:
  775. logger.info(f"[ARCHIVE] HMS errors at failure: {hms_errors}")
  776. # Map known HMS error modules to failure reasons
  777. # Module 0x07 = Filament, 0x0C = MC (Motion Controller), etc.
  778. for err in hms_errors:
  779. module = err.get("module", 0)
  780. if module == 0x07: # Filament module
  781. failure_reason = "Filament runout"
  782. break
  783. elif module == 0x0C: # Motion controller
  784. failure_reason = "Layer shift"
  785. break
  786. elif module == 0x05: # Nozzle/extruder
  787. failure_reason = "Clogged nozzle"
  788. break
  789. if failure_reason:
  790. logger.info(f"[ARCHIVE] Detected failure_reason from HMS: {failure_reason}")
  791. else:
  792. logger.info("[ARCHIVE] No HMS errors available to determine failure reason")
  793. await service.update_archive_status(
  794. archive_id,
  795. status=status,
  796. completed_at=datetime.now() if status in ("completed", "failed", "aborted") else None,
  797. failure_reason=failure_reason,
  798. )
  799. logger.info(f"[ARCHIVE] Archive {archive_id} status updated to {status}, failure_reason={failure_reason}")
  800. await ws_manager.send_archive_updated(
  801. {
  802. "id": archive_id,
  803. "status": status,
  804. }
  805. )
  806. logger.info(f"[ARCHIVE] WebSocket notification sent for archive {archive_id}")
  807. except Exception as e:
  808. logger.error(f"[ARCHIVE] Failed to update archive {archive_id} status: {e}", exc_info=True)
  809. # Continue with other operations even if archive update fails
  810. log_timing("Archive status update")
  811. # Report filament usage to Spoolman if print completed successfully
  812. if data.get("status") == "completed":
  813. try:
  814. await _report_spoolman_usage(printer_id, archive_id, logger)
  815. log_timing("Spoolman usage report")
  816. except Exception as e:
  817. logger.warning(f"Spoolman usage reporting failed: {e}")
  818. # Run slow operations as background tasks to avoid blocking the event loop
  819. # These operations can take 5-10+ seconds and would freeze the UI if awaited
  820. starting_kwh = _print_energy_start.pop(archive_id, None)
  821. async def _background_energy_calculation():
  822. """Calculate and save energy usage in background."""
  823. try:
  824. logger.info(f"[ENERGY-BG] Starting energy calculation for archive {archive_id}")
  825. async with async_session() as db:
  826. plug_result = await db.execute(select(SmartPlug).where(SmartPlug.printer_id == printer_id))
  827. plug = plug_result.scalar_one_or_none()
  828. if plug:
  829. energy = await tasmota_service.get_energy(plug)
  830. logger.info(f"[ENERGY-BG] Energy response: {energy}")
  831. energy_used = None
  832. if starting_kwh is not None and energy and energy.get("total") is not None:
  833. ending_kwh = energy["total"]
  834. energy_used = round(ending_kwh - starting_kwh, 4)
  835. logger.info(f"[ENERGY-BG] Per-print energy: {energy_used} kWh")
  836. if energy_used is not None and energy_used >= 0:
  837. from backend.app.api.routes.settings import get_setting
  838. energy_cost_per_kwh = await get_setting(db, "energy_cost_per_kwh")
  839. cost_per_kwh = float(energy_cost_per_kwh) if energy_cost_per_kwh else 0.15
  840. energy_cost = round(energy_used * cost_per_kwh, 2)
  841. from backend.app.models.archive import PrintArchive
  842. result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
  843. archive = result.scalar_one_or_none()
  844. if archive:
  845. archive.energy_kwh = energy_used
  846. archive.energy_cost = energy_cost
  847. await db.commit()
  848. logger.info(f"[ENERGY-BG] Saved: {energy_used} kWh, cost={energy_cost}")
  849. else:
  850. logger.info(f"[ENERGY-BG] No smart plug for printer {printer_id}")
  851. except Exception as e:
  852. logger.warning(f"[ENERGY-BG] Failed: {e}")
  853. async def _background_finish_photo():
  854. """Capture finish photo in background."""
  855. try:
  856. logger.info(f"[PHOTO-BG] Starting finish photo capture for archive {archive_id}")
  857. from backend.app.api.routes.camera import _active_streams, get_buffered_frame
  858. async with async_session() as db:
  859. from backend.app.api.routes.settings import get_setting
  860. capture_enabled = await get_setting(db, "capture_finish_photo")
  861. if capture_enabled is None or capture_enabled.lower() == "true":
  862. from backend.app.models.printer import Printer
  863. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  864. printer = result.scalar_one_or_none()
  865. if printer and archive_id:
  866. from backend.app.models.archive import PrintArchive
  867. result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
  868. archive = result.scalar_one_or_none()
  869. if archive:
  870. import uuid
  871. from datetime import datetime
  872. from pathlib import Path
  873. archive_dir = app_settings.base_dir / Path(archive.file_path).parent
  874. photo_filename = None
  875. # Check if camera stream is active - use buffered frame to avoid freeze
  876. active_for_printer = [k for k in _active_streams if k.startswith(f"{printer_id}-")]
  877. buffered_frame = get_buffered_frame(printer_id)
  878. if active_for_printer and buffered_frame:
  879. # Use frame from active stream
  880. logger.info("[PHOTO-BG] Using buffered frame from active stream")
  881. photos_dir = archive_dir / "photos"
  882. photos_dir.mkdir(parents=True, exist_ok=True)
  883. timestamp = datetime.now().strftime("%Y%m%d_%H%M%S")
  884. photo_filename = f"finish_{timestamp}_{uuid.uuid4().hex[:8]}.jpg"
  885. photo_path = photos_dir / photo_filename
  886. await asyncio.to_thread(photo_path.write_bytes, buffered_frame)
  887. logger.info(f"[PHOTO-BG] Saved buffered frame: {photo_filename}")
  888. else:
  889. # No active stream - capture new frame
  890. from backend.app.services.camera import capture_finish_photo
  891. photo_filename = await capture_finish_photo(
  892. printer_id=printer_id,
  893. ip_address=printer.ip_address,
  894. access_code=printer.access_code,
  895. model=printer.model,
  896. archive_dir=archive_dir,
  897. )
  898. if photo_filename:
  899. photos = archive.photos or []
  900. photos.append(photo_filename)
  901. archive.photos = photos
  902. await db.commit()
  903. logger.info(f"[PHOTO-BG] Saved: {photo_filename}")
  904. except Exception as e:
  905. logger.warning(f"[PHOTO-BG] Failed: {e}")
  906. asyncio.create_task(_background_energy_calculation())
  907. asyncio.create_task(_background_finish_photo()) # Skips if camera stream active
  908. log_timing("Background tasks scheduled (energy, photo)")
  909. # Also run smart plug, notifications, and maintenance as background tasks
  910. print_status = data.get("status", "completed")
  911. async def _background_smart_plug():
  912. """Handle smart plug automation in background."""
  913. try:
  914. logger.info(f"[AUTO-OFF-BG] Starting smart plug automation for printer {printer_id}")
  915. async with async_session() as db:
  916. await smart_plug_manager.on_print_complete(printer_id, print_status, db)
  917. logger.info("[AUTO-OFF-BG] Completed")
  918. except Exception as e:
  919. logger.warning(f"[AUTO-OFF-BG] Failed: {e}")
  920. async def _background_notifications():
  921. """Send print complete notifications in background."""
  922. try:
  923. logger.info(f"[NOTIFY-BG] Starting notifications for printer {printer_id}")
  924. async with async_session() as db:
  925. from backend.app.models.archive import PrintArchive
  926. from backend.app.models.printer import Printer
  927. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  928. printer = result.scalar_one_or_none()
  929. printer_name = printer.name if printer else f"Printer {printer_id}"
  930. archive_data = None
  931. if archive_id:
  932. archive_result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
  933. archive = archive_result.scalar_one_or_none()
  934. if archive:
  935. archive_data = {
  936. "print_time_seconds": archive.print_time_seconds,
  937. "actual_filament_grams": archive.filament_used_grams,
  938. "failure_reason": archive.failure_reason,
  939. }
  940. await notification_service.on_print_complete(
  941. printer_id, printer_name, print_status, data, db, archive_data=archive_data
  942. )
  943. logger.info("[NOTIFY-BG] Completed")
  944. except Exception as e:
  945. logger.warning(f"[NOTIFY-BG] Failed: {e}")
  946. async def _background_maintenance_check():
  947. """Check for maintenance due in background."""
  948. if print_status != "completed":
  949. return
  950. try:
  951. logger.info(f"[MAINT-BG] Starting maintenance check for printer {printer_id}")
  952. async with async_session() as db:
  953. from backend.app.models.printer import Printer
  954. result = await db.execute(select(Printer).where(Printer.id == printer_id))
  955. printer = result.scalar_one_or_none()
  956. printer_name = printer.name if printer else f"Printer {printer_id}"
  957. await ensure_default_types(db)
  958. overview = await _get_printer_maintenance_internal(printer_id, db, commit=True)
  959. items_needing_attention = [
  960. {"name": item.maintenance_type_name, "is_due": item.is_due, "is_warning": item.is_warning}
  961. for item in overview.maintenance_items
  962. if item.enabled and (item.is_due or item.is_warning)
  963. ]
  964. if items_needing_attention:
  965. await notification_service.on_maintenance_due(printer_id, printer_name, items_needing_attention, db)
  966. logger.info(f"[MAINT-BG] Sent notification: {len(items_needing_attention)} items need attention")
  967. else:
  968. logger.info("[MAINT-BG] Completed (no items need attention)")
  969. except Exception as e:
  970. logger.warning(f"[MAINT-BG] Failed: {e}")
  971. asyncio.create_task(_background_smart_plug())
  972. asyncio.create_task(_background_notifications())
  973. asyncio.create_task(_background_maintenance_check())
  974. log_timing("All background tasks scheduled")
  975. # Auto-scan for timelapse if recording was active during the print
  976. if archive_id and data.get("timelapse_was_active") and data.get("status") == "completed":
  977. logger.info(f"[TIMELAPSE] Timelapse was active during print, scheduling auto-scan for archive {archive_id}")
  978. # Schedule timelapse scan as background task with retries
  979. # The printer needs time to encode the video after print completion
  980. asyncio.create_task(_scan_for_timelapse_with_retries(archive_id))
  981. log_timing("Timelapse scan scheduled")
  982. # Update queue item if this was a scheduled print
  983. try:
  984. async with async_session() as db:
  985. from backend.app.models.print_queue import PrintQueueItem
  986. # Note: SmartPlug is already imported at module level (line 56)
  987. # Do NOT import it here as it would shadow the module-level import
  988. # and cause "cannot access local variable" errors earlier in this function
  989. result = await db.execute(
  990. select(PrintQueueItem)
  991. .where(PrintQueueItem.printer_id == printer_id)
  992. .where(PrintQueueItem.status == "printing")
  993. )
  994. queue_item = result.scalar_one_or_none()
  995. if queue_item:
  996. status = data.get("status", "completed")
  997. queue_item.status = status
  998. queue_item.completed_at = datetime.now()
  999. await db.commit()
  1000. logger.info(f"Updated queue item {queue_item.id} status to {status}")
  1001. # Handle auto_off_after - power off printer if requested (after cooldown)
  1002. if queue_item.auto_off_after:
  1003. result = await db.execute(select(SmartPlug).where(SmartPlug.printer_id == printer_id))
  1004. plug = result.scalar_one_or_none()
  1005. if plug and plug.enabled:
  1006. logger.info(f"Auto-off requested for printer {printer_id}, waiting for cooldown...")
  1007. async def cooldown_and_poweroff(pid: int, plug_id: int):
  1008. # Wait for nozzle to cool down
  1009. await printer_manager.wait_for_cooldown(pid, target_temp=50.0, timeout=600)
  1010. # Re-fetch plug in new session
  1011. async with async_session() as new_db:
  1012. result = await new_db.execute(select(SmartPlug).where(SmartPlug.id == plug_id))
  1013. p = result.scalar_one_or_none()
  1014. if p and p.enabled:
  1015. success = await tasmota_service.turn_off(p)
  1016. if success:
  1017. logger.info(f"Powered off printer {pid} via smart plug '{p.name}'")
  1018. else:
  1019. logger.warning(f"Failed to power off printer {pid} via smart plug")
  1020. asyncio.create_task(cooldown_and_poweroff(printer_id, plug.id))
  1021. except Exception as e:
  1022. import logging
  1023. logging.getLogger(__name__).warning(f"Queue item update failed: {e}")
  1024. log_timing("Queue item update")
  1025. logger.info(f"[CALLBACK] on_print_complete finished for printer {printer_id}, archive {archive_id}")
  1026. # AMS sensor history recording
  1027. _ams_history_task: asyncio.Task | None = None
  1028. AMS_HISTORY_INTERVAL = 300 # Record every 5 minutes
  1029. AMS_HISTORY_RETENTION_DAYS = 30 # Keep data for 30 days
  1030. _ams_cleanup_counter = 0 # Track recordings to trigger periodic cleanup
  1031. _ams_alarm_cooldown: dict[str, datetime] = {} # Track alarm cooldowns (printer_id:ams_id:type -> last_alarm_time)
  1032. AMS_ALARM_COOLDOWN_MINUTES = 60 # Don't send same alarm more than once per hour
  1033. async def record_ams_history():
  1034. """Background task to record AMS humidity and temperature data."""
  1035. import logging
  1036. logger = logging.getLogger(__name__)
  1037. # Wait a short time for MQTT connections to establish on startup
  1038. await asyncio.sleep(10)
  1039. while True:
  1040. try:
  1041. from backend.app.models.ams_history import AMSSensorHistory
  1042. from backend.app.models.printer import Printer
  1043. from backend.app.models.settings import Settings
  1044. async with async_session() as db:
  1045. # Get all active printers
  1046. result = await db.execute(select(Printer).where(Printer.is_active.is_(True)))
  1047. printers = result.scalars().all()
  1048. # Get alarm thresholds from settings
  1049. humidity_threshold = 60.0 # Default: fair threshold
  1050. temp_threshold = 35.0 # Default: fair threshold
  1051. result = await db.execute(select(Settings).where(Settings.key == "ams_humidity_fair"))
  1052. setting = result.scalar_one_or_none()
  1053. if setting:
  1054. try:
  1055. humidity_threshold = float(setting.value)
  1056. except (ValueError, TypeError):
  1057. pass
  1058. result = await db.execute(select(Settings).where(Settings.key == "ams_temp_fair"))
  1059. setting = result.scalar_one_or_none()
  1060. if setting:
  1061. try:
  1062. temp_threshold = float(setting.value)
  1063. except (ValueError, TypeError):
  1064. pass
  1065. recorded_count = 0
  1066. for printer in printers:
  1067. # Get current state from printer manager
  1068. state = printer_manager.get_status(printer.id)
  1069. if not state or not state.raw_data:
  1070. continue
  1071. raw_data = state.raw_data
  1072. if "ams" not in raw_data or not isinstance(raw_data["ams"], list):
  1073. continue
  1074. # Record data for each AMS unit
  1075. for ams_data in raw_data["ams"]:
  1076. ams_id = int(ams_data.get("id", 0))
  1077. # Get humidity (prefer humidity_raw)
  1078. humidity_raw = ams_data.get("humidity_raw")
  1079. humidity_idx = ams_data.get("humidity")
  1080. humidity = None
  1081. if humidity_raw is not None:
  1082. try:
  1083. humidity = float(humidity_raw)
  1084. except (ValueError, TypeError):
  1085. pass
  1086. if humidity is None and humidity_idx is not None:
  1087. try:
  1088. humidity = float(humidity_idx)
  1089. except (ValueError, TypeError):
  1090. pass
  1091. # Get temperature
  1092. temperature = None
  1093. temp_str = ams_data.get("temp")
  1094. if temp_str is not None:
  1095. try:
  1096. temperature = float(temp_str)
  1097. except (ValueError, TypeError):
  1098. pass
  1099. # Skip if no data
  1100. if humidity is None and temperature is None:
  1101. continue
  1102. # Record the data point
  1103. history = AMSSensorHistory(
  1104. printer_id=printer.id,
  1105. ams_id=ams_id,
  1106. humidity=humidity,
  1107. humidity_raw=float(humidity_raw) if humidity_raw else None,
  1108. temperature=temperature,
  1109. )
  1110. db.add(history)
  1111. recorded_count += 1
  1112. # Generate AMS label and determine if it's AMS-HT (A, B, C, D or HT-A for AMS-Lite/Hub)
  1113. is_ams_ht = ams_id >= 128
  1114. if is_ams_ht:
  1115. ams_label = f"HT-{chr(65 + (ams_id - 128))}"
  1116. else:
  1117. ams_label = f"AMS-{chr(65 + ams_id)}"
  1118. # Check humidity alarm (only if above threshold)
  1119. if humidity is not None and humidity > humidity_threshold:
  1120. cooldown_key = f"{printer.id}:{ams_id}:humidity"
  1121. last_alarm = _ams_alarm_cooldown.get(cooldown_key)
  1122. now = datetime.now()
  1123. if (
  1124. last_alarm is None
  1125. or (now - last_alarm).total_seconds() >= AMS_ALARM_COOLDOWN_MINUTES * 60
  1126. ):
  1127. _ams_alarm_cooldown[cooldown_key] = now
  1128. logger.info(
  1129. f"Sending humidity alarm for {printer.name} {ams_label}: {humidity}% > {humidity_threshold}%"
  1130. )
  1131. try:
  1132. # Call different notification method based on AMS type
  1133. if is_ams_ht:
  1134. await notification_service.on_ams_ht_humidity_high(
  1135. printer.id, printer.name, ams_label, humidity, humidity_threshold, db
  1136. )
  1137. else:
  1138. await notification_service.on_ams_humidity_high(
  1139. printer.id, printer.name, ams_label, humidity, humidity_threshold, db
  1140. )
  1141. except Exception as e:
  1142. logger.warning(f"Failed to send humidity alarm: {e}")
  1143. # Check temperature alarm (only if above threshold)
  1144. if temperature is not None and temperature > temp_threshold:
  1145. cooldown_key = f"{printer.id}:{ams_id}:temperature"
  1146. last_alarm = _ams_alarm_cooldown.get(cooldown_key)
  1147. now = datetime.now()
  1148. if (
  1149. last_alarm is None
  1150. or (now - last_alarm).total_seconds() >= AMS_ALARM_COOLDOWN_MINUTES * 60
  1151. ):
  1152. _ams_alarm_cooldown[cooldown_key] = now
  1153. logger.info(
  1154. f"Sending temperature alarm for {printer.name} {ams_label}: {temperature}°C > {temp_threshold}°C"
  1155. )
  1156. try:
  1157. # Call different notification method based on AMS type
  1158. if is_ams_ht:
  1159. await notification_service.on_ams_ht_temperature_high(
  1160. printer.id, printer.name, ams_label, temperature, temp_threshold, db
  1161. )
  1162. else:
  1163. await notification_service.on_ams_temperature_high(
  1164. printer.id, printer.name, ams_label, temperature, temp_threshold, db
  1165. )
  1166. except Exception as e:
  1167. logger.warning(f"Failed to send temperature alarm: {e}")
  1168. await db.commit()
  1169. if recorded_count > 0:
  1170. logger.info(f"Recorded {recorded_count} AMS sensor history entries")
  1171. # Periodic cleanup of old data (every ~288 recordings = ~24 hours at 5min interval)
  1172. global _ams_cleanup_counter
  1173. _ams_cleanup_counter += 1
  1174. if _ams_cleanup_counter >= 288:
  1175. _ams_cleanup_counter = 0
  1176. # Get retention days from settings
  1177. from backend.app.models.settings import Settings
  1178. result = await db.execute(select(Settings).where(Settings.key == "ams_history_retention_days"))
  1179. setting = result.scalar_one_or_none()
  1180. retention_days = int(setting.value) if setting else AMS_HISTORY_RETENTION_DAYS
  1181. cutoff = datetime.now() - timedelta(days=retention_days)
  1182. result = await db.execute(delete(AMSSensorHistory).where(AMSSensorHistory.recorded_at < cutoff))
  1183. await db.commit()
  1184. if result.rowcount > 0:
  1185. logger.info(
  1186. f"Cleaned up {result.rowcount} old AMS sensor history entries (older than {retention_days} days)"
  1187. )
  1188. # Wait until next recording interval
  1189. await asyncio.sleep(AMS_HISTORY_INTERVAL)
  1190. except asyncio.CancelledError:
  1191. break
  1192. except Exception as e:
  1193. logger.warning(f"AMS history recording failed: {e}")
  1194. await asyncio.sleep(60) # Wait a bit before retrying
  1195. def start_ams_history_recording():
  1196. """Start the AMS history recording background task."""
  1197. global _ams_history_task
  1198. if _ams_history_task is None:
  1199. _ams_history_task = asyncio.create_task(record_ams_history())
  1200. logging.getLogger(__name__).info("AMS history recording started")
  1201. def stop_ams_history_recording():
  1202. """Stop the AMS history recording background task."""
  1203. global _ams_history_task
  1204. if _ams_history_task:
  1205. _ams_history_task.cancel()
  1206. _ams_history_task = None
  1207. logging.getLogger(__name__).info("AMS history recording stopped")
  1208. @asynccontextmanager
  1209. async def lifespan(app: FastAPI):
  1210. # Startup
  1211. await init_db()
  1212. # Set up printer manager callbacks
  1213. loop = asyncio.get_event_loop()
  1214. printer_manager.set_event_loop(loop)
  1215. printer_manager.set_status_change_callback(on_printer_status_change)
  1216. printer_manager.set_print_start_callback(on_print_start)
  1217. printer_manager.set_print_complete_callback(on_print_complete)
  1218. printer_manager.set_ams_change_callback(on_ams_change)
  1219. # Connect to all active printers
  1220. async with async_session() as db:
  1221. await init_printer_connections(db)
  1222. # Auto-connect to Spoolman if enabled
  1223. async with async_session() as db:
  1224. from backend.app.api.routes.settings import get_setting
  1225. spoolman_enabled = await get_setting(db, "spoolman_enabled")
  1226. spoolman_url = await get_setting(db, "spoolman_url")
  1227. if spoolman_enabled and spoolman_enabled.lower() == "true" and spoolman_url:
  1228. try:
  1229. client = await init_spoolman_client(spoolman_url)
  1230. if await client.health_check():
  1231. logging.info(f"Auto-connected to Spoolman at {spoolman_url}")
  1232. else:
  1233. logging.warning(f"Spoolman at {spoolman_url} is not reachable")
  1234. except Exception as e:
  1235. logging.warning(f"Failed to auto-connect to Spoolman: {e}")
  1236. # Start the print scheduler
  1237. asyncio.create_task(print_scheduler.run())
  1238. # Start the smart plug scheduler for time-based on/off
  1239. smart_plug_manager.start_scheduler()
  1240. # Resume any pending auto-offs that were interrupted by restart
  1241. await smart_plug_manager.resume_pending_auto_offs()
  1242. # Start the notification digest scheduler
  1243. notification_service.start_digest_scheduler()
  1244. # Start AMS history recording
  1245. start_ams_history_recording()
  1246. # Start anonymous telemetry (opt-out via settings)
  1247. asyncio.create_task(start_telemetry_loop(async_session))
  1248. yield
  1249. # Shutdown
  1250. print_scheduler.stop()
  1251. smart_plug_manager.stop_scheduler()
  1252. notification_service.stop_digest_scheduler()
  1253. stop_ams_history_recording()
  1254. printer_manager.disconnect_all()
  1255. await close_spoolman_client()
  1256. app = FastAPI(
  1257. title=app_settings.app_name,
  1258. description="Archive and manage Bambu Lab 3MF files",
  1259. version=APP_VERSION,
  1260. lifespan=lifespan,
  1261. )
  1262. # API routes
  1263. app.include_router(printers.router, prefix=app_settings.api_prefix)
  1264. app.include_router(archives.router, prefix=app_settings.api_prefix)
  1265. app.include_router(filaments.router, prefix=app_settings.api_prefix)
  1266. app.include_router(settings_routes.router, prefix=app_settings.api_prefix)
  1267. app.include_router(cloud.router, prefix=app_settings.api_prefix)
  1268. app.include_router(smart_plugs.router, prefix=app_settings.api_prefix)
  1269. app.include_router(print_queue.router, prefix=app_settings.api_prefix)
  1270. app.include_router(kprofiles.router, prefix=app_settings.api_prefix)
  1271. app.include_router(notifications.router, prefix=app_settings.api_prefix)
  1272. app.include_router(notification_templates.router, prefix=app_settings.api_prefix)
  1273. app.include_router(spoolman.router, prefix=app_settings.api_prefix)
  1274. app.include_router(updates.router, prefix=app_settings.api_prefix)
  1275. app.include_router(maintenance.router, prefix=app_settings.api_prefix)
  1276. app.include_router(camera.router, prefix=app_settings.api_prefix)
  1277. app.include_router(external_links.router, prefix=app_settings.api_prefix)
  1278. app.include_router(projects.router, prefix=app_settings.api_prefix)
  1279. app.include_router(api_keys.router, prefix=app_settings.api_prefix)
  1280. app.include_router(webhook.router, prefix=app_settings.api_prefix)
  1281. app.include_router(ams_history.router, prefix=app_settings.api_prefix)
  1282. app.include_router(system.router, prefix=app_settings.api_prefix)
  1283. app.include_router(websocket.router, prefix=app_settings.api_prefix)
  1284. # Serve static files (React build)
  1285. if app_settings.static_dir.exists() and any(app_settings.static_dir.iterdir()):
  1286. app.mount(
  1287. "/assets",
  1288. StaticFiles(directory=app_settings.static_dir / "assets"),
  1289. name="assets",
  1290. )
  1291. if (app_settings.static_dir / "img").exists():
  1292. app.mount(
  1293. "/img",
  1294. StaticFiles(directory=app_settings.static_dir / "img"),
  1295. name="img",
  1296. )
  1297. if (app_settings.static_dir / "icons").exists():
  1298. app.mount(
  1299. "/icons",
  1300. StaticFiles(directory=app_settings.static_dir / "icons"),
  1301. name="icons",
  1302. )
  1303. @app.get("/")
  1304. async def serve_frontend():
  1305. """Serve the React frontend."""
  1306. index_file = app_settings.static_dir / "index.html"
  1307. if index_file.exists():
  1308. return FileResponse(index_file)
  1309. return {
  1310. "message": "Bambuddy API",
  1311. "docs": "/docs",
  1312. "frontend": "Build and place React app in /static directory",
  1313. }
  1314. @app.get("/health")
  1315. async def health_check():
  1316. """Health check endpoint."""
  1317. return {"status": "healthy"}
  1318. @app.get("/manifest.json")
  1319. async def serve_manifest():
  1320. """Serve PWA manifest."""
  1321. manifest_file = app_settings.static_dir / "manifest.json"
  1322. if manifest_file.exists():
  1323. return FileResponse(manifest_file, media_type="application/manifest+json")
  1324. return {"error": "Manifest not found"}
  1325. @app.get("/sw.js")
  1326. async def serve_service_worker():
  1327. """Serve service worker."""
  1328. sw_file = app_settings.static_dir / "sw.js"
  1329. if sw_file.exists():
  1330. return FileResponse(sw_file, media_type="application/javascript")
  1331. return {"error": "Service worker not found"}
  1332. # Catch-all route for React Router (must be last)
  1333. @app.get("/{full_path:path}")
  1334. async def serve_spa(full_path: str):
  1335. """Serve React app for client-side routing."""
  1336. # Don't intercept API routes
  1337. if full_path.startswith("api/"):
  1338. return {"error": "Not found"}
  1339. index_file = app_settings.static_dir / "index.html"
  1340. if index_file.exists():
  1341. return FileResponse(index_file)
  1342. return {"error": "Frontend not built"}