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..5f83e41c7 100644 --- a/doc/testing.md +++ b/doc/testing.md @@ -323,6 +323,44 @@ $ 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 +test/.log/last/syslog/0006-set-hostname/target/messages +``` + +After the run, `make test` packs them in `test/.log/last/logs.tar.gz`, +which CI uploads as the `dut-syslog` artifact. + +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, and each test step, are marked in the +DUT's log, with msgid `test-start`, `test-stop`, and `step`, and +structured data `test@61046` holding the test name, node, step number, +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, 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/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 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 diff --git a/test/infamy/dutlog.py b/test/infamy/dutlog.py new file mode 100644 index 000000000..cf95638a9 --- /dev/null +++ b/test/infamy/dutlog.py @@ -0,0 +1,222 @@ +"""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///. The start and +stop of the test, and each step, are marked in each DUT's log with the +log RPC, using msgid test-start, test-stop, and step. 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 + +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) + _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): + # 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 = None + self.duts = {} + self.mute = set() + + 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 + + The RPCs have no timeout, 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 = [] + for node, (dev, _) in self.duts.items(): + if node not in self.mute: + threads.append(threading.Thread(target=mark, args=(node, dev), daemon=True)) + threads[-1].start() + + deadline = time.monotonic() + 1 + for t in threads: + t.join(max(0, deadline - time.monotonic())) + + for node in self.duts: + if node not in done and node not in self.mute: + print(f"dutlog: {node}: no more markers until next attach") + self.mute.add(node) + return done + + 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 RULES: + 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) + self.mute.discard(node) + 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 step(self, num, msg): + """Mark the start of a test step, without waiting for delivery""" + try: + if self.duts: + self._marks("step", f"step {num}: {msg}", step=str(num)) + except Exception as e: + print(f"dutlog: failed logging step marker: {e}") + + def end(self): + """Mark the stop of the test, and stop sorting logs to this test""" + if not self.duts: + return + + try: + for node in self._marks("test-stop"): + _wait(lambda: _logged(self._path(node), self.run, "test-stop"), 2) + except Exception as e: + print(f"dutlog: 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}") diff --git a/test/infamy/env.py b/test/infamy/env.py index 6a6359ac8..3451c03ed 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 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}\"") 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'