Skip to content

fix(log): route production logs directly to the systemd journal#199

Merged
JanZachmann merged 5 commits into
omnect:mainfrom
JanZachmann:fix-log-severity-race
Apr 16, 2026
Merged

fix(log): route production logs directly to the systemd journal#199
JanZachmann merged 5 commits into
omnect:mainfrom
JanZachmann:fix-log-severity-race

Conversation

@JanZachmann
Copy link
Copy Markdown
Contributor

@JanZachmann JanZachmann commented Apr 15, 2026

Summary

  • Replace env_logger with systemd-journal-logger for production builds; keep env_logger for the mock feature only.
  • MESSAGE bodies lose the inline "{target}: " prefix; the target now lives in the structured TARGET= journal field.
  • Move logger setup from main.rs into src/logging.rs.

Reason

base_test.sh in omnect-os/ci/tests/lib_test.sh runs journalctl -b -q -p err and checks every PRIORITY≤3 line against a per-platform whitelist. It has been tripping on ods debug messages like:

omnect-device-service : omnect_device_service::twin::network: <7>omnect_device_service::twin::network: signal received, (re)arming debounce
base_test.sh: found syslog errors not in whitelist

Mechanism

env_logger encodes severity as an in-band "<N>" text prefix at the start of each line. journald's SyslogLevelPrefix parser only accepts "<N>" at byte 0 — if anything precedes it, parsing fails silently and the line falls back to the stream's default priority, which on our unit config is ERROR. So a debug!() call lands at PRIORITY=3 and gets flagged.

We didn't identify the exact byte-perturbation source. The class of failure is inherent to in-band textual prefixes: it cannot be ruled out as long as severity travels through the MESSAGE byte stream.

Why systemd-journal-logger

systemd-journal-logger sends records via the native sd-journal socket protocol. PRIORITY becomes a structured field alongside MESSAGE, SYSLOG_IDENTIFIER, and TARGET. It is not text, not parsed from a stream, and cannot be corrupted by concurrent writes.

Advantages

  • Correct severity, always. No textual prefix to lose. journalctl -p err only returns actual errors.
  • Structured fields for free. TARGET=, CODE_FILE=, CODE_LINE=, CODE_MODULE= become queryable (journalctl TARGET=omnect_device_service::twin::network).
  • Filter semantics unchanged. RUST_LOG and the same warn,azure_iot_sdk=debug,... defaults are preserved via env_filter (env_logger's filter half, published as a standalone crate).
  • Mock path untouched. cargo test --features mock and cargo run --features mock still log to stdout through env_logger with the <N>{args} format, so test harness output stays readable.
  • Backend selection is compile-time. Production binaries never link env_logger; mock builds never link the journal backend. The mock feature now implies dep:env_logger.

env_logger emits PRIORITY via an in-band "<N>" text prefix at the start of
each line. journald's SyslogLevelPrefix parser only accepts "<N>" at byte
0, so any perturbation of the byte stream before journald sees it defeats
the parser. journald then falls back to the stream's default priority
(ERROR on our unit config). This trips base_test.sh's whitelist check in
omnect-os/ci/tests (journalctl -b -p err) with unrelated debug messages.

Replace env_logger with systemd-journal-logger for production builds.
PRIORITY becomes a structured journal field, not a text prefix, so the
class of failure becomes impossible. Keep env_logger under the mock
feature so cargo test / cargo run --features mock output remains visible
in the test harness.

MESSAGE loses its "{target}: " prefix; the target lives in the structured
TARGET= field. Whitelist entries in omnect-os are updated in the
companion PR.

Move logger setup from main.rs to a dedicated logging module.

Signed-off-by: Jan Zachmann <50990105+JanZachmann@users.noreply.github.com>
@JanZachmann JanZachmann marked this pull request as draft April 15, 2026 13:38
Signed-off-by: Jan Zachmann <50990105+JanZachmann@users.noreply.github.com>
Logger installation can fail on systems without a journal socket or on
double-init. Propagate the error through main() so the binary exits
cleanly with a stderr message that still carries a syslog priority
prefix.

Signed-off-by: Jan Zachmann <50990105+JanZachmann@users.noreply.github.com>
@JanZachmann JanZachmann marked this pull request as ready for review April 15, 2026 14:59
@JoergZeidler JoergZeidler requested a review from Copilot April 15, 2026 15:00
Copy link
Copy Markdown
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Routes production logging directly to journald using systemd-journal-logger, while keeping an env_logger-based stdout logger for the mock feature, and centralizes logger setup into a dedicated module.

Changes:

  • Move logger initialization out of main.rs into src/logging.rs.
  • Use journald-native logging for non-mock builds; keep env_logger for mock.
  • Update dependencies/features and bump crate version to 0.42.2.

Reviewed changes

Copilot reviewed 4 out of 5 changed files in this pull request and generated 2 comments.

Show a summary per file
File Description
src/main.rs Switches startup to call logging::init() and handles init failure via stderr.
src/logging.rs Introduces feature-gated logger initialization for mock (stdout) vs production (journald).
src/lib.rs Exposes the new logging module.
Cargo.toml Adds env_filter + systemd-journal-logger, makes env_logger optional, wires mock feature.
Cargo.lock Locks new dependency additions and version bump.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment thread src/logging.rs Outdated
Comment thread Cargo.toml Outdated
Comment thread Cargo.toml Outdated
… features

- Non-mock logger init now reads RUST_LOG, falling back to default_filter()
  only when the env var is absent or empty; matches the mock path's behavior.
- systemd-journal-logger is now an optional dependency, pulled in only by
  bootloader_grub / bootloader_uboot. Mock builds no longer compile it.

Signed-off-by: Jan Zachmann <50990105+JanZachmann@users.noreply.github.com>
@JanZachmann JanZachmann requested a review from mlilien April 15, 2026 18:14
Comment thread Cargo.toml
When using the systemd-journal-logger, debug and trace records now
include the log target in the MESSAGE body ("{target}: {args}"), matching
the old env_logger format for these levels. Info/warn/error records keep
the bare "{args}" shape, consistent with the platform convention and the
existing syslog whitelist patterns.

This gives operators module-path context in interactive debug sessions
(journalctl -p debug) without requiring -o verbose or jq, while keeping
production-level messages clean.

The mock/env_logger path is unchanged — it always includes the target at
all levels.

Signed-off-by: Jan Zachmann <50990105+JanZachmann@users.noreply.github.com>
@JanZachmann JanZachmann requested a review from mlilien April 16, 2026 11:13
@JanZachmann JanZachmann merged commit 446ee10 into omnect:main Apr 16, 2026
2 checks passed
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.

3 participants