Unified logging: rsyslog as the system logger, the ForgeFIRM log tree

rsyslog replaces busybox syslogd/klogd (VIRTUAL-RUNTIME_base-utils-syslog, trimmed PACKAGECONFIG) and becomes the only log writer: the appended /etc/rsyslog.conf sets the inputs and the ff_line format and includes the per-logger rules that `forgectrl --render-syslog` renders from the machine settings at boot. forgefirm-logrotate becomes forgefirm-logging: render before rsyslog starts (S19), sweep the pre-syslog log files into /data/forgefirm/legacy-logs once, and rotate the tree at boot and hourly by rename + HUP instead of copytruncate. Pins bumped to the pushed forgectrl (syslog emitter, Logs tab, export), grblHAL-glowforge (syslog emitter) and python3-gfhardware apps (syslog handlers, capture dir); the CI harnesses set FFLOG_STDERR=1 so failure diagnostics keep the controller's log lines. BRINGUP carries the bench validation checklist (Next work item 14); this is an image change and rides the next flash.
2026-09-28 01:01:12 -07:00 · 2026-08-15 14:37:33 -04:00
parent b08e5ab929
commit 6050c0e703
16 changed files with 257 additions and 95 deletions
@@ -34,6 +34,11 @@ machine is idle:**
 * A **web control panel** on port 8080: machine status and position, coolant
  and fan telemetry, safety-switch states, camera view, machine settings,
  hardware diagnostics, firmware updates, and boot-slot management.
+* **Unified logging**: every ForgeFIRM component logs through syslog into its
+  own directory under `/data/log/forgefirm`, with per-logger levels for the
+  device and for an optional remote syslog server, a live viewer in the
+  panel, and a one-click log bundle — sanitized of identifying details — for
+  attaching to an issue report.
 * Both **cameras** as MJPEG streams and full-resolution snapshots — the lid
  camera feeds LightBurn's camera overlay directly.
 * **Camera-referenced homing**: `$H` from any sender runs the factory-style
@@ -1,6 +1,15 @@
 # ForgeFIRM bring-up status & cold-start runbook

-Last updated: **2026-08-15** — **audit remediation Phases 0 through 11
+Last updated: **2026-08-15** — **unified logging landed in every repo
+(code-complete, host-verified end to end, pushed, pins bumped): rsyslog
+is the system logger and the only log writer, every ForgeFIRM process
+emits through syslog under its own program name, each logger has its own
+directory under `/data/log/forgefirm/`, per-logger disk and remote levels
+plus a remote syslog target are machine settings (applied at reboot) with
+a Logs tab in the panel (levels, live viewer, sanitized tar.gz export for
+issue reports). It is an image change (rsyslog replaces busybox
+syslogd/klogd) and rides the next full image flash — bench validation
+checklist is "Next work" item 14.** Before that: **audit remediation Phases 0 through 11
 landed: every one of the 159 findings from the independent whole-tree
 audit dated 2026-08-13 has its fix committed** (the remediation was
 sequenced behind two gates — GATE A, uncommanded energy, before any
@@ -1044,16 +1053,17 @@ DRV8825 drivers and a loud `motion-fault` state), the **cooling
 engine** (single owner of fans/pump/TEC/heater for both modes:
 `POST /cool/state` job reports in, the `/run/forgefirm/cooling.state`
 verdict file out), plus cameras, telemetry, settings, diagnostics, the
-web panel, and updates. It runs under a respawn wrapper (its init
-script) and a restarted daemon retakes supervision automatically once
-the machine is idle. The meta-forgefirm recipe pins its SRCREV (bump
+web panel, updates, and the **logging tree** (`GET /logs`, `/logs/tail`,
+`POST /logs/export`; `forgectrl --render-syslog` at boot). It runs under
+a respawn wrapper (its init script) and a restarted daemon retakes
+supervision automatically once the machine is idle. The meta-forgefirm recipe pins its SRCREV (bump
 deliberately after pushing) and installs the sysvinit script from the
 repo's `init/`; bench builds cross-compile with
 `forgefirm/scripts/bench/build-forgectrl.sh` (same toolchain-borrow
 pattern as build-glowforge.sh). The **machine-services contract** —
 the EV_SW switch map, the authoritative sensor conversions, the
 hardware single-writer ownership matrix, the cooling channels, mode
-supervision, and pulse-device ownership — is
+supervision, pulse-device ownership, and logging — is
 `forgectrl/docs/SERVICES.md` in the forgectrl repo. One ulfius daemon
 serves it all, including both OV5648 cameras as MJPEG over the
 mainline imx-media pipeline:
@@ -1148,7 +1158,9 @@ a head-stream request ended the lid viewer's stream cleanly (curl exit
 likewise. **Motion coexistence proven**: X
 round-trip jogs at F1200 with an active stream — producer stats
 `clamped 0`, max behind 4.5 ms (the daemon runs at nice +5, single
-core). Run by hand: `/usr/bin/forgectrl >> /data/forgectrl.log 2>&1 &`
+core). Run by hand: `/usr/bin/forgectrl &` — it logs through syslog
+(`/data/log/forgefirm/forgectrl/forgectrl.log`; a terminal, or
+`FFLOG_STDERR=1`, echoes the lines) — after `/etc/init.d/forgectrl stop`
 (kill before scp when redeploying, text-file-busy).

 **LightBurn consumes the stream directly — operator-verified
@@ -2544,3 +2556,75 @@ accordingly ("Automatic — AP country, else World").
    `WARNING … wlcore/main.c:874 wl12xx_queue_recovery_work` block that
    accompanies the event is upstream noise (an "unintended recovery"
    `WARN_ON`), not a crash — the `-84` line is the signal to watch.
+14. **Unified logging — CODE-COMPLETE, host-verified, pushed and pinned
+    2026-08-15; bench validation pending — ships with the next full image
+    flash (rsyslog replaces busybox syslogd/klogd, so it is an image
+    change).** Design and contract: `forgectrl/docs/SERVICES.md`
+    "Logging". In brief: rsyslog is the only log writer; forgectrl and
+    the grblHAL driver emit through the shared non-blocking `fflog`
+    emitter (drops, never waits — a stalled log daemon can never park a
+    controller thread), gfcloud/gfhome through `SysLogHandler`, the
+    kernel through `imklog`; a controller's stray stdout/stderr rides a
+    per-controller `logger` relay under its own name; the daemon's own
+    stray output a fifo relay in its init script. Tree:
+    `/data/log/forgefirm/{forgectrl,grblhal,gfcloud,gfhome,kernel,system}/`,
+    size-capped and rotated (`forgefirm-logging` recipe: renders the
+    rsyslog rules from the settings at S19 via `forgectrl
+    --render-syslog`, sweeps the pre-syslog files once into
+    `/data/forgefirm/legacy-logs/`, logrotate at boot + hourly with a
+    `HUP`, never `copytruncate`). Levels: `log_<logger>_disk` /
+    `_remote` and `syslog_server/port/proto` in `/data/forgefirm.conf`,
+    **applied at reboot** (the panel's Logs tab shows configured vs.
+    effective and offers the reboot); a process emits at the more
+    verbose of its two levels, rsyslog filters per destination. Export:
+    `POST /logs/export` streams a `tar.gz` (tree + system snapshot),
+    sanitized by default (`src/sanitize.c`: known values first — serial,
+    hostname, cloud credentials, panel token, WiFi SSID/PSK — then
+    patterns; stable placeholders; `tests/sanitize_test.c` in CI, 39
+    fixtures). Host proof done: forgectrl/grblHAL `-Werror` builds and
+    all three CI test sets green (sanitizer, idle fail-closed, switch
+    map, arm re-check, laser stream + armed-window harnesses on the
+    null-sink build); `tests/fflog_e2e.sh` against a private rsyslogd on
+    the shipped `rsyslog.conf` (emitter format, per-logger routing,
+    level filtering, `logger` relay routing) and the equivalent Python
+    check both pass; `/logs`, `/logs/tail` (full + incremental follow),
+    and both export variants exercised over HTTP on a host build and
+    the panel's Logs tab driven in a browser (levels table, viewer,
+    follow, export). **Bench, on the flashed image:**
+    - boot: `S19forgefirm-logging` ran (`/data/forgefirm/rsyslog-forgefirm.conf`
+      present, `/var/run/forgefirm-loglevels` present, six directories
+      under `/data/log/forgefirm`), `rsyslogd` up and no busybox
+      `syslogd`/`klogd`; `/var/log/messages` gone (nothing writes it);
+      the legacy files moved to `/data/forgefirm/legacy-logs/` and
+      `/data/forgectrl.log`, `/data/gfcloud.log`, `/data/log/gfcloud`,
+      `/data/log/gfhome` no longer exist; the factory's
+      `/data/glowforge.log*` untouched and no longer growing.
+    - routing: forgectrl lines in `forgectrl/forgectrl.log`, the grbl
+      controller's in `grblhal/grblhal.log` (a `$H` shows the gfhome
+      lines in `gfhome/gfhome.log`), kernel `glowforge_cnc` lines in
+      `kernel/kernel.log` with correlated RFC 3339 timestamps, sshd in
+      `system/system.log`; a mode switch to cloud puts gfcloud's lines
+      in `gfcloud/gfcloud.log` and a deliberate Python traceback (or a
+      `print`) shows up there via the relay tagged `gfcloud`.
+    - levels: set `grblhal` disk to `debug` in the panel → the pending
+      marker and banner appear; after reboot the per-run
+      `gfstream: run:` stats appear; set it to `warning` → they stop;
+      `off` → the file stops growing. Remote: point `syslog_server` at a
+      LAN host running `nc -ul 514` (or rsyslog), one logger's remote
+      level `info`, reboot → RFC 5424 lines arrive; unplug the host →
+      the machine keeps cutting/logging locally, nothing stalls
+      (per-action queue discards).
+    - rotation: `logger -t grblhal` a 3 MB burst (or a debug-level
+      session) → the hourly/boot logrotate produces `grblhal.log.1.gz`
+      and the live file keeps receiving lines (HUP reopen).
+    - export: download both bundle variants from the panel; the
+      sanitized `README.txt` lists redactions and no bundle file
+      contains the machine's serial, `XXX-YYY` hostname, WiFi SSID, or
+      a LAN IP (`grep` the extracted tree); the unsanitized one does.
+      Staging under `/data/forgefirm/tmp/` is empty afterwards.
+    - RT: a debug-level GRBL session with LightBurn streaming — producer
+      stats `clamped 0`, no underrun (fflog is non-blocking; nothing
+      logs from the shipper).
+    - `/etc/init.d/forgectrl stop`/`start` — the fifo relay comes and
+      goes with the wrapper; a forced daemon crash logs the wrapper's
+      `exited (N) - respawning in 5 s` line under `forgectrl`.
@@ -7,3 +7,13 @@ DISTRO_VERSION = "0.0.0"
 DISTRO_FEATURES:remove = " \
  3g alsa avahi bluetooth bluez5 ext2 ipv6 irda nfc nfs opengl pci pcmcia \
  pulseaudio vulkan wayland x11 zeroconf "
+
+# System logger: rsyslog replaces busybox syslogd/klogd. Every ForgeFIRM
+# process logs through it and it is the only log writer (one directory
+# per logger under /data/log/forgefirm; per-logger levels and the remote
+# target come from the machine settings). Trimmed to what the image uses:
+# the local socket and kernel inputs, file output, plain UDP/TCP
+# forwarding, and rainerscript filters - no TLS, database, HTTP, or
+# signing modules (rootfs must fit the 200 MiB factory slot).
+VIRTUAL-RUNTIME_base-utils-syslog = "rsyslog"
+PACKAGECONFIG:pn-rsyslog = "rsyslogd rsyslogrt klog inet regexp"
@@ -0,0 +1,12 @@
+# rsyslog is the ForgeFIRM system logger: the only log writer, one
+# directory per logger under /data/log/forgefirm. This appends the
+# ForgeFIRM /etc/rsyslog.conf (inputs, line format, and the include of
+# the per-logger rules that forgectrl renders at boot); the feature set
+# is trimmed in conf/distro/forgefirm.conf (PACKAGECONFIG:pn-rsyslog).
+FILESEXTRAPATHS:prepend := "${THISDIR}/${PN}:"
+
+do_install:append() {
+    # The stock rotation set covers /var/log files this image never
+    # writes; the ForgeFIRM tree has its own (forgefirm-logging).
+    rm -f ${D}${sysconfdir}/logrotate.d/logrotate.rsyslog
+}
@@ -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 = "801f1f3a1f90c38157429ee1e4ff79b0c2fe68e3"
+SRCREV = "b4e01c5b24c75d09d6784c690d1c10654bc46da3"

 S = "${WORKDIR}/git"

@@ -11,7 +11,7 @@ LIC_FILES_CHKSUM = "file://LICENSE;md5=62f8bb455fcc4bf177ecab380f71cd5d"

 SRC_URI = "git://github.com/ScottW514/python3-gfhardware.git;protocol=https;branch=master"
 # Pinned; bump deliberately (AUTOREV is not reproducible).
-SRCREV = "c3d1790e6cd8f11eee7b386b5314d53454a1c2db"
+SRCREV = "a0a174d8e9a6b4b6e3abe63acc51018199df4202"

 # Bump PV with every SRCREV move: the hash-derived package version is not
 # monotonic on its own and buildhistory QA fails the build when it sorts
@@ -0,0 +1,80 @@
+#!/bin/sh
+### BEGIN INIT INFO
+# Provides:          forgefirm-logging
+# Required-Start:    $local_fs
+# Required-Stop:
+# Default-Start:     2 3 4 5
+# Default-Stop:
+# Short-Description: ForgeFIRM logging tree: rsyslog rules, rotation
+### END INIT INFO
+
+# Runs before rsyslog (S19 < S20):
+#  1. renders the per-logger rsyslog rules and log directories from the
+#     machine settings (forgectrl --render-syslog) - this is why a log
+#     level changed in the control panel applies at the next reboot;
+#  2. moves log files from before the syslog tree out of the way, once;
+#  3. rotates at boot (bounds carry-over bloat), then hourly from a small
+#     background loop (the image runs no cron daemon).
+
+FORGECTRL=/usr/bin/forgectrl
+LOGROTATE=/usr/sbin/logrotate
+CONF=/etc/logrotate.conf
+PIDFILE=/var/run/forgefirm-logging.pid
+LEGACY=/data/forgefirm/legacy-logs
+
+render() {
+    [ -x "$FORGECTRL" ] || return 0
+    # syslog is not up yet at this point: report to the console
+    "$FORGECTRL" --render-syslog || echo "forgefirm-logging: render-syslog failed"
+}
+
+# Files written by ForgeFIRM before it logged through syslog. Moved, not
+# deleted, so nothing on the bench is lost; the factory's own
+# /data/glowforge.log and /data/log/glowforge* are not ours and stay.
+sweep_legacy() {
+    moved=0
+    for f in /data/forgectrl.log /data/forgectrl.log.* /data/forgectrl.log-* \
+             /data/gfcloud.log /data/gfcloud.log.* /data/gfhome.log /data/gfhome.log.*; do
+        [ -e "$f" ] || continue
+        mkdir -p "$LEGACY"
+        mv "$f" "$LEGACY/" && moved=1
+    done
+    for d in /data/log/gfcloud /data/log/gfhome; do
+        [ -d "$d" ] || continue
+        mkdir -p "$LEGACY"
+        mv "$d" "$LEGACY/" && moved=1
+    done
+    [ $moved -eq 1 ] && \
+        echo "forgefirm-logging: pre-syslog log files moved to $LEGACY (delete when no longer needed)"
+    return 0
+}
+
+case "$1" in
+  start)
+    render
+    sweep_legacy
+    [ -x "$LOGROTATE" ] || exit 0
+    "$LOGROTATE" "$CONF" 2>/dev/null
+    ( while :; do
+        sleep 3600
+        "$LOGROTATE" "$CONF" 2>/dev/null
+      done ) &
+    echo $! > "$PIDFILE"
+    ;;
+  stop)
+    [ -r "$PIDFILE" ] && kill "$(cat "$PIDFILE")" 2>/dev/null
+    rm -f "$PIDFILE"
+    ;;
+  restart)
+    $0 stop
+    $0 start
+    ;;
+  render)
+    render
+    ;;
+  *)
+    echo "Usage: $0 {start|stop|restart|render}"
+    exit 1
+    ;;
+esac
+exit 0
@@ -0,0 +1,17 @@
+# The ForgeFIRM logging tree: one directory per logger under
+# /data/log/forgefirm, rsyslog the only writer. Size-capped, so a
+# chatty debug level cannot fill /data; rotation renames and HUPs
+# rsyslog (never copytruncate - no lost lines).
+/data/log/forgefirm/*/*.log {
+    size 2M
+    rotate 3
+    nodateext
+    compress
+    missingok
+    notifempty
+    create 0640 root root
+    sharedscripts
+    postrotate
+        pkill -HUP rsyslogd 2>/dev/null || true
+    endscript
+}
@@ -0,0 +1,30 @@
+SUMMARY = "ForgeFIRM logging tree: rsyslog rules at boot, rotation"
+DESCRIPTION = "Boot-time glue for the ForgeFIRM logging tree \
+(/data/log/forgefirm/<logger>/): renders the per-logger rsyslog rules \
+from the machine settings before rsyslog starts (forgectrl \
+--render-syslog), moves pre-syslog log files out of the way once, and \
+drives size-capped logrotate at boot and hourly (a full /data breaks \
+settings, update staging, and the controllers' own writes)."
+LICENSE = "MIT"
+LIC_FILES_CHKSUM = "file://${COMMON_LICENSE_DIR}/MIT;md5=0835ade698e0bcf8506ecda2f7b4f302"
+
+SRC_URI = " \
+    file://forgefirm.logrotate \
+    file://forgefirm-logging.init \
+"
+
+S = "${WORKDIR}"
+
+inherit update-rc.d
+
+INITSCRIPT_NAME = "forgefirm-logging"
+# 19: before rsyslog's own script (syslog, S20) so the rendered rules
+# exist when it reads its config.
+INITSCRIPT_PARAMS = "start 19 2 3 4 5 ."
+
+RDEPENDS:${PN} = "logrotate rsyslog forgectrl"
+
+do_install() {
+    install -Dm 0644 ${WORKDIR}/forgefirm.logrotate ${D}${sysconfdir}/logrotate.d/forgefirm
+    install -Dm 0755 ${WORKDIR}/forgefirm-logging.init ${D}${sysconfdir}/init.d/forgefirm-logging
+}
@@ -1,43 +0,0 @@
-#!/bin/sh
-### BEGIN INIT INFO
-# Provides:          forgefirm-logrotate
-# Required-Start:    $local_fs
-# Required-Stop:
-# Default-Start:     2 3 4 5
-# Default-Stop:
-# Short-Description: rotate the /data logs at boot and hourly
-### END INIT INFO
-
-# The image runs no cron daemon, so rotation is driven here: once at
-# every boot (bounds carry-over bloat), then hourly from a small
-# background loop (bounds growth across long uptimes - a full /data
-# breaks settings, update staging, and the controllers' own writes).
-
-LOGROTATE=/usr/sbin/logrotate
-CONF=/etc/logrotate.conf
-PIDFILE=/var/run/forgefirm-logrotate.pid
-
-case "$1" in
-  start)
-    [ -x "$LOGROTATE" ] || exit 0
-    "$LOGROTATE" "$CONF" 2>/dev/null
-    ( while :; do
-        sleep 3600
-        "$LOGROTATE" "$CONF" 2>/dev/null
-      done ) &
-    echo $! > "$PIDFILE"
-    ;;
-  stop)
-    [ -r "$PIDFILE" ] && kill "$(cat "$PIDFILE")" 2>/dev/null
-    rm -f "$PIDFILE"
-    ;;
-  restart)
-    $0 stop
-    $0 start
-    ;;
-  *)
-    echo "Usage: $0 {start|stop|restart}"
-    exit 1
-    ;;
-esac
-exit 0
@@ -1,12 +0,0 @@
-# ForgeFIRM logs on the persistent /data partition. copytruncate: the
-# daemon and both controllers keep their log fds open for their whole
-# lifetime, so the file must be truncated in place, never moved out
-# from under them.
-/data/forgectrl.log /data/glowforge.log /data/gfcloud.log /data/gfhome.log {
-    size 1M
-    rotate 3
-    copytruncate
-    compress
-    missingok
-    notifempty
-}
@@ -1,26 +0,0 @@
-SUMMARY = "Log rotation for the ForgeFIRM logs on /data"
-DESCRIPTION = "Size-capped rotation for the daemon and controller logs \
-on the persistent /data partition: a full /data breaks settings, update \
-staging, and the controllers' own writes. Rotation runs at every boot \
-and hourly while the machine is up."
-LICENSE = "MIT"
-LIC_FILES_CHKSUM = "file://${COMMON_LICENSE_DIR}/MIT;md5=0835ade698e0bcf8506ecda2f7b4f302"
-
-SRC_URI = " \
-    file://forgefirm.logrotate \
-    file://forgefirm-logrotate.init \
-"
-
-S = "${WORKDIR}"
-
-inherit update-rc.d
-
-INITSCRIPT_NAME = "forgefirm-logrotate"
-INITSCRIPT_PARAMS = "defaults 40"
-
-RDEPENDS:${PN} = "logrotate"
-
-do_install() {
-    install -Dm 0644 ${WORKDIR}/forgefirm.logrotate ${D}${sysconfdir}/logrotate.d/forgefirm
-    install -Dm 0755 ${WORKDIR}/forgefirm-logrotate.init ${D}${sysconfdir}/init.d/forgefirm-logrotate
-}
@@ -11,7 +11,7 @@ PV = "0.1.0"
 # upstream).
 SRC_URI = "gitsm://github.com/ScottW514/grblHAL-glowforge.git;protocol=https;branch=main"
 # Pinned; bump deliberately after pushing grblHAL-glowforge changes.
-SRCREV = "b629c188227a0ad4eb47095cf9ebe7783a2b9a74"
+SRCREV = "67d026d39ac03286937774f5e28946b88c44d490"

 SRC_URI += "file://grblhal.init"

@@ -24,9 +24,12 @@ IMAGE_INSTALL:remove = "gfui-client"
 # to the inactive rootfs slot.
 # ffboot: boot-slot inventory and switching (also ships fw_env.config).
 # slotmigrate: boot-time reclaim of the legacy p4 layout (grows /data).
-# forgefirm-logrotate: size-capped rotation of the /data logs (boot +
-# hourly; a full /data breaks settings, updates, and controller writes).
-IMAGE_INSTALL:append = " grblhal-glowforge forgectrl gfhome gfcloud v4l-utils fwup ffboot slotmigrate forgefirm-logrotate"
+# forgefirm-logging: the ForgeFIRM logging tree - renders the per-logger
+# rsyslog rules from the settings before rsyslog starts, and drives
+# size-capped rotation (boot + hourly; a full /data breaks settings,
+# updates, and controller writes). rsyslog itself comes in through
+# VIRTUAL-RUNTIME_base-utils-syslog (conf/distro/forgefirm.conf).
+IMAGE_INSTALL:append = " grblhal-glowforge forgectrl gfhome gfcloud v4l-utils fwup ffboot slotmigrate forgefirm-logging"

 # NXP's firmware EULA covers the i.MX VPU/EPDC blobs the BSP installs, so the
 # image ships the license text with them (/usr/share/licenses/firmware-imx).
@@ -129,7 +129,8 @@ class Session:
        with open(conf, "w") as f:
            f.write("laser_disarm_s = %d\n" % disarm_s)
        verdict = os.path.join(self.workdir, "cooling.state")
-        env = dict(os.environ, GF_VERDICT_FILE=verdict, GFHOME_CONF=conf)
+        env = dict(os.environ, GF_VERDICT_FILE=verdict, GFHOME_CONF=conf,
+                   FFLOG_STDERR="1")
        env.pop("GFSINK", None)
        self.stop = threading.Event()
        self.pub = threading.Thread(target=publish_verdicts,
@@ -149,7 +149,8 @@ def run_session(name, steps):
    workdir = tempfile.mkdtemp(prefix="laser-test-")
    dump = os.path.join(workdir, "stream.bin")
    verdict = os.path.join(workdir, "cooling.state")
-    env = dict(os.environ, GFSINK_DUMP=dump, GF_VERDICT_FILE=verdict)
+    env = dict(os.environ, GFSINK_DUMP=dump, GF_VERDICT_FILE=verdict,
+               FFLOG_STDERR="1")
    env.pop("GFSINK", None)

    stop = threading.Event()