feat(logger): add rate limiter

CHANGELOG.md

@@ -18,6 +18,12 @@ and this project adheres to
   optional rate limiting to serial console output, configurable via the
   `rate_limiter` field on `PUT /serial`. A new metric is exposed under `uart`:
   `rate_limiter_dropped_bytes`.
+- [#5799](https://github.com/firecracker-microvm/firecracker/pull/5799): Add
+  per-callsite rate limiting for error, warn, and info level log messages. Each
+  callsite independently allows up to 10 messages per 5-second window. When
+  logging resumes after suppression, a warn-level summary reports the count of
+  suppressed messages. A new `rate_limited_log_count` metric tracks the total
+  number of suppressed messages.
 
 ### Changed
 

src/firecracker/src/api_server/mod.rs

@@ -17,7 +17,8 @@ use parsed_request::{ParsedRequest, RequestAction};
 use serde_json::json;
 use utils::time::{ClockType, get_time_us};
 use vmm::logger::{
-    METRICS, ProcessTimeReporter, debug, error, info, update_metric_with_elapsed_time, warn,
+    METRICS, ProcessTimeReporter, debug, error_unrestricted, info_unrestricted,
+    update_metric_with_elapsed_time, warn_unrestricted,
 };
 use vmm::rpc_interface::{ApiRequest, ApiResponse, VmmAction};
 use vmm::seccomp::BpfProgramRef;
@@ -81,7 +82,7 @@ impl ApiServer {
         }
 
         server.start_server().expect("Cannot start HTTP server");
-        info!("API server started.");
+        info_unrestricted!("API server started.");
 
         // Store process start time metric.
         process_time_reporter.report_start_time();
@@ -98,7 +99,7 @@ impl ApiServer {
                 }
                 Err(err) => {
                     // print request error, but keep server running
-                    error!("API Server error on retrieving incoming request: {}", err);
+                    error_unrestricted!("API Server error on retrieving incoming request: {}", err);
                     continue;
                 }
             };
@@ -108,7 +109,7 @@ impl ApiServer {
                 let response = server_request
                     .process(|request| self.handle_request(request, request_processing_start_us));
                 if let Err(err) = server.respond(response) {
-                    error!("API Server encountered an error on response: {}", err);
+                    error_unrestricted!("API Server encountered an error on response: {}", err);
                 };
 
                 let delta_us = get_time_us(ClockType::Monotonic) - request_processing_start_us;
@@ -131,13 +132,13 @@ impl ApiServer {
                     }
                 };
                 if let Some(message) = parsing_info.take_deprecation_message() {
-                    warn!("{}", message);
+                    warn_unrestricted!("{}", message);
                     response.set_deprecation();
                 }
                 response
             }
             Err(err) => {
-                error!("{:?}", err);
+                error_unrestricted!("{:?}", err);
                 err.into()
             }
         }
@@ -179,7 +180,7 @@ impl ApiServer {
         {
             let elapsed_time_us =
                 update_metric_with_elapsed_time(metric, request_processing_start_us);
-            info!("'{}' API request took {} us.", action, elapsed_time_us);
+            info_unrestricted!("'{}' API request took {} us.", action, elapsed_time_us);
         }
         response
     }

src/firecracker/src/api_server/parsed_request.rs

@@ -6,7 +6,7 @@ use std::fmt::Debug;
 use micro_http::{Body, Method, Request, Response, StatusCode, Version};
 use serde::ser::Serialize;
 use serde_json::Value;
-use vmm::logger::{Level, error, info, log_enabled};
+use vmm::logger::{Level, error_unrestricted, info_unrestricted, log_enabled};
 use vmm::rpc_interface::{VmmAction, VmmActionError, VmmData};
 
 use super::ApiServer;
@@ -71,7 +71,7 @@ impl TryFrom<&Request> for ParsedRequest {
             request_uri.as_str(),
             request.body.as_ref(),
         );
-        info!("The API server received a {description}.");
+        info_unrestricted!("The API server received a {description}.");
 
         // Split request uri by '/' by doing:
         // 1. Trim starting '/' characters
@@ -153,14 +153,14 @@ impl ParsedRequest {
     where
         T: ?Sized + Serialize + Debug,
     {
-        info!("The request was executed successfully. Status code: 200 OK.");
+        info_unrestricted!("The request was executed successfully. Status code: 200 OK.");
         let mut response = Response::new(Version::Http11, StatusCode::OK);
         response.set_body(Body::new(serde_json::to_string(body_data).unwrap()));
         response
     }
 
     pub(crate) fn success_response_with_mmds_value(body_data: &Value) -> Response {
-        info!("The request was executed successfully. Status code: 200 OK.");
+        info_unrestricted!("The request was executed successfully. Status code: 200 OK.");
         let mut response = Response::new(Version::Http11, StatusCode::OK);
         let body_str = match body_data {
             Value::Null => "{}".to_string(),
@@ -176,7 +176,9 @@ impl ParsedRequest {
         match request_outcome {
             Ok(vmm_data) => match vmm_data {
                 VmmData::Empty => {
-                    info!("The request was executed successfully. Status code: 204 No Content.");
+                    info_unrestricted!(
+                        "The request was executed successfully. Status code: 204 No Content."
+                    );
                     Response::new(Version::Http11, StatusCode::NoContent)
                 }
                 VmmData::MachineConfiguration(machine_config) => {
@@ -200,14 +202,14 @@ impl ParsedRequest {
             Err(vmm_action_error) => {
                 let mut response = match vmm_action_error {
                     VmmActionError::MmdsLimitExceeded(_err) => {
-                        error!(
+                        error_unrestricted!(
                             "Received Error. Status code: 413 Payload too large. Message: {}",
                             vmm_action_error
                         );
                         Response::new(Version::Http11, StatusCode::PayloadTooLarge)
                     }
                     _ => {
-                        error!(
+                        error_unrestricted!(
                             "Received Error. Status code: 400 Bad Request. Message: {}",
                             vmm_action_error
                         );

src/firecracker/src/api_server_adapter.rs

@@ -8,7 +8,7 @@ use std::sync::{Arc, Mutex};
 use std::thread;
 
 use event_manager::{EventOps, Events, MutEventSubscriber, SubscriberOps};
-use vmm::logger::{ProcessTimeReporter, error, info, warn};
+use vmm::logger::{ProcessTimeReporter, error_unrestricted, info_unrestricted, warn_unrestricted};
 use vmm::rpc_interface::{
     ApiRequest, ApiResponse, BuildMicrovmFromRequestsError, PrebootApiController,
     RuntimeApiController, VmmAction,
@@ -115,20 +115,20 @@ impl MutEventSubscriber for ApiServerAdapter {
                     }
                 }
                 Err(TryRecvError::Empty) => {
-                    warn!("Got a spurious notification from api thread");
+                    warn_unrestricted!("Got a spurious notification from api thread");
                 }
                 Err(TryRecvError::Disconnected) => {
                     panic!("The channel's sending half was disconnected. Cannot receive data.");
                 }
             };
         } else {
-            error!("Spurious EventManager event for handler: ApiServerAdapter");
+            error_unrestricted!("Spurious EventManager event for handler: ApiServerAdapter");
         }
     }
 
     fn init(&mut self, ops: &mut EventOps) {
         if let Err(err) = ops.add(Events::new(&self.api_event_fd, EventSet::IN)) {
-            error!("Failed to register activate event: {}", err);
+            error_unrestricted!("Failed to register activate event: {}", err);
         }
     }
 }
@@ -174,7 +174,7 @@ pub(crate) fn run_with_api(
             return Err(ApiServerError::FailedToBindAndRunHttpServer(err));
         }
     };
-    info!("Listening on API socket ({bind_path:?}).");
+    info_unrestricted!("Listening on API socket ({bind_path:?}).");
 
     let api_kill_switch_clone = api_kill_switch
         .try_clone()

src/firecracker/src/main.rs

@@ -28,9 +28,10 @@ use utils::validators::validate_instance_id;
 use vmm::arch::host_page_size;
 use vmm::builder::StartMicrovmError;
 #[cfg(feature = "fuzzing")]
-use vmm::logger::warn;
+use vmm::logger::warn_unrestricted;
 use vmm::logger::{
-    LOGGER, LoggerConfig, METRICS, ProcessTimeReporter, StoreMetric, debug, error, info,
+    LOGGER, LoggerConfig, METRICS, ProcessTimeReporter, StoreMetric, debug, error_unrestricted,
+    info_unrestricted,
 };
 use vmm::persist::SNAPSHOT_VERSION;
 use vmm::resources::VmResources;
@@ -106,13 +107,13 @@ impl From<MainError> for FcExitCode {
 fn main() -> ExitCode {
     let result = main_exec();
     if let Err(err) = result {
-        error!("{err}");
+        error_unrestricted!("{err}");
         eprintln!("Error: {err:?}");
         let exit_code = FcExitCode::from(err) as u8;
-        error!("Firecracker exiting with error. exit_code={exit_code}");
+        error_unrestricted!("Firecracker exiting with error. exit_code={exit_code}");
         ExitCode::from(exit_code)
     } else {
-        info!("Firecracker exiting successfully. exit_code=0");
+        info_unrestricted!("Firecracker exiting successfully. exit_code=0");
         ExitCode::SUCCESS
     }
 }
@@ -135,9 +136,9 @@ fn main_exec() -> Result<(), MainError> {
         // We're currently using the closure parameter, which is a &PanicInfo, for printing the
         // origin of the panic, including the payload passed to panic! and the source code location
         // from which the panic originated.
-        error!("Firecracker {}", info);
+        error_unrestricted!("Firecracker {}", info);
         if let Err(err) = stdin.lock().set_canon_mode() {
-            error!(
+            error_unrestricted!(
                 "Failure while trying to reset stdin to canonical mode: {}",
                 err
             );
@@ -147,7 +148,7 @@ fn main_exec() -> Result<(), MainError> {
 
         // Write the metrics before aborting.
         if let Err(err) = METRICS.write() {
-            error!("Failed to write metrics while panicking: {}", err);
+            error_unrestricted!("Failed to write metrics while panicking: {}", err);
         }
     }));
 
@@ -329,10 +330,10 @@ fn main_exec() -> Result<(), MainError> {
             module,
         })
         .map_err(MainError::LoggerInitialization)?;
-    info!("Running Firecracker v{FIRECRACKER_VERSION}");
+    info_unrestricted!("Running Firecracker v{FIRECRACKER_VERSION}");
 
     #[cfg(feature = "fuzzing")]
-    warn!(
+    warn_unrestricted!(
         "This Firecracker binary was built with the `fuzzing` feature enabled. This disables \
          security-critical randomness and relaxes error handling. DO NOT use in production."
     );
@@ -537,12 +538,12 @@ pub fn enable_ssbd_mitigation() {
 
     if ret < 0 {
         let last_error = std::io::Error::last_os_error().raw_os_error().unwrap();
-        error!(
+        error_unrestricted!(
             "Could not enable SSBD mitigation through prctl, error {}",
             last_error
         );
         if last_error == libc::EINVAL {
-            error!("The host does not support SSBD mitigation through prctl.");
+            error_unrestricted!("The host does not support SSBD mitigation through prctl.");
         }
     }
 }
@@ -604,7 +605,7 @@ fn build_microvm_from_json(
     )
     .map_err(BuildFromJsonError::StartMicroVM)?;
 
-    info!("Successfully started microvm that was configured from one single json");
+    info_unrestricted!("Successfully started microvm that was configured from one single json");
 
     Ok(vmm)
 }

src/firecracker/src/metrics.rs

@@ -6,7 +6,7 @@ use std::time::Duration;
 
 use event_manager::{EventOps, Events, MutEventSubscriber};
 use utils::time::TimerFd;
-use vmm::logger::{IncMetric, METRICS, error, warn};
+use vmm::logger::{IncMetric, METRICS, error_unrestricted, warn_unrestricted};
 use vmm_sys_util::epoll::EventSet;
 
 /// Metrics reporting period.
@@ -44,7 +44,7 @@ impl PeriodicMetrics {
     fn write_metrics(&mut self) {
         if let Err(err) = METRICS.write() {
             METRICS.logger.missed_metrics_count.inc();
-            error!("Failed to write metrics: {}", err);
+            error_unrestricted!("Failed to write metrics: {}", err);
         }
 
         #[cfg(test)]
@@ -64,9 +64,10 @@ impl MutEventSubscriber for PeriodicMetrics {
         // to handle errors in devices.
         let supported_events = EventSet::IN;
         if !supported_events.contains(event_set) {
-            warn!(
+            warn_unrestricted!(
                 "Received unknown event: {:?} from source: {:?}",
-                event_set, source
+                event_set,
+                source
             );
             return;
         }
@@ -75,13 +76,13 @@ impl MutEventSubscriber for PeriodicMetrics {
             self.write_metrics_event_fd.read();
             self.write_metrics();
         } else {
-            error!("Spurious METRICS event!");
+            error_unrestricted!("Spurious METRICS event!");
         }
     }
 
     fn init(&mut self, ops: &mut EventOps) {
         if let Err(err) = ops.add(Events::new(&self.write_metrics_event_fd, EventSet::IN)) {
-            error!("Failed to register metrics event: {}", err);
+            error_unrestricted!("Failed to register metrics event: {}", err);
         }
     }
 }

src/vmm/clippy.toml

@@ -0,0 +1,6 @@
+disallowed-macros = [
+    { path = "log::error", reason = "use crate::logger::error or error_unrestricted instead" },
+    { path = "log::warn", reason = "use crate::logger::warn or warn_unrestricted instead" },
+    { path = "log::info", reason = "use crate::logger::info or info_unrestricted instead" },
+    { path = "log::debug", reason = "use crate::logger::debug instead" },
+]

src/vmm/src/acpi/mod.rs

@@ -3,7 +3,6 @@
 
 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 vm_allocator::AllocPolicy;
 
 use crate::Vcpu;
@@ -12,6 +11,7 @@ use crate::acpi::x86_64::{
 };
 use crate::arch::x86_64::layout;
 use crate::device_manager::DeviceManager;
+use crate::logger::{debug, error};
 use crate::vstate::memory::{GuestAddress, GuestMemoryMmap};
 use crate::vstate::resources::ResourceAllocator;
 

src/vmm/src/arch/mod.rs

@@ -4,10 +4,11 @@
 use std::fmt;
 use std::sync::LazyLock;
 
-use log::warn;
 use serde::{Deserialize, Serialize};
 use vm_memory::GuestAddress;
 
+use crate::logger::warn;
+
 /// Module for aarch64 related functionality.
 #[cfg(target_arch = "aarch64")]
 pub mod aarch64;