diff --git a/docs/BRINGUP.md b/docs/BRINGUP.md index ee73865..2b54c40 100644 --- a/docs/BRINGUP.md +++ b/docs/BRINGUP.md @@ -2754,6 +2754,22 @@ motion, cooling, camera, cloud, then the live tests from the page. separately drilled: a Python traceback through the relay — there is no external trigger for that; the relay pipe is the same one the `logger` probes and the wrapper's `exited (137)` line went through. + Acceptance catalog: `logs.tree-tail-export` (list, tail, sanitized + export with the token-leak check), `logs.routing` (one logger + daemon, rendered rules and effective record consistent with + `/logs`, the tree, the daemon's own emitter line, `logger` relay + probes routed by name in the ff_line format, a stray program only + in system/, kernel lines, relay processes, nothing outside the + tree) and `logs.level-settings` (bad level/port/proto/server + refused, a level change configured-not-effective with + `pending_reboot`, restored) — all three PASS on the bench + 2026-08-15 through the real Runner against an isolated results log + (the image's forgetest still carries the older catalog until the + next dev image). Finding from that run, fixed: the sanitized export + took 13.9 s on the target (0.95 s unsanitized) and tripped the hw + client's 10 s default — the export call now has its own timeout + and the sanitizer skips a pattern pass when the line cannot match + it (4x faster on the host; forgectrl 4d19e9d, next image). 15. **Release acceptance tool (forgetest) - CODE-COMPLETE 2026-08-15, host- and build-verified; bench validation pending, ships with the diff --git a/forgetest/forgetest/suite/logs.py b/forgetest/forgetest/suite/logs.py index e601c4e..e48b96e 100644 --- a/forgetest/forgetest/suite/logs.py +++ b/forgetest/forgetest/suite/logs.py @@ -1,9 +1,23 @@ -"""logs.* - unified logging: the log tree, tail, and the sanitized export.""" +"""logs.* - unified logging: the log tree, tail, and the sanitized export; +the routing path (emitters, relays, rendered rules); the level settings.""" import gzip import io +import os +import re import tarfile +import time from ..catalog import test +from .. import hw + + +def _read(path, default=None): + try: + with open(path, "r", encoding="utf-8", errors="replace") as f: + return f.read() + except OSError: + return default + _LOG_COVERS = [("forgectrl", "src/logs.*"), ("forgectrl", "src/fflog.*"), ("forgectrl", "src/sanitize.*"), ("forgectrl", "src/main.c")] @@ -33,8 +47,13 @@ def tree_tail_export(ctx): st, tail = fc.get("/logs/tail", params={"name": "no-such-logger"}) ctx.check(st == 404, "unknown logger -> %s, expected 404", st) - st, data = fc.post("/logs/export", raw=True) - ctx.log("POST /logs/export -> %s (%d bytes)", st, len(data) if data else 0) + # the sanitizer walks every log file; a full tree takes tens of + # seconds on the target, so this call gets its own client timeout + slow = hw.Forgectrl(token=fc.token, timeout=300.0) + t0 = time.time() + st, data = slow.post("/logs/export", raw=True) + ev["export_s"] = round(time.time() - t0, 1) + ctx.log("POST /logs/export -> %s (%d bytes, %.1f s)", st, len(data) if data else 0, ev["export_s"]) ctx.check(st == 200, "POST /logs/export -> %s", st) ev["export_bytes"] = len(data) try: @@ -57,3 +76,226 @@ def tree_tail_export(ctx): leaked.append(m.name) ev["token_leaks"] = leaked ctx.check(not leaked, "the sanitized bundle contains the panel token: %s", leaked) + + +# The routing test proves the whole path every logger takes: emitter (or +# relay) -> /dev/log -> rsyslog rules rendered from the settings -> the +# logger's own file in the ff_line format. It stands for the emitters in +# every component (fflog in forgectrl and grblHAL, the SysLogHandler in the +# Python apps), the supervisor's per-controller relay, the daemon's fifo +# relay in its init script, and the render step. +_ROUTING_COVERS = [("forgectrl", "src/logs.*"), ("forgectrl", "src/fflog.*"), ("forgectrl", "src/super.c"), + ("forgectrl", "init/**"), + ("grblhal-glowforge", "src/fflog.*"), ("grblhal-glowforge", "src/main.c"), + ("forgefirm-app", "forgefirm-app/ffmachine.py"), ("forgefirm-app", "forgefirm-app/gfcloud.py"), + ("forgefirm-app", "forgefirm-app/gfhome.py")] + +LOGS_ROOT = "/data/log/forgefirm" +LOGGERS = ("forgectrl", "grblhal", "gfcloud", "gfhome", "kernel", "system") +_LINE_RE = re.compile(r"^\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d(\.\d+)?[+-]\d\d:\d\d (?P[A-Za-z0-9_.-]+)\[(?P[-\d]+)\] " + r"(?PEMERG|ALERT|CRIT|ERR|WARNING|NOTICE|INFO|DEBUG) (?P.*)$") +_SEV_RANK = {"off": -1, "error": 3, "warning": 4, "notice": 5, "info": 6, "debug": 7} + + +def _tail_lines(path, n=400): + try: + with open(path, "rb") as f: + f.seek(0, 2) + size = f.tell() + f.seek(max(0, size - 256 * 1024)) + data = f.read() + except OSError: + return [] + return data.decode("utf-8", "replace").splitlines()[-n:] + + +def _wait_line(path, needle, timeout=6.0): + """Poll a log file for a line containing needle; the matched line or None.""" + deadline = time.time() + timeout + while time.time() < deadline: + for line in _tail_lines(path, 200): + if needle in line: + return line + time.sleep(0.25) + return None + + +@test("logs.routing", title="Log routing, relays, and the rendered rules", subsystem="logs", + kind="auto", est_min=1, + covers=_ROUTING_COVERS, requires=["logs.tree-tail-export"], + description="rsyslog is the only logger (no busybox syslogd/klogd), the rules rendered from " + "the settings and the effective-levels record exist and agree with /logs, every " + "logger has its directory, the daemon's own emitter and the per-controller " + "`logger` relay both land in the right file in the ff_line format, a stray " + "program's line goes to system/ and nowhere else, kernel lines reach kernel/, " + "and nothing of ours is written outside the tree.") +def routing(ctx): + fc = ctx.forgectrl + ev = ctx.evidence + + # 1. one logger daemon + rs = hw.pidof("rsyslogd") + ev["rsyslogd_pids"] = rs + ctx.check(rs, "rsyslogd is not running") + for legacy in ("syslogd", "klogd"): + pids = hw.pidof(legacy) + ctx.check(not pids, "busybox %s is running (%s) next to rsyslog", legacy, pids) + ctx.log("rsyslogd %s; no syslogd/klogd", rs) + + # 2. the render step: rules + effective levels, consistent with what + # the API reports as effective + ctx.check(os.path.isfile("/data/forgefirm/rsyslog-forgefirm.conf"), + "rendered rules missing: /data/forgefirm/rsyslog-forgefirm.conf") + rules = _read("/data/forgefirm/rsyslog-forgefirm.conf") or "" + for name in LOGGERS: + ctx.check(("# %s:" % name) in rules, "rendered rules carry no block for %s", name) + ctx.check(os.path.isfile("/var/run/forgefirm-loglevels"), "effective-levels record missing") + st, body = fc.get("/logs") + ctx.check(st == 200 and isinstance(body, dict), "GET /logs -> %s", st) + ctx.check(body.get("effective_known") is True, "/logs does not know the effective levels") + eff = {} + for l in body.get("loggers") or []: + eff[l["name"]] = (l.get("effective_disk"), l.get("effective_remote")) + ev["effective"] = eff + ctx.log("effective levels: %s", eff) + ctx.check(set(eff) == set(LOGGERS), "loggers reported: %s", sorted(eff)) + levels = _read("/var/run/forgefirm-loglevels") or "" + for name, (disk, _remote) in eff.items(): + ctx.check(("log_%s_disk=%s" % (name, disk)) in levels, + "effective record and /logs disagree on %s (%s)", name, disk) + + # 3. the tree + for name in LOGGERS: + ctx.check(os.path.isdir(os.path.join(LOGS_ROOT, name)), "no directory for %s", name) + + # 4. the daemon's own emitter (fflog): a line from the running pid, if + # its level admits info + pids = hw.pidof("forgectrl") + ctx.check(pids, "forgectrl is not running") + disk_rank = _SEV_RANK.get(eff.get("forgectrl", ("info", "off"))[0], 6) + fpath = os.path.join(LOGS_ROOT, "forgectrl", "forgectrl.log") + if disk_rank >= 6: + own = [l for l in _tail_lines(fpath, 2000) + if any((" forgectrl[%d] " % p) in l for p in pids)] + ev["own_lines"] = len(own) + ctx.log("forgectrl[%s] lines in its file: %d", pids, len(own)) + ctx.check(own, "no line from the running daemon in %s (emitter path broken?)", fpath) + m = _LINE_RE.match(own[-1]) + ctx.check(m and m.group("prog") == "forgectrl", "not in the ff_line format: %r", own[-1]) + else: + ctx.log("forgectrl disk level %s: own-emitter check skipped", eff["forgectrl"][0]) + + # 5. the relay path: a `logger` probe under a controller's name lands + # in that controller's file with the ff_line format + nonce = "forgetest-routing-%d" % int(time.time()) + for name in ("grblhal", "gfhome"): + rank = _SEV_RANK.get(eff.get(name, ("info", "off"))[0], 6) + if rank < 3: + ctx.log("%s disk level off: relay probe skipped", name) + continue + rc, out = hw.run(["logger", "-t", name, "-p", "daemon.err", "%s %s" % (nonce, name)]) + ctx.check(rc == 0, "logger -t %s failed: %s", name, out) + path = os.path.join(LOGS_ROOT, name, name + ".log") + line = _wait_line(path, nonce) + ev["probe_" + name] = line + ctx.check(line, "%s probe did not reach %s", name, path) + m = _LINE_RE.match(line) + ctx.check(m and m.group("prog") == name and m.group("sev") == "ERR", + "%s probe line not in the ff_line format: %r", name, line) + ctx.log("%s: %s", name, line) + # a probe under another name must NOT leak into these files + rc, out = hw.run(["logger", "-t", "forgetest-stray", "-p", "daemon.err", "%s stray" % nonce]) + time.sleep(1.5) + for name in ("grblhal", "gfhome", "forgectrl"): + path = os.path.join(LOGS_ROOT, name, name + ".log") + ctx.check(not any((nonce + " stray") in l for l in _tail_lines(path, 100)), + "a stray program's line landed in %s", path) + sys_rank = _SEV_RANK.get(eff.get("system", ("info", "off"))[0], 6) + if sys_rank >= 3: + line = _wait_line(os.path.join(LOGS_ROOT, "system", "system.log"), nonce + " stray") + ctx.check(line, "the stray program's line did not reach system/") + + # 6. relay processes: the supervisor spawns one `logger` per controller + # (its stdin is the controller's output pipe); the daemon's init + # script keeps one on the fifo + st, mode = fc.get("/mode") + relays = hw.pidof("logger") + ev["logger_relays"] = relays + ev["controller"] = mode.get("controller") if isinstance(mode, dict) else None + ctx.log("logger relays: %s (controller %s)", relays, ev["controller"]) + if isinstance(mode, dict) and mode.get("controller") == "running": + ctx.check(relays, "controller running but no `logger` relay process") + if os.path.exists("/var/run/forgectrl.stderr"): + ctx.check(len(relays) >= 2 or ev["controller"] != "running", + "fifo relay present but only %s logger process(es)", relays) + + # 7. the kernel reaches kernel/ (unless filtered off) + if _SEV_RANK.get(eff.get("kernel", ("info", "off"))[0], 6) >= 6: + klines = _tail_lines(os.path.join(LOGS_ROOT, "kernel", "kernel.log"), 50) + ev["kernel_lines"] = len(klines) + ctx.check(klines and any(" kernel[" in l for l in klines), "no kernel lines in kernel/") + + # 8. nothing outside the tree + for stray in ("/data/forgectrl.log", "/data/gfcloud.log", "/data/gfhome.log", + "/data/log/gfcloud", "/data/log/gfhome", "/var/log/messages"): + ctx.check(not os.path.exists(stray), "pre-syslog log path still present: %s", stray) + ctx.log("no ForgeFIRM log outside %s", LOGS_ROOT) + + +@test("logs.level-settings", title="Log level and remote-target settings", subsystem="logs", + kind="auto", est_min=1, + covers=[("forgectrl", "src/logs.*"), ("forgectrl", "src/main.c"), ("forgectrl", "src/settings.*")], + requires=["logs.tree-tail-export", "forgectrl.settings-bounds"], + description="A log level outside off..debug, a bad remote port, a bad protocol and a bad " + "server name are refused (400); a valid remote level is accepted and /logs shows " + "it as configured but not effective (pending_reboot); the setting is restored to " + "its prior value.") +def level_settings(ctx): + fc = ctx.forgectrl + ev = ctx.evidence + ctx.check(fc.wait_idle(timeout=30, abort=ctx.aborted), "machine not idle: settings are locked") + + for key, val in (("log_grblhal_disk", "verbose"), ("log_kernel_remote", "7"), + ("syslog_port", "70000"), ("syslog_proto", "tls"), + ("syslog_server", "bad host name")): + st, body = fc.post("/settings", data={key: val}) + ev["refused %s=%s" % (key, val)] = st + ctx.log("POST /settings %s=%s -> %s", key, val, st) + ctx.check(st == 400, "%s=%s -> %s, expected 400", key, val, st) + + st, before = fc.get("/logs") + ctx.check(st == 200 and isinstance(before, dict), "GET /logs -> %s", st) + prior = {l["name"]: l for l in before.get("loggers") or []} + ctx.check("system" in prior, "/logs lacks the system logger") + was = prior["system"].get("remote") or "off" + was_pending = bool(before.get("pending_reboot")) + new = "warning" if was != "warning" else "error" + ev["system_remote_before"] = was + ev["pending_before"] = was_pending + try: + st, body = fc.post("/settings", data={"log_system_remote": new}) + ctx.log("POST /settings log_system_remote=%s -> %s", new, st) + ctx.check(st == 200, "valid level refused: %s", st) + st, after = fc.get("/logs") + now = {l["name"]: l for l in after.get("loggers") or []} + ctx.check(now["system"].get("remote") == new, "configured level reads %r", now["system"].get("remote")) + ctx.check(now["system"].get("effective_remote") == prior["system"].get("effective_remote"), + "effective level changed without a reboot") + ctx.check(after.get("pending_reboot") is True, "pending_reboot not raised by a level change") + ctx.log("configured %s, effective %s, pending_reboot %s", + now["system"].get("remote"), now["system"].get("effective_remote"), after.get("pending_reboot")) + finally: + # restore: a value that was stored goes back as a value; a default + # is restored by clearing the key (a query parameter - empty + # values never reach the form body) + stored = fc.settings().get("log_system_remote", "") + if was == "off" and stored in ("", None, new): + st, body = fc.post("/settings", params={"log_system_remote": ""}) + else: + st, body = fc.post("/settings", data={"log_system_remote": was}) + ctx.log("restore log_system_remote -> %s", st) + st, final = fc.get("/logs") + fin = {l["name"]: l for l in final.get("loggers") or []} + ctx.check(fin["system"].get("remote") == was, "system remote level not restored (%r)", fin["system"].get("remote")) + ctx.check(bool(final.get("pending_reboot")) == was_pending, + "pending_reboot did not return to %s after the restore", was_pending) diff --git a/meta-forgefirm/recipes-forgefirm/forgectrl/forgectrl.bb b/meta-forgefirm/recipes-forgefirm/forgectrl/forgectrl.bb index 2ccfaff..78e845a 100644 --- a/meta-forgefirm/recipes-forgefirm/forgectrl/forgectrl.bb +++ b/meta-forgefirm/recipes-forgefirm/forgectrl/forgectrl.bb @@ -9,7 +9,7 @@ PV = "0.1.0" SRC_URI = "git://github.com/ScottW514/forgectrl.git;protocol=https;branch=main" # Pinned; bump deliberately after pushing forgectrl changes. -SRCREV = "b4e01c5b24c75d09d6784c690d1c10654bc46da3" +SRCREV = "4d19e9dd6e2fe14c0c92908efe4aee4ec6f765b6" S = "${WORKDIR}/git"