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

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,

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

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

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)