feat(vmm): migrate all log callsites to rate-limited macros

Replace every error, warn, and info macro invocation in
the vmm crate with its rate-limited counterpart. This
covers all subsystems: virtio devices, legacy devices,
PCI, ACPI, vCPU handling, signal handlers, device
manager, snapshot paths, RPC interface, GDB support,
and the rate limiter itself.

debug-level calls are left unchanged as they are
filtered out in production builds.

Signed-off-by: Nikita Kalyazin <kalyazin@amazon.com>

Author: kalyazin

src/vmm/src/acpi/mod.rs

@@ -3,7 +3,7 @@
 
 use acpi_tables::fadt::{FADT_F_HW_REDUCED_ACPI, FADT_F_PWR_BUTTON, FADT_F_SLP_BUTTON};
 use acpi_tables::{Aml, Dsdt, Fadt, Madt, Mcfg, Rsdp, Sdt, Xsdt, aml};
-use log::{debug, error};
+use log::debug;
 use vm_allocator::AllocPolicy;
 
 use crate::Vcpu;
@@ -12,6 +12,7 @@ use crate::acpi::x86_64::{
 };
 use crate::arch::x86_64::layout;
 use crate::device_manager::DeviceManager;
+use crate::logger::error_rate_limited;
 use crate::vstate::memory::{GuestAddress, GuestMemoryMmap};
 use crate::vstate::resources::ResourceAllocator;
 
@@ -68,7 +69,9 @@ impl AcpiTableWriter<'_> {
 
         table
             .write_to_guest(self.mem, GuestAddress(addr))
-            .inspect_err(|err| error!("acpi: Could not write table in guest memory: {err}"))?;
+            .inspect_err(|err| {
+                error_rate_limited!("acpi: Could not write table in guest memory: {err}")
+            })?;
 
         debug!(
             "acpi: Wrote table ({} bytes) at address: {:#010x}",
@@ -179,7 +182,9 @@ impl AcpiTableWriter<'_> {
     fn build_rsdp(&mut self, xsdt_addr: u64) -> Result<(), AcpiError> {
         let mut rsdp = Rsdp::new(OEM_ID, xsdt_addr);
         rsdp.write_to_guest(self.mem, rsdp_addr())
-            .inspect_err(|err| error!("acpi: Could not write RSDP in guest memory: {err}"))?;
+            .inspect_err(|err| {
+                error_rate_limited!("acpi: Could not write RSDP in guest memory: {err}")
+            })?;
 
         debug!(
             "acpi: Wrote RSDP ({} bytes) at address: {:#010x}",

src/vmm/src/arch/aarch64/cache_info.rs

@@ -4,7 +4,7 @@
 use std::path::{Path, PathBuf};
 use std::{fs, io};
 
-use crate::logger::warn;
+use crate::logger::warn_rate_limited;
 
 // Based on https://elixir.free-electrons.com/linux/v4.9.62/source/arch/arm64/kernel/cacheinfo.c#L29.
 const MAX_CACHE_LEVEL: u8 = 7;
@@ -304,7 +304,7 @@ pub(crate) fn read_cache_config(
                 let level = cache.level;
                 append_cache_level(cache_l1, cache_non_l1, cache);
                 if !msg.is_empty() && !logged_missing_attr {
-                    warn!("Could not read the {msg} for cache level {level}.");
+                    warn_rate_limited!("Could not read the {msg} for cache level {level}.");
                     logged_missing_attr = true;
                 }
             }

src/vmm/src/arch/aarch64/mod.rs

@@ -30,7 +30,7 @@ use crate::cpu_config::templates::CustomCpuTemplate;
 use crate::initrd::InitrdConfig;
 use zerocopy::IntoBytes;
 
-use crate::logger::warn;
+use crate::logger::warn_rate_limited;
 use crate::utils::{align_up, u64_to_usize, usize_to_u64};
 use crate::vmm_config::machine_config::MachineConfig;
 use crate::vstate::memory::{
@@ -66,7 +66,7 @@ pub fn arch_memory_regions(size: usize) -> Vec<(GuestAddress, usize)> {
     let dram_size = min(size, layout::DRAM_MEM_MAX_SIZE);
 
     if dram_size != size {
-        logger::warn!(
+        logger::warn_rate_limited!(
             "Requested memory size {} exceeds architectural maximum (1022GiB). Size has been \
              truncated to {}",
             size,
@@ -176,7 +176,7 @@ fn override_clidr(vcpus: &[Vcpu]) -> Result<(), ConfigurationError> {
     // Writing an all-zero CLIDR would tell the guest there are no caches,
     // which is worse than whatever KVM fabricated. Leave it alone.
     if l1_caches.is_empty() {
-        warn!("No L1 caches found in sysfs, skipping CLIDR override");
+        warn_rate_limited!("No L1 caches found in sysfs, skipping CLIDR override");
         return Ok(());
     }
 
@@ -191,7 +191,7 @@ fn override_clidr(vcpus: &[Vcpu]) -> Result<(), ConfigurationError> {
         .fd
         .get_one_reg(regs::CLIDR_EL1, cur_clidr.as_mut_bytes())
     {
-        warn!("Failed to read CLIDR_EL1, skipping override: {e}");
+        warn_rate_limited!("Failed to read CLIDR_EL1, skipping override: {e}");
         return Ok(());
     }
 
@@ -204,9 +204,10 @@ fn override_clidr(vcpus: &[Vcpu]) -> Result<(), ConfigurationError> {
                 .fd
                 .set_one_reg(regs::CLIDR_EL1, new_clidr.as_bytes())
             {
-                warn!(
+                warn_rate_limited!(
                     "Failed to set CLIDR_EL1 to {:#x} on vCPU {}, skipping override: {e}",
-                    new_clidr, vcpu.kvm_vcpu.index
+                    new_clidr,
+                    vcpu.kvm_vcpu.index
                 );
                 return Ok(());
             }

src/vmm/src/arch/aarch64/vcpu.rs

@@ -21,7 +21,7 @@ use crate::arch::aarch64::kvm::OptionalCapabilities;
 use crate::arch::aarch64::regs::{Aarch64RegisterVec, KVM_REG_ARM64_SVE_VLS};
 use crate::cpu_config::aarch64::custom_cpu_template::VcpuFeatures;
 use crate::cpu_config::templates::CpuConfiguration;
-use crate::logger::{IncMetric, METRICS, error};
+use crate::logger::{IncMetric, METRICS, error_rate_limited};
 use crate::vcpu::{VcpuConfig, VcpuError};
 use crate::vstate::bus::Bus;
 use crate::vstate::memory::{Address, GuestMemoryMmap};
@@ -503,7 +503,7 @@ impl Peripherals {
         METRICS.vcpu.failures.inc();
         // TODO: Are we sure we want to finish running a vcpu upon
         // receiving a vm exit that is not necessarily an error?
-        error!("Unexpected exit reason on vcpu run: {:?}", exit);
+        error_rate_limited!("Unexpected exit reason on vcpu run: {:?}", exit);
         Err(VcpuError::UnhandledKvmExit(format!("{:?}", exit)))
     }
 }

src/vmm/src/arch/mod.rs

@@ -4,7 +4,7 @@
 use std::fmt;
 use std::sync::LazyLock;
 
-use log::warn;
+use crate::logger::warn_rate_limited;
 use serde::{Deserialize, Serialize};
 use vm_memory::GuestAddress;
 
@@ -66,7 +66,9 @@ pub fn host_page_size() -> usize {
         // # Safety: Value always valid
         let r = unsafe { libc::sysconf(libc::_SC_PAGESIZE) };
         usize::try_from(r).unwrap_or_else(|_| {
-            warn!("Could not get host page size with sysconf, assuming default 4K host pages");
+            warn_rate_limited!(
+                "Could not get host page size with sysconf, assuming default 4K host pages"
+            );
             4096
         })
     });

src/vmm/src/arch/x86_64/mod.rs

@@ -117,7 +117,7 @@ pub fn arch_memory_regions(size: usize) -> Vec<(GuestAddress, usize)> {
     );
 
     if dram_size != size {
-        logger::warn!(
+        logger::warn_rate_limited!(
             "Requested memory size {} exceeds architectural maximum (1022GiB). Size has been \
              truncated to {}",
             size,

src/vmm/src/arch/x86_64/vcpu.rs

@@ -14,7 +14,6 @@ use kvm_bindings::{
     kvm_mp_state, kvm_regs, kvm_sregs, kvm_vcpu_events, kvm_xcrs, kvm_xsave, kvm_xsave2,
 };
 use kvm_ioctls::{VcpuExit, VcpuFd};
-use log::{error, warn};
 use serde::{Deserialize, Serialize};
 use vmm_sys_util::fam::{self, FamStruct};
 
@@ -24,7 +23,7 @@ use crate::arch::x86_64::interrupts;
 use crate::arch::x86_64::msr::{MsrError, create_boot_msr_entries};
 use crate::arch::x86_64::regs::{SetupFpuError, SetupRegistersError, SetupSpecialRegistersError};
 use crate::cpu_config::x86_64::{CpuConfiguration, cpuid};
-use crate::logger::{IncMetric, METRICS};
+use crate::logger::{IncMetric, METRICS, error_rate_limited, warn_rate_limited};
 use crate::vstate::bus::Bus;
 use crate::vstate::memory::GuestMemoryMmap;
 use crate::vstate::vcpu::{VcpuConfig, VcpuEmulation, VcpuError};
@@ -281,7 +280,7 @@ impl KvmVcpu {
         // https://elixir.bootlin.com/linux/v6.17.5/source/arch/x86/kvm/x86.c#L5736-L5737
         if let Err(err) = self.fd.kvmclock_ctrl() {
             METRICS.vcpu.kvmclock_ctrl_fails.inc();
-            warn!("KVM_KVMCLOCK_CTRL call failed {}", err);
+            warn_rate_limited!("KVM_KVMCLOCK_CTRL call failed {}", err);
         }
     }
 
@@ -403,7 +402,7 @@ impl KvmVcpu {
                 .flat_map(|msrs| msrs.as_mut_slice())
                 .filter(|msr| msr.index == MSR_IA32_TSC_DEADLINE && msr.data == 0)
                 .for_each(|msr| {
-                    warn!(
+                    warn_rate_limited!(
                         "MSR_IA32_TSC_DEADLINE is 0, replacing with {:#x}.",
                         tsc_value
                     );
@@ -430,9 +429,10 @@ impl KvmVcpu {
                     deferred_msrs
                         .push(*msr)
                         .inspect_err(|err| {
-                            error!(
+                            error_rate_limited!(
                                 "Failed to move MSR {} into later chunk: {:?}",
-                                msr.index, err
+                                msr.index,
+                                err
                             )
                         })
                         .is_err()
@@ -589,7 +589,9 @@ impl KvmVcpu {
             // v0.25 and newer snapshots without TSC will only work on
             // the same CPU model as the host on which they were taken.
             // TODO: Add negative test for this warning failure.
-            warn!("TSC freq not available. Snapshot cannot be loaded on a different CPU model.");
+            warn_rate_limited!(
+                "TSC freq not available. Snapshot cannot be loaded on a different CPU model."
+            );
             None
         });
         let cpuid = self.get_cpuid()?;
@@ -729,7 +731,10 @@ impl Peripherals {
                 if let Some(pio_bus) = &self.pio_bus {
                     let _metric = METRICS.vcpu.exit_io_in_agg.record_latency_metrics();
                     if let Err(err) = pio_bus.read(u64::from(addr), data) {
-                        warn!("vcpu: IO read @ {addr:#x}:{:#x} failed: {err}", data.len());
+                        warn_rate_limited!(
+                            "vcpu: IO read @ {addr:#x}:{:#x} failed: {err}",
+                            data.len()
+                        );
                     }
                     METRICS.vcpu.exit_io_in.inc();
                 }
@@ -739,15 +744,18 @@ impl Peripherals {
                 if let Some(pio_bus) = &self.pio_bus {
                     let _metric = METRICS.vcpu.exit_io_out_agg.record_latency_metrics();
                     if let Err(err) = pio_bus.write(u64::from(addr), data) {
-                        warn!("vcpu: IO write @ {addr:#x}:{:#x} failed: {err}", data.len());
+                        warn_rate_limited!(
+                            "vcpu: IO write @ {addr:#x}:{:#x} failed: {err}",
+                            data.len()
+                        );
                     }
                     METRICS.vcpu.exit_io_out.inc();
                 }
                 Ok(VcpuEmulation::Handled)
             }
             unexpected_exit => {
                 METRICS.vcpu.failures.inc();
-                error!("Unexpected exit reason on vcpu run: {:?}", unexpected_exit);
+                error_rate_limited!("Unexpected exit reason on vcpu run: {:?}", unexpected_exit);
                 Err(VcpuError::UnhandledKvmExit(format!(
                     "{:?}",
                     unexpected_exit

src/vmm/src/arch/x86_64/xstate.rs

@@ -4,7 +4,7 @@
 use vmm_sys_util::syscall::SyscallReturnCode;
 
 use crate::arch::x86_64::generated::arch_prctl;
-use crate::logger::info;
+use crate::logger::info_rate_limited;
 
 const INTEL_AMX_MASK: u64 = 1u64 << arch_prctl::ARCH_XCOMP_TILEDATA;
 
@@ -76,7 +76,7 @@ fn get_supported_xfeatures() -> Result<Option<u64>, std::io::Error> {
         // version prior to v5.16).
         // https://github.com/torvalds/linux/commit/db8268df0983adc2bb1fb48c9e5f7bfbb5f617f3
         Err(err) if err.raw_os_error() == Some(libc::EINVAL) => {
-            info!("Dynamic XSTATE feature enabling is not supported.");
+            info_rate_limited!("Dynamic XSTATE feature enabling is not supported.");
             Ok(None)
         }
         Err(err) => Err(err),
@@ -117,7 +117,7 @@ fn request_xfeature_permission(xfeature: u32) -> Result<(), std::io::Error> {
         // https://github.com/torvalds/linux/blame/f443e374ae131c168a065ea1748feac6b2e76613/arch/x86/kvm/x86.c#L8850-L8853
         // https://github.com/firecracker-microvm/firecracker/pull/5065
         Err(err) if err.raw_os_error() == Some(libc::EINVAL) => {
-            info!("Dynamic XSTATE feature enabling is not supported for guest.");
+            info_rate_limited!("Dynamic XSTATE feature enabling is not supported for guest.");
             Ok(())
         }
         Err(err) => Err(err),

src/vmm/src/builder.rs

@@ -41,6 +41,8 @@ use crate::devices::virtio::vsock::{Vsock, VsockUnixBackend};
 use crate::gdb;
 use crate::initrd::{InitrdConfig, InitrdError};
 use crate::logger::debug;
+#[cfg(target_arch = "aarch64")]
+use crate::logger::warn_rate_limited;
 use crate::persist::{MicrovmState, MicrovmStateError};
 use crate::resources::VmResources;
 use crate::seccomp::BpfThreadMap;
@@ -294,7 +296,7 @@ pub fn build_microvm_for_boot(
     if vcpus[0].kvm_vcpu.supports_pvtime() {
         setup_pvtime(&mut vm.resource_allocator(), &mut vcpus)?;
     } else {
-        log::warn!("Vcpus do not support pvtime, steal time will not be reported to guest");
+        warn_rate_limited!("Vcpus do not support pvtime, steal time will not be reported to guest");
     }
 
     configure_system_for_boot(

src/vmm/src/cpu_config/x86_64/cpuid/normalize.rs

@@ -4,7 +4,7 @@
 use crate::cpu_config::x86_64::cpuid::{
     CpuidEntry, CpuidKey, CpuidRegisters, CpuidTrait, KvmCpuidFlags, cpuid,
 };
-use crate::logger::warn;
+use crate::logger::warn_rate_limited;
 use crate::vmm_config::machine_config::MAX_SUPPORTED_VCPUS;
 
 /// Error type for [`super::Cpuid::normalize`].
@@ -379,7 +379,7 @@ impl super::Cpuid {
                         // However, we intentionally leave Firecracker not fail for unsupported
                         // kernels to keep working. Note that we can detect KVM regression thanks
                         // to the test that compares a fingerprint with its baseline.
-                        warn!("Subleaf {index} not expected for CPUID leaf 0xB.");
+                        warn_rate_limited!("Subleaf {index} not expected for CPUID leaf 0xB.");
                         subleaf.result.ecx = index;
                     }
                 }