test: collect DUT logs in test mode

.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

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

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-<time>.log`.
+Infamy does not know about the sink.  It only logs markers in the DUTs'
+logs, using the `infix-syslog:log` RPC:
+
+| MSGID        | Logged                          | Structured data                     |
+|--------------|---------------------------------|-------------------------------------|
+| `test-start` | on attach to a DUT              | `[test@32473 name="<test>" role="<node>"]` |
+| `step`       | when a step starts, on all DUTs | as above, and `step="<num>"`        |
+| `test-stop`  | when the test exits, on all DUTs | as above                           |
+
+The test name is the one 9PM gives it, e.g., `0006-set-hostname`, or
+the test's directory name when it runs on its own.
+
+`test/utils/syslog_split.py` uses the markers to filter the 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
+`test/.log/last/logs.tar.gz`, which CI uploads as the `dut-syslog`
+artifact.
+
+> [!NOTE]
+> `32473` is the documentation enterprise number from RFC 5612, a
+> placeholder until KernelKit has a Private Enterprise Number.
 
 ### Test Mode on Virtual Devices
 
@@ -272,6 +317,11 @@ script (`test/inject-test-mode`) is run automatically.  It copies the
 base disk image and writes the `test-mode` marker into the `aux`
 partition of that copy, which is then used as the Qeneth backing image.
 
+All virtual DUTs share that image, so their test mode settings come
+from Qeneth instead: each node gets its management port and its name
+in the topology over QEMU's `fw_cfg` (`opt/test-mode`), which takes
+precedence over the `test-mode` file.
+
 ### Test Mode on Physical Devices
 
 For a physical device, log in as `root` (or `admin`) and create the
@@ -282,6 +332,15 @@ marker file on the `aux` partition, then reboot:
 # reboot
 ```
 
+To also collect the device's logs during tests, write its management
+port and its name in the topology to the file instead, see
+[DUT Logs](#dut-logs):
+
+```
+# echo '{ "management-interface": "e1", "physical-name": "dut1" }' >/mnt/aux/test-mode
+# reboot
+```
+
 Alternatively, if you want to prepare the disk image before flashing,
 use the `inject-test-mode` script:
 

doc/testing.md

@@ -197,6 +197,28 @@ admin@infix-00-00-00:~$
 > "menu" using Ctrl-], compared to standard Telnet this is the BusyBox
 > version so you press 'e' + enter instead of 'q' to quit.
 
+### Reading DUT Logs
+
+When a test fails, the DUTs' logs often show why.  The test environment
+collects the logs of all DUTs in test mode in one file per session, see
+[DUT Logs](test-arch.md#dut-logs).
+Its name is in `$TEST_SYSLOG` inside the environment:
+
+```
+11:42:54 infamy0:test # tail -f $TEST_SYSLOG
+```
+
+Filter it on a test, a device, or both:
+
+```
+11:42:54 infamy0:test # utils/syslog_split.py -t 0006-set-hostname -d dut1 $TEST_SYSLOG
+```
+
+After `make test`, the logs of each test and device are also in
+`test/.log/last/syslog/<test>/<device>.log`, and packed in
+`test/.log/last/logs.tar.gz`.  In CI, download the `dut-syslog`
+artifact.
+
 ### Attaching to MACVLANs
 
 To fully isolate the host's interfaces from one another, many tests

test/env

@@ -110,14 +110,23 @@ 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 <<EOF >"$envdir/bin/qeneth"
 #!/bin/sh
 cd $envdir/qeneth && exec $testdir/qeneth/qeneth "\$@"
 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

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 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,25 +201,21 @@ 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,
                                                              username,
                                                              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

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

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/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 <TOPOLOGY> <LOGFILE>"
+}
+
+[ $# -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"

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 \

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

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