Technician tool v0.2

Imported from the Google Drive folder 004-technician_tool/v0.2.

kota_tech/diag/engine.py

@@ -0,0 +1,554 @@
+"""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),
+    ("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
+
+    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 ""))
+        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
+
+    @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)
+
+    # ------------------------------------------------------------ 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())