fix(harness): let boot-args configure logging

services/harness/src/bootenv.rs

@@ -37,13 +37,60 @@ 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<String> {
+    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: `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) };
+    }
+}
+
 /// Prepare the environment for a microVM boot.
 ///
 /// Order matters: the cert drive is mounted BEFORE boot-args are translated, so
 /// the in-guest TLS paths are already published and the boot-args' host paths
 /// (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();
@@ -86,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");
@@ -144,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,
@@ -202,7 +249,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) {
@@ -254,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]);
@@ -383,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);
     }
@@ -416,6 +466,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 \

services/harness/src/main.rs

@@ -94,8 +94,23 @@ fn parse_env() -> Result<HarnessEnv> {
     })
 }
 
-#[tokio::main]
-async fn main() -> Result<()> {
+/// 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()
         .with_env_filter(
             EnvFilter::try_from_default_env()
@@ -107,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();