Skip to content

Support logging of serial traffic in the exporter #1862

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
sjg20 wants to merge 2 commits into
base: master
Choose a base branch
from
Open

Support logging of serial traffic in the exporter #1862

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
00f4748
protocol: Pass acquiring user from coordinator to exporter
sjg20 May 3, 2026
0d9c88a
exporter: Allow logging of serial traffic
sjg20 May 3, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
27 changes: 26 additions & 1 deletion doc/man/exporter.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -77,13 +77,38 @@ for more information.

ENVIRONMENT VARIABLES
---------------------
The following environment variable can be used to configure labgrid-exporter.
The following environment variables can be used to configure
labgrid-exporter.

LG_COORDINATOR
~~~~~~~~~~~~~~
This variable can be used to set the default coordinator in the format
``HOST[:PORT]`` (instead of using the ``-x`` option).

LG_SERIAL_TRACE_DIR
~~~~~~~~~~~~~~~~~~~
When set, the exporter records all serial-port traffic for each
acquired resource into ``<LG_SERIAL_TRACE_DIR>/<board>-<user>.log``,
where ``<board>`` is the resource group name and ``<user>`` is the
acquiring user identity reported by the coordinator (in
``host/user`` form, with ``/`` rewritten to ``_``). Both directions
are captured verbatim, and ser2net writes timestamped OPEN/CLOSE
markers at the start and end of each session so the lab admin has
an independent record that is not affected by per-client logging
options.

The directory is created on demand. A fresh ser2net instance is
started for each acquire, so repeated acquires by the same user on
the same board append to the same file.

LG_SERIAL_TRACE_HEXDUMP
~~~~~~~~~~~~~~~~~~~~~~~
When set to ``1`` (and ``LG_SERIAL_TRACE_DIR`` is also set), the
exporter additionally enables ser2net's hexdump format for the
trace. This prepends a timestamp to every line at the cost of
producing hex+ASCII output instead of readable text. Use this
when correlating to the millisecond matters more than readability.

EXAMPLES
--------

Expand Down
139 changes: 139 additions & 0 deletions doc/usage.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -166,6 +166,145 @@ allocated before returning.
A reservation will time out after a short time, if it is neither refreshed nor
used by locked places.

Logging Serial Traffic on the Exporter
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

When several developers (or CI jobs) share the same boards through a single
coordinator, it is often useful for the lab admin to keep an independent
record of every serial-console session. The per-client ``--logfile`` option
only records output for the user who set it, so it does not help the operator
answer questions like *which commands left this board in a bad state?* after
the fact.

To enable a centralised log on the exporter host, set the
``LG_SERIAL_TRACE_DIR`` environment variable before starting
``labgrid-exporter``:

.. code-block:: bash

$ export LG_SERIAL_TRACE_DIR=/var/log/labgrid/serial
$ labgrid-exporter my-config.yaml

For each acquire, the exporter asks ``ser2net`` to record both sides of the
serial connection to a file named ``<board>-<user>.log`` under that directory,
where ``<board>`` is the resource group name (falling back to the basename of
the device path if the resource has no group) and ``<user>`` is the host/user
identity reported by the coordinator (slashes rewritten to underscores so the
result is filesystem safe, or ``unknown`` for older coordinators that do not
send a user).

Because ``ser2net`` is started fresh on each acquire and stopped on release,
the trace covers exactly one session per acquire. Repeated acquires by the
same user on the same board append to the same file, so a long-running
developer ends up with a single, continuous log per board.

This feature complements rather than replaces user-side logging (``--logfile``
on the client, ``--lg-log`` on the pytest plugin, or ``ConsoleLoggingReporter``
when using labgrid as a library): the user-side logs are what the developer
sees in their terminal and chooses what to capture, while the exporter trace
is the operator's independent record that the user cannot influence.

A default-mode trace looks like this (user typed ``echo Me again`` at the
U-Boot prompt; each character of the input appears twice because ``tcp`` and
``term`` are written into the same stream, so the typed character and the
board's local echo are interleaved)::

2026/05/13 06:58:50 OPEN (ipv6,::ffff:192.168.4.7,60208)
...
Press SPACE to abort autoboot in 2 seconds
=> 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)

Connection events (``OPEN`` when ser2net accepts the client connection,
``CLOSE`` when the acquire is released) are timestamped by ser2net, giving
the session boundary that the lab admin can use to correlate a trace with
other audit logs. The console traffic itself is recorded verbatim with both
directions interleaved as they arrive, so the file reads like a transcript of
what was on the wire.

If per-line timestamps are needed (for example, when correlating to the
millisecond against another log source), additionally set
``LG_SERIAL_TRACE_HEXDUMP=1`` before starting ``labgrid-exporter``. The
exporter then enables ser2net's hexdump format for the trace, which prepends
a timestamp and a direction tag to every line at the cost of producing
hex+ASCII output instead of readable text. The direction tag is ``term`` for
bytes the board emitted and ``tcp`` for bytes the client sent. A hex trace
of the same ``echo Hello Again`` session looks like this — each typed
character shows up as a ``tcp`` line immediately followed by a ``term`` line
as the board echoes it, then the board's output appears as a single
multi-byte ``term`` line::

2026/05/13 07:21:02 OPEN (ipv6,::ffff:192.168.4.7,44566)
...
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:11 tcp 68 |h|
2026/05/13 07:21:11 term 68 |h|
2026/05/13 07:21:11 tcp 6f |o|
2026/05/13 07:21:11 term 6f |o|
2026/05/13 07:21:11 tcp 20 | |
2026/05/13 07:21:11 term 20 | |
...
2026/05/13 07:21:15 tcp 0a |.|
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..=|
2026/05/13 07:21:15 term 3e 20 |> |
2026/05/13 07:21:16 CLOSE netcon (network read close)

Setup with systemd
^^^^^^^^^^^^^^^^^^

When the exporter runs from a systemd unit, drop the variables into the
``[Service]`` section so they survive restarts:

.. code-block:: ini

[Service]
Environment=LG_SERIAL_TRACE_DIR=/var/log/labgrid/serial
# Optional, for per-line timestamps:
#Environment=LG_SERIAL_TRACE_HEXDUMP=1

Apply with ``systemctl daemon-reload && systemctl restart labgrid-exporter``.
Environment variables are read only when the exporter process starts, so a
config change needs a restart, not just a reload.

Permissions
^^^^^^^^^^^

Trace files are created with the exporter user's umask (typically mode
``0600``, owned by whatever user the systemd unit runs as). An admin reading
them needs either ``sudo`` privileges, membership in the exporter user's
group, or the umask widened so a known operator group can read. Keep this in
mind when oncall reaches for the log: ``cat`` as your normal user is not
enough.

Log rotation is intentionally not handled by the exporter itself: files live
on the lab host where the admin already manages the filesystem, so rotation
is best left to ``logrotate`` or an equivalent tool pointed at
``LG_SERIAL_TRACE_DIR``. Because ser2net opens the trace file in append mode
on each acquire, rotating between sessions (e.g. with ``logrotate``'s
``copytruncate`` or ``daily`` options) is safe.

Privacy and disk usage
^^^^^^^^^^^^^^^^^^^^^^

The trace captures **everything** that flows on the serial console, which can
include passwords typed at a U-Boot or login prompt, ssh keys pasted into a
shell, and anything else the user types or that the board prints. Treat
``LG_SERIAL_TRACE_DIR`` as an audit log: restrict the directory's permissions,
document its existence to users, and check the contents against your
organisation's privacy policy before turning it on in production.

Disk usage is modest in default mode (the trace is the same byte stream as
the console, plus the OPEN/CLOSE markers) but grows roughly ten-fold in
hexdump mode, where each byte becomes a full timestamped line. Plan rotation
accordingly when enabling ``LG_SERIAL_TRACE_HEXDUMP=1`` on a busy lab.

Library
-------
labgrid can be used directly as a Python library, without the infrastructure
Expand Down
2 changes: 2 additions & 0 deletions labgrid/remote/coordinator.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -647,6 +647,8 @@ async def _acquire_resource(self, place, resource):
request.group_name = resource.path[1]
request.resource_name = resource.path[3]
request.place_name = place.name
if place.acquired:
request.user = place.acquired
cmd = ExporterCommand(request)
self.get_exporter_by_name(resource.path[0]).queue.put_nowait(cmd)
await cmd.wait()
Expand Down
59 changes: 57 additions & 2 deletions labgrid/remote/exporter.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -67,6 +67,8 @@ class ResourceExport(ResourceEntry):
host = attr.ib(default=gethostname(), validator=attr.validators.instance_of(str))
proxy = attr.ib(default=None)
proxy_required = attr.ib(default=False)
group_name = attr.ib(default="")
user = attr.ib(default=None, init=False)
local = attr.ib(init=False)
local_params = attr.ib(init=False)
start_params = attr.ib(init=False)
Expand Down Expand Up @@ -230,6 +232,43 @@ def _get_params(self):
},
}

@staticmethod
def _build_trace_args(group_name, user, path):
"""Return ser2net YAML args for trace logging, or [] if disabled

Reads LG_SERIAL_TRACE_DIR; when set, creates the directory and
builds a per-board, per-user file path under it, then returns
the YAML option pairs needed to enable trace-both for that
file. The board comes from the resource's group name when
available, falling back to the basename of the device path so
the filename is still meaningful. The user is the host/user
identity passed in by the coordinator (slashes are rewritten
to underscores so it is filesystem-safe), or ``unknown`` when
the coordinator did not send one.

Setting LG_SERIAL_TRACE_HEXDUMP=1 additionally enables ser2net's
hexdump format for the trace, which prepends a timestamp to
every line at the cost of producing hex+ASCII rather than raw
text. Without it, only the OPEN and CLOSE session markers are
timestamped, but the traffic remains readable.
"""
trace_dir = os.environ.get("LG_SERIAL_TRACE_DIR")
if not trace_dir:
return []
os.makedirs(trace_dir, exist_ok=True)
board = group_name or os.path.basename(path)
user_label = (user or "unknown").replace("/", "_")
trace_path = os.path.join(trace_dir, f"{board}-{user_label}.log")
args = [
"-Y",
f" trace-both: {trace_path}",
"-Y",
" trace-both-timestamp: true",
]
if os.environ.get("LG_SERIAL_TRACE_HEXDUMP") == "1":
args += ["-Y", " trace-both-hexdump: true"]
return args

def _start(self, start_params):
"""Start ``ser2net`` subprocess"""
assert self.local.avail
Expand Down Expand Up @@ -263,6 +302,12 @@ def _start(self, start_params):
"-Y",
" max-connections: 10",
]
# If LG_SERIAL_TRACE_DIR is set, ask ser2net to log all
# serial traffic for this device. Useful for centralised
# audit on the exporter host. ser2net is started fresh
# on each acquire and stopped on release, so the trace
# file scope is one acquire session.
cmd += self._build_trace_args(self.group_name, self.user, start_params["path"])
else:
cmd = [
self.ser2net_bin,
Expand Down Expand Up @@ -912,6 +957,7 @@ async def message_pump(self):
out_message.set_acquired_request.group_name,
out_message.set_acquired_request.resource_name,
out_message.set_acquired_request.place_name,
out_message.set_acquired_request.user or None,
)
else:
await self.release(
Expand Down Expand Up @@ -952,7 +998,7 @@ async def message_pump(self):
# perhaps with queue join/task_done
# this should be a command from the coordinator

async def acquire(self, group_name, resource_name, place_name):
async def acquire(self, group_name, resource_name, place_name, user=None):
resource = self.groups.get(group_name, {}).get(resource_name)
if resource is None:
raise UnknownResourceError(
Expand All @@ -964,6 +1010,11 @@ async def acquire(self, group_name, resource_name, place_name):
f"Resource {group_name}/{resource_name} is already acquired by {resource.acquired}"
)

# Stash the acquiring user so ResourceExport subclasses can use it
# (e.g. for per-user trace files). Older coordinators don't send
# this field, in which case it stays None.
if isinstance(resource, ResourceExport):
resource.user = user
try:
resource.acquire(place_name)
finally:
Expand Down Expand Up @@ -1023,7 +1074,11 @@ async def add_resource(self, group_name, resource_name, cls, params):
proxy_req = self.isolated
if issubclass(export_cls, ResourceExport):
res = group[resource_name] = export_cls(
config, host=self.hostname, proxy=getfqdn(), proxy_required=proxy_req
config,
host=self.hostname,
proxy=getfqdn(),
proxy_required=proxy_req,
group_name=group_name,
)
res.poll()
else:
Expand Down
Loading
Loading