From aca3f3ee417406571b8f135f5c32805ced0c615f Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Tue, 27 Oct 2026 07:30:33 +0100 Subject: [PATCH 1/4] board/common: forward logs to the test controller in test mode When a test fails in CI the DUTs are gone, and with them their logs. In test mode, a DUT with a management interface in its test mode settings now sends all its logs to ff02::161 on that port, tagged with its name in the topology, since tests change the hostname. This is set up at boot, outside the configuration, so it keeps working when a test configures syslog or reboots the DUT. Signed-off-by: Ejub Sabic --- .../usr/libexec/infix/init.d/30-test-mode | 28 +++++++++++++++++++ 1 file changed, 28 insertions(+) create mode 100755 board/common/rootfs/usr/libexec/infix/init.d/30-test-mode diff --git a/board/common/rootfs/usr/libexec/infix/init.d/30-test-mode b/board/common/rootfs/usr/libexec/infix/init.d/30-test-mode new file mode 100755 index 0000000000..9662774451 --- /dev/null +++ b/board/common/rootfs/usr/libexec/infix/init.d/30-test-mode @@ -0,0 +1,28 @@ +#!/bin/sh +# In test mode, forward all logs to the test controller's syslog sink. +# +# The test mode settings are a JSON object, from qemu (fw_cfg) or the +# test-mode file on aux, which is an empty marker on older setups: +# +# { "management-interface": "e1", "physical-name": "dut1" } + +ident=$(basename "$0") +conf=/etc/syslog.d/test-mode.conf +group=ff02::161 + +[ -f /mnt/aux/test-mode ] || exit 0 + +# Qemu settings (for testing) take precedence over the test-mode file +file=/sys/firmware/qemu_fw_cfg/by_name/opt/test-mode/raw +[ -f "$file" ] || file=/mnt/aux/test-mode + +iface=$(jq -r '."management-interface" // empty' "$file" 2>/dev/null) +[ -n "$iface" ] || exit 0 +name=$(jq -r '."physical-name" // empty' "$file" 2>/dev/null) + +opts="RFC5424,iface=$iface" +[ -n "$name" ] && opts="$opts,sd=[device@32473 name=\"$name\"]" +echo "*.* @[$group] ;$opts" > "$conf" + +logger -k -p user.notice -t "$ident" "Forwarding logs to $group on $iface" +kill -HUP "$(cat /run/syslogd.pid)" From bfb59719db8e16a4561c7f932f26b50c43c9abc8 Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Mon, 26 Oct 2026 21:20:40 +0100 Subject: [PATCH 2/4] test: pass test mode settings to virtual DUTs over fw_cfg All virtual DUTs share one image, and with it one test-mode file, so each node gets its management port and topology name from Qeneth in opt/test-mode instead. Signed-off-by: Ejub Sabic --- test/templates/inc/infix-fwcfg.mustache | 1 + test/templates/inc/infix-test-mode.mustache | 7 +++++++ test/templates/infix-bios-x86_64.mustache | 1 + test/templates/infix-kernel-x86_64.mustache | 1 + test/templates/infix-x86_64.mustache | 1 + 5 files changed, 11 insertions(+) create mode 100644 test/templates/inc/infix-test-mode.mustache diff --git a/test/templates/inc/infix-fwcfg.mustache b/test/templates/inc/infix-fwcfg.mustache index 2689a41ef9..0292f8d318 100644 --- a/test/templates/inc/infix-fwcfg.mustache +++ b/test/templates/inc/infix-fwcfg.mustache @@ -1,3 +1,4 @@ -fw_cfg name=opt/mactab,file=$imgdir/{{name}}.mactab \ -fw_cfg name=opt/wifi,file=$imgdir/{{name}}.wifi \ -fw_cfg name=opt/modem,file=$imgdir/{{name}}.modem \ + -fw_cfg name=opt/test-mode,file=$imgdir/{{name}}.test-mode \ diff --git a/test/templates/inc/infix-test-mode.mustache b/test/templates/inc/infix-test-mode.mustache new file mode 100644 index 0000000000..34c59f8c23 --- /dev/null +++ b/test/templates/inc/infix-test-mode.mustache @@ -0,0 +1,7 @@ +# Test mode settings for this node, read at boot by 30-test-mode (fw_cfg +# opt/test-mode): its port on the mgmt link and its name in the topology. +mgmt= +{{#links}} +case " {{provides}} " in *" mgmt "*) mgmt="{{qn_name}}";; esac +{{/links}} +echo "{ \"management-interface\": \"$mgmt\", \"physical-name\": \"{{name}}\" }" > $imgdir/{{name}}.test-mode diff --git a/test/templates/infix-bios-x86_64.mustache b/test/templates/infix-bios-x86_64.mustache index 0dc6683620..b706ed92d1 100644 --- a/test/templates/infix-bios-x86_64.mustache +++ b/test/templates/infix-bios-x86_64.mustache @@ -15,6 +15,7 @@ qemu-img create -b $origimg -F raw -f qcow2 {{name}}.qcow2 4G {{> inc/infix-wifi}} {{> inc/infix-modem}} +{{> inc/infix-test-mode}} {{#qn_gps}} mkfifo /tmp/{{name}}-gps.in /tmp/{{name}}-gps.out 2>/dev/null diff --git a/test/templates/infix-kernel-x86_64.mustache b/test/templates/infix-kernel-x86_64.mustache index d5e814b028..b7c3758c69 100644 --- a/test/templates/infix-kernel-x86_64.mustache +++ b/test/templates/infix-kernel-x86_64.mustache @@ -17,6 +17,7 @@ unsquashfs -n -f -d $imgdir $img boot/bzImage >/dev/null {{> inc/infix-wifi}} {{> inc/infix-modem}} +{{> inc/infix-test-mode}} exec qemu-system-x86_64 -M pc,accel=kvm:tcg -cpu max \ -m {{#qn_mem}}{{qn_mem}}{{/qn_mem}}{{^qn_mem}}384M{{/qn_mem}} \ diff --git a/test/templates/infix-x86_64.mustache b/test/templates/infix-x86_64.mustache index a8d8673cda..5c930bd6a9 100644 --- a/test/templates/infix-x86_64.mustache +++ b/test/templates/infix-x86_64.mustache @@ -17,6 +17,7 @@ unsquashfs -n -f -d $imgdir $img boot/bzImage >/dev/null {{> inc/infix-wifi}} {{> inc/infix-modem}} +{{> inc/infix-test-mode}} exec qemu-system-x86_64 -M pc,accel=kvm:tcg -cpu max \ -m {{#qn_mem}}{{qn_mem}}{{/qn_mem}}{{^qn_mem}}384M{{/qn_mem}} \ From bc3032eee31a8b01db17b7746fe70a8969468c4e Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Mon, 26 Oct 2026 21:20:41 +0100 Subject: [PATCH 3/4] test: collect DUT logs and split them per test and device test/env starts a sysklogd listening to ff02::161 on each of the controller's management ports, saving the logs of all DUTs in one file per session, named in $TEST_SYSLOG. Infamy logs test-start on attach, step at the start of each step, and test-stop on exit, with the test name and the DUT's role as structured data. Markers are best effort: a DUT that does not answer is skipped until it is attached again. syslog_split.py uses the markers to filter the collected log on a test or a device, or to split it into one file per test and device. After make test the split logs are packed in .log/last/logs.tar.gz, which CI uploads as the dut-syslog artifact. Resolves: #1608 Signed-off-by: Ejub Sabic --- .github/workflows/test.yml | 8 +++ test/env | 12 ++++- test/infamy/env.py | 29 +++++----- test/infamy/marker.py | 57 ++++++++++++++++++++ test/infamy/tap.py | 4 ++ test/syslog-sink | 47 ++++++++++++++++ test/test.mk | 6 +++ test/utils/syslog_split.py | 108 +++++++++++++++++++++++++++++++++++++ 8 files changed, 256 insertions(+), 15 deletions(-) create mode 100644 test/infamy/marker.py create mode 100755 test/syslog-sink create mode 100755 test/utils/syslog_split.py diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 8ab4162e4a..fa915872d3 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -160,3 +160,11 @@ jobs: with: name: ${{ inputs.name && inputs.name != 'infix' && format('xpath-coverage-report-{0}', inputs.name) || 'xpath-coverage-report' }} path: output/images/xpath-coverage-report.pdf + + - name: Upload DUT Syslog as Artifact + if: always() + uses: actions/upload-artifact@v7 + with: + name: ${{ inputs.name && inputs.name != 'infix' && format('dut-syslog-{0}', inputs.name) || 'dut-syslog' }} + path: ${{ env.TEST_PATH }}/.log/last/logs.tar.gz + if-no-files-found: ignore diff --git a/test/env b/test/env index 21bcda80a6..3ecca340eb 100755 --- a/test/env +++ b/test/env @@ -110,7 +110,7 @@ start_topology() sed -i "s/qn_image=\".*\"/qn_image=\"$img_name\"/" "$envdir/qeneth/topology.dot.in" (cd "$envdir/qeneth/" && $qeneth generate && $qeneth start) - INFAMY_ARGS="$INFAMY_ARGS $envdir/qeneth/topology.dot" + topology="$envdir/qeneth/topology.dot" cat <"$envdir/bin/qeneth" #!/bin/sh cd $envdir/qeneth && exec $testdir/qeneth/qeneth "\$@" @@ -118,6 +118,15 @@ EOF chmod +x "$envdir/bin/qeneth" } +start_syslog_sink() +{ + [ "$topology" ] || return 0 + + TEST_SYSLOG="$logdir/syslog-$(date +%Y%m%d-%H%M%S).log" + export TEST_SYSLOG + "$testdir/syslog-sink" "$topology" "$TEST_SYSLOG" || true +} + name() { nm=infamy @@ -272,6 +281,7 @@ export PYTHONPATH="$testdir" INFAMY_ARGS="$INFAMY_ARGS -y $envdir/yangdir" start_topology "$qenethdir" "$files" [ "$topology" ] && INFAMY_ARGS="$INFAMY_ARGS $topology" +start_syslog_sink if [ -n "$INFAMY_EXTRA_ARGS" ]; then INFAMY_ARGS="$INFAMY_ARGS $INFAMY_EXTRA_ARGS" fi diff --git a/test/infamy/env.py b/test/infamy/env.py index daf5ae80a1..1aa960be37 100644 --- a/test/infamy/env.py +++ b/test/infamy/env.py @@ -1,4 +1,5 @@ import argparse +import atexit import os import pydot import shlex @@ -6,7 +7,7 @@ import random import inspect -from . import neigh, netconf, restconf, ssh, tap, topology, util +from . import marker, neigh, netconf, restconf, ssh, tap, topology, util class NullEnv: @@ -79,6 +80,10 @@ 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.markers = marker.Markers() + tap.Test.step_hooks.append(self.markers.step) + atexit.register(self.markers.stop) + self.ltop = None if self.args.ltop != False: if self.args.ltop is None: @@ -196,15 +201,9 @@ def attach(self, node, port="mgmt", protocol=None, test_reset=True, username=Non password), mapping=mapping, yangdir=self.args.yangdir) - if test_reset: - dev.test_reset() - util.until(lambda: self.is_reachable(node, cport), 30) - return dev - - if protocol == "ssh": + elif protocol == "ssh": return ssh.Device(name, ssh.Location(mgmtip, username, password)) - - if protocol == "restconf": + elif protocol == "restconf": dev = restconf.Device(name, location=restconf.Location(cport, mgmtip, @@ -212,9 +211,11 @@ def attach(self, node, port="mgmt", protocol=None, test_reset=True, username=Non password), mapping=mapping, yangdir=self.args.yangdir) - if test_reset: - dev.test_reset() - util.until(lambda: self.is_reachable(node, cport), 30) - return dev + else: + raise Exception(f"Unsupported management procotol \"{protocol}\"") - raise Exception(f"Unsupported management procotol \"{protocol}\"") + if test_reset: + dev.test_reset() + util.until(lambda: self.is_reachable(node, cport), 30) + self.markers.attach(dev) + return dev diff --git a/test/infamy/marker.py b/test/infamy/marker.py new file mode 100644 index 0000000000..e127ec3b93 --- /dev/null +++ b/test/infamy/marker.py @@ -0,0 +1,57 @@ +"""Mark test and step boundaries in the DUTs' logs, see doc/test-arch.md""" +import os +import sys +import threading +import time + +SDID = "test@32473" + + +def test_name(): + """Name of the running test, as 9PM knows it or its directory""" + name = os.path.basename(os.path.dirname(os.path.realpath(sys.argv[0]))) + return os.environ.get("NINEPM_TEST_NAME", name) + + +class Markers: + """Best-effort, a DUT that does not answer is skipped until attached again""" + + def __init__(self): + self.test = test_name() + self.devs = {} + + def _log_one(self, dev, msgid, text, **params): + try: + dev.log(text, app_name="infamy", msgid=msgid, + sd={SDID: {"name": self.test, "role": dev.name, **params}}) + return True + except Exception as e: + print(f"{dev.name}: failed logging {msgid} marker: {e}") + return False + + def _log(self, devs, msgid, text, **params): + def log(dev): + if self._log_one(dev, msgid, text, **params): + done.add(dev.name) + + done = set() + threads = [threading.Thread(target=log, args=(dev,), daemon=True) for dev in devs] + for t in threads: + t.start() + deadline = time.monotonic() + 1 + for t in threads: + t.join(max(0, deadline - time.monotonic())) + + for dev in devs: + if dev.name not in done: + self.devs.pop(dev.name, None) + + def attach(self, dev): + if dev.name in self.devs or self._log_one(dev, "test-start", f"Test {self.test} starts"): + self.devs[dev.name] = dev + + def step(self, num, msg): + self._log(list(self.devs.values()), "step", f"Step {num}: {msg}", step=str(num)) + + def stop(self): + self._log(list(self.devs.values()), "test-stop", f"Test {self.test} stops") diff --git a/test/infamy/tap.py b/test/infamy/tap.py index 2ff55074db..bf06b07029 100644 --- a/test/infamy/tap.py +++ b/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) diff --git a/test/syslog-sink b/test/syslog-sink new file mode 100755 index 0000000000..4bbada56a3 --- /dev/null +++ b/test/syslog-sink @@ -0,0 +1,47 @@ +#!/bin/sh +# Collect the logs DUTs in test mode forward to ff02::161 on their mgmt +# port, all in one file. See doc/test-arch.md, and utils/syslog_split.py +set -e + +syslogd=/usr/sbin/syslogd +group=ff02::161 + +usage() +{ + echo "usage: syslog-sink " +} + +[ $# -eq 2 ] || { usage; exit 1; } +topology=$1 +log=$2 + +if [ ! -x "$syslogd" ]; then + echo "syslog-sink: $syslogd missing, not collecting DUT logs" >&2 + exit 0 +fi + +ports=$(python3 - "$topology" <<'EOF' +import sys +import pydot +from infamy.topology import Topology + +top = Topology(pydot.graph_from_dot_file(sys.argv[1])[0]) +ctrl = top.get_ctrl() +links = [top.get_mgmt_link(ctrl, node) for node in top.get_infixen()] +print(" ".join(link[0] for link in links if link)) +EOF +) + +dir=$(mktemp -d /tmp/syslog-sink.XXXXXX) +{ + echo "secure_mode 0" + for port in $ports; do + echo "listen [$group%$port]%$port" + done + echo "*.* -$log ;RFC5424" +} > "$dir/syslog.conf" + +mkdir -p "$(dirname "$log")" +$syslogd -f "$dir/syslog.conf" -p "$dir/log.sock" -P "$dir/syslogd.pid" \ + -C "$dir/syslogd.cache" -m 0 -8 -H -n -K +echo "syslog-sink: DUT logs saved in $log" diff --git a/test/test.mk b/test/test.mk index 5eb8e3256b..9e09718fa1 100644 --- a/test/test.mk +++ b/test/test.mk @@ -12,6 +12,7 @@ TESTS ?= $(test-dir)/case/all.yaml yang_extractor := $(test-dir)/utils/extract_xpaths.py coverage_reporter := $(test-dir)/utils/coverage_report.py +syslog_split := $(test-dir)/utils/syslog_split.py YANG_DIR ?= $(BR2_EXTERNAL_INFIX_PATH)/src/confd/yang/confd xpaths_all_csv := $(test-dir)/.log/xpaths_all.csv @@ -43,6 +44,11 @@ test: $(test-dir)/.log/last/xpath_coverage.log \ $(test-dir)/.log/last/xpath_coverage_report.md \ 2>/dev/null || true; \ + test ! -f "$$TEST_SYSLOG" || { \ + python3 $(syslog_split) -o $(test-dir)/.log/last/syslog "$$TEST_SYSLOG" && \ + ln -f "$$TEST_SYSLOG" $(test-dir)/.log/last/syslog/full.log && \ + tar czf $(test-dir)/.log/last/logs.tar.gz -C $(test-dir)/.log/last syslog; } || true; \ + chmod -R 777 $(test-dir)/.log; \ exit $$rc' test-sh: diff --git a/test/utils/syslog_split.py b/test/utils/syslog_split.py new file mode 100755 index 0000000000..79dae286c3 --- /dev/null +++ b/test/utils/syslog_split.py @@ -0,0 +1,108 @@ +#!/usr/bin/env python3 +"""Filter or split the DUT log collected by test/syslog-sink + +Lines are sorted to the test that runs when they are logged, from the +Infamy markers, and to the device that sent them, from its physical +name, or its hostname if it has none. Lines logged between two tests +belong to the next test, it is resetting the DUTs. + + syslog_split.py -t 0006-set-hostname -d dut1 syslog.log + syslog_split.py -o syslog/ syslog.log # syslog//.log +""" +import argparse +import os +import re +import sys + +TEST_SDID = "test@32473" +DEVICE_SDID = "device@32473" +HEADER = re.compile(r"^<\d+>1 ") +PARAM = re.compile(r'(\S+?)="((?:[^"\\]|\\.)*)"') +ELEMENT = re.compile(r'\[(\S+?)((?: \S+?="(?:[^"\\]|\\.)*")*)\]') + + +def parse_sd(text): + """Return {SD-ID: {name: value}} for the RFC 5424 STRUCTURED-DATA at the start of text""" + sd, pos = {}, 0 + while m := ELEMENT.match(text, pos): + sd[m[1]] = dict(PARAM.findall(m[2])) + pos = m.end() + return sd + + +def parse(line): + """Return (device, msgid, sd) of an RFC 5424 log line, None if it is not one""" + fields = HEADER.sub("", line, count=1).split(" ", 5) + if len(fields) < 6: + return None + + _, host, _, _, msgid, rest = fields + sd = parse_sd(rest) + device = sd.get(DEVICE_SDID, {}).get("name", host) + return device, msgid, sd + + +def split(lines): + """Yield (test, device, line), test is None for lines after the last test""" + test = None + pending = [] + + for line in lines: + entry = parse(line) + if not entry: + continue + + device, msgid, sd = entry + marked = sd.get(TEST_SDID, {}).get("name") + if msgid == "test-start" and marked: + test = marked + for dev, ln in pending: + yield test, dev, ln + pending = [] + + owner = marked or test + if owner: + yield owner, device, line + else: + pending.append((device, line)) + + if msgid == "test-stop" and marked == test: + test = None + + for dev, ln in pending: + yield None, dev, ln + + +def main(): + parser = argparse.ArgumentParser(description="Filter or split the DUT log from test/syslog-sink") + parser.add_argument("-t", "--test", help="only lines from this test") + parser.add_argument("-d", "--device", help="only lines from this device") + parser.add_argument("-o", "--outdir", help="write each test's log per device to OUTDIR//.log") + parser.add_argument("log", help="log file, - for stdin") + args = parser.parse_args() + + f = sys.stdin if args.log == "-" else open(args.log, errors="replace") + files = {} + try: + for test, device, line in split(f): + if args.test and test != args.test: + continue + if args.device and device != args.device: + continue + + if not args.outdir: + sys.stdout.write(line) + continue + + path = os.path.join(args.outdir, test or "after-last-test", f"{device}.log") + if path not in files: + os.makedirs(os.path.dirname(path), exist_ok=True) + files[path] = open(path, "w") + files[path].write(line) + finally: + for out in files.values(): + out.close() + + +if __name__ == "__main__": + main() From 645f0c34308c6f82b1768cb7d6ffc2286b1f1431 Mon Sep 17 00:00:00 2001 From: Ejub Sabic Date: Mon, 26 Oct 2026 21:20:42 +0100 Subject: [PATCH 4/4] doc: describe DUT log collection during tests Signed-off-by: Ejub Sabic --- doc/test-arch.md | 63 ++++++++++++++++++++++++++++++++++++++++++++++-- doc/testing.md | 22 +++++++++++++++++ 2 files changed, 83 insertions(+), 2 deletions(-) diff --git a/doc/test-arch.md b/doc/test-arch.md index a0cceb5064..6f6e3248b6 100644 --- a/doc/test-arch.md +++ b/doc/test-arch.md @@ -262,8 +262,53 @@ Infamy: once, instead of the `test-config` (used by tests that verify save-and-reboot behaviour) -Test mode is activated by the presence of an empty file named -`test-mode` on the device's `aux` partition (`/mnt/aux/test-mode`). +Test mode is activated by the presence of a file named `test-mode` on +the device's `aux` partition (`/mnt/aux/test-mode`). The file may be +empty, or hold the device's test mode settings as a JSON object: + +```json +{ "management-interface": "e1", "physical-name": "dut1" } +``` + +### DUT Logs + +When a test fails in CI, the DUTs' logs are often the only way to find +out why, but by then the DUTs are gone. So every DUT in test mode +forwards all its logs to the test controller, and the test environment +saves them. + +With `management-interface` set in the test mode settings, the DUT +sends all its logs, in RFC 5424 format, to the multicast group +`ff02::161` on that interface. This is set up at boot, outside the +configuration, so it keeps going when a test configures syslog, and +starts again after a reboot. With `physical-name` set, each message +also carries the structured data `[device@32473 name="dut1"]`, since +tests change the hostname to the DUT's role in the test. + +`test/env` always starts a syslog sink, `test/syslog-sink`, which +listens to the group on each of the controller's management ports and +saves the logs of all DUTs in one file, `test/.log/syslog-