From 4f26c7080a3e0b401b59dfb9eeaa4bbf65ee8616 Mon Sep 17 00:00:00 2001 From: Shekhar Mudarapu Date: Fri, 31 Jul 2026 09:45:46 -0400 Subject: [PATCH 1/2] fix(harness): let boot-args configure logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `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. --- services/harness/src/bootenv.rs | 68 ++++++++++++++++++++++++++++++++- services/harness/src/main.rs | 6 +++ 2 files changed, 73 insertions(+), 1 deletion(-) diff --git a/services/harness/src/bootenv.rs b/services/harness/src/bootenv.rs index 9f4cfb94..66de5b12 100644 --- a/services/harness/src/bootenv.rs +++ b/services/harness/src/bootenv.rs @@ -37,6 +37,48 @@ const CERT_DEVICE_CANDIDATES: [&str; 3] = ["/dev/vdb", "/dev/vdc", "/dev/vdd"]; #[cfg(target_os = "linux")] const CERT_FILES: [&str; 3] = ["tls.crt", "tls.key", "manager-ca.crt"]; +/// Set when this process mounted procfs itself, so `bootstrap` can report it +/// once tracing exists — `ensure_procfs` may run before the subscriber does. +#[cfg(target_os = "linux")] +static PROCFS_MOUNTED: std::sync::atomic::AtomicBool = std::sync::atomic::AtomicBool::new(false); + +/// The log filter carried in boot-args, if any. +/// +/// Split out so the selection is testable without touching `/proc` or process +/// environment. +pub fn log_filter_from_cmdline(cmdline: &str) -> Option { + env_from_cmdline(cmdline) + .into_iter() + .find(|(name, _)| name == "RUST_LOG") + .map(|(_, value)| value) +} + +/// Publish `RUST_LOG` from boot-args BEFORE the tracing subscriber is built. +/// +/// `EnvFilter::try_from_default_env` reads `RUST_LOG` once, at initialisation. +/// The rest of the boot-args bridge runs after that — deliberately, so its work +/// is visible in the log — which left no way to configure logging from +/// boot-args at all: a `lantern.env.RUST_LOG=...` was applied long after the +/// filter had been fixed. Diagnosing a guest therefore meant editing the +/// harness's compiled-in default and rebuilding the image. +/// +/// So this one variable is resolved first, silently (there is nothing to log +/// to yet). Everything else stays in `bootstrap`, which runs after the +/// subscriber exists. An explicit `RUST_LOG` in the environment still wins. +pub fn preinit_log_filter() { + if std::env::var_os("RUST_LOG").is_some() { + return; + } + ensure_procfs(); + let Ok(cmdline) = std::fs::read_to_string(CMDLINE_PATH) else { + return; + }; + if let Some(filter) = log_filter_from_cmdline(&cmdline) { + // SAFETY: called at the top of main, before any thread is spawned. + unsafe { std::env::set_var("RUST_LOG", filter) }; + } +} + /// Prepare the environment for a microVM boot. /// /// Order matters: the cert drive is mounted BEFORE boot-args are translated, so @@ -44,6 +86,10 @@ const CERT_FILES: [&str; 3] = ["tls.crt", "tls.key", "manager-ca.crt"]; /// (which never resolve in the guest) are correctly ignored. pub fn bootstrap() { ensure_procfs(); + #[cfg(target_os = "linux")] + if PROCFS_MOUNTED.load(std::sync::atomic::Ordering::Relaxed) { + tracing::debug!("bootenv: mounted /proc"); + } report_entropy_source(); mount_cert_drive(); hydrate_env_from_cmdline(); @@ -202,7 +248,9 @@ fn ensure_procfs() { ) }; if rc == 0 { - tracing::debug!("bootenv: mounted /proc"); + // Cannot log yet: this may run before tracing is initialised (see + // `preinit_log_filter`). Record it and let `bootstrap` report it. + PROCFS_MOUNTED.store(true, std::sync::atomic::Ordering::Relaxed); } else { let errno = std::io::Error::last_os_error(); if errno.raw_os_error() != Some(libc::EBUSY) { @@ -416,6 +464,24 @@ fn is_guest_path_var(name: &str) -> bool { mod tests { use super::*; + #[test] + fn log_filter_is_picked_out_of_boot_args() { + // The whole point: a filter passed as a boot-arg must be findable + // before tracing exists. + let cmdline = "console=ttyS0 lantern.vm_id=vm-1 \ + lantern.env.RUST_LOG=info,rustls=trace lantern.env.OTHER=x"; + assert_eq!( + log_filter_from_cmdline(cmdline).as_deref(), + Some("info,rustls=trace") + ); + } + + #[test] + fn no_log_filter_in_boot_args_is_none() { + assert!(log_filter_from_cmdline("console=ttyS0 lantern.vm_id=vm-1").is_none()); + assert!(log_filter_from_cmdline("").is_none()); + } + #[test] fn maps_the_documented_contract_keys() { let cmdline = "console=ttyS0 reboot=k panic=1 pci=off \ diff --git a/services/harness/src/main.rs b/services/harness/src/main.rs index 6fac6e87..64d4b467 100644 --- a/services/harness/src/main.rs +++ b/services/harness/src/main.rs @@ -96,6 +96,12 @@ fn parse_env() -> Result { #[tokio::main] async fn main() -> Result<()> { + // BEFORE the subscriber is built: EnvFilter reads RUST_LOG once, at + // initialisation, so a filter arriving via boot-args has to be published + // first or it can never take effect. Silent by necessity — there is + // nothing to log to yet. + bootenv::preinit_log_filter(); + tracing_subscriber::fmt() .with_env_filter( EnvFilter::try_from_default_env() From 118524358af4f721229715b85b8f0f0232351f9c Mon Sep 17 00:00:00 2001 From: Shekhar Mudarapu Date: Fri, 31 Jul 2026 10:43:57 -0400 Subject: [PATCH 2/2] fix(harness): do the env bootstrap before the Tokio runtime exists MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- services/harness/src/bootenv.rs | 14 +++++++------ services/harness/src/main.rs | 35 ++++++++++++++++++++++++--------- 2 files changed, 34 insertions(+), 15 deletions(-) diff --git a/services/harness/src/bootenv.rs b/services/harness/src/bootenv.rs index 66de5b12..93f3da00 100644 --- a/services/harness/src/bootenv.rs +++ b/services/harness/src/bootenv.rs @@ -74,7 +74,8 @@ pub fn preinit_log_filter() { return; }; if let Some(filter) = log_filter_from_cmdline(&cmdline) { - // SAFETY: called at the top of main, before any thread is spawned. + // SAFETY: `main` runs this before it builds the Tokio runtime, so the + // process is still single-threaded. See the contract on `main`. unsafe { std::env::set_var("RUST_LOG", filter) }; } } @@ -132,7 +133,7 @@ fn assemble_declared_secrets() { let count = declared.len(); match serde_json::to_string(&declared) { Ok(json) => { - // SAFETY: called from main before any thread is spawned. + // SAFETY: single-threaded startup — see the contract on `main`. unsafe { std::env::set_var("LANTERN_DECLARED_SECRETS", &json) }; // Names only — a secret URI can identify sensitive material. tracing::info!(count, "bootenv: assembled declared secrets from boot-args"); @@ -190,7 +191,7 @@ fn pin_manager_hostname() { } let named = format!("{MANAGER_HOSTNAME}:{port}"); - // SAFETY: called from main before any thread is spawned. + // SAFETY: single-threaded startup — see the contract on `main`. unsafe { std::env::set_var("LANTERN_MANAGER_ADDR", &named) }; tracing::info!( manager_ip = host, @@ -302,7 +303,7 @@ fn mount_cert_drive() { .map(|name| format!("{CERT_MOUNT}/{name}")) .collect(); if paths.iter().all(|p| std::path::Path::new(p).exists()) { - // SAFETY: called from main before any thread is spawned. + // SAFETY: single-threaded startup — see the contract on `main`. unsafe { std::env::set_var("LANTERN_VM_TLS_CERT", &paths[0]); std::env::set_var("LANTERN_VM_TLS_KEY", &paths[1]); @@ -431,8 +432,9 @@ pub fn hydrate_env_from_cmdline() { unresolved.push(name); continue; } - // SAFETY: called from main before any thread is spawned, so no other - // thread can be reading the environment concurrently. + // SAFETY: single-threaded startup — `main` does all of this before the + // Tokio runtime exists, so no other thread can be reading the + // environment concurrently. See the contract on `main`. unsafe { std::env::set_var(&name, &value) }; applied.push(name); } diff --git a/services/harness/src/main.rs b/services/harness/src/main.rs index 64d4b467..41f041f5 100644 --- a/services/harness/src/main.rs +++ b/services/harness/src/main.rs @@ -94,12 +94,21 @@ fn parse_env() -> Result { }) } -#[tokio::main] -async fn main() -> Result<()> { - // BEFORE the subscriber is built: EnvFilter reads RUST_LOG once, at - // initialisation, so a filter arriving via boot-args has to be published - // first or it can never take effect. Silent by necessity — there is - // nothing to log to yet. +/// Single-threaded startup, then the async runtime. +/// +/// NOT `#[tokio::main]`. That macro builds the (multi-threaded) 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` would then be mutating process-global state with other threads +/// running, which is unsound; that is exactly why `set_var` is `unsafe` in +/// edition 2024. Doing the environment work here, before the runtime exists, +/// is what makes those SAFETY comments true rather than aspirational. +fn main() -> Result<()> { + // ---- single-threaded phase: no runtime, no threads --------------------- + + // EnvFilter reads RUST_LOG once, when the subscriber is built, so a filter + // arriving via boot-args has to be published before that or it can never + // take effect. Silent by necessity — there is nothing to log to yet. bootenv::preinit_log_filter(); tracing_subscriber::fmt() @@ -113,11 +122,19 @@ async fn main() -> Result<()> { // As PID 1 in a microVM the harness starts with an essentially empty // environment — the kernel passes the spawn contract on the command line - // instead. Translate it BEFORE anything reads configuration (including - // LANTERN_TRACE_PARENT below), and before any thread exists, since - // set_var mutates process-global state. + // instead. Translate it before anything reads configuration (including + // LANTERN_TRACE_PARENT below). bootenv::bootstrap(); + // ---- async phase: the environment is now frozen ------------------------ + tokio::runtime::Builder::new_multi_thread() + .enable_all() + .build() + .context("failed to build the Tokio runtime")? + .block_on(run()) +} + +async fn run() -> Result<()> { // Set the W3C propagator globally and parse LANTERN_TRACE_PARENT so every // outgoing gRPC call to the manager carries the spawn trace's traceparent. let _spawn_cx = otel::init_propagator();