diff --git a/CubeShim/Cargo.lock b/CubeShim/Cargo.lock index 863e2ccfa..0d1472ff4 100644 --- a/CubeShim/Cargo.lock +++ b/CubeShim/Cargo.lock @@ -1430,7 +1430,6 @@ dependencies = [ name = "logging" version = "0.1.0" dependencies = [ - "chrono", "lazy_static", "serde", "slog", @@ -3232,6 +3231,7 @@ dependencies = [ "libc", "linux-loader", "log", + "logging", "micro_http", "net_util", "once_cell", diff --git a/CubeShim/shim/src/log/mod.rs b/CubeShim/shim/src/log/mod.rs index 372767a75..530596e66 100644 --- a/CubeShim/shim/src/log/mod.rs +++ b/CubeShim/shim/src/log/mod.rs @@ -12,7 +12,7 @@ use std::io; use std::io::Write; use std::mem; use std::os::unix::io::AsRawFd; -use std::path::PathBuf; +use std::path::{Path, PathBuf}; use std::time::SystemTime; use time::format_description::well_known::Rfc3339; @@ -57,6 +57,7 @@ macro_rules! errf { } const LOG_ITEM_COUNT: usize = 1024; +const LOG_REOPEN_INTERVAL: Duration = Duration::from_secs(1800); const LOG_DIR: &str = "/data/log/CubeShim/"; const LOF_FILE: &str = "cube-shim-req.log"; const STAT_FILE: &str = "cube-shim-stat.log"; @@ -117,6 +118,55 @@ struct StatItem { function_type: String, } +struct ReopenableFile { + path: PathBuf, + file: tokio::fs::File, +} + +impl ReopenableFile { + async fn open(path: &Path) -> CResult { + let file = OpenOptions::new() + .create(true) + .write(true) + .append(true) + .open(path) + .await + .map_err(|e| format!("open log file failed:{} file:{:?}", e, path))?; + Ok(Self { + path: path.to_path_buf(), + file, + }) + } + + async fn reopen(&mut self) -> CResult<()> { + self.file + .flush() + .await + .map_err(|e| format!("flush log file before reopen failed:{}", e))?; + let file = OpenOptions::new() + .create(true) + .write(true) + .append(true) + .open(&self.path) + .await + .map_err(|e| format!("reopen log file failed:{} file:{:?}", e, self.path))?; + self.file = file; + Ok(()) + } + + async fn write(&mut self, content: &[u8]) -> CResult<()> { + self.file + .write_all(content) + .await + .map_err(|e| format!("write log file failed:{} file:{:?}", e, self.path))?; + self.file + .flush() + .await + .map_err(|e| format!("flush log file failed:{} file:{:?}", e, self.path))?; + Ok(()) + } +} + impl Default for Log { fn default() -> Self { let (sender, _) = mpsc::channel::<(LogType, String)>(1); @@ -252,7 +302,7 @@ impl Log { }); loop { - sleep(Duration::from_secs(1800)).await; + sleep(LOG_REOPEN_INTERVAL).await; if let Err(e) = send.send((LogType::Rotate, "".to_string())).await { eprintln!("send rotate failed:{}", e); } @@ -264,51 +314,21 @@ impl Log { log_file_path: &PathBuf, stat_file_path: &PathBuf, ) -> CResult<()> { - let log_file = OpenOptions::new() - .create(true) - .write(true) - .append(true) - .open(log_file_path.clone()) - .await - .map_err(|e| format!("open log file failed:{} file:{:?}", e, log_file_path))?; - let mut log_writer = tokio::io::BufReader::new(log_file); - - let stat_file = OpenOptions::new() - .create(true) - .write(true) - .append(true) - .open(stat_file_path.clone()) - .await - .map_err(|e| format!("open stat file failed:{} file:{:?}", e, stat_file_path))?; - let mut stat_writer = tokio::io::BufReader::new(stat_file); + let mut log_writer = ReopenableFile::open(log_file_path).await?; + let mut stat_writer = ReopenableFile::open(stat_file_path).await?; //let lf = ['\n' as u8]; while let Some(msg) = recv.recv().await { match msg.0 { LogType::Log => { - log_writer - .write_all(msg.1.as_bytes()) - .await - .map_err(|e| format!("write log file failed:{}", e))?; - //log_writer.write_all(&lf).await.map_err(|e| format!("write log file failed:{}", e)); - log_writer - .flush() - .await - .map_err(|e| format!("flush log failed:{}", e))?; + log_writer.write(msg.1.as_bytes()).await?; } LogType::Stat => { - stat_writer - .write_all(msg.1.as_bytes()) - .await - .map_err(|e| format!("write stat file failed:{}", e))?; - //stat_writer.write_all(&lf).await.map_err(|e| format!("write stat file failed:{}", e)); - stat_writer - .flush() - .await - .map_err(|e| format!("flush stat failed:{}", e))?; + stat_writer.write(msg.1.as_bytes()).await?; } LogType::Rotate => { - break; + log_writer.reopen().await?; + stat_writer.reopen().await?; } } } @@ -434,3 +454,80 @@ fn log_to_file(module: String, insid: String, log: String, func_type: String) -> Ok(()) } + +#[cfg(test)] +mod tests { + use super::*; + use std::fs; + use std::sync::atomic::{AtomicU64, Ordering}; + use std::time::{SystemTime, UNIX_EPOCH}; + + static NEXT_TEST_ID: AtomicU64 = AtomicU64::new(0); + + fn test_log_path() -> PathBuf { + let suffix = SystemTime::now() + .duration_since(UNIX_EPOCH) + .expect("system clock before unix epoch") + .as_nanos(); + let test_id = NEXT_TEST_ID.fetch_add(1, Ordering::Relaxed); + std::env::temp_dir().join(format!( + "cube-shim-log-reopen-{}-{}-{}", + std::process::id(), + suffix, + test_id + )) + } + + struct TestLogFiles { + active: PathBuf, + rotated: PathBuf, + } + + impl TestLogFiles { + fn new() -> Self { + let active = test_log_path(); + let rotated = active.with_extension("log.1"); + Self { active, rotated } + } + } + + impl Drop for TestLogFiles { + fn drop(&mut self) { + let _ = fs::remove_file(&self.active); + let _ = fs::remove_file(&self.rotated); + } + } + + #[tokio::test] + async fn reopens_after_periodic_rotation() { + let files = TestLogFiles::new(); + let mut writer = ReopenableFile::open(&files.active).await.unwrap(); + + writer.write(b"before\n").await.unwrap(); + fs::rename(&files.active, &files.rotated).unwrap(); + fs::File::create(&files.active).unwrap(); + writer.reopen().await.unwrap(); + writer.write(b"after\n").await.unwrap(); + drop(writer); + + assert_eq!(fs::read_to_string(&files.rotated).unwrap(), "before\n"); + assert_eq!(fs::read_to_string(&files.active).unwrap(), "after\n"); + } + + #[tokio::test] + async fn failed_reopen_keeps_current_descriptor_usable() { + let files = TestLogFiles::new(); + let mut writer = ReopenableFile::open(&files.active).await.unwrap(); + + writer.write(b"before\n").await.unwrap(); + writer.path = std::env::temp_dir(); + assert!(writer.reopen().await.is_err()); + writer.write(b"after\n").await.unwrap(); + drop(writer); + + assert_eq!( + fs::read_to_string(&files.active).unwrap(), + "before\nafter\n" + ); + } +} diff --git a/docs/guide/service-management.md b/docs/guide/service-management.md index 5264a49ad..d650ac643 100644 --- a/docs/guide/service-management.md +++ b/docs/guide/service-management.md @@ -252,6 +252,49 @@ sudo tail -F /data/log/CubeAPI/cube-api-$(date +%F).log sudo tail -200 /data/log/CubeVmm/vmm.log ``` +### Rotating CubeShim and VMM logs + +CubeShim and the VMM keep their log files open while they run. CubeShim +reopens its files on an internal 30-minute rotation event. The VMM control +thread owns a monotonic `timerfd` and emits the existing `LOG_CTRL_REOPEN` +control record once per hour. Reopen is schedule-driven: an external +`rename` + `create` is picked up at the next scheduled reopen rather than +detected immediately on an arbitrary write. The timer is owned by the VMM +control thread, not by deferred logger initialization or a vCPU/API thread. +The host-side policy should run hourly and use `rename` + `create`; do not use +`copytruncate`. + +For example, install the following as `/etc/logrotate.d/cubesandbox` and make +sure the host invokes `logrotate` hourly: + +```text +/data/log/CubeVmm/vmm.log +/data/log/CubeShim/*.log { + hourly + rotate 24 + missingok + notifempty + compress + delaycompress + create 0640 root root +} +``` + +`rotate 24` retains 24 hourly files; adjust it to the required retention period. +`delaycompress` keeps the newest rotated file uncompressed for one cycle because +a writer may still use the old descriptor until its next scheduled reopen. +CubeShim's internal event runs every 30 minutes, while the VMM control thread +sends a reopen control event every hour. No `postrotate` signal or service +restart is required. This policy guarantees bounded retention on the host, +but does not promise immediate handling of an arbitrary manual rotation; it +does not support `copytruncate`. + +The example uses `root root` because the bundled one-click systemd services run as +root. If CubeShim or the VMM run under another account, set the `create` owner and +group to that account; otherwise a newly-created file may not be reopenable. +The `0640` mode in this example applies to files created by `logrotate`; the +CubeShim and VMM writers themselves continue to use the process umask. + ### `journalctl` startup logs journalctl captures **stdout/stderr from when systemd starts the process until it stabilizes (or exits)**, useful for: diff --git a/docs/zh/guide/service-management.md b/docs/zh/guide/service-management.md index 768398a59..1d6b0084a 100644 --- a/docs/zh/guide/service-management.md +++ b/docs/zh/guide/service-management.md @@ -252,6 +252,30 @@ sudo tail -F /data/log/CubeAPI/cube-api-$(date +%F).log sudo tail -200 /data/log/CubeVmm/vmm.log ``` +### CubeShim 和 VMM 日志轮转 + +CubeShim 和 VMM 运行期间会保持日志文件打开。CubeShim 通过内部每 30 分钟轮转事件 reopen。VMM 控制线程自己持有 monotonic `timerfd`，每小时发出已有的 `LOG_CTRL_REOPEN` 控制记录。reopen 由固定周期驱动：宿主机执行“`rename` + `create`”后，会在下一次计划中的 reopen 时切换到新文件，而不是在任意一次写入时立即检测。该定时器由 VMM 控制线程持有，不依赖延迟 logger 初始化，也不会由 vCPU/API 线程创建。因此宿主机侧仍应按小时执行轮转，并使用“`rename` + `create`”方式，不要使用 `copytruncate`。 + +例如，将下面内容保存为 `/etc/logrotate.d/cubesandbox`，并确保宿主机每小时执行一次 `logrotate`： + +```text +/data/log/CubeVmm/vmm.log +/data/log/CubeShim/*.log { + hourly + rotate 24 + missingok + notifempty + compress + delaycompress + create 0640 root root +} +``` + +`rotate 24` 表示保留 24 个小时文件，可按实际保留周期调整。`delaycompress` 会将最新的轮转文件延迟一个周期压缩，因为 writer 在下一次计划中的 reopen 之前可能仍使用旧 fd。CubeShim 每 30 分钟触发一次内部事件，VMM 控制线程每小时发送一次 reopen 控制事件。不需要 `postrotate` 信号或重启服务；该策略保证宿主机侧 retention 有界，但不承诺对任意手工轮转立即响应，也不支持 `copytruncate`。 + +示例使用 `root root`，因为随附的一键部署 systemd 服务以 root 运行。如果 CubeShim 或 VMM 使用其他账号运行，请把 `create` 的 owner 和 group 改成对应账号；否则新建文件可能无法被 reopen。 +示例中的 `0640` 只适用于 `logrotate` 创建的文件；CubeShim 和 VMM writer 本身仍遵循进程的 umask。 + ### `journalctl` 启动期日志 journalctl 看的是**进程被 systemd 拉起到稳定运行（或失败退出）期间**的 stdout/stderr，主要用于： diff --git a/hypervisor/Cargo.lock b/hypervisor/Cargo.lock index ad8f70797..f15d8f326 100644 --- a/hypervisor/Cargo.lock +++ b/hypervisor/Cargo.lock @@ -1026,7 +1026,6 @@ dependencies = [ name = "logging" version = "0.1.0" dependencies = [ - "chrono", "lazy_static", "serde", "slog", @@ -2532,6 +2531,7 @@ dependencies = [ "libc", "linux-loader", "log", + "logging", "micro_http", "net_util", "once_cell", diff --git a/hypervisor/logging/Cargo.toml b/hypervisor/logging/Cargo.toml index 5c53e21a6..3d06454d8 100644 --- a/hypervisor/logging/Cargo.toml +++ b/hypervisor/logging/Cargo.toml @@ -5,7 +5,6 @@ authors = ["The Cloud Hypervisor Authors"] edition = "2018" [dependencies] -chrono = "0.4.24" lazy_static = "1.2" serde = { workspace = true, features = ["derive"] } slog = "2.7.0" diff --git a/hypervisor/logging/src/lib.rs b/hypervisor/logging/src/lib.rs index 2d92a552b..79efee43e 100644 --- a/hypervisor/logging/src/lib.rs +++ b/hypervisor/logging/src/lib.rs @@ -1,4 +1,3 @@ -use chrono::{Datelike, Timelike, Utc}; use slog::*; use slog_term::{Decorator, RecordDecorator}; use std::cell::RefCell; @@ -9,8 +8,23 @@ use std::{io, result}; #[macro_use] extern crate lazy_static; +/// Slog tag used to request an explicit log-file reopen. pub const LOG_CTRL_REOPEN: &str = "LogReopen"; +fn open_log_file(name: &str) -> io::Result { + std::fs::File::options() + .create(true) + .append(true) + .open(std::path::Path::new(name)) +} + +fn open_replacement_log_file(name: &str) -> io::Result { + std::fs::File::options() + .create(true) + .append(true) + .open(std::path::Path::new(name)) +} + lazy_static! { pub static ref START_TM: Mutex = Mutex::new(std::time::Instant::now()); } @@ -19,7 +33,6 @@ lazy_static! { pub struct RawPlainDecorator { name: String, - current: u64, output: std::fs::File, } @@ -30,32 +43,29 @@ pub struct PlainDecorator { impl PlainDecorator { /// Create `PlainDecorator` instance pub fn new(name: String) -> Self { - let now = Utc::now(); - let current = now.year() as u64 * 1_000_000 - + now.month() as u64 * 10_000 - + now.day() as u64 * 100 - + now.hour() as u64; let filename = name.clone(); + let output = open_log_file(&filename).unwrap(); PlainDecorator { - deco: RefCell::new(RawPlainDecorator { - name: name, - current: current, - output: std::fs::File::options() - .create(true) - .append(true) - .open(std::path::Path::new(&filename.to_string())) - .unwrap(), - }), + deco: RefCell::new(RawPlainDecorator { name, output }), } } } impl Decorator for PlainDecorator { - fn with_record(&self, _record: &Record, _logger_values: &OwnedKVList, f: F) -> io::Result<()> + fn with_record(&self, record: &Record, _logger_values: &OwnedKVList, f: F) -> io::Result<()> where F: FnOnce(&mut dyn RecordDecorator) -> io::Result<()>, { let mut deco = self.deco.borrow_mut(); + if record.tag() == LOG_CTRL_REOPEN { + if let Err(error) = deco.reopen() { + eprintln!( + "cube-vmm: failed to reopen log file {:?}: {}", + deco.name, error + ); + } + return Ok(()); + } let mut deco = PlainRecordDecorator { deco: &mut *deco }; f(&mut deco) } @@ -66,24 +76,17 @@ pub struct PlainRecordDecorator<'a> { deco: &'a mut RawPlainDecorator, } +impl RawPlainDecorator { + fn reopen(&mut self) -> io::Result<()> { + self.output.flush()?; + let output = open_replacement_log_file(&self.name)?; + self.output = output; + Ok(()) + } +} + impl<'a> io::Write for PlainRecordDecorator<'a> { fn write(&mut self, buf: &[u8]) -> io::Result { - { - let now = Utc::now(); - let current = now.year() as u64 * 1_000_000 - + now.month() as u64 * 10_000 - + now.day() as u64 * 100 - + now.hour() as u64; - if self.deco.current != current { - self.deco.current = current; - let filename = self.deco.name.clone(); - self.deco.output = std::fs::File::options() - .create(true) - .append(true) - .open(std::path::Path::new(&filename.to_string())) - .unwrap(); - } - } self.deco.output.write(buf) } @@ -175,3 +178,102 @@ pub fn create_logger(name: String) -> slog::Logger { logger } + +#[cfg(test)] +mod tests { + use super::*; + use std::fs; + use std::sync::atomic::{AtomicU64, Ordering}; + use std::time::{SystemTime, UNIX_EPOCH}; + + static NEXT_TEST_ID: AtomicU64 = AtomicU64::new(0); + + fn test_log_path() -> std::path::PathBuf { + let suffix = SystemTime::now() + .duration_since(UNIX_EPOCH) + .expect("system clock before unix epoch") + .as_nanos(); + let test_id = NEXT_TEST_ID.fetch_add(1, Ordering::Relaxed); + std::env::temp_dir().join(format!( + "cube-vmm-log-reopen-{}-{}-{}", + std::process::id(), + suffix, + test_id + )) + } + + struct TestLogFiles { + active: std::path::PathBuf, + rotated: std::path::PathBuf, + } + + impl TestLogFiles { + fn new() -> Self { + let active = test_log_path(); + let rotated = active.with_extension("log.1"); + Self { active, rotated } + } + } + + impl Drop for TestLogFiles { + fn drop(&mut self) { + let _ = fs::remove_file(&self.active); + let _ = fs::remove_file(&self.rotated); + } + } + + #[test] + fn control_record_reopens_after_rename_based_rotation() { + let files = TestLogFiles::new(); + let drain = RawFormat::new(PlainDecorator::new( + files.active.to_string_lossy().into_owned(), + )) + .build(); + let values = OwnedKVList::from(o!()); + + drain + .log( + &slog::record!(Level::Info, "", &format_args!("before"), b!()), + &values, + ) + .unwrap(); + + fs::rename(&files.active, &files.rotated).unwrap(); + fs::File::create(&files.active).unwrap(); + + drain + .log( + &slog::record!(Level::Info, LOG_CTRL_REOPEN, &format_args!(""), b!()), + &values, + ) + .unwrap(); + drain + .log( + &slog::record!(Level::Info, "", &format_args!("after"), b!()), + &values, + ) + .unwrap(); + + assert_eq!(fs::read_to_string(&files.rotated).unwrap(), "before"); + assert_eq!(fs::read_to_string(&files.active).unwrap(), "after"); + } + + #[test] + fn failed_reopen_keeps_current_descriptor_usable() { + let files = TestLogFiles::new(); + let output = open_log_file(files.active.to_str().expect("utf-8 log path")).unwrap(); + let mut raw = RawPlainDecorator { + name: std::env::temp_dir().to_string_lossy().into_owned(), + output, + }; + + raw.output.write_all(b"before\n").unwrap(); + assert!(raw.reopen().is_err()); + raw.output.write_all(b"after\n").unwrap(); + + assert_eq!( + fs::read_to_string(&files.active).unwrap(), + "before\nafter\n" + ); + } +} diff --git a/hypervisor/vmm/Cargo.toml b/hypervisor/vmm/Cargo.toml index 00181f7ed..f4ef35913 100644 --- a/hypervisor/vmm/Cargo.toml +++ b/hypervisor/vmm/Cargo.toml @@ -33,6 +33,7 @@ hypervisor = { path = "../hypervisor" } lazy_static = "1.2" libc = "0.2.137" linux-loader = { workspace = true, features = ["elf", "bzimage", "pe"] } +logging = { path = "../logging" } log = "0.4.17" micro_http = { git = "https://github.com/firecracker-microvm/micro-http", branch = "main" } net_util = { path = "../net_util" } diff --git a/hypervisor/vmm/src/lib.rs b/hypervisor/vmm/src/lib.rs index 1a1d7bd49..93ba37fe5 100644 --- a/hypervisor/vmm/src/lib.rs +++ b/hypervisor/vmm/src/lib.rs @@ -31,7 +31,8 @@ use crate::vm_config::{ }; use anyhow::anyhow; use event_notifier::{event_notify, NotifyEvent}; -use libc::{EFD_NONBLOCK, SIGINT, SIGTERM}; +use libc::{EFD_NONBLOCK, SIGINT, SIGTERM, TFD_NONBLOCK}; +use logging::LOG_CTRL_REOPEN; use memory_manager::MemoryManagerSnapshotData; use pci::PciBdf; use seccompiler::{apply_filter, SeccompAction}; @@ -51,7 +52,7 @@ use std::rc::Rc; use std::sync::atomic::AtomicBool; use std::sync::mpsc::{Receiver, RecvError, SendError, Sender}; use std::sync::{Arc, Barrier, Mutex}; -use std::time::Instant; +use std::time::{Duration, Instant}; use std::{result, thread}; use thiserror::Error; use tracer::trace_scoped; @@ -119,6 +120,14 @@ pub enum Error { #[error("Error reading from EventFd: {0}")] EventFdRead(#[source] io::Error), + /// Cannot create the periodic log-reopen timer. + #[error("Error creating log-reopen timer: {0}")] + LogReopenTimerCreate(#[source] io::Error), + + /// Cannot consume the periodic log-reopen timer event. + #[error("Error reading log-reopen timer: {0}")] + LogReopenTimerRead(#[source] io::Error), + /// Cannot create epoll context. #[error("Error creating epoll context: {0}")] Epoll(#[source] io::Error), @@ -197,6 +206,7 @@ pub enum EpollDispatch { Api = 2, ActivateVirtioDevices = 3, Debug = 4, + LogReopen = 5, Unknown, } @@ -209,11 +219,66 @@ impl From for EpollDispatch { 2 => Api, 3 => ActivateVirtioDevices, 4 => Debug, + 5 => LogReopen, _ => Unknown, } } } +const LOG_REOPEN_INTERVAL: Duration = Duration::from_secs(60 * 60); + +fn create_log_reopen_timer(interval: Duration) -> io::Result { + // This is called from the VMM control thread after its VMM-specific + // seccomp filter has been installed. The vCPU and API thread filters do + // not allow timerfd syscalls. + let timer_fd = + unsafe { libc::timerfd_create(libc::CLOCK_MONOTONIC, libc::TFD_CLOEXEC | TFD_NONBLOCK) }; + if timer_fd < 0 { + return Err(io::Error::last_os_error()); + } + + // SAFETY: timer_fd is a valid, newly-created file descriptor owned by us. + let timer = unsafe { File::from_raw_fd(timer_fd) }; + let interval = libc::itimerspec { + it_interval: libc::timespec { + tv_sec: interval.as_secs() as _, + tv_nsec: interval.subsec_nanos() as _, + }, + it_value: libc::timespec { + tv_sec: interval.as_secs() as _, + tv_nsec: interval.subsec_nanos() as _, + }, + }; + + let result = + unsafe { libc::timerfd_settime(timer.as_raw_fd(), 0, &interval, std::ptr::null_mut()) }; + if result < 0 { + return Err(io::Error::last_os_error()); + } + + Ok(timer) +} + +fn read_log_reopen_timer(reader: &mut R) -> io::Result { + let mut expirations = [0_u8; std::mem::size_of::()]; + match reader.read(&mut expirations) { + Ok(size) if size == expirations.len() => Ok(true), + Ok(size) => Err(io::Error::new( + io::ErrorKind::UnexpectedEof, + format!("short log-reopen timer read: {size} bytes"), + )), + Err(error) + if matches!( + error.kind(), + io::ErrorKind::Interrupted | io::ErrorKind::WouldBlock + ) => + { + Ok(false) + } + Err(error) => Err(error), + } +} + pub struct EpollContext { epoll_file: File, } @@ -383,6 +448,7 @@ struct VmMigrationConfig { pub struct Vmm { epoll: EpollContext, + log_reopen_timer: File, exit_evt: EventFd, reset_evt: EventFd, api_evt: EventFd, @@ -492,9 +558,15 @@ impl Vmm { vcpu_started: Arc, ) -> Result { let mut epoll = EpollContext::new().map_err(Error::Epoll)?; + let log_reopen_timer = + create_log_reopen_timer(LOG_REOPEN_INTERVAL).map_err(Error::LogReopenTimerCreate)?; let reset_evt = EventFd::new(EFD_NONBLOCK).map_err(Error::EventFdCreate)?; let activate_evt = EventFd::new(EFD_NONBLOCK).map_err(Error::EventFdCreate)?; + epoll + .add_event(&log_reopen_timer, EpollDispatch::LogReopen) + .map_err(Error::Epoll)?; + epoll .add_event(&exit_evt, EpollDispatch::Exit) .map_err(Error::Epoll)?; @@ -518,6 +590,7 @@ impl Vmm { Ok(Vmm { epoll, + log_reopen_timer, exit_evt, reset_evt, api_evt, @@ -1884,6 +1957,17 @@ impl Vmm { .map_err(Error::ActivateVirtioDevices)?; } } + EpollDispatch::LogReopen => { + if read_log_reopen_timer(&mut self.log_reopen_timer) + .map_err(Error::LogReopenTimerRead)? + { + // The default VMM verbosity is Warn. Keep the + // control record visible to the logger facade at + // that level; the file decorator consumes it + // without writing a warning line. + warn!(target: LOG_CTRL_REOPEN, "periodic log reopen"); + } + } EpollDispatch::Api => { // Consume the events. for _ in 0..self.api_evt.read().map_err(Error::EventFdRead)? { @@ -2209,6 +2293,46 @@ mod unit_tests { RngConfig, VmConfig, }; + #[test] + fn log_reopen_timer_expires() { + let mut timer = create_log_reopen_timer(Duration::from_millis(1)).unwrap(); + for _ in 0..100 { + if read_log_reopen_timer(&mut timer).unwrap() { + return; + } + thread::sleep(Duration::from_millis(1)); + } + panic!("log-reopen timer did not expire"); + } + + #[test] + fn log_reopen_timer_handles_would_block() { + let mut timer = create_log_reopen_timer(Duration::from_secs(3600)).unwrap(); + + assert!(!read_log_reopen_timer(&mut timer).unwrap()); + } + + #[test] + fn log_reopen_timer_handles_interrupted_read() { + struct InterruptOnceReader { + interrupted: bool, + } + + impl Read for InterruptOnceReader { + fn read(&mut self, buf: &mut [u8]) -> io::Result { + if !self.interrupted { + self.interrupted = true; + return Err(io::Error::from(io::ErrorKind::Interrupted)); + } + Ok(buf.len()) + } + } + + let mut reader = InterruptOnceReader { interrupted: false }; + assert!(!read_log_reopen_timer(&mut reader).unwrap()); + assert!(read_log_reopen_timer(&mut reader).unwrap()); + } + fn create_dummy_vmm() -> Vmm { Vmm::new( "dummy".to_string(),