From 1f38791c173d1831a6cd5832acca13407592daa2 Mon Sep 17 00:00:00 2001 From: Jonathan Woollett-Light Date: Mon, 14 Aug 2023 00:35:51 +0100 Subject: [PATCH] feat: Support additional log filtering options Add the ` FilterFn` layer to support filtering by crates, modules and spans. With `tracing::instrument` spans wrap functions, this would support filtering to specific functions. Signed-off-by: Jonathan Woollett-Light --- src/api_server/src/request/logger.rs | 8 +- src/firecracker/src/api_server_adapter.rs | 7 +- src/firecracker/src/main.rs | 45 +++- src/vmm/src/rpc_interface.rs | 16 +- src/vmm/src/vmm_config/logger.rs | 242 +++++++++++++--------- 5 files changed, 209 insertions(+), 109 deletions(-) diff --git a/src/api_server/src/request/logger.rs b/src/api_server/src/request/logger.rs index 2dce15d8183..cf3e36ecee8 100644 --- a/src/api_server/src/request/logger.rs +++ b/src/api_server/src/request/logger.rs @@ -22,7 +22,7 @@ pub(crate) fn parse_put_logger(body: &Body) -> Result { mod tests { use std::path::PathBuf; - use vmm::vmm_config::logger::Level; + use vmm::vmm_config::logger::LevelFilter; use super::*; use crate::parsed_request::tests::vmm_action_from_request; @@ -38,9 +38,10 @@ mod tests { let mut expected_cfg = LoggerConfig { log_path: Some(PathBuf::from("log")), - level: Some(Level::Warn), + level: Some(LevelFilter::Warn), show_level: Some(false), show_log_origin: Some(false), + filter: None, }; match vmm_action_from_request(parse_put_logger(&Body::new(body)).unwrap()) { VmmAction::ConfigureLogger(cfg) => assert_eq!(cfg, expected_cfg), @@ -56,9 +57,10 @@ mod tests { expected_cfg = LoggerConfig { log_path: Some(PathBuf::from("log")), - level: Some(Level::Debug), + level: Some(LevelFilter::Debug), show_level: Some(false), show_log_origin: Some(false), + filter: None, }; match vmm_action_from_request(parse_put_logger(&Body::new(body)).unwrap()) { VmmAction::ConfigureLogger(cfg) => assert_eq!(cfg, expected_cfg), diff --git a/src/firecracker/src/api_server_adapter.rs b/src/firecracker/src/api_server_adapter.rs index 7f17578b494..279cc21ee26 100644 --- a/src/firecracker/src/api_server_adapter.rs +++ b/src/firecracker/src/api_server_adapter.rs @@ -132,7 +132,10 @@ impl MutEventSubscriber for ApiServerAdapter { } #[allow(clippy::too_many_arguments)] -pub(crate) fn run_with_api( +pub(crate) fn run_with_api< + F: Fn(&tracing::Metadata<'_>) -> bool, + G: Fn(&tracing::Metadata<'_>) -> bool, +>( seccomp_filters: &mut BpfThreadMap, config_json: Option, bind_path: PathBuf, @@ -142,7 +145,7 @@ pub(crate) fn run_with_api( api_payload_limit: usize, mmds_size_limit: usize, metadata_json: Option<&str>, - logger_handles: vmm::vmm_config::logger::LoggerHandles, + logger_handles: vmm::vmm_config::logger::LoggerHandles, ) -> Result<(), ApiServerError> { // FD to notify of API events. This is a blocking eventfd by design. // It is used in the config/pre-boot loop which is a simple blocking loop diff --git a/src/firecracker/src/main.rs b/src/firecracker/src/main.rs index 9267dbf2fb1..b98bf5101f1 100644 --- a/src/firecracker/src/main.rs +++ b/src/firecracker/src/main.rs @@ -26,7 +26,7 @@ use vmm::resources::VmResources; use vmm::signal_handler::register_signal_handlers; use vmm::version_map::{FC_VERSION_TO_SNAP_VERSION, VERSION_MAP}; use vmm::vmm_config::instance_info::{InstanceInfo, VmState}; -use vmm::vmm_config::logger::Level; +use vmm::vmm_config::logger::LevelFilter; use vmm::vmm_config::metrics::{init_metrics, MetricsConfig}; use vmm::{EventManager, FcExitCode, HTTP_MAX_PAYLOAD_SIZE}; @@ -47,8 +47,13 @@ enum MainError { ParseArguments(#[from] utils::arg_parser::Error), #[error("When printing Snapshot Data format: {0}")] PrintSnapshotDataFormat(#[from] SnapshotVersionError), - #[error("Invalid value for logger level: {0}.Possible values: [Error, Warning, Info, Debug]")] - InvalidLogLevel(::Err), + #[error( + "Invalid value for logger level: {0}.Possible values: [Off, Error, Warning, Info, Debug, \ + Trace]" + )] + InvalidLogLevel(::Err), + #[error("Failed to deserialize log filter: {0}")] + DeserializeLogFilter(serde_json::Error), #[error("Could not initialize logger: {0}")] LoggerInitialization(vmm::vmm_config::logger::InitLoggerError), #[error("Could not initialize metrics: {0:?}")] @@ -173,6 +178,27 @@ fn main_exec() -> Result<(), MainError> { "Path to a file that contains metadata in JSON format to add to the mmds.", ), ) + .arg( + Argument::new("start-time-us").takes_value(true).help( + "Process start time (wall clock, microseconds). This parameter is optional.", + ), + ) + .arg(Argument::new("start-time-cpu-us").takes_value(true).help( + "Process start CPU time (wall clock, microseconds). This parameter is optional.", + )) + .arg(Argument::new("parent-cpu-time-us").takes_value(true).help( + "Parent process CPU time (wall clock, microseconds). This parameter is optional.", + )) + .arg( + Argument::new("config-file") + .takes_value(true) + .help("Path to a file that contains the microVM configuration in JSON format."), + ) + .arg( + Argument::new(MMDS_CONTENT_ARG).takes_value(true).help( + "Path to a file that contains metadata in JSON format to add to the mmds.", + ), + ) .arg( Argument::new("no-api") .takes_value(false) @@ -187,6 +213,11 @@ fn main_exec() -> Result<(), MainError> { .takes_value(true) .help("Path to a fifo or a file used for configuring the logger on startup."), ) + .arg( + Argument::new("log-filter") + .takes_value(true) + .help("Filter for logging, if set overrides `level`."), + ) .arg( Argument::new("level") .takes_value(true) @@ -270,15 +301,21 @@ fn main_exec() -> Result<(), MainError> { let logger_handles = { let level_res = arguments .single_value("level") - .map(|s| Level::from_str(s)) + .map(|s| LevelFilter::from_str(s)) .transpose(); let level = level_res.map_err(MainError::InvalidLogLevel)?; + let filter = if let Some(log_filter) = arguments.single_value("log-filter") { + Some(serde_json::from_str(log_filter).map_err(MainError::DeserializeLogFilter)?) + } else { + None + }; let logger_config = vmm::vmm_config::logger::LoggerConfig { log_path: arguments.single_value("log-path").map(PathBuf::from), level, show_level: Some(arguments.flag_present("show-level")), show_log_origin: Some(arguments.flag_present("show-log-origin")), + filter, }; logger_config .init() diff --git a/src/vmm/src/rpc_interface.rs b/src/vmm/src/rpc_interface.rs index 2f8497f3be4..3e72e509886 100644 --- a/src/vmm/src/rpc_interface.rs +++ b/src/vmm/src/rpc_interface.rs @@ -259,7 +259,7 @@ trait MmdsRequestHandler { } /// Enables pre-boot setup and instantiation of a Firecracker VMM. -pub struct PrebootApiController<'a> { +pub struct PrebootApiController<'a, F, G> { seccomp_filters: &'a BpfThreadMap, instance_info: InstanceInfo, vm_resources: &'a mut VmResources, @@ -272,11 +272,11 @@ pub struct PrebootApiController<'a> { // should cleanly teardown if they occur. fatal_error: Option, /// Handles that allow re-configuring the logger. - logger_handles: LoggerHandles, + logger_handles: LoggerHandles, } // TODO Remove when `EventManager` implements `std::fmt::Debug`. -impl<'a> fmt::Debug for PrebootApiController<'a> { +impl<'a, F, G> fmt::Debug for PrebootApiController<'a, F, G> { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { f.debug_struct("PrebootApiController") .field("seccomp_filters", &self.seccomp_filters) @@ -290,7 +290,7 @@ impl<'a> fmt::Debug for PrebootApiController<'a> { } } -impl MmdsRequestHandler for PrebootApiController<'_> { +impl MmdsRequestHandler for PrebootApiController<'_, F, G> { fn mmds(&mut self) -> MutexGuard<'_, Mmds> { self.vm_resources.locked_mmds_or_default() } @@ -315,14 +315,16 @@ pub type ApiRequest = Box; /// Shorthand type for a response containing a boxed Result. pub type ApiResponse = Box>; -impl<'a> PrebootApiController<'a> { +impl<'a, F: Fn(&tracing::Metadata<'_>) -> bool, G: Fn(&tracing::Metadata<'_>) -> bool> + PrebootApiController<'a, F, G> +{ /// Constructor for the PrebootApiController. pub fn new( seccomp_filters: &'a BpfThreadMap, instance_info: InstanceInfo, vm_resources: &'a mut VmResources, event_manager: &'a mut EventManager, - logger_handles: LoggerHandles, + logger_handles: LoggerHandles, ) -> Self { Self { seccomp_filters, @@ -350,7 +352,7 @@ impl<'a> PrebootApiController<'a> { boot_timer_enabled: bool, mmds_size_limit: usize, metadata_json: Option<&str>, - logger_handles: LoggerHandles, + logger_handles: LoggerHandles, ) -> Result<(VmResources, Arc>), FcExitCode> { let mut vm_resources = VmResources::default(); // Silence false clippy warning. Clippy suggests using diff --git a/src/vmm/src/vmm_config/logger.rs b/src/vmm/src/vmm_config/logger.rs index 71e919cb34a..de9dffd7625 100644 --- a/src/vmm/src/vmm_config/logger.rs +++ b/src/vmm/src/vmm_config/logger.rs @@ -12,7 +12,6 @@ use std::sync::Mutex; use serde::{Deserialize, Serialize}; use tracing::Event; -use tracing_subscriber::filter::LevelFilter; use tracing_subscriber::fmt::format::{self, FormatEvent, FormatFields}; use tracing_subscriber::fmt::writer::BoxMakeWriter; use tracing_subscriber::fmt::{FmtContext, Layer as FmtLayer}; @@ -24,81 +23,81 @@ use tracing_subscriber::util::SubscriberInitExt; type ReloadError = tracing_subscriber::reload::Error; // TODO: See below doc comment. -/// Mimic of `log::Level`. +/// Mimic of `log::LevelFilter`. /// -/// This is used instead of `log::Level` to support: -/// 1. Aliasing `Warn` as `Warning` to avoid a breaking change in the API (which previously only -/// accepted `Warning`). -/// 2. Setting the default to `Warn` to avoid a breaking change. +/// This is used instead of `log::LevelFilter` to support aliasing `Warn` as `Warning` to avoid a +/// breaking change in the API (which previously only accepted `Warning`). /// -/// This alias, custom `Default` and type should be removed in the next breaking update to simplify -/// the code and API (and `log::Level` should be used in place). +/// This alias should be removed in the next breaking update to simplify +/// the code and API (and `log::LevelFilter` should be used in place). #[derive(Clone, Copy, Debug, PartialEq, Eq, Deserialize, Serialize)] -pub enum Level { - /// The “error” level. - /// - /// Designates very serious errors. +pub enum LevelFilter { + /// A level lower than all log levels. + Off, + /// Corresponds to the `Error` log level. #[serde(alias = "ERROR")] Error, - /// The “warn” level. - /// - /// Designates hazardous situations. + /// Corresponds to the `Warn` log level. #[serde(alias = "WARNING", alias = "Warning")] Warn, - /// The “info” level. - /// - /// Designates useful information. + /// Corresponds to the `Info` log level. #[serde(alias = "INFO")] Info, - /// The “debug” level. - /// - /// Designates lower priority information. + /// Corresponds to the `Debug` log level. #[serde(alias = "DEBUG")] Debug, - /// The “trace” level. - /// - /// Designates very low priority, often extremely verbose, information. + /// Corresponds to the `Trace` log level. #[serde(alias = "TRACE")] Trace, } -impl Default for Level { - fn default() -> Self { - Self::Warn + +fn from_log(level: log::LevelFilter) -> tracing_subscriber::filter::LevelFilter { + match level { + log::LevelFilter::Off => tracing_subscriber::filter::LevelFilter::OFF, + log::LevelFilter::Error => tracing_subscriber::filter::LevelFilter::ERROR, + log::LevelFilter::Warn => tracing_subscriber::filter::LevelFilter::WARN, + log::LevelFilter::Info => tracing_subscriber::filter::LevelFilter::INFO, + log::LevelFilter::Debug => tracing_subscriber::filter::LevelFilter::DEBUG, + log::LevelFilter::Trace => tracing_subscriber::filter::LevelFilter::TRACE, } } -impl From for tracing::Level { - fn from(level: Level) -> tracing::Level { + +impl From for log::LevelFilter { + fn from(level: LevelFilter) -> log::LevelFilter { match level { - Level::Error => tracing::Level::ERROR, - Level::Warn => tracing::Level::WARN, - Level::Info => tracing::Level::INFO, - Level::Debug => tracing::Level::DEBUG, - Level::Trace => tracing::Level::TRACE, + LevelFilter::Off => log::LevelFilter::Off, + LevelFilter::Error => log::LevelFilter::Error, + LevelFilter::Warn => log::LevelFilter::Warn, + LevelFilter::Info => log::LevelFilter::Info, + LevelFilter::Debug => log::LevelFilter::Debug, + LevelFilter::Trace => log::LevelFilter::Trace, } } } -impl From for Level { - fn from(level: log::Level) -> Level { +impl From for LevelFilter { + fn from(level: log::LevelFilter) -> LevelFilter { match level { - log::Level::Error => Level::Error, - log::Level::Warn => Level::Warn, - log::Level::Info => Level::Info, - log::Level::Debug => Level::Debug, - log::Level::Trace => Level::Trace, + log::LevelFilter::Off => LevelFilter::Off, + log::LevelFilter::Error => LevelFilter::Error, + log::LevelFilter::Warn => LevelFilter::Warn, + log::LevelFilter::Info => LevelFilter::Info, + log::LevelFilter::Debug => LevelFilter::Debug, + log::LevelFilter::Trace => LevelFilter::Trace, } } } -impl FromStr for Level { - type Err = ::Err; +impl FromStr for LevelFilter { + type Err = ::Err; fn from_str(s: &str) -> std::result::Result { // This is required to avoid a breaking change. match s { - "ERROR" => Ok(Level::Error), - "WARNING" | "Warning" => Ok(Level::Warn), - "INFO" => Ok(Level::Info), - "DEBUG" => Ok(Level::Debug), - "TRACE" => Ok(Level::Trace), - _ => log::Level::from_str(s).map(Level::from), + "OFF" => Ok(LevelFilter::Off), + "ERROR" => Ok(LevelFilter::Error), + "WARNING" | "Warning" => Ok(LevelFilter::Warn), + "INFO" => Ok(LevelFilter::Info), + "DEBUG" => Ok(LevelFilter::Debug), + "TRACE" => Ok(LevelFilter::Trace), + _ => log::LevelFilter::from_str(s).map(LevelFilter::from), } } } @@ -109,12 +108,15 @@ impl FromStr for Level { pub struct LoggerConfig { /// Named pipe or file used as output for logs. pub log_path: Option, + // TODO Deprecate this API argument. /// The level of the Logger. - pub level: Option, + pub level: Option, /// When enabled, the logger will append to the output the severity of the log entry. pub show_level: Option, /// When enabled, the logger will append the origin of the log entry. pub show_log_origin: Option, + /// Filter components. If this is `Some` it overrides `self.level`. + pub filter: Option, } /// Error type for [`LoggerConfig::init`]. @@ -134,21 +136,44 @@ pub enum UpdateLoggerError { /// Failed to open target file. #[error("Failed to open target file: {0}")] File(std::io::Error), - /// Failed to modify format subscriber writer. - #[error("Failed to modify format subscriber writer: {0}")] + /// Failed to modify format layer writer. + #[error("Failed to modify format layer writer: {0}")] Fmt(ReloadError), - /// Failed to modify filter level. - #[error("Failed to modify filter level: {0}")] - Filter(ReloadError), + /// Failed to modify level filter. + #[error("Failed to modify level filter: {0}")] + Level(ReloadError), +} + +/// The filter arguments for logs. +#[derive(Clone, Debug, PartialEq, Eq, Deserialize, Serialize)] +pub struct FilterArgs { + /// A filepath to filter by e.g. `src/main.rs`. + file: Option, + /// A module path to filter by e.g. `vmm::vmm_config`. + module: Option, + /// A level to filter by e.g. `tracing::Level::INFO`. + level: Option, +} + +// Initialize filter to default. +static FILTER: Mutex = Mutex::new(FilterArgs { + file: None, + module: None, + level: Some(log::LevelFilter::Warn), +}); + +// `type_alias_impl_trait` is the nightly feature required to move this to a `type FmtHandle = ..` +// and remove these polluting generics. +/// Handles that allow re-configuring the logger. +#[derive(Debug)] +pub struct LoggerHandles { + fmt: FmtHandle, } -type FmtHandle = tracing_subscriber::reload::Handle< +type FmtHandle = tracing_subscriber::reload::Handle< tracing_subscriber::fmt::Layer< tracing_subscriber::layer::Layered< - tracing_subscriber::reload::Layer< - tracing_subscriber::filter::LevelFilter, - tracing_subscriber::registry::Registry, - >, + tracing_subscriber::filter::FilterFn, tracing_subscriber::registry::Registry, >, tracing_subscriber::fmt::format::DefaultFields, @@ -156,36 +181,59 @@ type FmtHandle = tracing_subscriber::reload::Handle< tracing_subscriber::fmt::writer::BoxMakeWriter, >, tracing_subscriber::layer::Layered< - tracing_subscriber::reload::Layer< - tracing_subscriber::filter::LevelFilter, - tracing_subscriber::registry::Registry, - >, + tracing_subscriber::filter::FilterFn, tracing_subscriber::registry::Registry, >, >; -type FilterHandle = tracing_subscriber::reload::Handle< - tracing_subscriber::filter::LevelFilter, - tracing_subscriber::registry::Registry, ->; - -/// Handles that allow re-configuring the logger. -#[derive(Debug)] -pub struct LoggerHandles { - filter: FilterHandle, - fmt: FmtHandle, -} impl LoggerConfig { /// Initializes the logger. /// /// Returns handles that can be used to dynamically re-configure the logger. - pub fn init(&self) -> Result { - // Setup filter - let (filter, filter_handle) = { - let level = tracing::Level::from(self.level.unwrap_or_default()); - let filter_subscriber = LevelFilter::from_level(level); - ReloadLayer::new(filter_subscriber) - }; + pub fn init( + self, + ) -> Result< + LoggerHandles< + impl Fn(&tracing::Metadata<'_>) -> bool, + impl Fn(&tracing::Metadata<'_>) -> bool, + >, + InitLoggerError, + > { + // Update default filter to match passed arguments. + match (self.level, self.filter) { + (_, Some(filter)) => { + *FILTER.lock().unwrap() = filter; + } + (Some(level), None) => { + *FILTER.lock().unwrap() = FilterArgs { + file: None, + module: None, + level: Some(log::LevelFilter::from(level)), + }; + } + (None, None) => {} + } + + // Setup filter layer + let filter = tracing_subscriber::filter::FilterFn::new(|metadata| { + let args = FILTER.lock().unwrap(); + let file_cond = args.file.as_ref().map_or(true, |f| { + metadata + .file() + .map(|file| file.starts_with(f)) + .unwrap_or(false) + }); + let module_cond = args.module.as_ref().map_or(true, |m| { + metadata + .module_path() + .map(|module_path| module_path.starts_with(m)) + .unwrap_or(false) + }); + let level_cond = args + .level + .map_or(true, |l| *metadata.level() <= from_log(l)); + file_cond && module_cond && level_cond + }); // Setup fmt layer let (fmt, fmt_handle) = { @@ -228,15 +276,15 @@ impl LoggerConfig { tracing::debug!("Debug level logs enabled."); tracing::trace!("Trace level logs enabled."); - Ok(LoggerHandles { - filter: filter_handle, - fmt: fmt_handle, - }) + Ok(LoggerHandles { fmt: fmt_handle }) } /// Updates the logger using the given handles. pub fn update( - &self, - LoggerHandles { filter, fmt }: &LoggerHandles, + self, + LoggerHandles { fmt }: &LoggerHandles< + impl Fn(&tracing::Metadata<'_>) -> bool, + impl Fn(&tracing::Metadata<'_>) -> bool, + >, ) -> Result<(), UpdateLoggerError> { // Update the log path if let Some(log_path) = &self.log_path { @@ -255,11 +303,19 @@ impl LoggerConfig { .map_err(UpdateLoggerError::Fmt)?; } - // Update the filter level - if let Some(level) = self.level { - filter - .modify(|f| *f = LevelFilter::from_level(tracing::Level::from(level))) - .map_err(UpdateLoggerError::Filter)?; + // Update the filter + match (self.level, self.filter) { + (_, Some(filter)) => { + *FILTER.lock().unwrap() = filter; + } + (Some(level), None) => { + *FILTER.lock().unwrap() = FilterArgs { + file: None, + module: None, + level: Some(log::LevelFilter::from(level)), + }; + } + (None, None) => {} } // Update if the logger shows the level