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.  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,

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/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/__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

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

test/infamy/env.py

@@ -1,12 +1,13 @@
 import argparse
+import atexit
 import os
 import pydot
 import shlex
 import sys
 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}\"")

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)

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'