master
John Lauer Update 40 file(s) 9334d49 2mo ago
"""Capture KiCad's own diagnostics, and read the new lines since last time.

WHY THIS EXISTS
---------------
KiCad writes NO log file. Ever. Its diagnostics go through wxLogTrace /
wxLogError to **stderr**, and on Windows a GUI process has no console, so stderr
goes to the void unless whoever launched it supplies a handle. This bridge
launches KiCad, and until now it launched it with:

    subprocess.Popen(..., stdout=DEVNULL, stderr=DEVNULL)

i.e. it was actively throwing away the only channel KiCad has for telling us what
went wrong. That is why a failed board load could only be discovered by
screenshotting a modal dialog and reading the pixels.

Two switches are needed and both are ours to set at launch:
  * KICAD_ENABLE_WXTRACE=1 — in a RELEASE build wx logging is off; KiCad turns it
    on only when this is set (common/single_top.cpp:202, kicad/kicad.cpp:579).
  * WXTRACE=<masks> — wxWidgets' own selector for WHICH trace masks print.
    KiCad's masks are named things like KICAD_LIBRARIES, KICAD_ENV_VARS. Errors
    and warnings (wxLogError/wxLogWarning) do NOT need a mask: they print once
    logging is enabled at all, which is the 90% case for us.

The log is per-launch, under the bridge's own state dir, and callers read it with
`kicad_log_tail`, which returns only what is NEW since a byte offset the caller
carries. That makes the natural loop cheap: tail, act, tail again, and the second
tail is exactly the consequences of your action.

WHAT THIS IS NOT: it is not a replacement for a verb's own error contract. A verb
that fails must still say so. This is the channel for what KiCad says about
ITSELF, which no verb can otherwise see.
"""

from __future__ import annotations

import os
import re
import time
from pathlib import Path

# One directory, one file per launch, newest wins. Kept beside the bridge's other
# state so an uninstall sweeps it up.
_LOG_DIR_NAME = "kicad-logs"
_KEEP_LOGS = 10


def log_dir() -> Path:
    base = Path(os.environ.get("LOCALAPPDATA") or Path.home() / ".local/share")
    d = base / "Adom Bridge" / _LOG_DIR_NAME
    d.mkdir(parents=True, exist_ok=True)
    return d


def new_log_path(tag: str = "kicad") -> Path:
    """A fresh per-launch log file, and prune old ones so this never grows without
    bound on a machine that launches KiCad all day."""
    d = log_dir()
    try:
        olds = sorted(d.glob("*.log"), key=lambda p: p.stat().st_mtime, reverse=True)
        for p in olds[_KEEP_LOGS - 1:]:
            p.unlink(missing_ok=True)
    except OSError:
        pass
    safe = re.sub(r"[^A-Za-z0-9_.-]+", "-", tag)[:40] or "kicad"
    return d / f"{time.strftime('%Y%m%d-%H%M%S')}-{safe}.log"


def latest_log() -> Path | None:
    try:
        logs = sorted(log_dir().glob("*.log"), key=lambda p: p.stat().st_mtime, reverse=True)
        return logs[0] if logs else None
    except OSError:
        return None


def trace_env(masks: str | None = None) -> dict:
    """Environment additions that make KiCad actually say something.

    Pass masks (comma-separated wx trace masks) only when you want the firehose;
    errors and warnings arrive without any mask once logging is enabled."""
    env = dict(os.environ)
    env["KICAD_ENABLE_WXTRACE"] = "1"
    if masks:
        env["WXTRACE"] = masks
    return env


_LEVEL = re.compile(r"^\s*(?P<lvl>Error|Warning|Trace|Info|Debug|Fatal)\b[: ]", re.I)


def _classify(line: str) -> str:
    m = _LEVEL.match(line)
    if m:
        return m.group("lvl").lower()
    low = line.lower()
    if "error" in low or "failed" in low or "cannot" in low or "unable to" in low:
        return "error"
    if "warning" in low or "deprecat" in low:
        return "warning"
    return "info"


def handle_log_tail(kicad_info: dict, args: dict) -> dict:
    """New KiCad log output since a byte offset (read-only).

    Args:
      sinceOffset  byte offset from a previous call (default 0 = whole file)
      maxBytes     cap on returned text (default 200000, newest kept)
      errorsOnly   true -> only lines classified error/warning
      path         explicit log file; default = the newest launch log
    """
    p = Path(args["path"]) if args.get("path") else latest_log()
    if not p or not p.exists():
        return {"success": True, "available": False, "lines": [], "nextOffset": 0,
                "_hint": ("No KiCad log yet. Logs exist only for KiCad instances THIS bridge "
                          "launched after 0.9.266 — a KiCad the user started themselves writes "
                          "nothing, because its stderr belongs to whoever launched it.")}
    since = int(args.get("sinceOffset") or 0)
    max_bytes = int(args.get("maxBytes") or 200_000)
    size = p.stat().st_size
    if since > size:  # file rotated/truncated under us
        since = 0
    with open(p, "rb") as f:
        f.seek(since)
        blob = f.read()
    truncated = len(blob) > max_bytes
    if truncated:
        blob = blob[-max_bytes:]
    text = blob.decode("utf-8", errors="replace")
    lines = [ln for ln in text.splitlines() if ln.strip()]
    classified = [{"level": _classify(ln), "text": ln} for ln in lines]
    if args.get("errorsOnly"):
        classified = [c for c in classified if c["level"] in ("error", "warning", "fatal")]
    counts: dict[str, int] = {}
    for c in classified:
        counts[c["level"]] = counts.get(c["level"], 0) + 1
    return {"success": True, "available": True, "logPath": str(p),
            "sinceOffset": since, "nextOffset": size, "truncated": truncated,
            "lineCount": len(classified), "levels": counts, "lines": classified,
            "_hint": ("Carry nextOffset into the next call and you get ONLY what happened "
                      "since — tail, act, tail again, and the second read is your action's "
                      "consequences. errorsOnly:true filters to error/warning.")}


# ---------------------------------------------------------------------------
# THE ERROR CHANNEL THAT ACTUALLY WORKS: KiCad's own dialogs.
#
# Measured on ConfRoomROG, KiCad 10.0, 2026-09-01. A board that fails to parse
# produces a "KiCad PCB Editor Error" window carrying the exact reason:
#
#   Error loading PCB '...demo-project.kicad_pcb'.
#   Expecting thru_hole, smd, connect, or np_thru_hole
#
# ...and the captured stderr log for that same launch was ZERO BYTES. That is
# not a bug in the capture: wxWidgets in a GUI app installs wxLogGui as the
# active log target, so wxLogError becomes a MESSAGE BOX, not a line on stderr.
# KICAD_ENABLE_WXTRACE turns logging on but does not redirect it to a console
# that a windowed process does not have.
#
# So: the dialogs ARE the log. This function reads them without screenshots,
# without OCR, and without touching the foreground - it is pure win32 text
# harvesting (EnumWindows + WM_GETTEXT), which is read-only by construction.
#
# stderr capture stays (kicad_log_tail) because it still catches the things that
# BYPASS wxLog: crashes, asserts, and anything printed with stdio. It is the
# second channel, not the first.

_ERR_TITLE = re.compile(r"\b(error|warning|problem|failed|cannot)\b", re.I)


def _enum_dialog_text(hwnd: int) -> list[str]:
    """Every static/text child of a window, in z-order. wx dialogs put the
    message in one or more Static controls."""
    import ctypes
    from ctypes import wintypes
    user32 = ctypes.windll.user32
    out: list[str] = []

    @ctypes.WINFUNCTYPE(wintypes.BOOL, wintypes.HWND, wintypes.LPARAM)
    def cb(child, _lp):
        buf = ctypes.create_unicode_buffer(2048)
        user32.GetWindowTextW(child, buf, 2048)
        txt = (buf.value or "").strip()
        cls = ctypes.create_unicode_buffer(256)
        user32.GetClassNameW(child, cls, 256)
        # Accept ANY child that carries text. The original filter listed
        # ("static","wxwindownr","wxstatictext") and returned nothing for a
        # KiCad 10 error, because that dialog is a Windows TASKDIALOG: its text
        # is drawn by DirectUI, in a DirectUIHWND with no per-string child
        # controls, so GetWindowText has nothing to find. UIA can read it,
        # win32 cannot. Keeping the broad filter still captures classic wx
        # dialogs; TaskDialogs fall through to the UIA hand-off below.
        if txt and cls.value.lower() not in ("button",):
            out.append(txt)
        return True

    user32.EnumChildWindows(hwnd, cb, 0)
    return out



def _uia_text(hwnd: int) -> str:
    """Longest Text node in a window's UIA tree, via ab's desktop_ui_tree.

    Best-effort by design: if ab is old, unreachable, or the window died in the
    microseconds since enumeration, return "" and let the caller report the
    dialog without text rather than failing the whole verb."""
    try:
        from handlers import ad_client
        r = ad_client.call("desktop_ui_tree", {"hwnd": int(hwnd), "maxDepth": 8,
                                               "maxNodes": 80}, timeout=8) or {}
    except Exception:  # pylint: disable=broad-except
        return ""
    out = r.get("output") if isinstance(r, dict) else None
    if isinstance(out, str):
        try:
            import json as _j
            out = _j.loads(out)
        except Exception:  # pylint: disable=broad-except
            out = None
    root = ((out or r) or {}).get("root") if isinstance((out or r), dict) else None
    if not root:
        return ""
    texts: list[str] = []

    def walk(n):
        if not isinstance(n, dict):
            return
        if n.get("role") == "Text":
            nm = (n.get("name") or "").strip()
            if nm:
                texts.append(nm)
        for c in n.get("children") or []:
            walk(c)

    walk(root)
    # Skip the icon/instruction placeholders ("MainInstructionIcon") and take the
    # longest real sentence — that is the message every time in KiCad's dialogs.
    texts = [t for t in texts if not t.endswith("Icon")]
    return max(texts, key=len) if texts else ""

def handle_errors(kicad_info: dict, args: dict) -> dict:
    """Every KiCad error/warning dialog currently on screen, with its text.

    Read-only and background: enumerates windows and reads their text. Never
    raises, never clicks, never screenshots. Args: includeAll:true to return
    every KiCad dialog rather than only ones whose title looks like an error."""
    # Window discovery comes from handlers/kicad_windows (AD's desktop_list_windows
    # when reachable, local EnumWindows otherwise). This used to run its own
    # EnumWindows and decide "is this KiCad?" by MATCHING THE TITLE, which is the
    # exact mistake skills/kicad-uia warns about: titles are localised and they
    # lie. Worse, it silently skipped any dialog whose caption does not contain a
    # KiCad word — a bare Win32 "#32770" error box owned by pcbnew.exe never
    # appeared at all. The shared finder decides by OWNING EXECUTABLE.
    from handlers import kicad_windows
    wins: list[dict] = []
    rows = kicad_windows.find(fresh=True)

    for row in rows:
        hwnd, title = row["hwnd"], (row.get("title") or "").strip()
        if not title:
            continue
        if not args.get("includeAll") and not _ERR_TITLE.search(title):
            continue
        texts = _enum_dialog_text(hwnd)
        # the message is the longest static; buttons are short ("OK", "Cancel")
        msg = max(texts, key=len) if texts else ""
        via = "win32"
        if not msg:
            # A Windows TASKDIALOG (KiCad 10 uses these): its text is drawn by
            # DirectUI with no per-string child controls, so GetWindowText finds
            # nothing. UI Automation reads it fine.
            #
            # HARVEST IT NOW, IN THIS CALL. The first cut returned the hwnd and
            # told the caller to run desktop_ui_tree themselves; that is a RACE
            # and it lost — the dialog closed between discovery and the
            # follow-up read, so the reason for the failure was gone. A verb
            # that finds an error must return the error's TEXT, not a promise
            # that the text is obtainable.
            #
            # ab owns UIA (desktop_ui_tree, read-only, no foreground), so we
            # call it rather than reimplementing IUIAutomation in here. That is
            # the same rule win_taskbar.py learned: the bridge owns KiCad, ab
            # owns Windows.
            ui = _uia_text(hwnd)
            if ui:
                msg, via = ui, "uia"
        entry = {"hwnd": hwnd, "title": title, "message": msg,
                 "messageVia": via if msg else None,
                 "allText": texts[:12],
                 "level": "error" if _ERR_TITLE.search(title) else "info"}
        if not msg:
            entry["messageUnavailable"] = "taskdialog_directui_and_uia_unavailable"
            entry["readTextWith"] = (f'desktop_ui_tree {{"hwnd":{hwnd},"maxDepth":8}} '
                                     "— read it IMMEDIATELY; these dialogs are transient")
        wins.append(entry)

    return {"success": True, "count": len(wins), "dialogs": wins,
            "windowSource": kicad_windows.source(),
            "_hint": ("KiCad has NO log file and in GUI mode its errors go to DIALOGS, not "
                      "stderr — so this is where a GUI failure reason lives. Read-only: nothing "
                      "is clicked or raised. THREE channels, use all three: (1) this verb; "
                      "(2) kicad_log_tail for what bypasses wxLog — crashes, asserts, stdio; "
                      "(3) kicad_screenshot_all when the first two say nothing and the result is "
                      "still wrong — the pixels have no preconditions and remain the floor under "
                      "any automation loop. Dismiss with kicad_dismiss_dialogs (which DOES "
                      "foreground, so caption first).")}