From d488b947a78e268dc78cbec638cc0188875949c7 Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Wed, 7 Oct 2026 09:07:01 +0200 Subject: [PATCH 1/4] test: ospf_bfd: update generated test specification The test.py docstring was changed on main without running make test-spec. Signed-off-by: Ejub Sabic --- test/case/routing/ospf_bfd/ospfv2.adoc | 6 +++--- test/case/routing/ospf_bfd/ospfv3.adoc | 6 +++--- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/test/case/routing/ospf_bfd/ospfv2.adoc b/test/case/routing/ospf_bfd/ospfv2.adoc index 78e548c64..a5e31f327 100644 --- a/test/case/routing/ospf_bfd/ospfv2.adoc +++ b/test/case/routing/ospf_bfd/ospfv2.adoc @@ -12,9 +12,9 @@ This can typically happen when one logical link, from OSPF's perspective, is made up of multiple physical links containing media converters without link fault forwarding. -Note: OSPFv3 next-hops are IPv6 link-local addresses, so the active path is -verified with traceroute rather than by matching a RIB next-hop, and its BFD -peers are only known by their session count. +Note: OSPFv3 next-hops and BFD peers are IPv6 link-local addresses, unknown in +advance, so both versions verify the active path with traceroute rather than by +matching a RIB next-hop, and count BFD sessions rather than name their peers. ==== Topology diff --git a/test/case/routing/ospf_bfd/ospfv3.adoc b/test/case/routing/ospf_bfd/ospfv3.adoc index 65aa96443..5fbe3a0de 100644 --- a/test/case/routing/ospf_bfd/ospfv3.adoc +++ b/test/case/routing/ospf_bfd/ospfv3.adoc @@ -12,9 +12,9 @@ This can typically happen when one logical link, from OSPF's perspective, is made up of multiple physical links containing media converters without link fault forwarding. -Note: OSPFv3 next-hops are IPv6 link-local addresses, so the active path is -verified with traceroute rather than by matching a RIB next-hop, and its BFD -peers are only known by their session count. +Note: OSPFv3 next-hops and BFD peers are IPv6 link-local addresses, unknown in +advance, so both versions verify the active path with traceroute rather than by +matching a RIB next-hop, and count BFD sessions rather than name their peers. ==== Topology From 778266841652b8b25b2827fdc3f3e0b763e2ddfc Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Wed, 7 Oct 2026 09:07:09 +0200 Subject: [PATCH 2/4] 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 d35a8e562491ad6df6a96cce809d36ae7544360c Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Wed, 7 Oct 2026 09:07:13 +0200 Subject: [PATCH 3/4] 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: test/.log//syslog///{syslog,kern.log,messages} 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/dutlog.py | 195 ++++++++++++++++++++++++++++++++++++++++++ test/infamy/env.py | 9 +- test/infamy/tap.py | 10 +++ test/test.mk | 7 ++ 4 files changed, 220 insertions(+), 1 deletion(-) create mode 100644 test/infamy/dutlog.py diff --git a/test/infamy/dutlog.py b/test/infamy/dutlog.py new file mode 100644 index 000000000..d84390d5c --- /dev/null +++ b/test/infamy/dutlog.py @@ -0,0 +1,195 @@ +"""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" + +# Same files as on the DUT, messages with the selector from its syslog.conf +RULES = ( + ("*.*", "syslog"), + ("kern.*", "kern.log"), + ("*.=info;*.=notice;*.=warn;auth,authpriv.none;cron,daemon.none;mail,news.none", + "messages"), +) + + +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 _logs(self, node): + return os.path.join(self.dir, node) + + def _reload(self, pid): + """Write rules for this test's DUTs, sorted on sender address""" + with open(CONF, "w") as f: + for node, (_, source) in self.duts.items(): + os.makedirs(self._logs(node), exist_ok=True) + # A filter only covers the rule following it + for sel, name in RULES: + f.write(f':source, isequal, "{source}"\n' + f"{sel}\t-{self._logs(node)}/{name}\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 = os.path.join(self._logs(node), "syslog") + 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 = [os.path.join(self._logs(node), "syslog") + 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 6a6359ac8..150744f22 100644 --- a/test/infamy/env.py +++ b/test/infamy/env.py @@ -39,6 +39,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) @@ -123,6 +124,10 @@ def is_reachable(self, node, port): return util.is_reachable(ip, self, self.get_password(node)) + def _dutlog(self, name, dev, mgmtip, cport, dport): + if tap.CURRENT and self.args.capture_syslog: + tap.CURRENT.dutlog.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.""" @@ -146,7 +151,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)) @@ -167,6 +172,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": @@ -183,6 +189,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..d521ed646 100644 --- a/test/infamy/tap.py +++ b/test/infamy/tap.py @@ -35,6 +35,10 @@ import traceback import infamy.netns +from infamy.dutlog import Capture + +# The running test, lets Env.attach() register DUTs for syslog capture +CURRENT = None class Test: def __init__(self, output=sys.stdout): @@ -45,6 +49,10 @@ def __init__(self, output=sys.stdout): self.test_cleanup=[] self.steps = 0 + self.dutlog = Capture() + + global CURRENT + CURRENT = self def push_test_cleanup(self, fn): self.test_cleanup.append(fn) @@ -66,6 +74,7 @@ def __exit__(self, t, e, tb): self.out.flush() self.cleanup() + self.dutlog.end() if not e: self._not_ok("Missing explicit test result\n") @@ -92,6 +101,7 @@ def __exit__(self, t, e, tb): @contextlib.contextmanager def step(self, msg): + self.dutlog.step(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 e217a585fba6b8e11adcdee77442cfc30ea76f8d Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Wed, 7 Oct 2026 09:07:17 +0200 Subject: [PATCH 4/4] 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..4dd02ff1c 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. The server writes one directory per test and DUT, next to +the test output: + +``` +test/.log/last/output/0006-set-hostname.log +test/.log/last/syslog/0006-set-hostname/target/syslog +test/.log/last/syslog/0006-set-hostname/target/kern.log +test/.log/last/syslog/0006-set-hostname/target/messages +``` + +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,