test: capture DUT syslog per test

[saba8814]

Description

This PR introduces a way for Infamy to collect each DUT's syslog per test.
Each DUT sends its syslog to the test container, which saves it per test
and DUT next to the test output:

test/.log/<run>/output/0006-set-hostname.log
test/.log/<run>/syslog/0006-set-hostname/target/{syslog,kern.log,messages}

After the run, make test packs the logs in logs.tar.gz, which CI uploads
as the dut-syslog artifact. Capture is off by default, enable it with
make TEST_SYSLOG_CAPTURE=y test.

The start and stop of each test, and each test step, are marked in the
DUT's log with the host's time, so DUT lines can be lined up with the test
output. Capture is best-effort: if a DUT reboots, its log is kept up to
the reboot and resumes when the test attaches again. Tests that set up
syslog themselves stop the capture for that DUT. The test result is
never affected.

Resolves: #1608

Checklist

Tick relevant boxes, this PR is-a or has-a:

• Bugfix
  • Regression tests
  • ChangeLog updates (for next release)
• Feature
  • YANG model change => revision updated?
  • Regression tests added?
  • ChangeLog updates (for next release)
  • Documentation added?
• Test changes
  • Checked in changed Readme.adoc (make test-spec)
  • Added new test to group Readme.adoc and yaml file
• Code style update (formatting, renaming)
• Refactoring (please detail in commit messages)
• Build related changes
• Documentation content changes
  • ChangeLog updated (for major changes)
• Other (please describe):

[saba8814]

@wkz - @rical Want your pair of eyes on this one.

[troglobit]

Minor feedback, the recipe in #1608 defines the boundaries and what I'd like to see in this PR.

(Upstream sysklogd has even more magic stuff, but it's not merged or released, yet so we can build upon that later.)

[wkz]

Sorry that I am late to this party. I have some general hesitations about this approach:

1. It adds an additional config cycle to the execution of every test case
2. The configuration is in-band in the syslog YANG model. Presumably this means that test cases that themselves make use of syslog will remove this config
3. Test cases that reboot the system will presumably stop logging after the reboot
4. It couples Infamy more tightly to 9PM, because I do not think the logfile paths will be resolved correctly unless test cases are invoked via 9PM.

I would suggest another approach with, IMO, a clearer separation of concerns between the actors involved. Broadly:

1. On our devices, we extend the test-mode plugin to generate a syslog config snippet that is out-of-band with respect to confd, that would enable remote logging to the controller. We do this by extending /mnt/aux/test-mode from a simple marker file to one that contains a JSON document. Initially, the document would contain a single key-value pair that let's the device know which interface is used as the management port, e.g., { "management-interface": "e1" }. With that information, the test-mode would be able to generate a syslog configuration snippet, very early in the boot process, that logs to a statically defined multicast group by just concatenating the group address with the management interface, e.g., ff02::161%e1. Logging would then start as soon as the management interface comes up, and would not be affected by reboots or syslog configuration via {NET,REST}CONF.
2. When launching a test environment (make test or make test-sh), a syslog sink is always launched, and logs are automatically collected whenever a test is run, whether invoked as part of a 9PM suite or interactively from a shell. This means we can also use this feature when debugging issues locally. Logs are collected in a single file, which means Infamy does not need to concern itself with any log paths. Instead, we create tooling that allow us to easily filter the full log to only see a single test case, a single DUT, or whatever is needed. In our graphical front-ends, like ghmoon-web, we can re-use this tooling to create the commonly needed per-DUT-per-test-case logs, either as a post-processing step after the whole suite has run, or on-demand in the backend.

In summary:

• An Infix device in test-mode intrinsically knows that it should send its logs remotely and where those logs should be sent.
• A test environment intrinsically knows that it should persist logs from Infix devices and where it needs to listen to receive those logs.
• Infamy knows only that it should call the log RPC at test and step boundaries. It knows nothing about the remote syslog setup, the group addresses being used, where the log file is stored, etc.

What do you think @saba8814? What does the team think? (ping @mattiaswal @rical @troglobit)

[troglobit]

@wkz thank you for taking the time to review this thoroughly!

We talked about this AFK so I'm 100% onboard with this approach. It drops the extra config step, reducing complexity, and makes infamy more separate from the whole logging, meaning a developer don't necessarily have to run a local sysklogd instance.

The only outstanding thing to figure out with this simplified take is ensuring the DUTs log with their DUTn names, because when tests run they change their hostname to their logical roles in each test.

Two ways to get DUTn names on the stream right now, both on the receiving side:

• Let the receiver rename by peer. Without -H, the receiving syslogd replaces the hostname in each remote message with the name of the sending peer. Put the DUT addresses in the server's /etc/hosts with their DUTn names and the log lines show up as DUT1, DUT2 and so on, regardless of what the DUT calls itself at that moment. This is the least work.

• However, I think it would be better if the DUT's syslogd always sends its name. And with the new JSON format for /mnt/aux/test-mode we could add a "hostname": "DUT1", or similar, that we use in the syslog.d/ snippet:

    *.*    @[ff02::161%e1]    ;RFC5424,hostname=DUT1
  

A per-action option is better than a global override, because local files and the local ring buffer would keep the real hostname while only the stream to the test server uses the fixed name. I'll cook this up and prepare a backport branch for the sysklogd 2.x series.

[wkz]

@wkz thank you for taking the time to review this thoroughly!

We talked about this AFK so I'm 100% onboard with this approach. It drops the extra config step, reducing complexity, and makes infamy more separate from the whole logging, meaning a developer don't necessarily have to run a local sysklogd instance.

The only outstanding thing to figure out with this simplified take is ensuring the DUTs log with their DUTn names, because when tests run they change their hostname to their logical roles in each test.

Two ways to get DUTn names on the stream right now, both on the receiving side:

* Let the receiver rename by peer. Without `-H`, the receiving `syslogd` replaces the hostname in each remote message with the name of the sending peer.  Put the DUT addresses in the server's `/etc/hosts` with their `DUTn` names and the log lines show up as `DUT1`, `DUT2` and so on, regardless of what the DUT calls itself at that moment. This is the least work.

* However, I think it would be better if the DUT's syslogd always sends its name.  And with the new JSON format for `/mnt/aux/test-mode` we could add a `"hostname": "DUT1"`, or similar, that we use in the syslog.d/ snippet:
  ```
    *.*    @[ff02::161%e1]    ;RFC5424,hostname=DUT1
  ```

A per-action option is better than a global override, because local files and the local ring buffer would keep the real hostname while only the stream to the test server uses the fixed name. I'll cook this up and prepare a backport branch for the sysklogd 2.x series.

Summary of further AFK discussions: We should add a "physical-name": "styx1" pair to the test-mode JSON document, and then send this as structured data. Then the hostname would always reflect the logical name set by the test, but we can still filter on a physical node when needed.

[troglobit]

Yup, I'm looking at adding a new feature that would be able to inject structured data on all log messages, like this:

*.*    @[ff02::161%e1]    ;RFC5424,sd=[device@32473 name="dut1"]