feat(devices): rate-limit log callsites in device paths

Migrate error!, warn!, and info! log callsites in device and VMM
paths to their rate-limited equivalents. debug! calls are left
unchanged as they are disabled in release Firecracker builds and
the log_enabled! check in the rate-limited macros already ensures
zero overhead for disabled levels.

Covers all virtio devices (balloon, net, block, rng, vsock, pmem,
mem), transport layers (MMIO, PCI), vCPU exit handling, memory
management, and the I/O rate limiter.

Each callsite independently rate-limits to 10 messages per
5-second refill period.

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

Author: kalyazin

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/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/devices/virtio/balloon/device.rs

@@ -5,7 +5,6 @@ use std::ops::Deref;
 use std::sync::Arc;
 use std::time::Duration;
 
-use log::{debug, error, info, warn};
 use serde::{Deserialize, Serialize};
 use utils::time::TimerFd;
 use vmm_sys_util::eventfd::EventFd;
@@ -32,7 +31,10 @@ use crate::devices::virtio::device::{ActiveState, VirtioDeviceType};
 use crate::devices::virtio::generated::virtio_config::VIRTIO_F_VERSION_1;
 use crate::devices::virtio::queue::InvalidAvailIdx;
 use crate::devices::virtio::transport::{VirtioInterrupt, VirtioInterruptType};
-use crate::logger::{IncMetric, log_dev_preview_warning};
+use crate::logger::{
+    IncMetric, debug, error_rate_limited, info_rate_limited, log_dev_preview_warning,
+    warn_rate_limited,
+};
 use crate::utils::u64_to_usize;
 use crate::vstate::memory::{
     Address, ByteValued, Bytes, GuestAddress, GuestMemoryExtension, GuestMemoryMmap,
@@ -404,7 +406,7 @@ impl Balloon {
                 if !head.is_write_only() && len.is_multiple_of(SIZE_OF_U32) {
                     // Check descriptor pfn count.
                     if len > max_len {
-                        error!(
+                        error_rate_limited!(
                             "Inflate descriptor has bogus page count {} > {}, skipping.",
                             len / SIZE_OF_U32,
                             MAX_PAGES_IN_DESC
@@ -455,7 +457,7 @@ impl Balloon {
                     guest_addr,
                     usize::try_from(range_len).unwrap() << VIRTIO_BALLOON_PFN_SHIFT,
                 ) {
-                    error!("Error removing memory range: {:?}", err);
+                    error_rate_limited!("Error removing memory range: {:?}", err);
                 }
             }
         }
@@ -496,7 +498,9 @@ impl Balloon {
             if let Some(prev_stats_desc) = self.stats_desc_index {
                 // We shouldn't ever have an extra buffer if the driver follows
                 // the protocol, but return it if we find one.
-                error!("balloon: driver is not compliant, more than one stats buffer received");
+                error_rate_limited!(
+                    "balloon: driver is not compliant, more than one stats buffer received"
+                );
                 self.queues[STATS_INDEX].add_used(prev_stats_desc, 0)?;
                 self.queues[STATS_INDEX].advance_used_ring_idx();
                 self.signal_used_queue(STATS_INDEX)?;
@@ -508,9 +512,10 @@ impl Balloon {
             // so that the stats request/response protocol is preserved and
             // trigger_stats_update can return it to the guest later.
             if head.len > MAX_STATS_DESC_LEN {
-                warn!(
+                warn_rate_limited!(
                     "balloon: stats descriptor too large: {} > {}, skipping",
-                    head.len, MAX_STATS_DESC_LEN
+                    head.len,
+                    MAX_STATS_DESC_LEN
                 );
                 self.stats_desc_index = Some(head.index);
                 continue;
@@ -571,7 +576,7 @@ impl Balloon {
 
                     // We don't expect this from the driver, but lets treat as a stop
                     if cmd == FREE_PAGE_HINT_DONE {
-                        warn!("balloon hinting: Unexpected cmd from guest: {cmd}");
+                        warn_rate_limited!("balloon hinting: Unexpected cmd from guest: {cmd}");
                         complete = true;
                     }
 
@@ -584,19 +589,21 @@ impl Balloon {
                 }
 
                 let Some(chain_cmd) = self.hinting_state.guest_cmd else {
-                    warn!("balloon hinting: received range with no command id.");
+                    warn_rate_limited!("balloon hinting: received range with no command id.");
                     continue;
                 };
 
                 if chain_cmd != host_cmd {
-                    info!("balloon hinting: Received chain from previous command ignoring.");
+                    info_rate_limited!(
+                        "balloon hinting: Received chain from previous command ignoring."
+                    );
                     continue;
                 }
 
                 METRICS.free_page_hint_count.inc();
                 if let Err(err) = mem.discard_range(desc.addr, desc.len as usize) {
                     METRICS.free_page_hint_fails.inc();
-                    error!("balloon hinting: failed to remove range: {err:?}");
+                    error_rate_limited!("balloon hinting: failed to remove range: {err:?}");
                 } else {
                     METRICS.free_page_hint_freed.add(desc.len as u64);
                 }
@@ -638,7 +645,7 @@ impl Balloon {
                 METRICS.free_page_report_count.inc();
                 if let Err(err) = mem.discard_range(desc.addr, desc.len as usize) {
                     METRICS.free_page_report_fails.inc();
-                    error!("balloon: failed to remove range: {err:?}");
+                    error_rate_limited!("balloon: failed to remove range: {err:?}");
                 } else {
                     METRICS.free_page_report_freed.add(desc.len as u64);
                 }
@@ -709,7 +716,7 @@ impl Balloon {
             self.queues[STATS_INDEX].advance_used_ring_idx();
             self.signal_used_queue(STATS_INDEX)
         } else {
-            error!("Failed to update balloon stats, missing descriptor.");
+            error_rate_limited!("Failed to update balloon stats, missing descriptor.");
             Ok(())
         }
     }
@@ -933,7 +940,7 @@ impl VirtioDevice for Balloon {
             let len = config_space_bytes.len().min(data.len());
             data[..len].copy_from_slice(&config_space_bytes[..len]);
         } else {
-            error!("Failed to read config space");
+            error_rate_limited!("Failed to read config space");
         }
     }
 
@@ -945,7 +952,7 @@ impl VirtioDevice for Balloon {
             .zip(end)
             .and_then(|(start, end)| config_space_bytes.get_mut(start..end))
         else {
-            error!("Failed to write config space");
+            error_rate_limited!("Failed to write config space");
             return;
         };
 
@@ -983,7 +990,7 @@ impl VirtioDevice for Balloon {
     fn kick(&mut self) {
         if self.is_activated() {
             if self.free_page_hinting() {
-                info!(
+                info_rate_limited!(
                     "[{:?}:{}] resetting free page hinting to DONE",
                     self.device_type(),
                     self.id()

src/vmm/src/devices/virtio/balloon/event_handler.rs

@@ -7,7 +7,7 @@ use vmm_sys_util::epoll::EventSet;
 use super::{DEFLATE_INDEX, INFLATE_INDEX, STATS_INDEX, report_balloon_event_fail};
 use crate::devices::virtio::balloon::device::Balloon;
 use crate::devices::virtio::device::VirtioDevice;
-use crate::logger::{error, warn};
+use crate::logger::{error_rate_limited, warn_rate_limited};
 
 impl Balloon {
     const PROCESS_ACTIVATE: u32 = 0;
@@ -24,29 +24,29 @@ impl Balloon {
             Self::PROCESS_VIRTQ_INFLATE,
             EventSet::IN,
         )) {
-            error!("Failed to register inflate queue event: {}", err);
+            error_rate_limited!("Failed to register inflate queue event: {}", err);
         }
         if let Err(err) = ops.add(Events::with_data(
             &self.queue_evts[DEFLATE_INDEX],
             Self::PROCESS_VIRTQ_DEFLATE,
             EventSet::IN,
         )) {
-            error!("Failed to register deflate queue event: {}", err);
+            error_rate_limited!("Failed to register deflate queue event: {}", err);
         }
         if self.stats_enabled() {
             if let Err(err) = ops.add(Events::with_data(
                 &self.queue_evts[STATS_INDEX],
                 Self::PROCESS_VIRTQ_STATS,
                 EventSet::IN,
             )) {
-                error!("Failed to register stats queue event: {}", err);
+                error_rate_limited!("Failed to register stats queue event: {}", err);
             }
             if let Err(err) = ops.add(Events::with_data(
                 &self.stats_timer,
                 Self::PROCESS_STATS_TIMER,
                 EventSet::IN,
             )) {
-                error!("Failed to register stats timerfd event: {}", err);
+                error_rate_limited!("Failed to register stats timerfd event: {}", err);
             }
         }
 
@@ -57,7 +57,7 @@ impl Balloon {
                 EventSet::IN,
             ))
         {
-            error!("Failed to register free page hinting queue event: {}", err);
+            error_rate_limited!("Failed to register free page hinting queue event: {}", err);
         }
 
         if self.free_page_reporting()
@@ -67,7 +67,7 @@ impl Balloon {
                 EventSet::IN,
             ))
         {
-            error!(
+            error_rate_limited!(
                 "Failed to register free page reporting queue event: {}",
                 err
             );
@@ -80,21 +80,21 @@ impl Balloon {
             Self::PROCESS_ACTIVATE,
             EventSet::IN,
         )) {
-            error!("Failed to register activate event: {}", err);
+            error_rate_limited!("Failed to register activate event: {}", err);
         }
     }
 
     fn process_activate_event(&self, ops: &mut EventOps) {
         if let Err(err) = self.activate_evt.read() {
-            error!("Failed to consume balloon activate event: {:?}", err);
+            error_rate_limited!("Failed to consume balloon activate event: {:?}", err);
         }
         self.register_runtime_events(ops);
         if let Err(err) = ops.remove(Events::with_data(
             &self.activate_evt,
             Self::PROCESS_ACTIVATE,
             EventSet::IN,
         )) {
-            error!("Failed to un-register activate event: {}", err);
+            error_rate_limited!("Failed to un-register activate event: {}", err);
         }
     }
 }
@@ -106,9 +106,10 @@ impl MutEventSubscriber for Balloon {
         let supported_events = EventSet::IN;
 
         if !supported_events.contains(event_set) {
-            warn!(
+            warn_rate_limited!(
                 "Received unknown event: {:?} from source: {:?}",
-                event_set, source
+                event_set,
+                source
             );
             return;
         }
@@ -135,11 +136,11 @@ impl MutEventSubscriber for Balloon {
                     .process_free_page_reporting_queue_event()
                     .unwrap_or_else(report_balloon_event_fail),
                 _ => {
-                    warn!("Balloon: Spurious event received: {:?}", source);
+                    warn_rate_limited!("Balloon: Spurious event received: {:?}", source);
                 }
             };
         } else {
-            warn!(
+            warn_rate_limited!(
                 "Balloon: The device is not yet activated. Spurious event received: {:?}",
                 source
             );

src/vmm/src/devices/virtio/balloon/mod.rs

@@ -10,7 +10,7 @@ pub mod persist;
 pub mod test_utils;
 mod util;
 
-use log::error;
+use crate::logger::error_rate_limited;
 
 pub use self::device::{Balloon, BalloonConfig, BalloonStats};
 use super::queue::{InvalidAvailIdx, QueueError};
@@ -120,6 +120,6 @@ pub(super) fn report_balloon_event_fail(err: BalloonError) {
     if let BalloonError::InvalidAvailIdx(err) = err {
         panic!("{}", err);
     }
-    error!("{:?}", err);
+    error_rate_limited!("{:?}", err);
     METRICS.event_fails.inc();
 }

src/vmm/src/devices/virtio/balloon/util.rs

@@ -4,7 +4,7 @@
 use std::io;
 
 use super::{MAX_PAGE_COMPACT_BUFFER, RemoveRegionError};
-use crate::logger::error;
+use crate::logger::error_rate_limited;
 use crate::utils::u64_to_usize;
 use crate::vstate::memory::{GuestAddress, GuestMemory, GuestMemoryMmap, GuestMemoryRegion};
 
@@ -36,7 +36,7 @@ pub(crate) fn compact_page_frame_numbers(v: &mut [u32]) -> Vec<(u32, u32)> {
         // Skip duplicate pages. This will ensure we only consider
         // distinct PFNs.
         if page_frame_number == v[pfn_index - 1] {
-            error!("Skipping duplicate PFN {}.", page_frame_number);
+            error_rate_limited!("Skipping duplicate PFN {}.", page_frame_number);
             continue;
         }