From 2c4cd7e814c0483d5cf222422fa18814568a4920 Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Sat, 3 Oct 2026 19:40:05 +0200 Subject: [PATCH 1/5] test/infamy: capture DUT syslog for each test This commit introduces a way for Infamy to log a marker on each DUT when a test attaches, and another when the test exits. The syslog lines between the two are fetched over SSH and saved next to the test output: test/.log//output/0006-set-hostname.log test/.log//syslog/0006-set-hostname-{target}.log Each marker also carries the host's wall-clock time, so DUT lines can be lined up with the test output. Markers are only logged at test start and end to keep overhead down. Capture is best-effort: if a DUT has rebooted or can't be reached, the test gets a diagnostic comment and no syslog file. The test result is never affected. Resolves: #1608 Signed-off-by: Ejub Sabic --- test/infamy/dutlog.py | 98 +++++++++++++++++++++++++++++++++++++++++++ test/infamy/env.py | 10 ++++- test/infamy/tap.py | 9 ++++ 3 files changed, 116 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..0494fc2b8 --- /dev/null +++ b/test/infamy/dutlog.py @@ -0,0 +1,98 @@ +"""Capture each attached DUT's syslog for the duration of a test + +A begin marker is logged on every DUT when the test attaches to it, +and an end marker when the test exits. The lines between the two are +then fetched over SSH and saved next to the 9pm test output, in +$NINEPM_LOG_PATH/syslog/-.log + +Both markers carry the host's wall-clock time, so the offset between +the DUT and host clocks can be read from the captured file and DUT +log lines lined up with the 9pm output log. Marker matching is done +on a per-run id, never on timestamps, so a DUT with a skewed clock or +another timezone does not matter. + +Everything here is best-effort, a DUT that has rebooted or lost its +management connectivity must never fail the test. +""" +import datetime +import os +import subprocess +import sys +import uuid + +from . import ssh + +LOGS = "/var/log/syslog.0 /var/log/syslog" +TAG = "infamy" + + +def _now(): + return datetime.datetime.now().astimezone().isoformat(timespec="milliseconds") + + +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.duts = {} + + def _marker(self, what): + return f"test-{what} {self.test} run={self.run} host-time={_now()}" + + def begin(self, node, dev, location): + """Log the begin marker on node, once, and remember how to reach it""" + if node in self.duts: + return + + self.duts[node] = ssh.Location(location.host, location.username, + location.password) + try: + if hasattr(dev, "log"): + dev.log(self._marker("begin"), app_name=TAG, msgid="test-begin") + else: + dev.runsh(f"logger -t {TAG} -p user.notice '{self._marker('begin')}'", + timeout=10) + except Exception as e: + print(f"dutlog: failed logging begin marker on {node}: {e}") + + def end(self): + """Log the end marker on all DUTs and save what was logged in-between""" + for node, location in self.duts.items(): + try: + self._fetch(node, location) + except Exception as e: + print(f"dutlog: failed capturing syslog from {node}: {e}") + + def _fetch(self, node, location): + # One SSH round-trip: log the end marker over the same transport + # for every DUT, wait for syslogd to write it, then extract this + # run. The rotated file is included in case the log rotated + # during the test. + run = f"run={self.run}" + script = f""" +logger -t {TAG} -p user.notice '{self._marker("end")}' +for i in $(seq 20); do + sudo grep -q 'test-end.*{run}' /var/log/syslog && break + sleep 0.1 +done +sudo cat {LOGS} 2>/dev/null | awk '/test-begin.*{run}/ {{p=1}} p; /test-end.*{run}/ {{exit}}' +""" + dev = ssh.Device(node, location, wait=False) + rc = dev.run("/bin/sh", text=True, input=script, stdout=subprocess.PIPE, + stderr=subprocess.DEVNULL, loglevel="QUIET", timeout=30) + if rc.returncode != 0 or not rc.stdout: + print(f"dutlog: no syslog captured from {node} (rc {rc.returncode})") + return + + logdir = os.environ.get("NINEPM_LOG_PATH") + if not logdir: + print(f"dutlog: {node}: {len(rc.stdout.splitlines())} lines, " + "set NINEPM_LOG_PATH to save them") + return + + path = os.path.join(logdir, "syslog", f"{self.test}-{node}.log") + os.makedirs(os.path.dirname(path), exist_ok=True) + with open(path, "w") as f: + f.write(rc.stdout) + print(f"dutlog: {node}: saved {len(rc.stdout.splitlines())} lines to {path}") diff --git a/test/infamy/env.py b/test/infamy/env.py index 6a6359ac8..365b0a08f 100644 --- a/test/infamy/env.py +++ b/test/infamy/env.py @@ -123,6 +123,10 @@ def is_reachable(self, node, port): return util.is_reachable(ip, self, self.get_password(node)) + def _dutlog(self, name, dev): + if tap.CURRENT: + tap.CURRENT.dutlog.begin(name, dev, dev.location) + def attach(self, node, port="mgmt", protocol=None, test_reset=True, username=None, password=None): """Attach to node on port using protocol.""" @@ -164,13 +168,16 @@ def attach(self, node, port="mgmt", protocol=None, test_reset=True, username=Non password), mapping=mapping, yangdir=self.args.yangdir) + self._dutlog(name, dev) if test_reset: dev.test_reset() util.until(lambda: self.is_reachable(node, cport), 30) return dev if protocol == "ssh": - return ssh.Device(name, ssh.Location(mgmtip, username, password)) + dev = ssh.Device(name, ssh.Location(mgmtip, username, password)) + self._dutlog(name, dev) + return dev if protocol == "restconf": dev = restconf.Device(name, @@ -180,6 +187,7 @@ def attach(self, node, port="mgmt", protocol=None, test_reset=True, username=Non password), mapping=mapping, yangdir=self.args.yangdir) + self._dutlog(name, dev) if test_reset: dev.test_reset() util.until(lambda: self.is_reachable(node, cport), 30) diff --git a/test/infamy/tap.py b/test/infamy/tap.py index 2ff55074d..26066721d 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") From 3f2cc67d33f3d212bd2a5886f91921c06153c648 Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Sat, 3 Oct 2026 19:48:50 +0200 Subject: [PATCH 2/5] test: make DUT syslog capture opt-in Capturing syslog adds an SSH call per DUT when each test exits, and most runs don't need the logs. Capture is now off unless enabled with the new --capture-syslog Infamy argument, or with: make TEST_SYSLOG_CAPTURE=y test Signed-off-by: Ejub Sabic --- test/infamy/dutlog.py | 20 ++++++-------------- test/infamy/env.py | 3 ++- test/test.mk | 5 +++++ 3 files changed, 13 insertions(+), 15 deletions(-) diff --git a/test/infamy/dutlog.py b/test/infamy/dutlog.py index 0494fc2b8..cdf0134e4 100644 --- a/test/infamy/dutlog.py +++ b/test/infamy/dutlog.py @@ -1,18 +1,10 @@ -"""Capture each attached DUT's syslog for the duration of a test +"""Save each DUT's syslog for the duration of a test -A begin marker is logged on every DUT when the test attaches to it, -and an end marker when the test exits. The lines between the two are -then fetched over SSH and saved next to the 9pm test output, in -$NINEPM_LOG_PATH/syslog/-.log - -Both markers carry the host's wall-clock time, so the offset between -the DUT and host clocks can be read from the captured file and DUT -log lines lined up with the 9pm output log. Marker matching is done -on a per-run id, never on timestamps, so a DUT with a skewed clock or -another timezone does not matter. - -Everything here is best-effort, a DUT that has rebooted or lost its -management connectivity must never fail the test. +Off by default, enable with --capture-syslog or TEST_SYSLOG_CAPTURE=y. +A marker with a per-run id is logged on each DUT when the test begins +and ends, and the lines between them are saved to +$NINEPM_LOG_PATH/syslog/-.log. Best-effort, a failed +capture never fails the test. """ import datetime import os diff --git a/test/infamy/env.py b/test/infamy/env.py index 365b0a08f..ccad777db 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) @@ -124,7 +125,7 @@ def is_reachable(self, node, port): return util.is_reachable(ip, self, self.get_password(node)) def _dutlog(self, name, dev): - if tap.CURRENT: + if tap.CURRENT and getattr(self.args, "capture_syslog", False): tap.CURRENT.dutlog.begin(name, dev, dev.location) def attach(self, node, port="mgmt", protocol=None, test_reset=True, username=None, password=None): diff --git a/test/test.mk b/test/test.mk index fdc10ff27..6784c5d18 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; \ From cf4a6c08548ddf576aea6890068debd1a31924e5 Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Sat, 3 Oct 2026 19:49:54 +0200 Subject: [PATCH 3/5] doc: describe DUT syslog capture in the test guide Explain what is saved, where the files end up, and how to enable it for make test and for interactive 9pm runs. Signed-off-by: Ejub Sabic --- doc/testing.md | 31 +++++++++++++++++++++++++++++++ 1 file changed, 31 insertions(+) diff --git a/doc/testing.md b/doc/testing.md index 99abffdcd..583f3f6ba 100644 --- a/doc/testing.md +++ b/doc/testing.md @@ -323,6 +323,37 @@ $ 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, Infamy logs a +marker in the syslog of each DUT when a test attaches to it, and +another when the test exits. The lines between the two are saved next +to the test output, one file per test and DUT: + +``` +test/.log/last/output/0006-set-hostname.log +test/.log/last/syslog/0006-set-hostname-target.log +``` + +Capture is disabled by default, since it adds an SSH call per DUT when +each test exits. 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 +``` + +Each marker carries the host's wall-clock time, which can be compared +with the DUT's own timestamp on 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, From fafe7e47df63799c3499c151028cfa85f92c13fd Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Sat, 3 Oct 2026 19:52:10 +0200 Subject: [PATCH 4/5] doc: add missing 'make test-spec' output from main 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 55c6386c61789222d4d583fc93db927b41cf18c0 Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Sat, 3 Oct 2026 23:34:59 +0200 Subject: [PATCH 5/5] test: collect DUT syslog in the test container As discussed in #1608, DUTs now send their syslog to the test container instead of Infamy fetching it over SSH. Logs up to a crash or reboot are kept, and each test and DUT gets its own directory: test/.log//syslog///syslog Test start and stop are marked with the log RPC, msgid test-start and test-stop. The container image gets sysklogd and is bumped to 2.15. Capture is still off by default. Signed-off-by: Ejub Sabic --- .github/workflows/test.yml | 9 ++ doc/testing.md | 22 +++-- test/.env | 2 +- test/docker/Dockerfile | 8 ++ test/infamy/dutlog.py | 196 ++++++++++++++++++++++++++----------- test/infamy/env.py | 14 ++- 6 files changed, 175 insertions(+), 76 deletions(-) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index be21f3725..21ec3d3ce 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/syslog/ + if-no-files-found: ignore diff --git a/doc/testing.md b/doc/testing.md index 583f3f6ba..280fe31ff 100644 --- a/doc/testing.md +++ b/doc/testing.md @@ -326,18 +326,18 @@ $ make test-sh ### 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, Infamy logs a -marker in the syslog of each DUT when a test attaches to it, and -another when the test exits. The lines between the two are saved next -to the test output, one file per test and DUT: +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.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 adds an SSH call per DUT when -each test exits. Enable it for a test run with: +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 @@ -350,9 +350,11 @@ $ make test-sh 09:08:17 infamy0:test # ./9pm/9pm.py -o"--capture-syslog" case/system/hostname.py ``` -Each marker carries the host's wall-clock time, which can be compared -with the DUT's own timestamp on the same line to line up DUT log lines -with the test output. +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 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 diff --git a/test/infamy/dutlog.py b/test/infamy/dutlog.py index cdf0134e4..b59e8852f 100644 --- a/test/infamy/dutlog.py +++ b/test/infamy/dutlog.py @@ -1,25 +1,70 @@ -"""Save each DUT's syslog for the duration of a test +"""Collect each DUT's syslog in the test container during a test Off by default, enable with --capture-syslog or TEST_SYSLOG_CAPTURE=y. -A marker with a per-run id is logged on each DUT when the test begins -and ends, and the lines between them are saved to -$NINEPM_LOG_PATH/syslog/-.log. Best-effort, a failed -capture never fails the test. +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 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 -from . import ssh +SYSLOGD = "/usr/local/sbin/syslogd" +CONF = "/tmp/infamy-syslog.conf" +PIDFILE = "/tmp/infamy-syslogd.pid" +SOCKET = "/tmp/infamy-syslog.sock" +SDID = "test@61046" -LOGS = "/var/log/syslog.0 /var/log/syslog" -TAG = "infamy" +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 -def _now(): - return datetime.datetime.now().astimezone().isoformat(timespec="milliseconds") + 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: @@ -27,64 +72,101 @@ 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 _marker(self, what): - return f"test-{what} {self.test} run={self.run} host-time={_now()}" + 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 begin(self, node, dev, location): - """Log the begin marker on node, once, and remember how to reach it""" - if node in self.duts: + 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 - self.duts[node] = ssh.Location(location.host, location.username, - location.password) + 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: - if hasattr(dev, "log"): - dev.log(self._marker("begin"), app_name=TAG, msgid="test-begin") + 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: - dev.runsh(f"logger -t {TAG} -p user.notice '{self._marker('begin')}'", - timeout=10) + print(f"dutlog: {node}: no syslog received in {self._path(node)}") except Exception as e: - print(f"dutlog: failed logging begin marker on {node}: {e}") + print(f"dutlog: {node}: failed setting up syslog capture: {e}") def end(self): - """Log the end marker on all DUTs and save what was logged in-between""" - for node, location in self.duts.items(): + """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._fetch(node, location) + self._mark(node, dev, "test-stop") + _wait(lambda: _logged(self._path(node), self.run, "test-stop"), 2) except Exception as e: - print(f"dutlog: failed capturing syslog from {node}: {e}") - - def _fetch(self, node, location): - # One SSH round-trip: log the end marker over the same transport - # for every DUT, wait for syslogd to write it, then extract this - # run. The rotated file is included in case the log rotated - # during the test. - run = f"run={self.run}" - script = f""" -logger -t {TAG} -p user.notice '{self._marker("end")}' -for i in $(seq 20); do - sudo grep -q 'test-end.*{run}' /var/log/syslog && break - sleep 0.1 -done -sudo cat {LOGS} 2>/dev/null | awk '/test-begin.*{run}/ {{p=1}} p; /test-end.*{run}/ {{exit}}' -""" - dev = ssh.Device(node, location, wait=False) - rc = dev.run("/bin/sh", text=True, input=script, stdout=subprocess.PIPE, - stderr=subprocess.DEVNULL, loglevel="QUIET", timeout=30) - if rc.returncode != 0 or not rc.stdout: - print(f"dutlog: no syslog captured from {node} (rc {rc.returncode})") - return + print(f"dutlog: {node}: failed logging stop marker: {e}") - logdir = os.environ.get("NINEPM_LOG_PATH") - if not logdir: - print(f"dutlog: {node}: {len(rc.stdout.splitlines())} lines, " - "set NINEPM_LOG_PATH to save them") - return + try: + self.duts = {} + self._reload(_syslogd()) + except Exception as e: + print(f"dutlog: failed resetting syslog capture: {e}") - path = os.path.join(logdir, "syslog", f"{self.test}-{node}.log") - os.makedirs(os.path.dirname(path), exist_ok=True) - with open(path, "w") as f: - f.write(rc.stdout) - print(f"dutlog: {node}: saved {len(rc.stdout.splitlines())} lines to {path}") + print(f"dutlog: syslog saved in {self.dir}") diff --git a/test/infamy/env.py b/test/infamy/env.py index ccad777db..3451c03ed 100644 --- a/test/infamy/env.py +++ b/test/infamy/env.py @@ -124,9 +124,9 @@ def is_reachable(self, node, port): return util.is_reachable(ip, self, self.get_password(node)) - def _dutlog(self, name, dev): + def _dutlog(self, name, dev, mgmtip, cport, dport): if tap.CURRENT and getattr(self.args, "capture_syslog", False): - tap.CURRENT.dutlog.begin(name, dev, dev.location) + 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.""" @@ -151,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)) @@ -169,16 +169,14 @@ def attach(self, node, port="mgmt", protocol=None, test_reset=True, username=Non password), mapping=mapping, yangdir=self.args.yangdir) - self._dutlog(name, dev) 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": - dev = ssh.Device(name, ssh.Location(mgmtip, username, password)) - self._dutlog(name, dev) - return dev + return ssh.Device(name, ssh.Location(mgmtip, username, password)) if protocol == "restconf": dev = restconf.Device(name, @@ -188,10 +186,10 @@ def attach(self, node, port="mgmt", protocol=None, test_reset=True, username=Non password), mapping=mapping, yangdir=self.args.yangdir) - self._dutlog(name, dev) 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}\"")