Skip to content

fix(harness): let boot-args configure logging - #206

Merged
dshakes merged 2 commits into
masterfrom
fix/boot-args-log-filter
Jul 31, 2026
Merged

dshakes merged 2 commits into
masterfrom
fix/boot-args-log-filter

Conversation

@dshakes

@dshakes dshakes commented Jul 31, 2026

Copy link
Copy Markdown
Owner

Item #3 from the remaining list — the last small one.

The problem

EnvFilter::try_from_default_env reads RUST_LOG once, when the subscriber is built — and that happened before bootenv::bootstrap(), which is what publishes boot-args into the environment. So a lantern.env.RUST_LOG=... was applied long after the filter had been fixed, and boot-args could not configure logging at all.

That isn't academic. It's why diagnosing the guest's TLS failure meant editing the harness's compiled-in filter default and rebuilding the entire image — twice. A microVM has no shell and no other channel; boot-args are the only way in.

The fix

preinit_log_filter() resolves that one variable first, at the top of main, silently — there's nothing to log to yet. Everything else stays in bootstrap() after the subscriber exists, so the rest of the bridge's work remains visible in the log. An explicit RUST_LOG in the environment still wins.

Observability preserved: moving procfs mounting earlier would have cost the mounted /proc debug line, since it now happens before tracing. ensure_procfs records the outcome and bootstrap reports it once the subscriber is up.

Verified on real KVM, stock binary

No compiled-in filter override in the image. Spawning with:

env: { "RUST_LOG": "info,lantern_harness=debug,rustls=trace" }

produced rustls trace output in the guest log (8 lines) — previously impossible — and bootenv: mounted /proc was still reported, confirming nothing was lost to the reordering.

155 harness tests pass (2 new, covering the pure filter extraction so the selection is testable without /proc or env mutation), clippy and rustfmt clean.

`EnvFilter::try_from_default_env` reads RUST_LOG once, when the subscriber is
built — and that happened before `bootenv::bootstrap()`, which is what
publishes boot-args into the environment. So a `lantern.env.RUST_LOG=...` was
applied long after the filter had been fixed, and boot-args could not configure
logging at all.

That is not academic: it is why diagnosing the guest's TLS failure meant editing
the harness's compiled-in filter default and rebuilding the whole image, twice.
A microVM has no shell and no other channel — boot-args are the only way in.

`preinit_log_filter()` now resolves that one variable first, at the top of main,
silently (there is nothing to log to yet). Everything else stays in
`bootstrap()` after the subscriber exists, so the rest of the bridge's work
remains visible. An explicit RUST_LOG in the environment still wins.

Moving procfs mounting earlier would have cost the "mounted /proc" debug line,
since it now happens before tracing. `ensure_procfs` records the outcome and
`bootstrap` reports it once the subscriber is up, so nothing is lost.

Verified on real KVM with a stock binary (no compiled-in filter override):
spawning with `env: {"RUST_LOG": "info,lantern_harness=debug,rustls=trace"}`
produced rustls trace output in the guest log, and "bootenv: mounted /proc" was
still reported. 155 harness tests pass (2 new for the pure filter extraction),
clippy and rustfmt clean.
@github-actions

Copy link
Copy Markdown
Contributor

🔎 Codex cross-audit (agent:audit)

Blocking

  • services/harness/src/main.rs:97 / bootenv.rs:77: preinit_log_filter() runs inside #[tokio::main], so Tokio has already built the runtime before this code executes. With the default multi-thread runtime, that invalidates the new unsafe assumption that std::env::set_var is called “before any thread is spawned.” This is a Rust 2024 safety issue and also undermines the stated boot-order guarantee. Fix by making main synchronous, doing preinit_log_filter(), subscriber init, and ideally bootenv::bootstrap() before constructing the Tokio runtime, then block_on the async body.

No other PR-introduced correctness or security issues stood out in this narrow diff. I did not run tests; this was a read-only diff audit.

@compass-sdlc-bot compass-sdlc-bot Bot added the agent:reviewed-clean Reviewer found no Blocking issues this round label Jul 31, 2026
@github-actions

Copy link
Copy Markdown
Contributor

🔷 Gemini cross-audit (agent:audit-gemini)

Audit Report: pr-diff.patch


1. Blocking Issues (High Severity)

🔴 Unsoundness and Undefined Behavior with std::env::set_var Under #[tokio::main]

  • Issue: bootenv::preinit_log_filter() is called at the beginning of the async fn main() body in main.rs.
  • Details: The #[tokio::main] macro wraps the async fn main() in a synchronous entry point that initializes the multi-threaded Tokio runtime before executing the body of the async function. Consequently, by the time preinit_log_filter() is reached, multiple background worker threads have already been spawned and are active in the process.
  • Impact: In Rust (particularly in modern toolchains like 1.93 used here), std::env::set_var is unsafe because mutating the process-wide environment while other threads exist is a POSIX safety violation and causes Undefined Behavior (data races with standard library/libc routines).
  • Remediation: Refactor the entry point to a synchronous fn main(), execute all synchronous environment setup (preinit_log_filter() and bootstrap()) before spawning any threads, and then spin up the Tokio runtime manually:
fn main() -> Result<()> {
    // 1. Synchronously pre-init environment before any threads exist
    bootenv::preinit_log_filter();

    // 2. Initialize tracing subscriber
    tracing_subscriber::fmt()
        .with_env_filter(
            EnvFilter::try_from_default_env()
                .unwrap_or_else(|_| EnvFilter::new("info,lantern_harness=debug")),
        )
        .json()
        .with_target(false)
        .init();

    // 3. Synchronously run the rest of the bootstrap setup
    bootenv::bootstrap();

    // 4. Manually start Tokio runtime
    let rt = tokio::runtime::Builder::new_multi_thread()
        .enable_all()
        .build()?;
        
    rt.block_on(async {
        let _spawn_cx = otel::init_propagator();
        let env = parse_env()?;
        // ... rest of async main logic ...
    })
}

2. Non-Blocking Observations & Verification

  • Discarded Warnings During Pre-Initialization:
    If ensure_procfs() fails with an error other than EBUSY when called from preinit_log_filter(), the tracing::warn! message is discarded because the tracing subscriber is not yet initialized. However, because ensure_procfs() is called again inside bootstrap() (after tracing is initialized), any persistent mount failure will still be correctly captured and logged on the second pass.
  • Atomic Ordering Soundness:
    PROCFS_MOUNTED correctly uses Relaxed memory ordering, which is sufficient for this single-direction boolean latch.
  • Robust Parser Edge Cases:
    The command-line parser handles empty values (e.g., lantern.env.RUST_LOG=) safely without panicking, and the fallback logic behaves correctly if invalid directives are supplied. Environment priority is preserved (existing environment variables always win over boot-args).

Flagged by both PR auditors on #206, and they were right.

`#[tokio::main]` builds the runtime and only THEN runs the async body, so its
worker threads are already alive by the time the body's first statement
executes. Every `std::env::set_var` in `bootenv` therefore ran with other
threads live — which is unsound, and exactly why `set_var` is `unsafe` in
edition 2024. The five SAFETY comments asserting "before any thread is spawned"
were not just imprecise, they were false, and had been since the boot-args
bridge landed. `preinit_log_filter` inherited the same bug rather than
introducing it.

`main` is now a plain fn: it does the environment work (log filter, then
`bootstrap`) while the process is genuinely single-threaded, then builds the
runtime and blocks on `run()`. The SAFETY comments now name the real invariant
— before the runtime is built — rather than a thread claim that was easy to
break silently, and `main` carries the contract so re-adding the macro is an
obvious mistake instead of an invisible one.

No behavior change: `new_multi_thread().enable_all()` is what the macro was
already doing.

Verified on real KVM, A/B on a clean host, same manager binary and image build:
  - pre-change  harness -> 5/5 assertions
  - post-change harness -> 5/5 assertions
      backend available · guest live · secret vended over mTLS ·
      tool invoked in-guest · all assertions passed
The guest log still shows the boot-args filter taking effect and the deferred
"bootenv: mounted /proc" report, so this PR's own feature is intact.
155 harness tests pass, clippy and rustfmt clean.
@dshakes
dshakes merged commit cc5acf5 into master Jul 31, 2026
9 checks passed
@dshakes
dshakes deleted the fix/boot-args-log-filter branch July 31, 2026 14:51
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

agent:reviewed-clean Reviewer found no Blocking issues this round

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant