Skip to content

Support logging of serial traffic in the exporter#1862

Open
sjg20 wants to merge 2 commits into
labgrid-project:masterfrom
sjg20:push6-log
Open

Support logging of serial traffic in the exporter#1862
sjg20 wants to merge 2 commits into
labgrid-project:masterfrom
sjg20:push6-log

Conversation

@sjg20
Copy link
Copy Markdown
Contributor

@sjg20 sjg20 commented May 6, 2026

Description

Add optional centralised serial-traffic logging on the exporter
host: when LG_SERIAL_TRACE_DIR is set, the exporter passes
trace-both to the per-acquire ser2net and the resulting log
files are named <board>-<user>.log. This closes a visibility
gap for shared/multi-user labs where the per-client --logfile
only captures one user's session and the operator otherwise has
no independent record of what is happening on the console.

Three commits:

  1. protocol: add a user field to ExporterSetAcquiredRequest
    so the exporter knows who acquired a place; needed by (2).
    Older coordinators that don't send the field continue to work.
  2. exporter: the trace-logging feature itself, plus tests, a
    usage section in doc/usage.rst, an env-var entry in the
    exporter man page (regenerated under man/).
  3. tests: omit labgrid/remote/generated/* from coverage so
    protoc regen noise stops dragging the patch-coverage threshold
    under on routine protocol changes.

Tested on my own lab (~50 boards exported via ser2net 4.x,
including BeagleBone Black, Raspberry Pi 3, Coral and a handful
of x86 systems) over tailscale. Trace files correctly capture
every keystroke and reply for each acquire session, and append
on repeated acquires by the same user on the same board.

Checklist

  • Documentation for the feature
  • Tests for the feature
  • The arguments and description in doc/configuration.rst have been updated
  • Add a section on how to use the feature to doc/usage.rst
  • Add a section on how to use the feature to doc/development.rst
  • PR has been tested
  • Man pages have been regenerated

@sjg20 sjg20 force-pushed the push6-log branch 2 times, most recently from 49eb27c to 0e1c1f0 Compare May 6, 2026 19:24
@codecov
Copy link
Copy Markdown

codecov Bot commented May 6, 2026

Codecov Report

❌ Patch coverage is 76.19048% with 5 lines in your changes missing coverage. Please review.
✅ Project coverage is 47.5%. Comparing base (c027b2d) to head (0d9c88a).
✅ All tests successful. No failed tests found.

Files with missing lines Patch % Lines
labgrid/remote/exporter.py 84.2% 3 Missing ⚠️
labgrid/remote/coordinator.py 0.0% 2 Missing ⚠️
Additional details and impacted files
@@           Coverage Diff            @@
##           master   #1862     +/-   ##
========================================
+ Coverage    46.0%   47.5%   +1.5%     
========================================
  Files         180     180             
  Lines       14439   14459     +20     
========================================
+ Hits         6654    6882    +228     
+ Misses       7785    7577    -208     
Flag Coverage Δ
3.10 47.5% <76.1%> (+1.5%) ⬆️
3.11 47.5% <76.1%> (+1.5%) ⬆️
3.12 47.5% <76.1%> (+1.5%) ⬆️
3.13 47.5% <76.1%> (+1.5%) ⬆️
3.14 47.5% <76.1%> (+1.5%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@sjg20 sjg20 changed the title Push6 log Support logging of serial traffic in the exporter May 6, 2026
@sjg20 sjg20 marked this pull request as ready for review May 6, 2026 20:01
@Emantor
Copy link
Copy Markdown
Member

Emantor commented May 13, 2026

I like the general idea, especially since we can make use of the existing ser2net configuration capabilities for that.
Users should have SSH access to the exporter anyway, so from a permission/access point of view this also makes sense as long as we expect all users to have the same permissions to access all hardware connected to an exporter.

The thing I worry about is how to make this accessible to users and how to handle log rotation and time stamping so users are able to correlate which part of the log file was generated by them. Or do you intend this to be a purely administrative aid in debugging failing lab hardware?

Edit: I haven't checked that time stamping is handled by ser2net, if you could add a sample log file that would be great.

For the user side we already have --lg-log for the pytest plugin and for library usage ConsoleLoggingReporter(<directory> can be created, so this may be a bit redundant?

sjg20 added 2 commits May 13, 2026 06:00
The exporter currently cannot tell which user acquired a place - only
which client did, via the host/user pair stored as 'acquired'.  This
blocks features that want to attribute resource use to a specific user,
such as per-user serial trace files or audit logs on the exporter host.

Extend ExporterSetAcquiredRequest with a 'user' field containing the
host/user identity that acquired the place.  The field is populated from
place.acquired which already holds host/user.

The exporter stashes the value on the ResourceExport so subclasses can
use it (e.g. SerialPortExport for per-user trace files).

Older coordinators that don't send the field continue to work as before;
the field defaults to None on the exporter side.

Signed-off-by: Simon Glass <sjg@chromium.org>
Lab admins running shared boards have no independent record of what is
happening on the serial console.  The per-client --logfile option
captures output for the user who set it, but the lab owner has no way to
see traffic across all sessions, which hampers post-mortem when a board
ends up in a bad state and the question is which commands got it there.

Add support for centralised serial-traffic logging on the exporter host.
When LG_SERIAL_TRACE_DIR is set, the exporter passes ser2net's
trace-both option for each acquire, capturing every byte that flows in
either direction to a per-board, per-user file under that directory.

ser2net is started fresh on each resource acquire and stopped on
release, so each instance can include both the board (group name) and
the acquiring user in the filename: <board>-<user>.log (e.g.
bbb-okaro_sjg.log).  Repeated acquires by the same user on the same
board append to the same file.

The user identity comes from the coordinator via the new 'user' field in
ExporterSetAcquiredRequest (added in a previous commit).  The group name
is plumbed from the resource config through add_resource() into the
ResourceExport so the trace path can use the human-readable board name
instead of the device path.

trace-both-timestamp is also enabled, so ser2net writes timestamped
OPEN and CLOSE markers around each session.  The console data itself is
recorded verbatim with both directions interleaved, and the session
markers give the lab admin the boundaries needed to correlate a trace
with other audit logs.  Admins who need per-line timestamps at the cost
of readability can additionally set LG_SERIAL_TRACE_HEXDUMP=1 to switch
ser2net into hex+ASCII mode, where every line is timestamped.

Series-changes: 2
- Mention --lg-log and ConsoleLoggingReporter alongside --logfile, and
  clarify that the exporter trace is the operator's independent record
  (the user cannot influence it)
- Add real default-mode and hex-mode trace snippets to doc/usage.rst,
  captured from a running kea exporter
- Add LG_SERIAL_TRACE_HEXDUMP=1 to opt into ser2net's hexdump mode
  (timestamp on every line, at the cost of readability); cover both
  code paths with tests
- Correct the description: in the default mode only the OPEN and CLOSE
  session markers are timestamped, not every line
- Document filename fallbacks: device basename for missing group_name,
  literal 'unknown' for missing user
- Add doc sub-sections for systemd setup, file permissions, privacy
  implications and disk-usage growth in hexdump mode
- Note that log rotation is left to logrotate on the admin host, and
  that ser2net's append-on-open behaviour makes copytruncate/daily safe

Signed-off-by: Simon Glass <sjg@chromium.org>
Co-developed-by: Claude Opus 4.6 <noreply@anthropic.com>
@sjg20
Copy link
Copy Markdown
Contributor Author

sjg20 commented May 13, 2026

I like the general idea, especially since we can make use of the existing ser2net configuration capabilities for that. Users should have SSH access to the exporter anyway, so from a permission/access point of view this also makes sense as long as we expect all users to have the same permissions to access all hardware connected to an exporter.

The thing I worry about is how to make this accessible to users and how to handle log rotation and time stamping so users are able to correlate which part of the log file was generated by them. Or do you intend this to be a purely administrative aid in debugging failing lab hardware?

Edit: I haven't checked that time stamping is handled by ser2net, if you could add a sample log file that would be great.

For the user side we already have --lg-log for the pytest plugin and for library usage ConsoleLoggingReporter(<directory> can be created, so this may be a bit redundant?

Thanks for the review!

To clarify the intent: this is an admin-only audit/debug aid, not a user-facing logging mechanism. It complements rather than replaces --lg-log and ConsoleLoggingReporter:

  • --lg-log and ConsoleLoggingReporter record what the user sees, in a location the user controls. Users can turn them off, change the filter, or just not enable them.
  • LG_SERIAL_TRACE_DIR records every byte that flows through the serial console of every acquire, on the exporter host, where the lab admin can read it. The user can't affect what gets logged.

The new exporter trace is specifically for "which user ran which commands on board X between Tue 14:00 and 17:00 to put it in this state"-type questions, which the per-client logs don't answer.

On timestamps, the exporter does pass trace-both-timestamp: true, but actually
ser2net only timestamps the OPEN and CLOSE session markers in the default trace
mode, so not individual data lines:

2026/05/13 06:58:50 OPEN (ipv6,::ffff:192.168.4.7,60208)
...
 => eecchhoo  MMee  aaggaaiinn
Me again

=> 2026/05/13 06:59:06 CLOSE netcon (network read close)
2026/05/13 06:59:06 CLOSE port (All users disconnected)

(Both directions land in the same byte stream, which is why each typed character shows up twice - once from the user, once from the board's local echo.)

If per-line timestamps actually matter for a deployment, v2 adds LG_SERIAL_TRACE_HEXDUMP=1 which switches ser2net into hex+ASCII mode. The output is no longer readable text but every line carries a timestamp and a direction tag (term from the board, tcp from the client):

2026/05/13 07:21:11 tcp  65                       |e|
2026/05/13 07:21:11 term 65                       |e|
2026/05/13 07:21:11 tcp  63                       |c|
2026/05/13 07:21:11 term 63                       |c|
...
2026/05/13 07:21:15 term 0d 0a 48 65 6c 6c 6f 20  |..Hello |
2026/05/13 07:21:15 term 41 67 61 69 6e 0d 0a 3d  |Again..=|

On log rotation: not handled in the exporter itself. ser2net opens the trace file in append mode on each acquire, so logrotate's copytruncate or daily modes on LG_SERIAL_TRACE_DIR work
unchanged.

I updated usage.rst to show examples and talk about log rotation.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants