"""Diagnostics engine: parsed log lines -> findings, milestones, LED, verdict. Line-level knowledge lives in rules.toml. This module adds what a single line cannot express: * boot tracking (ROM banner, reset reason, uptime drops when the banner was missed) and classification of why the previous boot ended; * the status-LED model (Status::set_status / set_status_conditional); * crash capture (panic / ESP_ERROR_CHECK output); * root-cause grouping via `explained_by` chains. Findings are session-wide (a reboot loop must keep its cause visible); milestones and the LED are per boot. """ from __future__ import annotations import re import tomllib from collections import Counter, deque from dataclasses import dataclass, field from enum import IntEnum from pathlib import Path from ..core.logline import LineKind, LogLine from .firmware import FirmwareInfo RULES_PATH = Path(__file__).with_name("rules.toml") class Severity(IntEnum): IGNORE = -1 INFO = 1 WARNING = 2 ERROR = 3 CRITICAL = 4 @property def label(self) -> str: return self.name.capitalize() # name -> (label, swatch colour) LED = { "UNKNOWN": ("Unknown", "#888888"), "OFF": ("Off", "#444444"), "GREEN": ("Green", "#2e9e44"), "PURPLE": ("Purple", "#8e44ad"), "RED": ("Red", "#d64541"), "BLUE": ("Blue", "#2f6fd6"), "YELLOW": ("Yellow", "#e6c229"), "ORANGE": ("Orange", "#f08c1a"), "WHITE": ("White", "#f4f4f4"), } # (id, label, optional) - optional milestones are listed only once reached. MILESTONES = [ ("rom_boot", "Board booted", False), ("app_started", "Firmware started", False), ("sd_mounted", "SD card mounted", False), ("env_loaded", "ENV.TXT read (InfluxDB settings)", False), ("matter_started", "Matter started", True), ("matter_commissioned", "Paired in Matter", True), ("local_wifi_mode", "Local Wi-Fi mode (SSID from SD card)", True), ("sensors_ready", "All sensors started", False), ("wifi_connected", "Connected to Wi-Fi", False), ("time_synced", "Clock set from the Internet", False), ("data_uploaded", "Data uploaded to InfluxDB", False), ("ota_registered", "Registered for firmware updates", False), ("ota_checked", "Checked for firmware updates", False), ("ota_update_started", "Firmware update started", True), ("ota_update_done", "Firmware update installed", True), ("ota_update_accepted", "Updated firmware accepted", True), ] # Findings that stop start-up; a crash/reboot right after them is their effect. _INIT_FAILURES = [ "rtc.init_failed", "sensor.init_failed", "sd.card_fail", "sd.mount_fail", "sd.env_open_fail", "influx.env_missing", "influx.init_fail", ] _NETWORK_ROOTS = [ "influx.buffer_fail", "ota.check_failed", "net.dns_fail", "matter.not_commissioned", "wifi.disconnected", ] _RESET_BY_TOOL_WINDOW_S = 5.0 _SHORT_BOOT_MS = 60_000 class _Fmt(dict): def __missing__(self, key: str) -> str: return "?" def _fmt(s: str, groups: dict[str, str]) -> str: return s.format_map(_Fmt(groups)) if s else s @dataclass(frozen=True) class Rule: id: str pattern: re.Pattern[str] severity: Severity title: str = "" meaning: str = "" actions: tuple[str, ...] = () explained_by: tuple[str, ...] = () milestone: str | None = None clears: tuple[str, ...] = () led: str | None = None led_from: str | None = None split_by: str | None = None min_count: int = 1 min_uptime_ms: int = 0 def load_rules(path: Path = RULES_PATH) -> list[Rule]: data = tomllib.loads(path.read_text(encoding="utf-8")) rules = [] for r in data["rule"]: rules.append(Rule( id=r["id"], pattern=re.compile(r["pattern"]), severity=Severity[r["severity"].upper()], title=r.get("title", ""), meaning=r.get("meaning", ""), actions=tuple(r.get("actions", ())), explained_by=tuple(r.get("explained_by", ())), milestone=r.get("milestone"), clears=tuple(r.get("clears", ())), led=r.get("led"), led_from=r.get("led_from"), split_by=r.get("split_by"), min_count=int(r.get("min_count", 1)), min_uptime_ms=int(r.get("min_uptime_ms", 0)), )) _validate(rules) return rules def _validate(rules: list[Rule]) -> None: ids = [r.id for r in rules] dupes = [i for i, n in Counter(ids).items() if n > 1] if dupes: raise ValueError(f"duplicate rule ids: {dupes}") known = set(ids) for r in rules: for ref in (*r.explained_by, *r.clears): if ref not in known: raise ValueError(f"{r.id}: unknown rule id {ref!r}") for colour in (r.led, r.led_from): if colour and colour not in LED: raise ValueError(f"{r.id}: unknown LED colour {colour!r}") if r.severity != Severity.IGNORE and not r.title: raise ValueError(f"{r.id}: visible rule needs a title") @dataclass class Finding: key: str # rule id, or "rule id:split value" rule_id: str severity: Severity title: str meaning: str actions: tuple[str, ...] explained_by: tuple[str, ...] = () min_count: int = 1 count: int = 0 first_uptime_ms: int | None = None last_uptime_ms: int | None = None last_seen: float = 0.0 boot: int = 0 resolved: bool = False resolved_by: str | None = None evidence: deque[str] = field(default_factory=lambda: deque(maxlen=3)) @property def active(self) -> bool: return self.count >= self.min_count and not self.resolved @dataclass class BootRecord: index: int host_time: float explicit: bool # ROM banner seen (vs. inferred) reset_reason: str | None = None tool_reset: bool = False last_uptime_ms: int = 0 saw_log: bool = False led_at_end: str | None = None panic_lines: list[str] = field(default_factory=list) recent_errors: deque[str] = field(default_factory=lambda: deque(maxlen=5)) intentional_restart: bool = False # factory reset / setup-mode toggle @dataclass class RootCause: finding: Finding consequences: list[Finding] @property def severity(self) -> Severity: return max([self.finding.severity, *(c.severity for c in self.consequences)]) @dataclass class Report: verdict: str verdict_severity: Severity | None # None = healthy / nothing found led: str led_reason: str firmware: FirmwareInfo milestones: list[tuple[str, str, int | None]] # (id, label, uptime_ms) roots: list[RootCause] earlier: list[Finding] # seen only in previous boots resolved: list[Finding] boots: list[BootRecord] lines: int mid_run: bool # no boot seen yet technician: list[str] = field(default_factory=list) # guided-check answers def to_text(self) -> str: out = [f"VERDICT: {self.verdict}", f"Expected status LED: {LED[self.led][0]}" + (f" (last change: {self.led_reason})" if self.led_reason else ""), f"Firmware: {self.firmware.describe()}", f"Boots seen: {max(len(self.boots) - (0 if self.boots and self.boots[0].explicit else 1), 0)}", "", "Milestones (current boot):"] for _, label, t in self.milestones: out.append(f" [{'x' if t is not None else ' '}] {label}" + (f" @ {t / 1000:.1f} s" if t is not None else "")) out.append("") out.append("Findings:" if self.roots else "Findings: none") for rc in self.roots: out += _finding_text(rc.finding, " ") for c in rc.consequences: out.append(" consequence:") out += _finding_text(c, " ") if self.earlier: out.append("") out.append("Seen in earlier boots only:") for f in self.earlier: out.append(f" - [{f.severity.label}] {f.title} (x{f.count})") if self.resolved: out.append("") out.append("Resolved during this session:") for f in self.resolved: out.append(f" - {f.title}" + (f" (by: {f.resolved_by})" if f.resolved_by else "")) if self.technician: out.append("") out.append("Technician checks:") out += [f" - {t}" for t in self.technician] return "\n".join(out) def _finding_text(f: Finding, ind: str) -> list[str]: lines = [f"{ind}- [{f.severity.label}] {f.title} (x{f.count})", f"{ind} {f.meaning}"] lines += [f"{ind} {i}. {a}" for i, a in enumerate(f.actions, 1)] if f.evidence: lines.append(f"{ind} log: {f.evidence[-1]}") return lines class DiagnosticsEngine: def __init__(self, rules: list[Rule] | None = None): self.rules = rules if rules is not None else load_rules() self._rule_by_id = {r.id: r for r in self.rules} self.reset() # ---------------------------------------------------------------- API def reset(self) -> None: self.findings: dict[str, Finding] = {} self.boots: list[BootRecord] = [BootRecord(0, 0.0, explicit=False)] self.milestones: dict[str, int] = {} self.led = "UNKNOWN" self.led_reason = "" self.firmware = FirmwareInfo() self.lines = 0 self._tool_reset_at: float | None = None self._panic_tail = 0 # RAW lines after a panic line to keep self.technician: list[str] = [] @property def boot(self) -> BootRecord: return self.boots[-1] def feed(self, line: LogLine) -> None: self.lines += 1 text = line.text if line.kind == LineKind.HOST: if "reset issued by tool" in text: self._tool_reset_at = line.host_time return if line.kind == LineKind.BOOT: self._new_boot(line.host_time, explicit=True) self.milestones["rom_boot"] = 0 return if line.kind == LineKind.RESET: self.boot.reset_reason = line.reset_reason if line.reset_reason and "POWERON" in line.reset_reason: self.led, self.led_reason = "OFF", "power-on - firmware not started yet" return if line.kind == LineKind.LOG and line.uptime_ms is not None: b = self.boot # Uptime jumped back to a fresh-boot value: the ROM banner was # missed (port reconnect, capture started late). if b.saw_log and line.uptime_ms + 3000 < b.last_uptime_ms and line.uptime_ms < 10_000: self._new_boot(line.host_time, explicit=False) b = self.boot b.saw_log = True b.last_uptime_ms = max(b.last_uptime_ms, line.uptime_ms) if line.kind == LineKind.PANIC: self._on_panic(line) elif self._panic_tail and line.kind == LineKind.RAW: self.boot.panic_lines.append(text) self._panic_tail -= 1 self._crash_finding().evidence.append(text) self.firmware.observe(text) matched = False for rule in self.rules: m = rule.pattern.search(text) if not m: continue matched = True if rule.min_uptime_ms and (line.uptime_ms or 0) < rule.min_uptime_ms: continue groups = {k: v for k, v in m.groupdict().items() if v is not None} if rule.milestone and rule.milestone not in self.milestones: self.milestones[rule.milestone] = line.uptime_ms or 0 if rule.led: self._set_led(rule.led, rule.led_from, text) for cid in rule.clears: for f in self.findings.values(): if f.rule_id == cid and not f.resolved: f.resolved = True f.resolved_by = rule.milestone or rule.id if rule.id in ("sys.factory_reset",) or "Short press:" in text: self.boot.intentional_restart = True if rule.severity != Severity.IGNORE: self._hit(rule, groups, line) self._stateful(line) if line.level == "E": self.boot.recent_errors.append(text) if not matched and line.tag: self._hit_other(line) def report(self) -> Report: all_f = list(self.findings.values()) + self._reboot_findings() cur = self.boot.index active = [f for f in all_f if f.active] current = [f for f in active if f.boot == cur] earlier = [f for f in active if f not in current] resolved = [f for f in all_f if f.resolved and f.count >= f.min_count] roots = _group(current) # Worst consequence first, then the root's own severity, then order seen. roots.sort(key=lambda rc: (-rc.severity, -rc.finding.severity, rc.finding.first_uptime_ms or 0)) mid_run = not any(b.explicit for b in self.boots) and self.boot.index == 0 if self.lines == 0: verdict, vsev = "Waiting for data from the sensorbox...", None elif roots and roots[0].severity >= Severity.WARNING: vsev = roots[0].severity prefix = "Problem" if vsev >= Severity.ERROR else "Attention" verdict = f"{prefix}: {roots[0].finding.title}" elif "data_uploaded" in self.milestones: verdict, vsev = "Healthy: data is reaching InfluxDB", None else: verdict, vsev = "No problems found so far", None if mid_run and self.lines: verdict += " (connected mid-run - press Reset & capture for a full check)" ms = [(mid, label, self.milestones.get(mid)) for mid, label, optional in MILESTONES if not optional or mid in self.milestones] # Reached milestones in the order they happened, then the pending ones. ms.sort(key=lambda m: (m[2] is None, m[2] or 0)) return Report(verdict, vsev, self.led, self.led_reason, self.firmware, ms, roots, earlier, resolved, list(self.boots), self.lines, mid_run, list(self.technician)) def add_confirmed(self, key: str, severity: Severity, title: str, meaning: str, actions: tuple[str, ...]) -> Finding: """A finding established by a guided check (technician answer + log).""" f = self.findings.get(key) if f is None: f = self.findings[key] = Finding(key, key, severity, title, meaning, tuple(actions)) f.count += 1 f.boot = self.boot.index f.resolved = False f.evidence.append("confirmed by the technician during a guided check") return f def note_technician(self, text: str) -> None: self.technician.append(text) # ------------------------------------------------------------ internals def _new_boot(self, host_time: float, explicit: bool) -> None: prev = self.boot # An inferred boot right after a banner-started boot is the same boot. if not explicit and prev.explicit and not prev.saw_log: return prev.led_at_end = self.led b = BootRecord(prev.index + 1, host_time, explicit) if self._tool_reset_at is not None and host_time - self._tool_reset_at <= _RESET_BY_TOOL_WINDOW_S: b.tool_reset = True self._tool_reset_at = None self.boots.append(b) self.milestones = {} # The WS2812 latches its colour through a software reset until # Status::init() rewrites it; only a power-on turns it dark. self.led_reason = "restarting - LED keeps its last colour until the firmware starts" self.firmware = FirmwareInfo() self._panic_tail = 0 def _set_led(self, colour: str, led_from: str | None, text: str) -> None: if led_from and self.led != led_from: return self.led = colour self.led_reason = text def _hit(self, rule: Rule, groups: dict[str, str], line: LogLine) -> None: key = rule.id if rule.split_by and rule.split_by in groups: key = f"{rule.id}:{groups[rule.split_by]}" f = self.findings.get(key) if f is None: f = self.findings[key] = Finding( key, rule.id, rule.severity, _fmt(rule.title, groups), _fmt(rule.meaning, groups), tuple(_fmt(a, groups) for a in rule.actions), rule.explained_by, rule.min_count) self._touch(f, line) def _touch(self, f: Finding, line: LogLine) -> None: f.count += 1 # Uptime restarts every boot, so "first seen" is per current boot. if f.first_uptime_ms is None or f.boot != self.boot.index: f.first_uptime_ms = line.uptime_ms f.last_uptime_ms = line.uptime_ms f.last_seen = line.host_time f.boot = self.boot.index f.evidence.append(line.text) if f.resolved: f.resolved, f.resolved_by = False, None # problem came back def _custom(self, key: str, severity: Severity, title: str, meaning: str, actions: tuple[str, ...], explained_by: tuple[str, ...] = ()) -> Finding: f = self.findings.get(key) if f is None: f = self.findings[key] = Finding(key, key, severity, title, meaning, actions, explained_by) return f def _hit_other(self, line: LogLine) -> None: f = self._custom( f"other.{line.tag}", Severity.INFO, f"Unrecognised error messages from {line.tag}", "These errors are not in the rule set yet; they may be harmless.", ("If the box misbehaves, save the session log and send it to the firmware team.",)) self._touch(f, line) def _crash_finding(self) -> Finding: return self._custom( "sys.crash", Severity.CRITICAL, "Firmware stopped with an error and restarts", "The firmware hit a fatal error. The error printed just before it is the real cause.", ("See the grouped cause; otherwise save the session log for the firmware team.",), tuple(_INIT_FAILURES)) def _on_panic(self, line: LogLine) -> None: b = self.boot if len(b.panic_lines) < 8: b.panic_lines.append(line.text) self._panic_tail = 4 # file/func/expression lines follow ESP_ERROR_CHECK f = self._crash_finding() if f.count == 0 and b.recent_errors: f.meaning += f" Last error before it: {b.recent_errors[-1]}" self._touch(f, line) def _stateful(self, line: LogLine) -> None: # RTC set by SNTP but reads "uninitialized" again later: the chip # does not keep time (crystal/module fault), not just a flat cell. synced = self.milestones.get("time_synced") if (synced is not None and line.uptime_ms is not None and line.uptime_ms > synced + 10_000 and "RTC is uninitialized" in line.text): f = self._custom( "rtc.lost_after_sync", Severity.ERROR, "Clock stops again after being set from the Internet", "The clock was set from the Internet but stopped running shortly after. The RTC module or its crystal is faulty.", ("Replace the RTC module (inside the case).",)) self._touch(f, line) def _reboot_findings(self) -> list[Finding]: """Classify why each earlier boot ended (needs the next boot's reset reason).""" out: list[Finding] = [] short_unexpected: list[BootRecord] = [] for prev, nxt in zip(self.boots, self.boots[1:]): if not prev.saw_log and prev.index == 0: continue # nothing captured before the first boot reason = nxt.reset_reason or "unknown" if nxt.tool_reset or prev.intentional_restart: continue key, sev, title, meaning, actions, expl = None, Severity.INFO, "", "", (), () if "USB_UART_CHIP_RESET" in reason: key, title = "reboot.usb", "Box was reset over USB" meaning = "The board was reset through its USB port (a flashing tool, a serial program, or this tool in an earlier session)." elif "POWERON" in reason: key, title = "reboot.power", "Box was switched off and on" meaning = "Power was interrupted (power switch, cable or supply)." actions = ("If nobody switched it off: check the power supply and cable.",) elif "BROWN" in reason: key, sev, title = "reboot.brownout", Severity.ERROR, "Power supply voltage dropped (brown-out)" meaning = "The supply voltage fell too low and the chip reset itself." actions = ("Check the power supply, cable and connectors.",) elif "WDT" in reason: key, sev, title = "reboot.watchdog", Severity.ERROR, "Firmware froze and was restarted by the watchdog" meaning = "The firmware stopped responding; the hardware watchdog restarted it." actions = ("Save the session log for the firmware team.",) elif prev.panic_lines: pass # covered by sys.crash elif prev.led_at_end in ("PURPLE", "RED") and prev.last_uptime_ms >= 140_000: key, title = "reboot.status_watchdog", "Box restarted itself after 2.5 minutes of errors" meaning = "By design the firmware restarts when it stays in an error state (purple/red) for 150 s." actions = ("Fix the grouped cause; the restarts stop by themselves.",) expl = tuple(_NETWORK_ROOTS) + ("sys.out_of_resources",) else: key, sev, title = "reboot.unexpected", Severity.WARNING, "Unexpected restart" meaning = f"The firmware restarted (reset reason {reason})." actions = ("Watch whether it repeats; save the session log for the firmware team.",) if key: out.append(self._reboot_finding(key, sev, title, meaning, actions, expl, nxt)) if prev.last_uptime_ms < _SHORT_BOOT_MS and "POWERON" not in reason: short_unexpected.append(prev) if len(short_unexpected) >= 2: avg = sum(b.last_uptime_ms for b in short_unexpected) / len(short_unexpected) / 1000 f = self._reboot_finding( "reboot.loop", Severity.CRITICAL, "Reboot loop", f"The box restarted {len(short_unexpected)} times, about every {avg:.0f} s. " "The error printed just before each restart is the cause.", ("Fix the grouped cause below.",), tuple(_INIT_FAILURES), self.boot) f.count = len(short_unexpected) out.append(f) return out def _reboot_finding(self, key, sev, title, meaning, actions, expl, boot: BootRecord) -> Finding: f = Finding(key, key, sev, title, meaning, actions, expl) f.count, f.boot, f.last_seen = 1, self.boot.index, boot.host_time if boot.reset_reason: f.evidence.append(f"reset reason: {boot.reset_reason}") return f def _group(findings: list[Finding]) -> list[RootCause]: """Attach each finding to the root of its explained_by chain.""" by_rule: dict[str, list[Finding]] = {} for f in findings: by_rule.setdefault(f.rule_id, []).append(f) def parent(f: Finding) -> Finding | None: for rid in f.explained_by: if by_rule.get(rid): return by_rule[rid][0] return None def root(f: Finding) -> Finding: seen = {f.key} while (p := parent(f)) is not None and p.key not in seen: seen.add(p.key) f = p return f roots: dict[str, RootCause] = {} for f in findings: r = root(f) rc = roots.setdefault(r.key, RootCause(r, [])) if r is not f: rc.consequences.append(f) for rc in roots.values(): rc.consequences.sort(key=lambda c: (-c.severity, c.first_uptime_ms or 0)) return list(roots.values())