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

[ZhengkaiWang]

Summary

Keep CubeShim and VMM log files bounded with host-side hourly rotation, retention, and periodic reopen without a service restart.

Root cause

Both writers keep log files open. Host-side rename + create rotation replaces the pathname while the process still holds the old file descriptor, so each writer needs a safe reopen path that does not discard writes when the replacement is temporarily unavailable.

Changes

• keep CubeShim's existing internal Rotate event and reopen both log files
• preserve the VMM's existing wall-clock-hour reopen on the first log write after the hour changes
• compare the VMM pathname and held descriptor by device/inode at most once per second, so rename-based rotation is detected on a subsequent write without waiting for the next hour
• let the VMM control thread own a monotonic timerfd and emit the existing LOG_CTRL_REOPEN control record once per hour
• keep the current descriptor usable when reopen fails; retry on later writes with a one-second cooldown
• open replacement files before swapping descriptors and let host-side logrotate create own replacement-file creation
• keep writer-created files subject to the process umask
• document an hourly /etc/logrotate.d/cubesandbox policy using rename + create, delaycompress, compression, and host-owned retention
• explicitly disallow copytruncate

The VMM timer is created and consumed by the VMM control thread after its VMM-specific seccomp filter is installed; it is not created from deferred logger initialization or a vCPU/API thread. The pathname/device/inode check remains a write-triggered fast path for arbitrary external rotations. This PR does not impose a fixed byte-size limit such as 100M; host-side rotation and retention remain the deployment policy.

Related to #1290
Related to #1136

Validation

• cargo fmt --all -- --check
• cargo test -p logging --lib
• cargo check --target x86_64-unknown-linux-gnu -p cube-hypervisor --lib
• cargo check --target x86_64-unknown-linux-gnu -p containerd-shim-cube-rs --tests

[cubesandboxbot]

Review of PR #1292 — Reopen CubeShim and VMM logs after rename-based rotation

AI-generated review — not a human approval.

Overall

The change is well-structured and the unit tests are thoughtful. The core fix is real and valuable: the old VMM decorator reopened its log file on the first write after a wall-clock hour change and .unwrap()-ed the open, so a failed reopen (e.g., the path temporarily missing between logrotate's rename and create) would panic the logging thread. The new design replaces that with a monotonic timerfd owned by the VMM control thread that emits the existing LOG_CTRL_REOPEN control record hourly, and both writers now reopen gracefully — keeping the current descriptor on failure. The rename + create logrotate policy, delaycompress, and the "no postrotate/restart" documentation are coherent with the implementation.

I traced the reopen-control path end to end and it does work in the default configuration: warn!(target: LOG_CTRL_REOPEN, …) (log facade, vmm) → Logger::log (hypervisor/src/common.rs) → log_async maps the log-crate target to the slog tag via slog_info!(…, #LOG_CTRL_REOPEN, …) → PlainDecorator::with_record checks record.tag() == LOG_CTRL_REOPEN → reopen. The seccomp filter for the VMM thread already allows timerfd_create/timerfd_settime/read, and the timer is created after the VMM-specific filter is installed, so the syscalls are permitted.

No critical correctness bugs were found in the primary flow. The issues below are documentation/description mismatches, coupling fragility, and minor cleanups.

Findings

1. PR description does not match the implementation (medium)

The PR body claims the VMM "compare[s] the VMM pathname and held descriptor by device/inode at most once per second, so rename-based rotation is detected on a subsequent write without waiting for the next hour." No such device/inode (or pathname) comparison exists anywhere in the diff. Reopen is purely schedule-driven: the hourly timerfd for the VMM, and the 30-minute Rotate event for CubeShim. The docs (docs/guide/service-management.md) correctly describe the schedule-driven behavior and even state "an external rename + create is picked up at the next scheduled reopen rather than detected immediately on an arbitrary write" — which directly contradicts the PR-body bullet. Please update the PR description to match what was implemented (and note that the old wall-clock-on-write check was removed, not preserved).

2. Reopen control depends on a fragile log-facade → slog-tag bridge (low)

Posted inline at hypervisor/vmm/src/lib.rs:1968. The hourly reopen fires only when all of the following hold: async logging is on (log_stderr is false), the log-crate level filter passes Warn, and Logger::log_async maps the target to the slog tag. In sync mode the control record is dropped outright (common.rs:209), and the buffered-drain path (common.rs:159) forwards without the tag. It works today, but a more robust design would let the control thread call a dedicated reopen API instead of routing the signal through the log record.

3. CubeShim reopen-failure behavior contradicts the PR description (low)

Posted inline at CubeShim/shim/src/log/mod.rs:330. On a failed reopen() the ? exits the writer task, the outer loop drops the ReopenableFile (closing the old descriptor), and retries after 3 s — not "keep the current descriptor usable … with a one-second cooldown" as the PR claims. ReopenableFile::reopen already preserves self.file on failure, so the Rotate arm could log-and-continue to match the described behavior.

4. Duplicate helper functions (low)

Posted inline at hypervisor/logging/src/lib.rs:23. open_replacement_log_file is identical to open_log_file; one can be removed.

5. Minor / informational

• The VMM's old wall-clock reopen (in PlainRecordDecorator::write) was removed. Rotation is now only as frequent as the timer — fine while the VMM reopens hourly and logrotate runs hourly (periods are equal, so a writer stops appending to a file before logrotate compresses it), but operators should keep the hourly cadence aligned as the docs say.
• delaycompress in the sample policy is helpful but the docs' rationale ("keeps the newest rotated file uncompressed for one cycle because a writer may still use the old descriptor") is only strictly true while the writer's reopen period ≤ the rotation period; worth a clarifying word.
• The docs correctly call out the owner/group caveat for create 0640 root root; note that if a non-root writer cannot open the replacement, CubeShim's writer task will log-fail every 3 s and drop messages once the bounded channel fills.
• The timerfd failure paths return errors from the VMM control loop (Error::LogReopenTimerCreate/Read), which aborts the loop — acceptable, but worth being aware that a spurious timer read error now terminates the VMM control thread.

Verification notes

• hypervisor/logging/Cargo.toml drops chrono and all chrono usages are removed from logging/src/lib.rs; the remaining chrono references are in other crates (vmm, hypervisor), which still declare it. Lockfiles are updated consistently.
• #[tokio::test] in the CubeShim tests is satisfied (tokio = { features = ["full"] }).
• The EpollDispatch::LogReopen = 5 token does not collide with existing registrations (Exit…Debug = 0…4).
• The three new VMM timer tests and both CubeShim reopen tests are self-contained (unique temp paths, drop cleanup) and should not be flaky.

[lisongqian]

Thank you for your contribution. Please fix your commit messages first. Here is some info: https://github.com/TencentCloud/CubeSandbox/blob/master/CONTRIBUTING.md#commit-messages
And some similar commits can be squashed.

[cubesandboxbot]

The hourly timerfd reopen is emitted as a log-crate info! record. With the hypervisor's default verbosity (-v 0 → LevelFilter::Warn, see main.rs), info! is filtered out by log::set_max_level before it ever reaches common.rs::Logger, so this control record is a no-op and the timer never triggers a reopen. It also does nothing in --log-stderr (sync) mode, where common.rs drops LOG_CTRL_REOPEN records entirely (line 209) and writes bypass the decorator.

So the "control thread emits the LOG_CTRL_REOPEN control record once per hour" guarantee only holds when the log level is Info or higher AND async file logging is in use. That's fine in practice because the write-triggered identity check (reopen_if_needed_at/file_replaced) covers rename-based rotation within ~1s of the next write, but the docs currently present the timer as an unconditional hourly reopen. Worth either documenting the Info+ / async precondition, or emitting at a level that isn't filtered (or using a path that doesn't depend on the log facade's max level).

[cubesandboxbot]

The PR description says "keep the current descriptor usable when reopen fails; retry on later writes with a one-second cooldown" — that behavior is implemented on the VMM side, but on the CubeShim side a failed reopen() propagates through ? and aborts the whole write_log_rotate invocation. The old descriptor is dropped when the function returns, and the consumer loop restarts the writer after a 3-second sleep with freshly-opened files.

Two consequences worth noting:

• log_writer.reopen() and stat_writer.reopen() are not independent: if the log-file reopen succeeds but the stat-file reopen fails (or vice-versa), the error tears down both writers even though one descriptor was already swapped, causing a 3s gap plus a redundant reopen of the healthy file.
• During the 3s restart window (or if the file remains unopenable and the 3s retry loop spins), the mpsc channel (cap 1024) can fill and try_send in Log::log/Log::stat silently drops messages.

This is recoverable, but it differs from the documented "keep old descriptor, retry with 1s cooldown" behavior. Consider matching the VMM's tolerant handling here (e.g. keep the old descriptor on reopen failure instead of ?), or adjusting the docs to describe the shim's restart behavior.

[zhuangel]

There already has the timerfd path to reopen logfile, so the log reopen logic in reopen_if_needed checks in RawPlainDecorator and PlainRecordDecorator could be deleted, let PlainRecordDecorator just do log write works.

Could you please help to verify this.

[ZhengkaiWang]

@zhuangel Thanks for the suggestion. I verified the timerfd-only simplification against the current logging path.

The timerfd remains the only scheduled hourly reopen mechanism, and I removed the duplicate wall-clock check. However, deleting reopen_if_needed entirely is not safe in the current design:

• With the default -v 0, the original info!(target: LOG_CTRL_REOPEN, ...) is filtered by LevelFilter::Warn before it reaches the logger.
• The control record uses the slog_async queue, configured with OverflowStrategy::Drop, so it can be lost during a log burst.

I changed the control record to warn! and kept only the once-per-second device/inode check as a narrow fallback for an external rename/create or a dropped control record. It is no longer a second scheduled reopen path; the normal path is still just log writing, with the fallback check only when due. The focused logging tests and the Linux-target cube-hypervisor check pass at 5e1ab61.

This seems to be the smallest safe version of the simplification while preserving the existing rotation behavior.

[lisongqian]

@ZhengkaiWang Thank you for your thoughts! Here is my view:

I changed the control record to warn!

Agree with you.

kept only the once-per-second device/inode check as a narrow fallback for an external rename/create or a dropped control record. It is no longer a second scheduled reopen path; the normal path is still just log writing, with the fallback check only when due.

I think the fallback should be removed since no additional CPU overhead should be added for unexpected behavior. Reopen configuration should be kept the same as log rotation. A stable operating environment without external operations. The log of shim is the same.

[cubesandboxbot]

The PR description claims rename-based rotation is detected "on a subsequent write" via a device/inode comparison ("at most once per second", with "retry on later writes with a one-second cooldown"). This write path performs no such comparison — the old hourly wall-clock check was removed and nothing replaced it. Reopen now happens only when the hourly LOG_CTRL_REOPEN control record reaches this decorator (CubeShim has its own 30-min Rotate event). The docs (service-management.md) describe the schedule-driven behavior correctly, so only the PR body overstates the fast-path detection — but worst-case reopen latency is now bounded by the timer, not by writes.

[cubesandboxbot]

The hourly reopen depends entirely on this control record surviving the slog_async channel (chan_size(8192), OverflowStrategy::Drop). Under heavy logging the record is silently dropped and the file stays rotated until the next hourly tick. There is also a second loss window in hypervisor/src/common.rs:158-160: records buffered before the logger thread starts are drained with a plain slog_info! (no #LOG_CTRL_REOPEN tag), so a reopen emitted in that window is written as a normal log line and never reopens the file. If a reopen is missed/delayed past the next delaycompress cycle, the writer can be appending to an inode logrotate is about to gzip (writes go to a deleted file) — silent data loss. Worth confirming a missed reopen is acceptable.

[cubesandboxbot]

create_log_reopen_timer failure (e.g. EMFILE/ENFILE — the VMM opens many fds) now aborts VMM startup via Error::LogReopenTimerCreate before any VM is created. A logging-rotation convenience turning into a fatal boot failure is a regression; consider making the timer best-effort (log a warning and continue without periodic reopen) so fd exhaustion degrades rotation, not the VM.

[cubesandboxbot]

? propagates a failed reopen() out of write_log_rotate, so the outer retry loop sleeps 3s during which the receiver is not drained; try_send (channel cap 1024) then drops log/stat messages. That drop window pre-exists for write errors, but reopen failures are a new, more likely trigger (e.g. logrotate create 0640 root root producing a file the shim's account can't reopen, which the docs explicitly warn about). Consider logging the reopen failure and continuing the loop instead of aborting it, so one failed reopen doesn't pause the writer.

[lisongqian]

LGTM

[zhuangel]

Almost done, could you please fix it @ZhengkaiWang.

[cubesandboxbot]

This test does not exercise the reopen path and its assertions will fail. slog::record!(level, msg, args, b) puts the 2nd argument in the record message and leaves the tag as "" — it does not set a tag. PlainDecorator::with_record only takes the reopen branch when record.tag() == LOG_CTRL_REOPEN, so this control record (tag "") is treated as an ordinary record. Meanwhile RawFormat::format_compact writes only record.msg(): the "before"/"after" payloads above are passed as args (never written), and this record writes the literal string LogReopen to the still-open old fd. The rotated file ends up as "LogReopen" and the active file stays empty, so both assert_eq!s at lines 257–258 fail — i.e. cargo test -p logging --lib will fail, contradicting the PR's validation claim.

To exercise the path, the control record must carry the tag and the payloads must be in the msg position, e.g. slog::Record::with_tag(LOG_CTRL_REOPEN, Level::Info, "", &format_args!(""), b!()) (and record!(Level::Info, "before", &format_args!(""), b!()) for the ordinary records).

[cubesandboxbot]

The whole reopen mechanism now depends on this warn! record surviving two filters that can silently drop it:

1. log facade max level. log::set_max_level(VmmConfig.log_level) is used at init (hypervisor/src/lib.rs:138). The CLI can't select Error, but VmmConfig.log_level = LevelFilter::Error via the library API would drop this record before it reaches PlainDecorator, so the VMM keeps appending to a renamed file that rotate 24 will eventually compress/delete out from under the still-open fd — unbounded hidden disk usage, with no log noise to indicate rotation broke.

2. Deferred-logger buffer. With the default config, defer_logger_thread == true (log_level <= Info, which includes the CLI default Warn), so common::Logger::log_async pushes records emitted before vcpu_started into self.buffer and replays them later via slog_info!(logger, "{}", v) without the #LOG_CTRL_REOPEN tag. If the hourly firing lands before vCPU start, that hour's reopen is skipped and the raw warning text is written to the file as an ordinary line; if vCPUs never start, control records are buffered indefinitely and the file is never reopened.

The warn! level is a deliberate hack to survive the facade filter; it would be more robust to route the reopen out-of-band (the timerfd could feed a channel/flag the control thread checks) or at least guard against log_level < Warn when creating the timer.

[cubesandboxbot]

open_log_file and open_replacement_log_file are byte-for-byte identical (same create(true).append(true).open). The "replacement" semantics are just the same create+append open, so consolidate into a single helper and call it from both PlainDecorator::new and RawPlainDecorator::reopen.

[cubesandboxbot]

open_replacement_log_file is byte-for-byte identical to open_log_file (both create(true) + append(true) + open). RawPlainDecorator::reopen can just call open_log_file and this second function can be removed — the "replacement" semantics the name suggests don't actually exist (the file is opened by path, not by swapping an existing handle).

[cubesandboxbot]

This reopen control only works through a fragile chain: the log-crate record (warn!(target: ...)) is bridged to the slog tag by Logger::log_async in hypervisor/src/common.rs (slog_info!(..., #LOG_CTRL_REOPEN, ...)), and only then does PlainDecorator::with_record see record.tag() == LOG_CTRL_REOPEN.

Two consequences worth documenting or hardening:

1. In sync mode (log_stderr = true), Logger::log drops the control record entirely (common.rs:209), so the hourly timer fires but the decorator never reopens. Today sync mode writes to stderr rather than the file, so this is latent — but any future change that writes to a file in sync mode will silently lose rotation.
2. If the control record is ever emitted directly through slog without the #LOG_CTRL_REOPEN tag (e.g., the buffered-drain path at common.rs:159 drains without the tag), the reopen is silently skipped.

Consider having the VMM control thread call a dedicated reopen API on the decorator/logger instead of routing the signal through the log-facade record.

[cubesandboxbot]

When reopen() fails here, ? exits write_log_rotate, the outer loop in consumer drops the ReopenableFile (closing the old descriptor), sleeps 3 s, and restarts. That contradicts the PR description's "keep the current descriptor usable when reopen fails; retry on later writes with a one-second cooldown": the shim's descriptor is closed on failure and the retry interval is 3 s (during which messages queue in the bounded 1024-slot channel and are silently dropped under load).

Since ReopenableFile::reopen already keeps self.file on failure, the Rotate arm could log the error and continue the loop, retrying at the next 30-minute Rotate — matching the stated design. If the current propagate-and-restart behavior is intended, the PR description should be updated.