From 6d1f947d956b8d9f5e3c90cf2393e000de150ad6 Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Wed, 7 Oct 2026 09:07:09 +0200 Subject: [PATCH 1/3] test: add sysklogd to the test container image Collecting DUT syslog in the test container needs a syslogd that can receive remote messages and sort them with property filters, which BusyBox syslogd can't. Build sysklogd 2.7.2, the same version as on the DUTs, into /usr/local and bump the image to 2.15. Signed-off-by: Ejub Sabic --- test/.env | 2 +- test/docker/Dockerfile | 8 ++++++++ 2 files changed, 9 insertions(+), 1 deletion(-) diff --git a/test/.env b/test/.env index d92081768..e18f2d57a 100644 --- a/test/.env +++ b/test/.env @@ -2,7 +2,7 @@ # shellcheck disable=SC2034,SC2154 # Current container image -INFIX_TEST=ghcr.io/kernelkit/infix-test:2.14 +INFIX_TEST=ghcr.io/kernelkit/infix-test:2.15 ixdir=$(readlink -f "$testdir/..") logdir=$(readlink -f "$testdir/.log") diff --git a/test/docker/Dockerfile b/test/docker/Dockerfile index 56e2dc193..6595e3567 100644 --- a/test/docker/Dockerfile +++ b/test/docker/Dockerfile @@ -72,6 +72,14 @@ RUN cd /tmp/ && tar zxf netsniff-ng-$NETSNIFF_NG_VERSION.tar.gz RUN cd /tmp/netsniff-ng-$NETSNIFF_NG_VERSION && ./configure --disable-geoip && \ make trafgen mausezahn && make trafgen_install mausezahn_install +# sysklogd, same version as on the DUTs, collects their syslog during +# tests. Installed in /usr/local to not clash with BusyBox syslogd. +ARG SYSKLOGD_VERSION="2.7.2" +RUN wget https://github.com/troglobit/sysklogd/releases/download/v$SYSKLOGD_VERSION/sysklogd-$SYSKLOGD_VERSION.tar.gz -O /tmp/sysklogd-$SYSKLOGD_VERSION.tar.gz +RUN cd /tmp/ && tar zxf sysklogd-$SYSKLOGD_VERSION.tar.gz +RUN cd /tmp/sysklogd-$SYSKLOGD_VERSION && ./configure --prefix=/usr/local --without-logger && \ + make && make install + # Alpine's QEMU package does not bundle this for some reason, copied # from Ubuntu COPY docker/qemu-ifup /etc From 546a0f908d63932c3c3ebf9a8c09a5e5f1d44a55 Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Wed, 7 Oct 2026 09:07:13 +0200 Subject: [PATCH 2/3] test/infamy: collect DUT syslog per test When a test fails in CI, the DUT logs are gone by the time anyone looks. With TEST_SYSLOG_CAPTURE=y to make test, or --capture-syslog to Infamy, each DUT logs to a syslogd in the test container, which writes everything to full and each DUT to a file of its own: test/.log//syslog//full test/.log//syslog//.log Infamy adds a remote action on each DUT after test_reset, and the container's syslogd sorts messages on sender address. Infamy marks the start and stop of each test, and the start of each step, in the DUT's log with the log RPC, using msgid test-start, test-stop, and step. After the run, make test packs the logs in logs.tar.gz. Capture is off by default and best-effort, it never changes a test result. Resolves: #1608 Signed-off-by: Ejub Sabic --- test/infamy/__init__.py | 1 + test/infamy/dutlog.py | 187 ++++++++++++++++++++++++++++++++++++++++ test/infamy/env.py | 20 ++++- test/infamy/tap.py | 4 + test/test.mk | 7 ++ 5 files changed, 217 insertions(+), 2 deletions(-) create mode 100644 test/infamy/dutlog.py diff --git a/test/infamy/__init__.py b/test/infamy/__init__.py index c3abc6f19..dd77cba83 100644 --- a/test/infamy/__init__.py +++ b/test/infamy/__init__.py @@ -1,6 +1,7 @@ import os from .container import Container +from .dutlog import Capture from .env import Env from .env import ArgumentParser from .env import test_argument diff --git a/test/infamy/dutlog.py b/test/infamy/dutlog.py new file mode 100644 index 000000000..db3340331 --- /dev/null +++ b/test/infamy/dutlog.py @@ -0,0 +1,187 @@ +"""Collect each DUT's syslog per test, see doc/testing.md + +Best-effort, a failed capture never fails the test. +""" +import datetime +import json +import os +import signal +import subprocess +import sys +import threading +import time +import uuid + +from . import util + +SYSLOGD = "/usr/local/sbin/syslogd" +CONF = "/tmp/infamy-syslog.conf" +PIDFILE = "/tmp/infamy-syslogd.pid" +SOCKET = "/tmp/infamy-syslog.sock" +SDID = "test@61046" +CAPTURE_SELECTOR = "*.*" # All facilities and priorities, nothing lost in translation + + +def _syslogd(): + """Return pid of the syslogd collecting DUT logs, start it if needed""" + try: + with open(PIDFILE) as f: + pid = int(f.read()) + os.kill(pid, 0) + return pid + except (OSError, ValueError): + pass + + open(CONF, "w").close() + # -n: no DNS, so the source property is the sender's address + # -k: keep facility kern from the DUTs, -K: no local kernel log + subprocess.run([SYSLOGD, "-f", CONF, "-P", PIDFILE, "-p", SOCKET, + "-n", "-k", "-K", "-m", "0"], check=True) + util.until(lambda: os.path.exists(PIDFILE), attempts=50, interval=0.1) + with open(PIDFILE) as f: + return int(f.read()) + + +def _ll_addr(ifname): + """Return our IPv6 link-local address on ifname""" + out = subprocess.run(["ip", "-6", "-j", "addr", "show", "dev", ifname, "scope", "link"], + stdout=subprocess.PIPE, check=True).stdout + return json.loads(out)[0]["addr_info"][0]["local"] + + +def _logged(path, run, msgid): + # Not every logged line is valid UTF-8 + try: + with open(path, errors="replace") as f: + return any(run in line and msgid in line for line in f) + except OSError: + return False + + +class Capture: + def __init__(self): + name = os.path.basename(os.path.dirname(os.path.realpath(sys.argv[0]))) + self.test = os.environ.get("NINEPM_TEST_NAME", name) + self.run = uuid.uuid4().hex[:12] + self.dir = os.path.join(os.environ.get("NINEPM_LOG_PATH", ""), "syslog", self.test) + self.duts = {} # node -> (dev, sender address), dev None when muted + + def _mark(self, node, dev, msgid, text=None, **params): + now = datetime.datetime.now().astimezone().isoformat(timespec="milliseconds") + dev.log(text or f"{msgid} {self.test}", app_name="infamy", msgid=msgid, + sd={SDID: {"name": self.test, "node": node, + "run": self.run, "host-time": now, **params}}) + + def _marks(self, msgid, text=None, **params): + """Mark all DUTs in parallel, return the nodes that answered + + RPC timeouts are 90-120 s, so a DUT that does not answer within a + second, e.g. while rebooting, is muted until it is attached again. + """ + done = set() + + def mark(node, dev): + try: + self._mark(node, dev, msgid, text, **params) + done.add(node) + except Exception as e: + print(f"dutlog: {node}: failed logging {msgid} marker: {e}") + + threads = [threading.Thread(target=mark, args=(node, dev), daemon=True) + for node, (dev, _) in self.duts.items() if dev] + for t in threads: + t.start() + deadline = time.monotonic() + 1 + for t in threads: + t.join(max(0, deadline - time.monotonic())) + + for node, (dev, source) in self.duts.items(): + if dev and node not in done: + print(f"dutlog: {node}: no more markers until next attach") + self.duts[node] = (None, source) + return done + + def _log(self, node): + return os.path.join(self.dir, f"{node}.log") + + def _reload(self, pid): + """Log everything to full, and each DUT to its own file""" + with open(CONF, "w") as f: + if self.duts: + os.makedirs(self.dir, exist_ok=True) + f.write(f"{CAPTURE_SELECTOR}\t-{self.dir}/full\t;RFC5424\n") + for node, (_, source) in self.duts.items(): + f.write(f':source, isequal, "{source}"\n' + f"{CAPTURE_SELECTOR}\t-{self._log(node)}\t;RFC5424\n") + os.kill(pid, signal.SIGHUP) + + def begin(self, node, dev, mgmtip, cport, dport): + """Make node log to us, and mark the start of the test in its log + + Called on every attach, test_reset drops the remote action. + """ + if "NINEPM_LOG_PATH" not in os.environ: + print("dutlog: NINEPM_LOG_PATH not set, not capturing syslog") + return + + try: + pid = _syslogd() + dev.patch_config("ietf-syslog", { + "syslog": { + "actions": { + "remote": { + "destination": [{ + "name": "infamy", + "udp": { + "address": f"{_ll_addr(cport)}%{dport}" + }, + "facility-filter": { + "facility-list": [{ + "facility": "all", + "severity": "all" + }] + }, + "infix-syslog:log-format": "rfc5424" + }] + } + } + } + }) + new = node not in self.duts + # The source property is the sender address, with scope + self.duts[node] = (dev, mgmtip) + if not new: + return + self._reload(pid) + + # The DUT applies the remote action asynchronously, resend + # the marker until it shows up + path = self._log(node) + util.until(lambda: _logged(path, self.run, "test-start") or + self._mark(node, dev, "test-start"), attempts=15, interval=0.3) + except Exception as e: + print(f"dutlog: {node}: failed setting up syslog capture: {e}") + + def step(self, num, msg): + """Mark the start of a test step""" + self._marks("step", f"step {num}: {msg}", step=str(num)) + + def end(self): + """Mark the stop of the test, and stop sorting logs to this test""" + if not self.duts: + return + + try: + paths = [self._log(node) for node in self._marks("test-stop")] + util.until(lambda: all(_logged(p, self.run, "test-stop") for p in paths), + attempts=10, interval=0.2) + except Exception: + pass # Tests that set up syslog drop our remote action + + try: + self.duts = {} + self._reload(_syslogd()) + except Exception as e: + print(f"dutlog: failed resetting syslog capture: {e}") + + print(f"dutlog: syslog saved in {self.dir}") diff --git a/test/infamy/env.py b/test/infamy/env.py index d7b4fbe04..c0140730c 100644 --- a/test/infamy/env.py +++ b/test/infamy/env.py @@ -1,4 +1,5 @@ import argparse +import atexit import os import pydot import shlex @@ -6,7 +7,7 @@ import random import inspect -from . import neigh, netconf, restconf, ssh, tap, topology, util +from . import dutlog, neigh, netconf, restconf, ssh, tap, topology, util class NullEnv: @@ -39,6 +40,7 @@ def __init__(self, top = None): self.args.add_argument("-p", "--package", default=None) self.args.add_argument("-y", "--yangdir", default=None) self.args.add_argument("-t", "--transport", default=ArgumentParser.DefaultTransport()) + self.args.add_argument("--capture-syslog", default=False, action="store_true") self.args.add_argument("ptop", nargs=1, metavar="topology") self.args.add_argument("-l", "--logical-topology", dest="ltop", default=top) @@ -79,6 +81,7 @@ def __init__(self, ltop=None, args=None, argv=sys.argv[1::], environ=os.environ, pdot = pydot.graph_from_dot_file(self.args.ptop[0])[0] self.ptop = topology.Topology(pdot) + self.capture = None self.ltop = None if self.args.ltop != False: if self.args.ltop is None: @@ -152,6 +155,17 @@ def reset_one(node): util.parallel(*[lambda n=n: reset_one(n) for n in sorted(strays)]) + def _dutlog(self, name, dev, mgmtip, cport, dport): + if not self.args.capture_syslog: + return + + if not self.capture: + self.capture = dutlog.Capture() + tap.Test.step_hooks.append(self.capture.step) + # Runs when the test exits, after Test.__exit__() + atexit.register(self.capture.end) + self.capture.begin(name, dev, mgmtip, cport, dport) + def attach(self, node, port="mgmt", protocol=None, test_reset=True, username=None, password=None): """Attach to node on port using protocol.""" @@ -175,7 +189,7 @@ def attach(self, node, port="mgmt", protocol=None, test_reset=True, username=Non username = "admin" ctrl = self.ptop.get_ctrl() - cport, _ = self.ptop.get_mgmt_link(ctrl, node) + cport, dport = self.ptop.get_mgmt_link(ctrl, node) print("Waiting for DUTs to become reachable...") util.parallel(lambda: util.until(lambda: self.is_reachable(node, cport), 300)) @@ -196,6 +210,7 @@ def attach(self, node, port="mgmt", protocol=None, test_reset=True, username=Non if test_reset: dev.test_reset() util.until(lambda: self.is_reachable(node, cport), 30) + self._dutlog(name, dev, mgmtip, cport, dport) return dev if protocol == "ssh": @@ -212,6 +227,7 @@ def attach(self, node, port="mgmt", protocol=None, test_reset=True, username=Non if test_reset: dev.test_reset() util.until(lambda: self.is_reachable(node, cport), 30) + self._dutlog(name, dev, mgmtip, cport, dport) return dev raise Exception(f"Unsupported management procotol \"{protocol}\"") diff --git a/test/infamy/tap.py b/test/infamy/tap.py index 2ff55074d..2d58b2a55 100644 --- a/test/infamy/tap.py +++ b/test/infamy/tap.py @@ -37,6 +37,8 @@ import infamy.netns class Test: + step_hooks = [] # fn(num, msg) called when a step starts + def __init__(self, output=sys.stdout): self.out = output self.commenter = CommentWriter(self.out) @@ -92,6 +94,8 @@ def __exit__(self, t, e, tb): @contextlib.contextmanager def step(self, msg): + for hook in self.step_hooks: + hook(self.steps + 1, msg) try: yield self._ok(msg) diff --git a/test/test.mk b/test/test.mk index fdc10ff27..415c6285c 100644 --- a/test/test.mk +++ b/test/test.mk @@ -18,6 +18,7 @@ xpaths_all_csv := $(test-dir)/.log/xpaths_all.csv base := -b $(base-dir) TEST_MODE ?= qeneth +TEST_SYSLOG_CAPTURE ?= n mode-qeneth := -q $(or $(QTOPOLOGY),$(test-dir)/virt/quad) mode-host := -t $(or $(TOPOLOGY),/etc/infamy.dot) mode-run := -t $(BINARIES_DIR)/qemu.dot @@ -33,6 +34,10 @@ ifneq ($(BR2_PACKAGE_ROUSETTE),y) export INFAMY_ARGS := --transport=netconf endif +ifeq ($(TEST_SYSLOG_CAPTURE),y) +export INFAMY_ARGS += --capture-syslog +endif + test: $(test-dir)/env -r $(base) $(mode) $(binaries) $(pkg-$(ARCH)) \ sh -c 'test -f $(xpaths_all_csv) || python3 $(yang_extractor) $(YANG_DIR) $(xpaths_all_csv) || true; \ @@ -44,6 +49,8 @@ test: $(test-dir)/.log/last/xpath_coverage.log \ $(test-dir)/.log/last/xpath_coverage_report.md \ 2>/dev/null || true; \ + test ! -d $(test-dir)/.log/last/syslog || \ + tar czf $(test-dir)/.log/last/logs.tar.gz -C $(test-dir)/.log/last syslog; \ chmod -R 777 $(test-dir)/.log; \ exit $$rc' From df93b6a9accfa4a37a3711d0e2c21d2b171420ce Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Wed, 7 Oct 2026 09:07:17 +0200 Subject: [PATCH 3/3] doc: describe DUT syslog capture, upload the logs from CI CI uploads logs.tar.gz as the dut-syslog artifact when capture is enabled. Signed-off-by: Ejub Sabic --- .github/workflows/test.yml | 9 +++++++++ doc/testing.md | 39 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 48 insertions(+) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index be21f3725..e13223fd4 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -155,3 +155,12 @@ jobs: with: name: xpath-coverage-report path: output/images/xpath-coverage-report.pdf + + - name: Upload DUT Syslog as Artifact + # Only when enabled with TEST_SYSLOG_CAPTURE=y + if: always() + uses: actions/upload-artifact@v7 + with: + name: dut-syslog + path: ${{ env.TEST_PATH }}/.log/last/logs.tar.gz + if-no-files-found: ignore diff --git a/doc/testing.md b/doc/testing.md index 99abffdcd..85918b091 100644 --- a/doc/testing.md +++ b/doc/testing.md @@ -323,6 +323,45 @@ $ make test-sh 09:08:17 infamy0:test # ./9pm/9pm.py -o"--transport=restconf" case/system/hostname.py ``` +### Capturing DUT Syslog + +When a test fails, what the DUT logged during the test is often the +quickest way to find out why. With syslog capture enabled, each DUT +logs to a syslog server in the test container over its management +interface. For each test, the server writes everything it receives +to `full`, and each DUT's messages to a file of its own, next to the +test output: + +``` +test/.log/last/output/0006-set-hostname.log +test/.log/last/syslog/0006-set-hostname/full +test/.log/last/syslog/0006-set-hostname/target.log +``` + +After the run, `make test` packs these in `test/.log/last/logs.tar.gz`, +which CI uploads as the `dut-syslog` artifact. + +Capture is off by default, because it changes the syslog setup of each +DUT and adds a few RPCs per test. Enable it for a test run with: + +``` +$ make TEST_SYSLOG_CAPTURE=y test +``` + +or, when running interactively: + +``` +$ make test-sh +09:08:17 infamy0:test # ./9pm/9pm.py -o"--capture-syslog" case/system/hostname.py +``` + +Infamy marks the start and stop of each test, and the start of each +step, in the DUT's log. The markers have msgid `test-start`, +`test-stop`, or `step`, and structured data `test@61046` with the test +name, node, step number, and the host's wall-clock time. To line up +DUT log lines with the test output, compare the host time in a marker +with the timestamp on the same line. + ### Test specification The test specification is automaticly generated from the test cases,