Skip to content

[STACKED on #968] fix(vmm): bound the logs a CVM writes within a boot - #970

Merged
kvinwang merged 1 commit into
masterfrom
codex/fix-vmm-serial-log-cap
Aug 6, 2026
Merged

[STACKED on #968] fix(vmm): bound the logs a CVM writes within a boot#970
kvinwang merged 1 commit into
masterfrom
codex/fix-vmm-serial-log-cap

Conversation

@kvinwang

@kvinwang kvinwang commented Jul 31, 2026

Copy link
Copy Markdown
Collaborator

STACKED PR — merge #968 first.

Problem

The logs a CVM writes into its work directory are unbounded within a boot. QEMU appends to serial.log for the whole life of a boot, and the supervisor appends to stdout.log / stderr.log across boots without ever clearing them. A chatty or malicious guest can fill the host disk, and the archiving step at the next boot read the whole serial log into memory in one allocation.

This PR started from a narrower symptom — serial-log trimming discarded the boot delimiter along with older output — but that symptom 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 the condition, so the PR now fixes the cause and the original workaround is deleted.

Why QEMU cannot do this

The QAPI schema for the file and pty chardev backends exposes only out / in / append plus the generic logfile / logappend. None 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.

Implementation

Rotation lives in a new logrotate module that works on a path and knows nothing about what it is rotating — the same way logrotate(8) does not care. <path>.N-1 becomes <path>.N, the live file is archived as <path>.1, and the oldest segment is discarded. A VM start is simply another rotation trigger, so the previous boot is preserved as .1 and boot boundaries land on segment boundaries.

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:

apparent size after
logappend=off 100010
logappend=on 10

This requirement is the module's documented contract. It holds equally for the supervisor's OpenOptions::append(true) sinks, which is why stdout/stderr are a call site rather than a second implementation.

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, 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.

All three logs, but not gated alike

log writer eligibility
stdout.log, stderr.log supervisor try_redirect always
serial.log QEMU chardev only when the annotation confirms logappend=on

The supervisor already opens its sinks with append(true) and reopens them when they change — its own comment calls that "logrotate detection" — so those two satisfy the contract regardless of which VMM launched the VM, and keep their cap across a VMM upgrade.

serial.log needs the gate. 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 sparse 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 an annotation written by an older VMM has no such key and deserializes to false. Reading the recorded argv would not work — TPM-backed VMs run through vm-launcher, whose argv is only ["vm-launcher", "--spec", <path>].

serial.history.log removed

The archive existed because the live log was unbounded and QEMU truncated it at every boot. Both premises are gone. rotate_serial_log, trim_serial_history, serial_history_max_bytes and serial_history_file are deleted, along with the splice branch that reconstructed a boot delimiter when one boot overflowed the archive cap — segments carry that structure in the filesystem instead, so the guest can no longer confuse a boundary search by printing delimiter-shaped output of its own.

Removing the config key is safe: 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 harmless.

Configuration

[cvm.log]
max_bytes = "4M"
max_backups = 3
check_interval_secs = 5

Named for the mechanism rather than for serial, because stdout and stderr use the same section. The values live in the shipped vmm.toml rather than in serde defaults, so the defaults are themselves parsed on every load — which 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.

Behaviour changes to be aware of

stdout.log / stderr.log previously accumulated across boots and were never cleared; they are now rotated at each VM start. Reading them still shows the current boot, with earlier boots in .1.N, and the boot separator is still written so a segment read on its own shows where a boot began.

Worst-case disk per VM is now 3 logs × (1 + max_backups) × max_bytes = 48 MB at the defaults. QEMU's own stdout/stderr are usually tiny and rarely rotate, so the practical figure is far lower.

Known limitation

The log API serves only the live file, 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:

===== rotated 4194304 bytes to serial.log.1 @ 2026-08-06T00:00:00Z =====

Making ch=serial span segments is deliberately left to a follow-up.

Rotation is triggered by a periodic stat, so a 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.

Verification

  • cargo test -p dstack-vmm --all-features: 105 passed.
  • cargo clippy -p dstack-vmm --all-features and cargo fmt --check: clean.
  • QEMU behaviours measured against QEMU 8.2.2; follower behaviour measured against the coreutils tail that tailf spawns.

Copilot AI review requested due to automatic review settings July 31, 2026 03:33

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot was unable to review this pull request because the user who requested the review has reached their quota limit.

Base automatically changed from codex/fix-vmm-restart-policy to master August 6, 2026 03:20
@kvinwang
kvinwang force-pushed the codex/fix-vmm-serial-log-cap branch from 93b8593 to 4ff2c0c Compare August 6, 2026 03:23
@kvinwang kvinwang changed the title [STACKED on #968] fix(vmm): retain the serial boot delimiter at the cap [STACKED on #968] fix(vmm): bound the serial log within a boot Aug 6, 2026
@kvinwang
kvinwang force-pushed the codex/fix-vmm-serial-log-cap branch 4 times, most recently from 0710f7a to e4749eb Compare August 6, 2026 09:10
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. `<path>.N-1` becomes `<path>.N`, the live file is archived
as `<path>.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", <path>].

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.
@kvinwang
kvinwang force-pushed the codex/fix-vmm-serial-log-cap branch from e4749eb to e6f9f8d Compare August 6, 2026 09:19
@kvinwang kvinwang changed the title [STACKED on #968] fix(vmm): bound the serial log within a boot [STACKED on #968] fix(vmm): bound the logs a CVM writes within a boot Aug 6, 2026
kvinwang added a commit that referenced this pull request Aug 6, 2026
The case tested serial.history.log: that a bounded archive kept exactly one
boot delimiter when a single boot overflowed its cap. #970 removes the archive
outright. The live logs are now bounded within a boot by rotation, so the
previous boot survives as serial.log.1 and boot boundaries land on segment
boundaries rather than on delimiters recovered from log text.

Every part of the case that named the archive was therefore testing something
that no longer exists. Retarget it:

- The decision matrix now covers segment retention, the oldest segment being
  discarded, an empty log not spending a slot, and stdout/stderr rotating
  alongside serial.
- Two properties are called out as observed rather than assumed, because both
  fail silently: the live file keeps its inode across a rotation (a rename
  would leave QEMU and the supervisor appending into an unlinked inode), and it
  is emptied rather than compacted (so a follower resumes instead of replaying).
- Step 3 gains the upgrade path: a VM inherited across a VMM restart must not
  be rotated on the serial channel, because its QEMU was launched without
  logappend=on. stdout and stderr stay eligible, being the supervisor's and
  always opened in append mode.

The automation stopped scraping DSTACK_SERIAL_ROW markers from the unit tests.
Rows are unit-test names now. The markers only existed to feed this case, they
made the production tests print for no other reason, and a silently renamed
marker read as a pass rather than a failure. Matching on names that must appear
in the passing set fails closed instead.

The fixture rewrites cvm.log.max_bytes in place rather than appending a key
after cvm.use_mrconfigid. cvm.log is a sub-table, so a key appended to the
[cvm] scalar block would either sit outside the table or swallow every [cvm]
key declared after it.

Requires #970. The behaviour under test does not exist before it merges.
@kvinwang
kvinwang merged commit cb961ad into master Aug 6, 2026
15 checks passed
kvinwang added a commit that referenced this pull request Aug 6, 2026
The case tested serial.history.log: that a bounded archive kept exactly one
boot delimiter when a single boot overflowed its cap. #970 removes the archive
outright. The live logs are now bounded within a boot by rotation, so the
previous boot survives as serial.log.1 and boot boundaries land on segment
boundaries rather than on delimiters recovered from log text.

Every part of the case that named the archive was therefore testing something
that no longer exists. Retarget it:

- The decision matrix now covers segment retention, the oldest segment being
  discarded, an empty log not spending a slot, and stdout/stderr rotating
  alongside serial.
- Two properties are called out as observed rather than assumed, because both
  fail silently: the live file keeps its inode across a rotation (a rename
  would leave QEMU and the supervisor appending into an unlinked inode), and it
  is emptied rather than compacted (so a follower resumes instead of replaying).
- Step 3 gains the upgrade path: a VM inherited across a VMM restart must not
  be rotated on the serial channel, because its QEMU was launched without
  logappend=on. stdout and stderr stay eligible, being the supervisor's and
  always opened in append mode.

The automation stopped scraping DSTACK_SERIAL_ROW markers from the unit tests.
Rows are unit-test names now. The markers only existed to feed this case, they
made the production tests print for no other reason, and a silently renamed
marker read as a pass rather than a failure. Matching on names that must appear
in the passing set fails closed instead.

The fixture rewrites cvm.log.max_bytes in place rather than appending a key
after cvm.use_mrconfigid. cvm.log is a sub-table, so a key appended to the
[cvm] scalar block would either sit outside the table or swallow every [cvm]
key declared after it.

Requires #970. The behaviour under test does not exist before it merges.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants