From e6f9f8d3e641a237e040f7475c71e43531e99ceb Mon Sep 17 00:00:00 2001 From: Kevin Wang Date: Thu, 6 Aug 2026 01:53:24 -0700 Subject: [PATCH] fix(vmm): bound the logs a CVM writes within a boot MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit QEMU appends to serial.log for the whole life of a boot and offers no way to bound it. A chatty or malicious guest could fill the host disk, and the next boot's archiving step read the entire file into memory in one allocation. The symptom this branch started from — trimming discarded the boot delimiter along with older output — only existed because several boots shared one capped archive file and the delimiter had to be recovered from the log text. Bounding a boot removes that condition, so this addresses the cause instead. QEMU cannot do it for us. The QAPI schema for the file and pty chardev backends exposes only out/in/append plus the generic logfile/logappend, none of which is a size limit; the one `size` knob in the chardev family belongs to `ringbuf`, an in-memory ring rather than a file. libvirt hit the same wall and answered it with a separate daemon, virtlogd. So bound it outside QEMU. Rotation lives in `logrotate`, which works on a path and knows nothing about serial logs — the same way logrotate(8) does not care what it is rotating. `.N-1` becomes `.N`, the live file is archived as `.1`, and the oldest segment is discarded. A VM start is simply another rotation trigger, so the previous boot is preserved as serial.log.1 and boot boundaries land on segment boundaries. Only two things stay serial-specific: which file to rotate, and the eligibility check below. Retention is configured under `[cvm.log]` as `max_bytes`, `max_backups` and `check_interval_secs`, named for the mechanism rather than for serial because stdout and stderr use the same section. All three logs are rotated, but they are not gated alike. stdout and stderr are written by the supervisor, which always opens them with append(true) and already reopens them when they change — its own comment calls that "logrotate detection" — so they satisfy the contract no matter which VMM launched the VM, and keep their cap across a VMM upgrade. serial.log is written by QEMU and is included only when its annotation confirms logappend=on. The values live in the shipped vmm.toml rather than in serde defaults, which means the defaults are themselves parsed on every load. That is not cosmetic: the doc comment inherited from serial_history_max_bytes advertised sizes like "4MB", which size_parser does not accept — a serde default had been hiding the fact that anyone following that comment would have failed to start the VMM. Three details carry the design. `logappend=on` is now passed to the chardev. QEMU otherwise opens the log without O_APPEND and keeps writing at its stale offset after a truncation, punching a sparse hole that leaves the file as large as it was. Measured on QEMU 8.2.2, truncating a 100000-byte log then writing 10 bytes: logappend=off leaves an apparent size of 100010, logappend=on leaves 10. This requirement is the module's contract, documented there, and it holds equally for a supervised process's `OpenOptions::append(true)` stdout — so stdout/stderr rotation is now a call site rather than a reimplementation. The live file is truncated in place, never renamed. The writer holds an open fd on it, so a rename would leave it appending into an unlinked inode and losing every later line without an error. A test pins the inode across rotation. Truncating to zero rather than compacting to a retained buffer is what keeps the log-viewing API working. A follower sees the file shrink and resumes at offset 0, where there is now nothing to re-read. Verified against the `tail` process `tailf` spawns: across a rotation of a 489 KB file a follower received its three trailing lines and then the three new ones, with no duplication. Compacting in place instead replayed the entire retained file to every connected viewer on every rotation. Upgrade safety needs care. The supervisor is a detached daemon and owns the QEMU processes, so restarting VMM leaves running CVMs untouched; after an upgrade those processes are the ones the previous binary launched, without logappend=on. Rotating their logs would punch the hole above, the cap would never hold, and every subsequent tick would rotate again. Eligibility is therefore recorded on the process itself, in the ProcessAnnotation the supervisor already stores: it describes the QEMU that is actually running and survives a VMM restart, and an annotation written by an older VMM has no such key and deserializes to false. Reading the recorded argv would not work, since TPM-backed VMs run through vm-launcher whose argv is only ["vm-launcher", "--spec", ]. serial.history.log is removed along with rotate_serial_log, trim_serial_history, serial_history_max_bytes and serial_history_file. The archive existed because the live log was unbounded and QEMU truncated it at every boot; both premises are gone. Dropping the config key is safe because CvmConfig does not deny unknown fields, so a vmm.toml that still sets it keeps loading. Existing serial.history.log files are left on disk: they are bounded, and deleting operator-visible data on upgrade is not this change's job. The log API serves only the live serial.log, so rotated segments are not readable through it and a rotation leaves a reader with an empty file. One line is written into the emptied log saying where the output went, so the absence is self-explanatory. Making ch=serial span segments is left to a follow-up. Rotation is triggered by a periodic stat, so the live log can overshoot the cap by one interval's worth of output. The overshoot only makes one segment larger and is reclaimed on the next tick. --- dstack/vmm/src/app.rs | 210 +++++++++++++++++------ dstack/vmm/src/app/qemu.rs | 12 +- dstack/vmm/src/app/workdir.rs | 4 - dstack/vmm/src/config.rs | 41 +++-- dstack/vmm/src/logrotate.rs | 307 ++++++++++++++++++++++++++++++++++ dstack/vmm/src/main.rs | 18 ++ dstack/vmm/vmm.toml | 13 ++ 7 files changed, 543 insertions(+), 62 deletions(-) create mode 100644 dstack/vmm/src/logrotate.rs diff --git a/dstack/vmm/src/app.rs b/dstack/vmm/src/app.rs index 1a6e78a74..24e7a744f 100644 --- a/dstack/vmm/src/app.rs +++ b/dstack/vmm/src/app.rs @@ -3,6 +3,7 @@ // SPDX-License-Identifier: Apache-2.0 use crate::config::{Config, Networking, ProcessAnnotation, Protocol}; +use crate::logrotate; use anyhow::{bail, Context, Result}; use bon::Builder; @@ -431,11 +432,16 @@ impl App { fs::remove_file(path)?; } } - // Append current serial.log to serial.history.log before QEMU truncates it. - rotate_serial_log(&work_dir, self.config.cvm.serial_history_max_bytes); - // Add boot separator to stdout/stderr (they are opened in append mode). - append_boot_separator(&work_dir.stdout_file()); - append_boot_separator(&work_dir.stderr_file()); + // Archive the previous boot into segments, which also clears the + // live logs for this boot. QEMU runs with logappend=on and no + // longer truncates serial.log on open, so a boot is simply another + // rotation trigger and boot boundaries land on segment boundaries. + for path in rotatable_logs(&work_dir, true) { + rotate_log(&path, self.config.cvm.log.max_backups); + // The logs are opened in append mode, so this marks the start + // of the new boot rather than replacing anything. + append_boot_separator(&path); + } let devices = self.try_allocate_gpus(&vm_config.manifest)?; let processes = vm_config.config_qemu(&work_dir, &self.config.cvm, &devices)?; @@ -1171,6 +1177,41 @@ impl App { Ok(gpus) } + /// Rotate any live log that has grown past the configured cap. + pub(crate) async fn rotate_oversized_logs(&self) -> Result<()> { + let max_bytes = self.config.cvm.log.max_bytes; + if max_bytes == 0 { + return Ok(()); + } + let max_backups = self.config.cvm.log.max_backups; + let running = self + .supervisor + .list() + .await + .context("failed to list VMs")? + .into_iter() + .filter(|process| process.state.status.is_running()); + for process in running { + let Ok(work_dir) = self.work_dir(&process.config.id) else { + continue; + }; + let serial = serial_log_is_rotatable(&process.config.note); + for path in rotatable_logs(&work_dir, serial) { + if let Some(rotated) = logrotate::rotate_if_oversized(&path, max_bytes, max_backups) + { + logrotate::append_rotation_note(&path, &rotated); + info!( + id = process.config.id, + log = %path.display(), + bytes = rotated.bytes, + "rotated oversized log" + ); + } + } + } + Ok(()) + } + pub(crate) async fn try_restart_exited_vms(&self) -> Result<()> { let running_vms = self .supervisor @@ -1266,6 +1307,12 @@ impl App { } } +/// Leading bytes of the separator written by [`append_boot_separator`]. +/// +/// Written to stdout, stderr and the serial log at each boot so a log read in +/// isolation still shows where a boot began. +const BOOT_SEPARATOR_PREFIX: &str = "\n===== boot @ "; + /// Append a boot separator line with timestamp to an append-mode log file. fn append_boot_separator(path: &std::path::Path) { use std::io::Write; @@ -1276,54 +1323,45 @@ fn append_boot_separator(path: &std::path::Path) { return; }; let timestamp = humantime::format_rfc3339_seconds(std::time::SystemTime::now()); - let _ = writeln!(file, "\n===== boot @ {timestamp} =====\n"); + let _ = writeln!(file, "{BOOT_SEPARATOR_PREFIX}{timestamp} =====\n"); } -/// Append current serial.log into serial.history.log with a boot separator, -/// then truncate history if it exceeds `max_bytes`. -fn rotate_serial_log(work_dir: &VmWorkDir, max_bytes: u64) { - use std::io::Write; +/// Logs a CVM writes into its work directory, subject to retention. +/// +/// stdout and stderr are written by the supervisor, which always opens them +/// with `append(true)` and reopens them when they change, so they satisfy +/// [`crate::logrotate`]'s contract no matter which VMM launched the VM. +/// serial.log is written by QEMU, whose fd only appends when *we* passed +/// `logappend=on`, so it is included only when `serial` says so. +fn rotatable_logs(work_dir: &VmWorkDir, serial: bool) -> Vec { + let mut paths = vec![work_dir.stdout_file(), work_dir.stderr_file()]; + if serial { + paths.push(work_dir.serial_file()); + } + paths +} - let serial = work_dir.serial_file(); - if !serial.exists() { - return; - } - let Ok(content) = fs::read(&serial) else { - return; - }; - if content.is_empty() { - return; - } - let history = work_dir.serial_history_file(); - let Ok(mut file) = fs::OpenOptions::new() - .create(true) - .append(true) - .open(&history) - else { - return; - }; - let timestamp = humantime::format_rfc3339_seconds(std::time::SystemTime::now()); - let _ = writeln!(file, "\n===== boot @ {timestamp} =====\n"); - let _ = file.write_all(&content); - drop(file); - - // Truncate from the front if history exceeds max_bytes. - if let Ok(meta) = fs::metadata(&history) { - if meta.len() > max_bytes { - if let Ok(data) = fs::read(&history) { - let skip = data.len() - max_bytes as usize; - // Find the next newline after skip point to avoid cutting mid-line. - let start = data[skip..] - .iter() - .position(|&b| b == b'\n') - .map(|p| skip + p + 1) - .unwrap_or(skip); - let _ = fs::write(&history, &data[start..]); - } - } +/// Rotate a log and record where its output went. +/// +/// The rotation itself is generic (see [`crate::logrotate`]); the note is here +/// because the VMM log API serves only the live file. +fn rotate_log(path: &Path, max_backups: usize) { + if let Some(rotated) = logrotate::rotate(path, max_backups) { + logrotate::append_rotation_note(path, &rotated); } } +/// Whether a supervised process's serial log may be rotated in place. +/// +/// Rotation truncates the log while QEMU holds it open, which only works when +/// QEMU opened it with `logappend=on`. Anything we cannot positively confirm — +/// an annotation from an older VMM, an unparseable note — answers `false`. +fn serial_log_is_rotatable(note: &str) -> bool { + serde_json::from_str::(note) + .unwrap_or_default() + .serial_logappend +} + pub(crate) fn simulator_config_for_manifest( cvm: &crate::config::CvmConfig, manifest: &Manifest, @@ -1704,6 +1742,84 @@ mod tests { } } + #[test] + fn serial_log_is_rotatable_only_when_the_annotation_confirms_it() { + // A VM launched by the current binary. + let current = serde_json::to_string(&ProcessAnnotation { + kind: "cvm".into(), + live_for: None, + serial_logappend: true, + }) + .unwrap(); + assert!(serial_log_is_rotatable(¤t)); + + // A VM inherited from a VMM that predates the option: its QEMU holds + // the log without O_APPEND, so truncating it would punch a sparse hole + // and the file would spring straight back over the cap. + assert!(!serial_log_is_rotatable(r#"{"kind":"cvm"}"#)); + assert!(!serial_log_is_rotatable( + r#"{"kind":"cvm","live_for":null}"# + )); + + // Anything we cannot read must answer conservatively. + assert!(!serial_log_is_rotatable("")); + assert!(!serial_log_is_rotatable("not json")); + assert!(!serial_log_is_rotatable(r#"{"serial_logappend":"yes"}"#)); + } + + #[test] + fn cvm_annotation_marks_the_serial_log_rotatable() { + // The flag must survive the round trip the supervisor performs, and + // must not disturb how existing consumers classify the process. + let note = serde_json::to_string(&ProcessAnnotation { + kind: "cvm".into(), + live_for: None, + serial_logappend: true, + }) + .unwrap(); + let parsed: ProcessAnnotation = serde_json::from_str(¬e).unwrap(); + assert!(parsed.serial_logappend); + assert!(parsed.is_cvm()); + } + + #[test] + fn rotatable_logs_always_include_supervisor_written_logs() -> Result<()> { + let temp = tempfile::tempdir()?; + let workdir = VmWorkDir::new(temp.path()); + + // A VM inherited from an older VMM: QEMU holds serial.log without + // O_APPEND, so rotating it would punch a sparse hole. stdout and stderr + // are the supervisor's, always opened with append(true), so they stay + // eligible and keep their cap across a VMM upgrade. + let inherited = rotatable_logs(&workdir, false); + assert_eq!( + inherited, + vec![workdir.stdout_file(), workdir.stderr_file()] + ); + + let launched = rotatable_logs(&workdir, true); + assert_eq!( + launched, + vec![ + workdir.stdout_file(), + workdir.stderr_file(), + workdir.serial_file() + ] + ); + Ok(()) + } + + #[test] + fn log_retention_defaults() -> Result<()> { + // These come from the shipped vmm.toml, not from serde defaults, so + // this also pins that the values there parse into what they read as. + let config = test_tdx_config()?; + assert_eq!(config.cvm.log.max_bytes, 4 * 1024 * 1024); + assert_eq!(config.cvm.log.max_backups, 3); + assert_eq!(config.cvm.log.check_interval_secs, 5); + Ok(()) + } + #[test] fn auto_restart_policy_backs_off_caps_and_exhausts_once() { let config = restart_config(); diff --git a/dstack/vmm/src/app/qemu.rs b/dstack/vmm/src/app/qemu.rs index f84b44fc8..85b7e18ad 100644 --- a/dstack/vmm/src/app/qemu.rs +++ b/dstack/vmm/src/app/qemu.rs @@ -457,8 +457,13 @@ impl QemuCommandBuilder<'_> { }); command.arg("-nographic"); command.arg("-nodefaults"); + // logappend=on stops QEMU from truncating the log when it opens the + // chardev, which is what makes in-place rotation safe: the fd is + // O_APPEND, so writes resume at the end of file after we truncate. + // Without it QEMU keeps writing at its old offset and punches a sparse + // hole instead, leaving the file as large as it was. command.arg("-chardev").arg(format!( - "pty,id=com0,path={},logfile={}", + "pty,id=com0,path={},logfile={},logappend=on", workdir.serial_pty().display(), workdir.serial_file().display() )); @@ -776,6 +781,11 @@ impl QemuCommandBuilder<'_> { let note = serde_json::to_string(&ProcessAnnotation { kind: "cvm".to_string(), live_for: None, + // Recorded on the process rather than tracked in VMM memory, so it + // survives a VMM restart and describes the QEMU that is actually + // running. The vm-launcher wrapper copies this note verbatim, so + // TPM-backed VMs carry it too. + serial_logappend: true, })?; Ok(ProcessConfig { id: self.vm.manifest.id.clone(), diff --git a/dstack/vmm/src/app/workdir.rs b/dstack/vmm/src/app/workdir.rs index c11c99f33..198dc7c94 100644 --- a/dstack/vmm/src/app/workdir.rs +++ b/dstack/vmm/src/app/workdir.rs @@ -168,10 +168,6 @@ impl VmWorkDir { self.workdir.join("serial.log") } - pub fn serial_history_file(&self) -> PathBuf { - self.workdir.join("serial.history.log") - } - pub fn serial_pty(&self) -> PathBuf { self.workdir.join("serial.pty") } diff --git a/dstack/vmm/src/config.rs b/dstack/vmm/src/config.rs index 62458ce5f..d0b8ab1be 100644 --- a/dstack/vmm/src/config.rs +++ b/dstack/vmm/src/config.rs @@ -178,6 +178,28 @@ pub struct AutoRestartConfig { pub reset_window: u64, } +/// Retention for the logs a CVM writes into its work directory. +/// +/// Currently governs serial.log. The caps are deliberately not named after it, +/// because rotation itself is generic (see `crate::logrotate`) and stdout/stderr +/// are the obvious next call sites. +#[derive(Debug, Clone, Deserialize)] +pub struct LogConfig { + /// Max size of a live log. QEMU appends to serial.log for the whole life of + /// a boot, so without a cap a chatty guest can fill the host disk. Past + /// this size the log is rotated and truncated in place. 0 disables + /// rotation. + #[serde(with = "size_parser::human_size")] + pub max_bytes: u64, + + /// Rotated segments to keep. Follows logrotate semantics: the oldest is + /// discarded. + pub max_backups: usize, + + /// How often a live log is checked against `max_bytes`, in seconds. + pub check_interval_secs: u64, +} + impl AutoRestartConfig { pub fn validate(&self) -> Result<()> { if self.enabled { @@ -353,12 +375,8 @@ pub struct CvmConfig { #[serde(default)] pub product: ProductConfig, - /// Max size in bytes for serial.history.log (default 4MB). - /// Previous boot serial logs are appended here before each restart. - /// Accepts human-readable sizes like "4MB", "512KB". - #[serde(default = "default_serial_history_max_bytes")] - #[serde(with = "size_parser::human_size")] - pub serial_history_max_bytes: u64, + /// Guest log retention. + pub log: LogConfig, /// Directory holding attachable volume images (e.g. pre-baked verity /// volumes). A deploy may only attach files under this directory, referenced @@ -522,6 +540,13 @@ pub struct ProcessAnnotation { pub kind: String, #[serde(default)] pub live_for: Option, + /// Whether this process's serial chardev log was opened with + /// `logappend=on`, which is what makes rotating it in place safe. + /// + /// Absent for processes launched before this option existed, and `default` + /// makes those deserialize to `false` — the conservative answer. + #[serde(default)] + pub serial_logappend: bool, } impl ProcessAnnotation { @@ -749,10 +774,6 @@ pub struct KeyProviderConfig { pub port: u16, } -fn default_serial_history_max_bytes() -> u64 { - 4 * 1024 * 1024 // 4MB -} - const CLIENT_CONF_PATH: &str = "/etc/dstack/client.conf"; fn read_qemu_path_from_client_conf() -> Option { #[derive(Debug, Deserialize)] diff --git a/dstack/vmm/src/logrotate.rs b/dstack/vmm/src/logrotate.rs new file mode 100644 index 000000000..fb004109c --- /dev/null +++ b/dstack/vmm/src/logrotate.rs @@ -0,0 +1,307 @@ +// SPDX-FileCopyrightText: © 2024-2025 Phala Network +// +// SPDX-License-Identifier: Apache-2.0 + +//! Logrotate-style rotation for files a live process holds open. +//! +//! Like the logrotate(8) this is modelled on, rotation works on a path and does +//! not care what the log contains or who writes it: `.N-1` becomes +//! `.N`, `` is archived as `.1`, and the oldest segment is +//! discarded. +//! +//! # The one requirement on callers +//! +//! The writer must hold the file open with `O_APPEND`. +//! +//! Rotation truncates the live file in place rather than renaming it. Renaming +//! would leave the writer appending into an unlinked inode, so its output would +//! vanish silently. Truncating keeps the writer's fd valid — but only under +//! `O_APPEND`, which forces every write to the current end of file. A writer +//! without it keeps writing at its stale offset, so the truncation punches a +//! sparse hole and the file springs straight back to its previous size. The cap +//! then never holds and every later check rotates again. +//! +//! For QEMU chardev logs that means `logappend=on`; for a process's stdout or +//! stderr, an `OpenOptions::append(true)` sink. + +use std::path::{Path, PathBuf}; + +use fs_err as fs; +use tracing::warn; + +/// Outcome of a rotation. +pub struct Rotated { + /// Bytes removed from the live log. + pub bytes: u64, + /// Where those bytes were kept, or `None` if they were discarded because + /// no backups are retained. + pub archived: Option, +} + +/// Path of rotated segment `index`, `1` being the most recent. +pub fn segment_path(path: &Path, index: usize) -> PathBuf { + let mut name = path.as_os_str().to_os_string(); + name.push(format!(".{index}")); + PathBuf::from(name) +} + +/// Empty `path` in place, keeping the writer's open fd valid. +/// +/// Missing files are not an error: callers use this to guarantee a log starts +/// empty without having to care whether it exists yet. +pub fn truncate(path: &Path) { + if !path.exists() { + return; + } + if let Err(err) = fs::write(path, b"") { + warn!("failed to truncate {}: {err}", path.display()); + } +} + +/// Rotate `path`, discarding the oldest of `max_backups` segments. +/// +/// Returns `None` when there was nothing to rotate, which includes an empty or +/// missing log — rotating those would spend a segment slot on an empty file and +/// push a segment that still has content off the end. +pub fn rotate(path: &Path, max_backups: usize) -> Option { + let bytes = match fs::metadata(path) { + Ok(meta) if meta.len() > 0 => meta.len(), + _ => return None, + }; + if max_backups == 0 { + truncate(path); + return Some(Rotated { + bytes, + archived: None, + }); + } + + let oldest = segment_path(path, max_backups); + if oldest.exists() { + if let Err(err) = fs::remove_file(&oldest) { + warn!( + "failed to remove oldest segment {}: {err}", + oldest.display() + ); + return None; + } + } + for index in (1..max_backups).rev() { + let from = segment_path(path, index); + if !from.exists() { + continue; + } + if let Err(err) = fs::rename(&from, segment_path(path, index + 1)) { + warn!("failed to shift segment {}: {err}", from.display()); + return None; + } + } + + // Copy rather than rename: the writer holds an open fd on the live log. + let archived = segment_path(path, 1); + if let Err(err) = fs::copy(path, &archived) { + warn!("failed to archive {}: {err}", path.display()); + return None; + } + truncate(path); + Some(Rotated { + bytes, + archived: Some(archived), + }) +} + +/// Rotate `path` if it has grown past `max_bytes`. `max_bytes == 0` disables +/// rotation entirely. +pub fn rotate_if_oversized(path: &Path, max_bytes: u64, max_backups: usize) -> Option { + if max_bytes == 0 { + return None; + } + match fs::metadata(path) { + Ok(meta) if meta.len() > max_bytes => {} + _ => return None, + } + rotate(path, max_backups) +} + +/// Record in the freshly emptied log where its previous content went. +/// +/// A reader that only ever sees the live file — as the VMM log API does — would +/// otherwise find it empty with no explanation. This does not make the segments +/// readable; it makes their absence self-explanatory. +pub fn append_rotation_note(path: &Path, rotated: &Rotated) { + use std::io::Write; + + let Ok(mut file) = fs::OpenOptions::new().append(true).open(path) else { + return; + }; + let timestamp = humantime::format_rfc3339_seconds(std::time::SystemTime::now()); + let bytes = rotated.bytes; + let _ = match &rotated.archived { + Some(archived) => { + let name = archived + .file_name() + .map(|name| name.to_string_lossy().into_owned()) + .unwrap_or_else(|| archived.display().to_string()); + writeln!( + file, + "\n===== rotated {bytes} bytes to {name} @ {timestamp} =====\n" + ) + } + None => writeln!( + file, + "\n===== discarded {bytes} bytes @ {timestamp} =====\n" + ), + }; +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn segment_path_appends_the_index_to_the_whole_name() { + // Suffixing the full name rather than replacing an extension keeps + // `serial.log.1` readable and works for files with no extension. + assert_eq!( + segment_path(Path::new("/run/serial.log"), 1).to_str(), + Some("/run/serial.log.1") + ); + assert_eq!( + segment_path(Path::new("/run/stdout"), 12).to_str(), + Some("/run/stdout.12") + ); + } + + #[test] + fn rotate_shifts_and_drops_the_oldest() -> anyhow::Result<()> { + let temp = tempfile::tempdir()?; + let log = temp.path().join("app.log"); + + for marker in ["first", "second", "third", "fourth"] { + fs::write(&log, format!("{marker}\n"))?; + assert!(rotate(&log, 3).is_some()); + } + + assert_eq!(fs::read(segment_path(&log, 1))?, b"fourth\n"); + assert_eq!(fs::read(segment_path(&log, 2))?, b"third\n"); + assert_eq!(fs::read(segment_path(&log, 3))?, b"second\n"); + assert!(!segment_path(&log, 4).exists()); + Ok(()) + } + + #[test] + fn rotate_keeps_the_live_file_inode() -> anyhow::Result<()> { + use std::os::unix::fs::MetadataExt; + let temp = tempfile::tempdir()?; + let log = temp.path().join("app.log"); + + fs::write(&log, b"before\n")?; + let before = fs::metadata(&log)?.ino(); + rotate(&log, 3); + + // Renaming the live file would leave the writer appending into an + // unlinked inode, losing every later line without an error. + assert_eq!(fs::metadata(&log)?.ino(), before); + assert_eq!(fs::read(&log)?.len(), 0); + Ok(()) + } + + #[test] + fn rotate_skips_an_empty_or_missing_log() -> anyhow::Result<()> { + let temp = tempfile::tempdir()?; + let log = temp.path().join("app.log"); + + // Missing: must not create anything. + assert!(rotate(&log, 3).is_none()); + assert!(!segment_path(&log, 1).exists()); + + // Empty: spending a slot here would push a segment that still has + // content off the end. + fs::write(&log, b"")?; + assert!(rotate(&log, 3).is_none()); + assert!(!segment_path(&log, 1).exists()); + Ok(()) + } + + #[test] + fn rotate_without_backups_discards_instead_of_archiving() -> anyhow::Result<()> { + let temp = tempfile::tempdir()?; + let log = temp.path().join("app.log"); + + fs::write(&log, b"discarded\n")?; + let rotated = rotate(&log, 0).expect("rotated"); + + assert_eq!(rotated.bytes, 10); + assert!(rotated.archived.is_none()); + assert_eq!(fs::read(&log)?.len(), 0); + assert!(!segment_path(&log, 1).exists()); + Ok(()) + } + + #[test] + fn rotate_if_oversized_respects_the_cap() -> anyhow::Result<()> { + let temp = tempfile::tempdir()?; + let log = temp.path().join("app.log"); + + fs::write(&log, vec![b'x'; 100])?; + assert!(rotate_if_oversized(&log, 4096, 3).is_none()); + assert_eq!(fs::read(&log)?.len(), 100); + + fs::write(&log, vec![b'x'; 8192])?; + assert!(rotate_if_oversized(&log, 4096, 3).is_some()); + assert_eq!(fs::read(&log)?.len(), 0); + assert_eq!(fs::read(segment_path(&log, 1))?.len(), 8192); + + // A zero cap disables rotation entirely. + fs::write(&log, vec![b'x'; 8192])?; + assert!(rotate_if_oversized(&log, 0, 3).is_none()); + assert_eq!(fs::read(&log)?.len(), 8192); + Ok(()) + } + + #[test] + fn truncate_is_unconditional_and_tolerates_a_missing_file() -> anyhow::Result<()> { + let temp = tempfile::tempdir()?; + let log = temp.path().join("app.log"); + + truncate(&log); + assert!(!log.exists(), "truncate must not create the file"); + + fs::write(&log, b"stale output\n")?; + truncate(&log); + assert_eq!(fs::read(&log)?.len(), 0); + Ok(()) + } + + #[test] + fn rotation_note_says_where_the_output_went() -> anyhow::Result<()> { + let temp = tempfile::tempdir()?; + let log = temp.path().join("serial.log"); + + fs::write(&log, vec![b'x'; 8192])?; + let rotated = rotate(&log, 3).expect("rotated"); + append_rotation_note(&log, &rotated); + + let note = String::from_utf8_lossy(&fs::read(&log)?).into_owned(); + assert!( + note.contains("rotated 8192 bytes to serial.log.1"), + "{note:?}" + ); + Ok(()) + } + + #[test] + fn rotation_note_does_not_claim_an_archive_that_was_discarded() -> anyhow::Result<()> { + let temp = tempfile::tempdir()?; + let log = temp.path().join("serial.log"); + + fs::write(&log, vec![b'x'; 8192])?; + let rotated = rotate(&log, 0).expect("rotated"); + append_rotation_note(&log, &rotated); + + let note = String::from_utf8_lossy(&fs::read(&log)?).into_owned(); + assert!(note.contains("discarded 8192 bytes"), "{note:?}"); + assert!(!note.contains("serial.log.1"), "{note:?}"); + Ok(()) + } +} diff --git a/dstack/vmm/src/main.rs b/dstack/vmm/src/main.rs index a572cfe9f..96fc1a072 100644 --- a/dstack/vmm/src/main.rs +++ b/dstack/vmm/src/main.rs @@ -26,6 +26,7 @@ mod config; mod discovery; mod guest_api_service; mod host_api_service; +mod logrotate; mod main_routes; mod main_service; mod one_shot; @@ -161,6 +162,22 @@ async fn auto_restart_task(app: App) { } } +async fn log_rotation_task(app: App) { + if app.config.cvm.log.max_bytes == 0 { + info!("Log rotation is disabled"); + return; + } + let mut interval = tokio::time::interval(Duration::from_secs( + app.config.cvm.log.check_interval_secs.max(1), + )); + loop { + interval.tick().await; + if let Err(err) = app.rotate_oversized_logs().await { + error!("Failed to rotate logs: {err:?}"); + } + } +} + #[rocket::main] async fn main() -> Result<()> { { @@ -288,6 +305,7 @@ async fn main() -> Result<()> { let state = app::App::new(config, supervisor); state.reload_vms().await.context("Failed to reload VMs")?; tokio::spawn(auto_restart_task(state.clone())); + tokio::spawn(log_rotation_task(state.clone())); tokio::select! { result = run_external_api(state.clone(), figment.clone(), api_auth) => { diff --git a/dstack/vmm/vmm.toml b/dstack/vmm/vmm.toml index 36fe2d47f..6b421463f 100644 --- a/dstack/vmm/vmm.toml +++ b/dstack/vmm/vmm.toml @@ -124,6 +124,19 @@ initial_backoff = 5 max_backoff = 300 reset_window = 300 +# Retention for the logs a CVM writes into its work directory. Currently +# governs serial.log: QEMU appends to it for the whole life of a boot, so +# without a cap a chatty guest can fill the host disk. +[cvm.log] +# Past this size the log is rotated to serial.log.1 and truncated in place. +# 0 disables rotation. Sizes take a single-letter suffix: "4M", "512K", "1G". +max_bytes = "4M" +# Rotated segments to keep; the oldest is discarded. A VM start rotates too, +# so this is also how many previous boots stay on disk. +max_backups = 3 +# How often a live log is checked against max_bytes. +check_interval_secs = 5 + [cvm.gpu] enabled = false # The product IDs of the GPUs to discover