8000 feat(minvmd,minimald,minimal): persistent, correlatable daemon logs by norrietaylor · Pull Request #833 · gominimal/minimal · GitHub
[go: up one dir, main page]

Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
1 change: 1 addition & 0 deletions Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

21 changes: 5 additions & 16 deletions crates/minimal/src/dirs.rs
Original file line number Diff line number Diff line change
Expand Up @@ -19,9 +19,6 @@ pub fn cmd_dirs(global: &GlobalArgs) -> Result<(), anyhow::Error> {
/// The `cmd_dirs` table as a string — also captured verbatim into `min bug`
/// diagnostic bundles as `host/dirs.txt`.
pub(crate) fn report(global: &GlobalArgs) -> String {
// Shown in the "Daemon logs" note to point users at today's
// rolling log file directly, e.g. `minimald.log.2026-07-08`.
let today = chrono::Local::now().format("%Y-%m-%d").to_string();
let dirs = DirsLookup {
config: resolve_minimal_config_dir(global),
mesh_enrolment: mesh_enrolment_path(global),
Expand All @@ -45,7 +42,6 @@ pub(crate) fn report(global: &GlobalArgs) -> String {
.as_utf8_path()
.as_std_path()
.to_path_buf(),
today,
};
format_dir_rows(&build_dir_rows(&dirs))
}
Expand All @@ -69,9 +65,6 @@ struct DirsLookup {
state: PathBuf,
/// `<cache>/minimal`.
cache: PathBuf,
/// Today's date in `YYYY-MM-DD`, used only in the "Daemon logs"
/// note next to the rolling filename suffix.
today: String,
}

/// Which top-level group the mesh-enrolment row prints under. Values
Expand Down Expand Up @@ -158,7 +151,7 @@ fn build_dir_rows(dirs: &DirsLookup) -> Vec<DirRow> {
"State",
"Daemon logs",
Some(dirs.state.join("logs")),
Some(format!("daily-rotated: minimald.log.{}", dirs.today)),
Some("daily-rotated: minimald.log*, minvmd.log*".to_string()),
)
.into_row(),
(
Expand Down Expand Up @@ -294,7 +287,6 @@ mod tests {
mesh_group: MeshGroup::Config,
state: PathBuf::from("/home/u/.local/state/minimal"),
cache: PathBuf::from("/home/u/.cache/minimal"),
today: "2026-07-08".to_string(),
};
let rows = build_dir_rows(&dirs);
let shape: Vec<(&str, &str, String)> = rows
Expand Down Expand Up @@ -369,24 +361,22 @@ mod tests {
);
}

/// The "Daemon logs" row's note interpolates `today` into the
/// rolling-file suffix so operators see the exact filename they
/// should look at.
/// The "Daemon logs" row's note names both daemons' rotated files so
/// operators know which filenames to look at.
#[test]
fn build_dir_rows_daemon_logs_note_interpolates_date() {
fn build_dir_rows_daemon_logs_note_names_both_daemons() {
let dirs = DirsLookup {
config: PathBuf::from("/c"),
mesh_enrolment: PathBuf::from("/c/mesh-enrolment"),
mesh_group: MeshGroup::Config,
state: PathBuf::from("/s"),
cache: PathBuf::from("/x"),
today: "2030-01-15".to_string(),
};
let rows = build_dir_rows(&dirs);
let daemon_logs = rows.iter().find(|r| r.name == "Daemon logs").unwrap();
assert_eq!(
daemon_logs.note.as_deref(),
Some("daily-rotated: minimald.log.2030-01-15"),
Some("daily-rotated: minimald.log*, minvmd.log*"),
);
}

Expand Down Expand Up @@ -420,7 +410,6 @@ mod tests {
mesh_group: MeshGroup::State,
state: PathBuf::from("/override"),
cache: PathBuf::from("/x"),
today: "_".to_string(),
};
let rows = build_dir_rows(&dirs);
let mesh = rows.iter().find(|r| r.name == "Mesh enrolment").unwrap();
Expand Down
119 changes: 119 additions & 0 deletions crates/minimald/src/logging.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,119 @@
//! The daemon's on-disk log in one place: appender creation, the reloadable
//! tracing layer, and the shutdown release. The native detached daemon and
//! the microVM pid-1 share this machinery unchanged — they differ only in
//! *when* the log directory is final (immediately for the native daemon,
//! after the state volume mounts for the microVM). A foreground run logs to
//! stdout only and never activates a file.
//!
//! [`DaemonLogger::install`] assembles the global subscriber;
//! [`DaemonLogger::activate`] points the file layer at a directory once it is
//! known and yields a [`DaemonLogRelease`](minimald::server::DaemonLogRelease)
//! for [`ServerState`](minimald::server::ServerState) to run at shutdown.

use std::path::Path;

use minimald::server::DaemonLogRelease;
use tracing_subscriber::layer::SubscriberExt as _;
use tracing_subscriber::util::SubscriberInitExt as _;
use tracing_subscriber::{EnvFilter, Layer as _, fmt};

use crate::MainError;

/// Where a daemon's records go.
pub enum LogMode {
/// Foreground: stdout only, no file.
Console,
/// Detached daemon or microVM pid-1: stdout (which the VM routes over the
/// serial console into the host `boot.log`) plus a reloadable file layer,
/// pointed at a directory by [`DaemonLogger::activate`].
File,
}

type Activator = Box<dyn FnOnce(&Path) -> Result<DaemonLogRelease, MainError> + Send>;

/// The daemon's logging, once installed into the global tracing subscriber.
pub struct DaemonLogger {
/// Present when [`install`](Self::install) set up a file layer (both file
/// modes); `None` for a console-only foreground run.
activate: Option<Activator>,
}

impl DaemonLogger {
/// Assemble and install the global subscriber for `mode`. Call once,
/// before any `tracing::*` whose output should be captured.
pub fn install(mode: LogMode) -> Result<Self, MainError> {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| {
EnvFilter::new("info")
.add_directive("topiary=off".parse().unwrap())
.add_directive("libcgroups=off".parse().unwrap())
});

let LogMode::File = mode else {
tracing_subscriber::registry()
.with(fmt::layer().with_writer(ot::StdoutWriter::new))
.with(filter)
.init();
return Ok(Self { activate: None });
};

// The file layer starts `None` (inert — records still reach the
// console). `reload` lets `activate` swap the appender in once the
// log dir is known, and the shutdown release swap it back out, with
// no deferred-writer hack or process-global hook.
let (file_layer, reload) = tracing_subscriber::reload::Layer::new(None);
tracing_subscriber::registry()
.with(fmt::layer().with_writer(ot::StdoutWriter::new))
.with(file_layer)
.with(filter)
.init();
let activate: Activator = Box::new(move |log_dir: &Path| {
std::fs::create_dir_all(log_dir)
.map_err(|e| MainError::IO(e, "creating minimald log directory"))?;
let appender = build_appender(log_dir)?;
// lossy(false): a diagnostic log that drops records under load
// answers the wrong question. The cost is backpressure onto
// logging threads if the sink wedges — accepted, because the
// console layer stays independent and the volume fallback
// collects without the daemon.
let (writer, guard) = tracing_appender::non_blocking::NonBlockingBuilder::default()
.lossy(false)
.finish(appender);
reload
.modify(|layer| {
*layer = Some(fmt::layer().with_ansi(false).with_writer(writer).boxed());
})
.map_err(|e| MainError::Other(format!("installing file log layer: {e}")))?;
// The release: reload the file layer back off, then drop the guard
// to flush pending records and close the file.
Ok(DaemonLogRelease::new(move || {
let _ = reload.modify(|layer| *layer = None);
drop(guard);
}))
});
Ok(Self {
activate: Some(activate),
})
}

/// Point the file log at `log_dir`, returning the release to hand to
/// `ServerState`. `Ok(None)` for a console-only (foreground) logger.
pub fn activate(self, log_dir: &Path) -> Result<Option<DaemonLogRelease>, MainError> {
self.activate.map(|f| f(log_dir)).transpose()
}
}

/// The daily-rotated, retention-bounded appender. Files carry a date suffix
/// (`minimald.log.<date>`); rotation and pruning are inline (no background
/// thread, no partial intermediates), so the release closes the file with a
/// plain guard drop — nothing to join.
fn build_appender(
log_dir: &Path,
) -> Result<tracing_appender::rolling::RollingFileAppender, MainError> {
tracing_appender::rolling::Builder::new()
.rotation(tracing_appender::rolling::Rotation::DAILY)
.filename_prefix("minimald.log")
// Two weeks: comfortably past "what happened last week", bounded on disk.
.max_log_files(14)
.build(log_dir)
.map_err(|e| MainError::IO(std::io::Error::other(e), "building rotating log appender"))
}
122 changes: 50 additions & 72 deletions crates/minimald/src/main.rs
Original file line number Diff line number Diff line change
Expand Up @@ -6,10 +6,12 @@ use clap_complete::Shell;
use paths::{CwdRelative, Daemon, DaemonAbsPath, sub_path};
use std::io::Write as _;
use tokio::{net::UnixListener, runtime::Builder};
use tracing_subscriber::{EnvFilter, fmt, prelude::*};

use minimald::server::{Config, HostKey, Server};

mod logging;
use logging::{DaemonLogger, LogMode};

#[cfg(target_os = "linux")]
use tokio_vsock::{VMADDR_CID_ANY, VsockAddr, VsockListener};

Expand Down Expand Up @@ -347,66 +349,6 @@ fn lock_held(path: &std::path::Path) -> std::io::Result<bool> {
}
}

/// Install the tracing subscriber. Foreground processes log to
/// stdout; detached daemons (marked by [`DETACHED_ENV`]) write to
/// `<state_dir>/logs/minimald.log`, daily-rotated. The returned
/// [`WorkerGuard`] must outlive the process — dropping it flushes
/// pending records and terminates the appender's worker thread.
///
/// [`WorkerGuard`]: tracing_appender::non_blocking::WorkerGuard
fn init_tracing(
cli: &Cli,
) -> Result<Option<tracing_appender::non_blocking::WorkerGuard>, MainError> {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| {
EnvFilter::new("info")
.add_directive("topiary=off".parse().unwrap())
.add_directive("libcgroups=off".parse().unwrap())
});

let detached = std::env::var_os(DETACHED_ENV).is_some();
if !detached {
tracing_subscriber::registry()
.with(fmt::layer().with_writer(ot::StdoutWriter::new))
.with(filter)
.init();
return Ok(None);
}

// Under `<state_dir>/logs/` so `<state_dir>` itself stays
// dominated by the sockets, sessions, and providers it already
// owns. `create_dir_all` is idempotent — subsequent daemon
// starts don't churn.
let log_dir = cli
.minimal_state_dir()
.as_utf8_path()
.as_std_path()
.join("logs");
std::fs::create_dir_all(&log_dir)
.map_err(|e| MainError::IO(e, "creating minimald log directory"))?;
// Cap retained files so a long-running daemon doesn't accumulate
// logs indefinitely. Two weeks is comfortably longer than the
// usual "look at what happened yesterday" window and short enough
// that the on-disk footprint stays bounded.
let appender = tracing_appender::rolling::Builder::new()
.rotation(tracing_appender::rolling::Rotation::DAILY)
.filename_prefix("minimald.log")
.max_log_files(14)
.build(&log_dir)
.map_err(|e| MainError::IO(std::io::Error::other(e), "building rolling log appender"))?;
let (writer, guard) = tracing_appender::non_blocking(appender);
tracing_subscriber::registry()
// ANSI colors only make sense on a terminal; a file logger
// just gets noise from the escape sequences.
.with(fmt::layer().with_ansi(false).with_writer(writer))
.with(filter)
.init();
tracing::info!(
log_dir = %log_dir.display(),
"detached minimald: routing tracing output to daily-rotated log file",
);
Ok(Some(guard))
}

async fn async_main() -> Result<(), MainError> {
// With `networking-proxy` on, both the `ring` (workspace rustls) and the
// `aws-lc-rs` (google-cloud) providers are compiled in, so rustls cannot
Expand Down Expand Up @@ -456,15 +398,18 @@ async fn async_main() -> Result<(), MainError> {
return Ok(());
}

// Initialize tracing. Foreground runs (or the parent-side of a
// `--detach` re-exec) log to stdout. A child spawned by
// `spawn_detached` has its stdio null'd — detectable via the
// `MINIMALD_DETACHED` env var — so it routes tracing to a daily-
// rotated log file under the state directory instead. `_log_guard`
// is bound at function scope so the non-blocking appender's
// worker survives for the daemon's entire lifetime; dropping it
// would flush and terminate the appender prematurely.
let _log_guard = init_tracing(&cli)?;
// Install tracing. A foreground run logs to stdout only. A detached
// native daemon (stdio null'd, marked by `MINIMALD_DETACHED`) and the
// microVM pid-1 both log to a daily-rotated file, wired up by
// `logger.activate` once the log directory is final (below): immediately
// for the native daemon, after the state volume mounts for the microVM.
// The activation yields a release the server state runs at shutdown.
let log_mode = if is_minimal_microvm() || std::env::var_os(DETACHED_ENV).is_some() {
LogMode::File
} else {
LogMode::Console
};
let logger = DaemonLogger::install(log_mode)?;

let listen_args = cli.listen_args().unwrap();

Expand Down Expand Up @@ -558,6 +503,39 @@ async fn async_main() -> Result<(), MainError> {
return Err(MainError::IO(e, "creating minimal dir"));
}

// The log directory is now final under `<state>/logs` — the native
// daemon's from the start, the microVM's now that the state volume is
// mounted and state relocated onto it, where `min bug`'s guest collector
// reads it. Point the file log at it; the release is handed to the server
// state and run at shutdown (in the microVM, before the quiesce — the
// appender's write-open fd would otherwise hold the volume busy and
// defeat the clean unmount). A foreground run's logger has no file and
// yields `None`. A failure here must not wedge the daemon (pid-1 in the
// microVM), so fall back to console-only.
let log_dir = cli
.minimal_state_dir()
.as_utf8_path()
.as_std_path()
.join("logs");
let log_release = match logger.activate(&log_dir) {
Ok(release) => {
if release.is_some() {
tracing::info!(
log_dir = %log_dir.display(),
"routing tracing output to daily-rotated log file",
);
}
release
}
Err(e) => {
tracing::warn!(
error = ?e,
"could not open the daemon log file; continuing with console logging only",
);
None
}
};

// The host-key path lives under the instance dir; ensure it exists for
// both the UDS and vsock paths.
if let Err(e) = std::fs::create_dir_all(cli.client_instance_dir())
Expand Down Expand Up @@ -724,7 +702,7 @@ async fn async_main() -> Result<(), MainError> {
);
// TODO: When we have a daemonize command, daemonize here.

Server::run(config, listener)
Server::run(config, listener, log_release)
.await
.map_err(|e| MainError::IO(e, "serving on UDS"))
} else {
Expand Down Expand Up @@ -755,7 +733,7 @@ async fn async_main() -> Result<(), MainError> {
}
};

Server::run(config, listener)
Server::run(config, listener, log_release)
.await
.map_err(|e| MainError::IO(e, "serving on guest vsock"))
}
Expand Down
8 changes: 8 additions & 0 deletions crates/minimald/src/rpc.rs
Original file line number Diff line number Diff line change
Expand Up @@ -331,6 +331,12 @@ async fn serve_shutdown(s: ServerStateHandle, c: RuChannel<Msg>) {
let mngr = s.sessions_manager().await;
Ok(match mngr.shutdown(req.force).await {
Ok(()) => {
// Close the file log first (both the native daemon and the
// microVM): it flushes buffered records, and in the
// microVM its write-open fd under the mountpoint would
// otherwise defeat the clean unmount below. Records still
// reach the console. A no-op for a foreground run.
s.release_log().await;
// R2.1/R2.2: with the sessions drained, quiesce the state
// volume (syncfs + detach) before acknowledging, so a
// caller-driven VMM teardown right after the ack leaves a
Expand Down Expand Up @@ -369,6 +375,8 @@ async fn quiesce_state_volume_if_mounted(s: &ServerStateHandle) {
if !s.state_volume_mounted().await {
return;
}
// The file log was already released by the shutdown handler, so its fd no
// longer holds the mountpoint busy.
let mountpoint = s.minimal_state_dir().await;
let quiesce = tokio::task::spawn_blocking(move || {
crate::guest::quiesce_state_volume(mountpoint.as_utf8_path().as_str())
Expand Down
Loading
0