test: capture DUT syslog per test

.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/syslog/
+          if-no-files-found: ignore

doc/testing.md

@@ -323,6 +323,39 @@ $ 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 see why.  With syslog capture enabled, each DUT logs to
+a syslog server in the test container over its management interface.
+The server sorts messages per test and per 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
+```
+
+Capture is disabled by default, since 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
+```
+
+The start and stop of each test are marked in the DUT's log, with
+msgid `test-start` and `test-stop`, and structured data `test@61046`
+holding the test name, node, and the host's wall-clock time.  Compare
+the host time with the timestamp of the same line to line up DUT log
+lines with the test output.
+
 ### Test specification
 
 The test specification is automaticly generated from the test cases,

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")

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
 

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
 

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

test/infamy/dutlog.py

@@ -0,0 +1,172 @@
+"""Collect each DUT's syslog in the test container during a test
+
+Off by default, enable with --capture-syslog or TEST_SYSLOG_CAPTURE=y.
+Each DUT logs to a syslogd in the test container, which sorts messages
+by sender into $NINEPM_LOG_PATH/syslog/<test>/<node>/.  The start and
+stop of the test are marked in each DUT's log with the log RPC, using
+msgid test-start and test-stop.  Best-effort, a failed capture never
+fails the test.
+"""
+import datetime
+import json
+import os
+import signal
+import subprocess
+import sys
+import time
+import uuid
+
+SYSLOGD = "/usr/local/sbin/syslogd"
+CONF = "/tmp/infamy-syslog.conf"
+PIDFILE = "/tmp/infamy-syslogd.pid"
+SOCKET = "/tmp/infamy-syslog.sock"
+SDID = "test@61046"
+
+
+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)
+    _wait(lambda: os.path.exists(PIDFILE))
+    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 _wait(fn, timeout=5):
+    end = time.monotonic() + timeout
+    while time.monotonic() < end:
+        if fn():
+            return True
+        time.sleep(0.2)
+    return False
+
+
+def _logged(path, run, msgid):
+    try:
+        with open(path) 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 = None
+        self.duts = {}
+
+    def _mark(self, node, dev, msgid):
+        now = datetime.datetime.now().astimezone().isoformat(timespec="milliseconds")
+        dev.log(f"{msgid} {self.test}", app_name="infamy", msgid=msgid,
+                sd={SDID: {"name": self.test, "node": node,
+                           "run": self.run, "host-time": now}})
+
+    def _path(self, node):
+        return os.path.join(self.dir, node, "syslog")
+
+    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():
+                path = os.path.dirname(self._path(node))
+                os.makedirs(path, exist_ok=True)
+                # A filter only covers the rule following it
+                for sel, name in (("*.*", "syslog"), ("kern.*", "kern.log")):
+                    f.write(f':source, isequal, "{source}"\n'
+                            f"{sel}\t-{path}/{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 not hasattr(dev, "log"):
+            return
+
+        logdir = os.environ.get("NINEPM_LOG_PATH")
+        if not logdir:
+            print("dutlog: NINEPM_LOG_PATH not set, not capturing syslog")
+            return
+        self.dir = os.path.join(logdir, "syslog", self.test)
+
+        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"
+                            }]
+                        }
+                    }
+                }
+            })
+            known = node in self.duts
+            # The source property is the sender address, with scope
+            self.duts[node] = (dev, mgmtip)
+            if known:
+                return
+            self._reload(pid)
+
+            # The DUT applies the remote action asynchronously, retry
+            # the marker until it shows up
+            for _ in range(5):
+                self._mark(node, dev, "test-start")
+                if _wait(lambda: _logged(self._path(node), self.run, "test-start"), 1):
+                    break
+            else:
+                print(f"dutlog: {node}: no syslog received in {self._path(node)}")
+        except Exception as e:
+            print(f"dutlog: {node}: failed setting up syslog capture: {e}")
+
+    def end(self):
+        """Mark the stop of the test, and stop sorting logs to this test"""
+        if not self.duts:
+            return
+
+        for node, (dev, _) in self.duts.items():
+            try:
+                self._mark(node, dev, "test-stop")
+                _wait(lambda: _logged(self._path(node), self.run, "test-stop"), 2)
+            except Exception as e:
+                print(f"dutlog: {node}: failed logging stop marker: {e}")
+
+        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}")

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 getattr(self.args, "capture_syslog", False):
+            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}\"")

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")

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; \