[Bugfix] Reopen CubeShim and VMM logs after rename-based rotation

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<Self> {
+        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"
+        );
+    }
+}

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:

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，主要用于：

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"