execution.py 35 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872873874875876877878879880881882883884885886
  1. """
  2. Firmware-delegated execution: the board runs everything, the host proxies
  3. commands and observes status.
  4. The FluidNC firmware owns kinematics, `.thr` playback, playlist sequencing,
  5. pre-execution clears, quiet hours and auto-home. This module is the host's
  6. entire runtime layer on top of that:
  7. - Commands: each user action is one or a few HTTP calls to the board
  8. ($Sand/Run, $Playlist/Run, /sand_stop, /sand_pause, /sand_resume,
  9. $Playlist/Skip, /sand_feed, /sand_goto).
  10. - Truth: /sand_status is the single source of runtime state. One observer
  11. task polls it, translates it into the frontend's /ws/status contract,
  12. detects edges (file transitions -> play history, Hold -> pause accounting,
  13. clearing -> clear-speed shim, run end -> state reset) and broadcasts.
  14. - Context: the host remembers what run *it* started (RunContext) to fill the
  15. contract fields the board doesn't report (playlist files, run mode).
  16. No sequencing happens on the host. If the board reboots or the backend
  17. restarts mid-run, the observer resynchronizes from /sand_status alone.
  18. """
  19. import asyncio
  20. import logging
  21. import os
  22. import time
  23. from dataclasses import dataclass, field
  24. from typing import Callable, Literal, Optional
  25. from modules.connection import connection_manager
  26. from modules.core.state import state
  27. logger = logging.getLogger(__name__)
  28. # ---------------------------------------------------------------------------
  29. # Board log harvesting (/sand_log)
  30. #
  31. # The board keeps only a small RAM ring buffer (~8 KB) that is lost on reboot.
  32. # The observer periodically pulls it and merges new lines (keyed by the
  33. # "[+<uptime>]" prefix) into a persistent host-side file, so users get table
  34. # history that outlives reboots — same idea as the mobile app's table log.
  35. # ---------------------------------------------------------------------------
  36. BOARD_LOG_FILE = "board_log.txt"
  37. BOARD_LOG_MAX_LINES = 4000
  38. BOARD_LOG_HARVEST_EVERY = 300.0 # seconds
  39. def _log_uptime(line: str) -> Optional[float]:
  40. """'[+1104] [MSG:...]' -> 1104.0; None for lines without the prefix."""
  41. if not line.startswith("[+"):
  42. return None
  43. end = line.find("]")
  44. if end < 2:
  45. return None
  46. try:
  47. return float(line[2:end])
  48. except ValueError:
  49. return None
  50. def merge_board_log(fetched: list[str], last_uptime: float, last_count: int) -> tuple[list[str], float, int, bool]:
  51. """Return (new_lines, new_last_uptime, new_last_count, restarted).
  52. Lines strictly newer than last_uptime are new; at exactly last_uptime we
  53. skip the `last_count` occurrences already stored (the ring can hold several
  54. lines within the same second). A drop in max uptime means the board
  55. rebooted — everything is new again.
  56. """
  57. parsed = [(u, ln) for ln in fetched if ln.strip() and (u := _log_uptime(ln)) is not None]
  58. if not parsed:
  59. return [], last_uptime, last_count, False
  60. max_uptime = max(u for u, _ in parsed)
  61. restarted = max_uptime < last_uptime
  62. if restarted:
  63. last_uptime, last_count = -1.0, 0
  64. new_lines: list[str] = []
  65. seen_at_last = 0
  66. for u, ln in parsed:
  67. if u > last_uptime:
  68. new_lines.append(ln)
  69. elif u == last_uptime:
  70. seen_at_last += 1
  71. if seen_at_last > last_count:
  72. new_lines.append(ln)
  73. new_count = sum(1 for u, _ in parsed if u == max_uptime)
  74. return new_lines, max_uptime, new_count, restarted
  75. # Firmware clear modes; legacy host values are mapped onto them.
  76. CLEAR_MODES = ("none", "adaptive", "in", "out", "sideway", "random")
  77. _LEGACY_CLEAR = {
  78. "clear_from_in": "in",
  79. "clear_from_out": "out",
  80. "clear_sideway": "sideway",
  81. "clear_in": "in",
  82. "clear_out": "out",
  83. }
  84. class ExecutionError(Exception):
  85. """Raised when the board rejects or times out on an execution command."""
  86. @dataclass
  87. class RunContext:
  88. """Host-side knowledge about the run we started (not board truth)."""
  89. kind: Literal["pattern", "playlist"]
  90. playlist_name: Optional[str] = None
  91. files: Optional[list] = None # host paths, unshuffled mirror order
  92. run_mode: str = "single" # frontend value: 'single' | 'indefinite'
  93. shuffle: bool = False
  94. clear_pattern: str = "none"
  95. started_at: float = field(default_factory=time.time)
  96. current_run: Optional[RunContext] = None
  97. def map_clear_mode(value) -> str:
  98. """Map a frontend/legacy clear value onto the firmware's clear modes."""
  99. if not value:
  100. return "none"
  101. value = str(value).lower()
  102. if value in CLEAR_MODES:
  103. return value
  104. if value in _LEGACY_CLEAR:
  105. return _LEGACY_CLEAR[value]
  106. logger.warning(f"Unknown clear mode '{value}', using none")
  107. return "none"
  108. def _state(st: Optional[dict]) -> str:
  109. """Machine state without the GRBL substate suffix ('Hold:0' -> 'Hold')."""
  110. return ((st or {}).get("state") or "").split(":", 1)[0]
  111. def _from_sd_path(sd_path: str) -> Optional[str]:
  112. """Map a board SD path ('/patterns/x.thr', '/sd/patterns/x.thr') to the
  113. host-relative path ('./patterns/x.thr') the frontend/history expect."""
  114. if not sd_path:
  115. return None
  116. p = sd_path.replace("\\", "/")
  117. if p.startswith("/sd/"):
  118. p = p[3:]
  119. if not p.startswith("/"):
  120. p = "/" + p
  121. return "." + p
  122. # ---------------------------------------------------------------------------
  123. # Commands
  124. # ---------------------------------------------------------------------------
  125. def _require_conn():
  126. if not state.conn or not state.conn.is_connected():
  127. raise ExecutionError("Connection not established")
  128. return state.conn
  129. async def _wait_for_idle(timeout: float = 15.0) -> bool:
  130. """Poll the board until it reports Idle (used before idle-gated NVS writes)."""
  131. deadline = time.time() + timeout
  132. while time.time() < deadline:
  133. try:
  134. st = await asyncio.to_thread(state.conn.get_status)
  135. if _state(st) == "Idle" and not st.get("running"):
  136. return True
  137. except Exception as e:
  138. logger.debug(f"Idle wait poll failed: {e}")
  139. await asyncio.sleep(0.5)
  140. return False
  141. async def run_pattern(file_path: str, clear_pattern: str = "none") -> None:
  142. """Run one pattern via $Sand/Run (firmware sequences clear -> pattern and
  143. aborts any current job first)."""
  144. global current_run
  145. conn = _require_conn()
  146. from modules.core.pattern_manager import _ensure_on_board, make_sd_path_resolver
  147. # Prefer a copy already on the board SD over uploading a duplicate.
  148. resolve_sd = make_sd_path_resolver(conn)
  149. sd_path = await asyncio.to_thread(resolve_sd, file_path)
  150. await asyncio.to_thread(_ensure_on_board, file_path, sd_path)
  151. try:
  152. await asyncio.to_thread(conn.set_feed, int(state.speed))
  153. except Exception as e:
  154. logger.warning(f"Could not set feed before run: {e}")
  155. mode = map_clear_mode(clear_pattern)
  156. await asyncio.to_thread(conn.run_pattern, sd_path, mode)
  157. current_run = RunContext(kind="pattern", clear_pattern=mode)
  158. state.current_playlist = None
  159. state.current_playlist_name = None
  160. # Optimistic; the observer confirms/corrects from /sand_status.
  161. state.current_playing_file = file_path
  162. observer.on_run_started()
  163. async def start_playlist(playlist_name: str, run_mode: str = "single",
  164. pause_time: float = 0, clear_pattern: str = "none",
  165. shuffle: bool = False) -> None:
  166. """Run a playlist on the board via $Playlist/Run.
  167. The run options are the firmware's NVS $Playlist/* globals; NVS writes are
  168. idle-gated, so a run-while-running stops the board first.
  169. """
  170. global current_run
  171. conn = _require_conn()
  172. from modules.core import playlist_manager, board_settings
  173. from modules.core.pattern_manager import THETA_RHO_DIR, _ensure_on_board, make_sd_path_resolver
  174. playlist = playlist_manager.get_playlist(playlist_name)
  175. if not playlist:
  176. raise ExecutionError(f"Playlist '{playlist_name}' not found")
  177. files = playlist["files"]
  178. if not files:
  179. raise ExecutionError(f"Playlist '{playlist_name}' is empty")
  180. host_paths = [os.path.join(THETA_RHO_DIR, f) for f in files]
  181. # Idle-gate: NVS settings writes are rejected mid-motion.
  182. st = None
  183. try:
  184. st = await asyncio.to_thread(conn.get_status)
  185. except Exception:
  186. pass
  187. if st and (st.get("running") or _state(st) not in ("Idle", "Alarm")):
  188. await asyncio.to_thread(conn.stop)
  189. if not await _wait_for_idle(15.0):
  190. raise ExecutionError("Table is busy and did not stop in time")
  191. mode = map_clear_mode(clear_pattern)
  192. for key, value in (
  193. ("Playlist/Mode", "loop" if run_mode == "indefinite" else "single"),
  194. ("Playlist/Shuffle", "ON" if shuffle else "OFF"),
  195. ("Playlist/PauseTime", max(0, int(pause_time or 0))),
  196. ("Playlist/ClearPattern", mode),
  197. ):
  198. await asyncio.to_thread(conn.set_setting, key, value)
  199. # The board needs the playlist file before Run; patterns can trail behind
  200. # (each one plays for minutes) except the first, which is ensured now.
  201. # One shared resolver so the playlist lines and the uploads agree on
  202. # paths, and existing board copies are reused instead of duplicated.
  203. resolve_sd = make_sd_path_resolver(conn)
  204. await asyncio.to_thread(
  205. board_settings.mirror_playlist, playlist_name, files, conn, False, resolve_sd)
  206. first_sd = await asyncio.to_thread(resolve_sd, host_paths[0])
  207. await asyncio.to_thread(_ensure_on_board, host_paths[0], first_sd)
  208. def _mirror_rest():
  209. for p in host_paths[1:]:
  210. _ensure_on_board(p, resolve_sd(p))
  211. import threading
  212. threading.Thread(target=_mirror_rest, daemon=True).start()
  213. try:
  214. await asyncio.to_thread(conn.set_feed, int(state.speed))
  215. except Exception as e:
  216. logger.warning(f"Could not set feed before playlist: {e}")
  217. await asyncio.to_thread(conn.run_command, f"$Playlist/Run={playlist_name}")
  218. current_run = RunContext(
  219. kind="playlist", playlist_name=playlist_name, files=host_paths,
  220. run_mode=run_mode, shuffle=shuffle, clear_pattern=mode,
  221. )
  222. state.current_playlist = host_paths
  223. state.current_playlist_name = playlist_name
  224. state.playlist_mode = run_mode
  225. observer.on_run_started()
  226. logger.info(f"Started playlist '{playlist_name}' on the board "
  227. f"(mode={run_mode}, shuffle={shuffle}, pause={pause_time}s, clear={mode})")
  228. async def stop(force: bool = False) -> bool:
  229. """Clean stop. Returns True once the board is Idle (always True for force)."""
  230. try:
  231. conn = _require_conn()
  232. await asyncio.to_thread(conn.stop)
  233. except Exception as e:
  234. if not force:
  235. raise ExecutionError(f"Stop failed: {e}")
  236. logger.warning(f"Force stop: board stop failed ({e}), resetting host state anyway")
  237. if force:
  238. _reset_run_state()
  239. observer.reset()
  240. return True
  241. return await _wait_for_idle(10.0)
  242. async def pause() -> None:
  243. conn = _require_conn()
  244. await asyncio.to_thread(conn.pause)
  245. async def resume() -> None:
  246. conn = _require_conn()
  247. await asyncio.to_thread(conn.resume)
  248. async def skip() -> bool:
  249. """Skip the current pattern: $Playlist/Skip for playlists (also overrides
  250. quiet hours for one pattern); stopping is the 'skip' of a single pattern."""
  251. conn = _require_conn()
  252. st = observer.last_raw or {}
  253. pl = st.get("playlist") or {}
  254. if pl.get("active"):
  255. await asyncio.to_thread(conn.skip)
  256. return True
  257. if st.get("running"):
  258. await asyncio.to_thread(conn.stop)
  259. return True
  260. return False
  261. async def set_speed(speed: float) -> None:
  262. conn = _require_conn()
  263. state.speed = speed
  264. await asyncio.to_thread(conn.set_feed, int(speed))
  265. def _reset_run_state() -> None:
  266. global current_run
  267. current_run = None
  268. state.current_playing_file = None
  269. state.current_playlist = None
  270. state.current_playlist_name = None
  271. state.pause_requested = False
  272. state.pause_time_remaining = 0
  273. state.execution_progress = None
  274. # ---------------------------------------------------------------------------
  275. # Status translation: /sand_status -> the frontend's /ws/status contract
  276. # ---------------------------------------------------------------------------
  277. def _board_health(st: Optional[dict]) -> dict:
  278. """Board health telemetry for the /ws/status payload (firmware API.md).
  279. Prefers the live /sand_status values; falls back to the last-known values
  280. mirrored into state so the UI keeps a reading across a dropped poll. Older
  281. firmware omits these keys — they surface as null.
  282. """
  283. def pick(key: str, attr: str):
  284. if st and key in st:
  285. return st[key]
  286. return getattr(state, attr, None)
  287. return {
  288. "heap": pick("heap", "board_heap"),
  289. "heap_min": pick("heap_min", "board_heap_min"),
  290. "heap_largest": pick("heap_largest", "board_heap_largest"),
  291. "last_reset": pick("last_reset", "board_last_reset"),
  292. "sd_ok": pick("sd_ok", "board_sd_ok"),
  293. "uptime": pick("uptime", "board_uptime"),
  294. }
  295. def translate_status(st: Optional[dict], obs: Optional["BoardObserver"] = None,
  296. now: Optional[float] = None) -> dict:
  297. """Translate a raw board status into the /ws/status data object.
  298. Pure given (st, observer timing, state); unit-testable with fixtures.
  299. """
  300. obs = obs or observer
  301. now = now if now is not None else time.time()
  302. connected = bool(state.conn and state.conn.is_connected())
  303. if st is None:
  304. return {
  305. "connection_status": connected,
  306. "current_file": None,
  307. "is_running": False,
  308. "is_paused": False,
  309. "is_alarm": False,
  310. "is_homing": state.is_homing,
  311. "sensor_homing_failed": state.sensor_homing_failed,
  312. "is_clearing": False,
  313. "speed": state.speed,
  314. "pause_time_remaining": 0,
  315. "original_pause_time": None,
  316. "progress": None,
  317. "playlist": None,
  318. "current_theta": state.current_theta,
  319. "current_rho": state.current_rho,
  320. "firmware_version": state.firmware_version,
  321. "table_type": None,
  322. "health": _board_health(None),
  323. }
  324. pl = st.get("playlist") or {}
  325. running = bool(st.get("running"))
  326. # GRBL states can carry a substate suffix (e.g. "Hold:0", "Door:1").
  327. machine_state = _state(st)
  328. clearing = bool(pl.get("clearing"))
  329. pause_remaining = pl.get("pause_remaining", -1)
  330. pause_total = pl.get("pause_total", -1)
  331. current_file = _from_sd_path(st.get("file")) if running else None
  332. # --- progress ---
  333. progress_obj = None
  334. if running:
  335. fraction = st.get("progress", -1)
  336. fraction = fraction if isinstance(fraction, (int, float)) and fraction >= 0 else 0
  337. elapsed = max(0.0, now - obs.file_started_at - obs.hold_accumulated
  338. - (now - obs.hold_started_at if obs.hold_started_at else 0))
  339. if fraction > 0.02:
  340. remaining = max(0.0, elapsed / fraction - elapsed)
  341. elif obs.cached_history and obs.cached_history.get("actual_time_seconds"):
  342. remaining = max(0.0, obs.cached_history["actual_time_seconds"] - elapsed)
  343. else:
  344. remaining = None
  345. progress_obj = {
  346. "current": int(fraction * 1000),
  347. "total": 1000,
  348. "percentage": round(fraction * 100, 1),
  349. "elapsed_time": elapsed,
  350. "remaining_time": remaining,
  351. }
  352. if obs.cached_history:
  353. progress_obj["last_completed_time"] = obs.cached_history
  354. # --- playlist ---
  355. playlist_obj = None
  356. playlist_active = bool(pl.get("active"))
  357. ctx = current_run
  358. if (playlist_active and pl.get("total", 0) > 0) or (ctx and ctx.kind == "playlist"):
  359. files = [f for f in (state.current_playlist or [])]
  360. index = int(pl.get("index", 0) or 0)
  361. total = int(pl.get("total", 0) or 0) or len(files)
  362. shuffled = bool(ctx.shuffle) if ctx else False
  363. next_file = None
  364. if files and not shuffled:
  365. # While clearing, the "next" thing is the pattern the clear precedes.
  366. next_idx = index if clearing else index + 1
  367. if 0 <= next_idx < len(files):
  368. next_file = files[next_idx]
  369. playlist_obj = {
  370. "name": pl.get("name") or (ctx.playlist_name if ctx else None),
  371. "current_index": index,
  372. "total_files": total,
  373. "mode": (ctx.run_mode if ctx else "indefinite"),
  374. "files": files,
  375. "next_file": next_file,
  376. "shuffled": shuffled,
  377. }
  378. return {
  379. "connection_status": connected,
  380. "current_file": current_file,
  381. "is_running": running,
  382. "is_paused": machine_state == "Hold",
  383. "is_alarm": machine_state == "Alarm",
  384. "is_homing": machine_state == "Home" or state.is_homing,
  385. "sensor_homing_failed": state.sensor_homing_failed,
  386. "is_clearing": clearing,
  387. "speed": state.speed,
  388. "pause_time_remaining": pause_remaining if pause_remaining >= 0 else 0,
  389. "original_pause_time": pause_total if pause_total >= 0 else None,
  390. "progress": progress_obj,
  391. "playlist": playlist_obj,
  392. "current_theta": st.get("theta", state.current_theta),
  393. "current_rho": st.get("rho", state.current_rho),
  394. "firmware_version": st.get("fw") or state.firmware_version,
  395. "table_type": None,
  396. "health": _board_health(st),
  397. }
  398. # ---------------------------------------------------------------------------
  399. # Observer: single poll loop — edges, history, shims, broadcast
  400. # ---------------------------------------------------------------------------
  401. class BoardObserver:
  402. """Polls /sand_status and turns transitions into host behavior."""
  403. POLL_ACTIVE = 1.0
  404. POLL_IDLE = 2.0
  405. OFFLINE_GRACE = 3 # consecutive failures before a run is declared over
  406. RECONNECT_EVERY = 15.0 # seconds between reconnect/relocate attempts while offline
  407. def __init__(self):
  408. self.prev: Optional[dict] = None
  409. self.last_raw: Optional[dict] = None
  410. self.last_translated: dict = {}
  411. self.file_started_at: float = 0.0
  412. self.hold_started_at: Optional[float] = None
  413. self.hold_accumulated: float = 0.0
  414. self.last_progress: float = -1.0
  415. self.cached_history: Optional[dict] = None
  416. self._clear_speed_saved: Optional[float] = None
  417. self._was_quiet_wled_off = False
  418. self._fail_count = 0
  419. self._tick = 0
  420. self._last_reconnect = 0.0
  421. self._task: Optional[asyncio.Task] = None
  422. # True while a firmware OTA is in flight: the board's web server is
  423. # single-threaded, so concurrent polls would wedge the flash upload.
  424. self.suspended = False
  425. # Board log harvest cursor (see merge_board_log)
  426. self._log_last_uptime = -1.0
  427. self._log_last_count = 0
  428. self._last_log_harvest = 0.0
  429. self._log_cursor_loaded = False
  430. # Set by main.py to fan out to /ws/status clients (avoids circular import).
  431. self.on_status: Optional[Callable] = None
  432. def reset(self) -> None:
  433. self.prev = None
  434. self.file_started_at = 0.0
  435. self.hold_started_at = None
  436. self.hold_accumulated = 0.0
  437. self.last_progress = -1.0
  438. self.cached_history = None
  439. self._clear_speed_saved = None
  440. def on_run_started(self) -> None:
  441. """Called by the command layer so the first poll attributes time correctly."""
  442. self.file_started_at = time.time()
  443. self.hold_accumulated = 0.0
  444. self.hold_started_at = None
  445. self.last_progress = -1.0
  446. # -- lifecycle ---------------------------------------------------------
  447. def start(self) -> None:
  448. self._task = asyncio.create_task(self._run())
  449. async def astop(self) -> None:
  450. if self._task:
  451. self._task.cancel()
  452. try:
  453. await self._task
  454. except asyncio.CancelledError:
  455. pass
  456. async def _run(self) -> None:
  457. while True:
  458. interval = self.POLL_IDLE
  459. try:
  460. interval = await self._tick_once()
  461. except asyncio.CancelledError:
  462. raise
  463. except Exception as e:
  464. logger.warning(f"Status observer tick failed: {e}")
  465. await asyncio.sleep(interval)
  466. async def _tick_once(self) -> float:
  467. if self.suspended:
  468. return self.POLL_IDLE
  469. st = None
  470. if state.conn and state.conn.is_connected():
  471. try:
  472. st = await asyncio.to_thread(connection_manager.poll_status_once)
  473. except Exception as e:
  474. logger.debug(f"Status poll failed: {e}")
  475. await self.process(st)
  476. if st is None:
  477. await self._maybe_reconnect()
  478. active = bool(st and (st.get("running") or (st.get("playlist") or {}).get("active")
  479. or _state(st) in ("Hold", "Home", "Jog")))
  480. return self.POLL_ACTIVE if active else self.POLL_IDLE
  481. # -- reconnect / DHCP relocate -------------------------------------------
  482. async def _maybe_reconnect(self) -> None:
  483. """While the board is unreachable, periodically retry the saved address
  484. and — when DHCP has moved the board — relocate to the mDNS entry with
  485. the same MAC (fallback: same hostname). Never homes; the board kept its
  486. own position, only its IP changed."""
  487. if state.user_disconnected or state.is_homing or state.board_locked:
  488. return
  489. if state.conn and state.conn.is_connected() and self._fail_count < self.OFFLINE_GRACE:
  490. return
  491. now = time.time()
  492. if now - self._last_reconnect < self.RECONNECT_EVERY:
  493. return
  494. self._last_reconnect = now
  495. try:
  496. await asyncio.to_thread(self._reconnect_sync)
  497. except Exception as e:
  498. logger.debug(f"Reconnect attempt failed: {e}")
  499. def _reconnect_sync(self) -> None:
  500. from modules.connection.fluidnc_client import FluidNCClient
  501. from modules.core.mdns_discovery import discovery
  502. url = connection_manager.board_url()
  503. probe = FluidNCClient(url, api_key=state.board_api_key)
  504. if probe.reachable():
  505. logger.info(f"Board back online at {url} — reconnecting")
  506. state.conn = probe
  507. state.board_locked = False
  508. state.port = url
  509. connection_manager.device_init(False)
  510. return
  511. if probe.locked:
  512. state.board_locked = True
  513. logger.warning(f"Board at {url} now rejects us (401) — password required")
  514. return
  515. # Saved address is dead: look for the same hardware elsewhere on the LAN.
  516. target = None
  517. boards = discovery.get_boards()
  518. if state.board_mac:
  519. target = next((b for b in boards if b.get("mac") == state.board_mac), None)
  520. if target is None and state.board_hostname:
  521. hn = state.board_hostname.lower()
  522. target = next(
  523. (b for b in boards if (b.get("hostname") or "").lower() == hn), None)
  524. if target is None or target["url"] == url:
  525. return
  526. probe = FluidNCClient(target["url"], api_key=state.board_api_key)
  527. if not probe.reachable():
  528. return
  529. logger.info(f"Board moved (DHCP): relocating from {url} to {target['url']} "
  530. f"(matched by {'mac' if state.board_mac else 'hostname'})")
  531. state.board_url = target["url"]
  532. state.port = target["url"]
  533. state.conn = probe
  534. state.board_locked = False
  535. state.save()
  536. connection_manager.device_init(False)
  537. # -- core (sync-friendly for tests; only I/O bits are awaited) ----------
  538. async def process(self, st: Optional[dict], now: Optional[float] = None) -> dict:
  539. """One observation step: edge detection + translation + broadcast."""
  540. now = now if now is not None else time.time()
  541. if st is None:
  542. self._fail_count += 1
  543. if self._fail_count == self.OFFLINE_GRACE and self.prev is not None:
  544. # Board gone: close out the run without claiming completion.
  545. logger.warning("Board unreachable — closing out the observed run")
  546. self._close_file(self.prev, now, aborted=True)
  547. _reset_run_state()
  548. self.reset()
  549. else:
  550. if self._fail_count >= self.OFFLINE_GRACE:
  551. # Just recovered: pull the board log promptly (it may hold the
  552. # reboot/crash story we missed while offline).
  553. self._last_log_harvest = 0.0
  554. self._fail_count = 0
  555. if self.prev is not None and st.get("uptime", 0) < self.prev.get("uptime", 0):
  556. logger.warning("Board rebooted mid-observation — resetting run context")
  557. _reset_run_state()
  558. self.reset()
  559. self._detect_edges(st, now)
  560. self.prev = st
  561. self.last_raw = st
  562. await self._quiet_hours_wled(now)
  563. if (st is not None and state.conn and state.conn.is_connected()
  564. and now - self._last_log_harvest > BOARD_LOG_HARVEST_EVERY):
  565. self._last_log_harvest = now
  566. asyncio.ensure_future(asyncio.to_thread(self._harvest_board_log_sync))
  567. self._tick += 1
  568. if self._tick % 30 == 0 and state.conn and state.conn.is_connected():
  569. from modules.core import board_settings
  570. try:
  571. settings_map = await asyncio.to_thread(state.conn.get_settings)
  572. board_settings.adopt_still_sands(settings_map)
  573. board_settings.adopt_auto_home(settings_map)
  574. except Exception as e:
  575. logger.debug(f"Board settings adopt failed: {e}")
  576. # Playlists change rarely and adopting reads every file — slower cadence.
  577. if self._tick % 300 == 0:
  578. asyncio.ensure_future(asyncio.to_thread(board_settings.adopt_board_playlists))
  579. self.last_translated = translate_status(st, self, now)
  580. # Mirror the progress 4-tuple for the MQTT handler, which unpacks it.
  581. prog = self.last_translated.get("progress")
  582. state.execution_progress = (
  583. (prog["current"], prog["total"], prog["remaining_time"], prog["elapsed_time"])
  584. if prog else None
  585. )
  586. if self.on_status:
  587. try:
  588. await self.on_status(self.last_translated)
  589. except Exception as e:
  590. logger.debug(f"Status broadcast failed: {e}")
  591. return self.last_translated
  592. # -- board log harvest ---------------------------------------------------
  593. def _load_log_cursor(self) -> None:
  594. """Recover the merge cursor from the stored file after a backend
  595. restart, so we don't re-append the board's whole ring buffer."""
  596. self._log_cursor_loaded = True
  597. try:
  598. with open(BOARD_LOG_FILE, "r", encoding="utf-8", errors="replace") as f:
  599. tail = f.readlines()[-200:]
  600. except FileNotFoundError:
  601. return
  602. last_uptime, count = -1.0, 0
  603. for line in tail:
  604. # Stored lines look like "2026-07-12 17:00:03 [+1104] [MSG:...]"
  605. idx = line.find("[+")
  606. u = _log_uptime(line[idx:]) if idx >= 0 else None
  607. if u is None:
  608. continue
  609. if u == last_uptime:
  610. count += 1
  611. else:
  612. # Any change (up OR down — the tail may span a board reboot)
  613. # moves the cursor: later lines are newer.
  614. last_uptime, count = u, 1
  615. self._log_last_uptime, self._log_last_count = last_uptime, count
  616. def _harvest_board_log_sync(self) -> None:
  617. try:
  618. if not self._log_cursor_loaded:
  619. self._load_log_cursor()
  620. text = state.conn._get("/sand_log", timeout=5.0).text
  621. new, self._log_last_uptime, self._log_last_count, restarted = merge_board_log(
  622. text.splitlines(), self._log_last_uptime, self._log_last_count)
  623. if not new:
  624. return
  625. now = time.time()
  626. max_uptime = self._log_last_uptime
  627. out = []
  628. if restarted:
  629. out.append(f"--- table restarted ({time.strftime('%Y-%m-%d %H:%M:%S')}) ---")
  630. for ln in new:
  631. # Estimated wall-clock time: now minus how long ago the line was
  632. # logged (per its uptime prefix).
  633. u = _log_uptime(ln) or max_uptime
  634. stamp = time.strftime("%Y-%m-%d %H:%M:%S", time.localtime(now - (max_uptime - u)))
  635. out.append(f"{stamp} {ln}")
  636. try:
  637. with open(BOARD_LOG_FILE, "r", encoding="utf-8", errors="replace") as f:
  638. existing = f.read().splitlines()
  639. except FileNotFoundError:
  640. existing = []
  641. merged = (existing + out)[-BOARD_LOG_MAX_LINES:]
  642. with open(BOARD_LOG_FILE, "w", encoding="utf-8") as f:
  643. f.write("\n".join(merged) + "\n")
  644. except Exception as e:
  645. logger.debug(f"Board log harvest failed: {e}")
  646. def _detect_edges(self, st: dict, now: float) -> None:
  647. prev = self.prev or {}
  648. prev_pl = prev.get("playlist") or {}
  649. pl = st.get("playlist") or {}
  650. prev_file = prev.get("file") or ""
  651. cur_file = st.get("file") or ""
  652. prev_running = bool(prev.get("running"))
  653. running = bool(st.get("running"))
  654. # File end: the file changed while running, or playback stopped.
  655. if prev_running and prev_file and (cur_file != prev_file or not running):
  656. self._close_file(prev, now, aborted=False)
  657. # File start.
  658. if running and cur_file and (not prev_running or cur_file != prev_file):
  659. self.file_started_at = now
  660. self.hold_accumulated = 0.0
  661. self.hold_started_at = None
  662. self.last_progress = -1.0
  663. host_path = _from_sd_path(cur_file)
  664. state.current_playing_file = host_path
  665. self._cache_history(host_path)
  666. self._on_playing_leds()
  667. if running and isinstance(st.get("progress"), (int, float)) and st["progress"] >= 0:
  668. self.last_progress = st["progress"]
  669. # Hold (pause) edges — for pause accounting and the MQTT mirror.
  670. prev_hold = _state(prev) == "Hold"
  671. hold = _state(st) == "Hold"
  672. if hold and not prev_hold:
  673. self.hold_started_at = now
  674. state.pause_requested = True
  675. elif prev_hold and not hold:
  676. if self.hold_started_at:
  677. self.hold_accumulated += now - self.hold_started_at
  678. self.hold_started_at = None
  679. state.pause_requested = False
  680. # Clearing edges — clear-speed shim.
  681. prev_clearing = bool(prev_pl.get("clearing"))
  682. clearing = bool(pl.get("clearing"))
  683. if clearing and not prev_clearing and state.clear_pattern_speed:
  684. self._clear_speed_saved = state.speed
  685. self._set_feed_safe(state.clear_pattern_speed)
  686. elif prev_clearing and not clearing and self._clear_speed_saved:
  687. self._set_feed_safe(self._clear_speed_saved)
  688. self._clear_speed_saved = None
  689. # Run end: nothing running, no active playlist, machine idle.
  690. was_active = prev_running or bool(prev_pl.get("active"))
  691. is_active = running or bool(pl.get("active"))
  692. if was_active and not is_active and _state(st) in ("Idle", "Alarm"):
  693. logger.info("Observed run end on the board")
  694. _reset_run_state()
  695. state.save()
  696. self._on_idle_leds()
  697. def _close_file(self, prev_st: dict, now: float, aborted: bool) -> None:
  698. """Log history for the file that just finished/stopped."""
  699. prev_pl = prev_st.get("playlist") or {}
  700. prev_file = prev_st.get("file") or ""
  701. if not prev_file or prev_pl.get("clearing"):
  702. return # clears are not history-worthy (matches old semantics)
  703. from modules.core.pattern_manager import log_execution_time
  704. hold_extra = (now - self.hold_started_at) if self.hold_started_at else 0.0
  705. actual = max(0.0, now - self.file_started_at - self.hold_accumulated - hold_extra)
  706. completed = (not aborted) and self.last_progress >= 0.98
  707. try:
  708. log_execution_time(
  709. pattern_name=os.path.basename(prev_file),
  710. table_type="fluidnc",
  711. speed=int(state.speed or 0),
  712. actual_time=actual,
  713. total_coordinates=0,
  714. was_completed=completed,
  715. )
  716. except Exception as e:
  717. logger.warning(f"Could not log execution history: {e}")
  718. def _cache_history(self, host_path: Optional[str]) -> None:
  719. self.cached_history = None
  720. if not host_path:
  721. return
  722. try:
  723. from modules.core.pattern_manager import get_last_completed_execution_time
  724. self.cached_history = get_last_completed_execution_time(
  725. os.path.basename(host_path), state.speed)
  726. except Exception as e:
  727. logger.debug(f"History lookup failed: {e}")
  728. def _set_feed_safe(self, mm: float) -> None:
  729. try:
  730. if state.conn:
  731. state.conn.set_feed(int(mm))
  732. except Exception as e:
  733. logger.warning(f"Clear-speed feed change failed: {e}")
  734. def _on_playing_leds(self) -> None:
  735. if state.led_controller and state.led_automation_enabled:
  736. try:
  737. asyncio.get_running_loop().create_task(
  738. state.led_controller.effect_playing_async(None))
  739. except RuntimeError:
  740. pass
  741. def _on_idle_leds(self) -> None:
  742. if state.led_controller and state.led_automation_enabled:
  743. try:
  744. asyncio.get_running_loop().create_task(
  745. state.led_controller.effect_idle_async(None))
  746. except RuntimeError:
  747. pass
  748. async def _quiet_hours_wled(self, now: float) -> None:
  749. """The one surviving host Still Sands behavior: switch WLED off during
  750. quiet hours (the board handles its own ring via $Sands/LedOff)."""
  751. if state.led_provider != "wled" or not state.led_controller:
  752. return
  753. from modules.core.pattern_manager import is_in_scheduled_pause_period
  754. in_quiet = bool(state.scheduled_pause_control_wled and is_in_scheduled_pause_period())
  755. if in_quiet and not self._was_quiet_wled_off:
  756. self._was_quiet_wled_off = True
  757. await state.led_controller.set_power_async(0)
  758. logger.info("Still Sands: WLED off")
  759. elif not in_quiet and self._was_quiet_wled_off:
  760. self._was_quiet_wled_off = False
  761. await state.led_controller.set_power_async(1)
  762. await state.led_controller.effect_idle_async(None)
  763. logger.info("Still Sands: WLED restored")
  764. observer = BoardObserver()
  765. def get_cached_status() -> dict:
  766. """Last translated status (what /ws/status clients get on connect)."""
  767. if observer.last_translated:
  768. return observer.last_translated
  769. return translate_status(observer.last_raw, observer)