diff --git a/Cargo.lock b/Cargo.lock index f8c984286cd..37520c782de 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -106,6 +106,7 @@ name = "api_server" version = "0.1.0" dependencies = [ "libc", + "log", "logger", "micro_http", "mmds", @@ -114,6 +115,7 @@ dependencies = [ "serde_derive", "serde_json", "thiserror", + "tracing", "utils", "vmm", ] @@ -191,7 +193,7 @@ version = "0.66.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f2b84e06fc203107bfbad243f4aba2af864eb7db3b1cf46ea0a023b0b433d2a7" dependencies = [ - "bitflags 2.3.3", + "bitflags 2.4.0", "cexpr", "clang-sys", "lazy_static", @@ -216,9 +218,9 @@ checksum = "bef38d45163c2f1dde094a7dfd33ccf595c92905c8f8f4fdc18d06fb1037718a" [[package]] name = "bitflags" -version = "2.3.3" +version = "2.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "630be753d4e58660abd17930c71b647fe46c27ea6b63cc59e1e3851406972e42" +checksum = "b4682ae6287fcf752ecaabbfcc7b6f9b72aa33933dc23a554d853aea8eea8635" [[package]] name = "byteorder" @@ -379,6 +381,7 @@ dependencies = [ "serde", "serde_json", "thiserror", + "tracing", "utils", "vmm", ] @@ -477,6 +480,7 @@ dependencies = [ "logger", "micro_http", "serde_json", + "tracing", "utils", ] @@ -537,6 +541,7 @@ dependencies = [ "cargo_toml", "event-manager", "libc", + "log", "logger", "mmds", "regex", @@ -546,6 +551,8 @@ dependencies = [ "snapshot", "thiserror", "timerfd", + "tracing", + "tracing-subscriber", "userfaultfd 0.6.0", "utils", "vmm", @@ -649,7 +656,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cb0889898416213fab133e1d33a0e5858a48177452750691bde3666d0fdbaf8b" dependencies = [ "hermit-abi", - "rustix 0.38.4", + "rustix 0.38.8", "windows-sys", ] @@ -676,6 +683,7 @@ dependencies = [ "nix", "regex", "thiserror", + "tracing", "utils", ] @@ -751,9 +759,9 @@ checksum = "ef53942eb7bf7ff43a617b3e2c1c4a5ecf5944a7c1bc12d7ee39bbb15e5c1519" [[package]] name = "linux-raw-sys" -version = "0.4.3" +version = "0.4.5" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "09fc20d2ca12cb9f044c93e3bd6d32d523e6e2ec3db4f7b2939cd99026ecd3f0" +checksum = "57bcfdad1b858c2db7c38303a6d2ad4dfaf5eb53dfeb0910128b2c26d6158503" [[package]] name = "log" @@ -774,6 +782,7 @@ dependencies = [ "serde", "serde_json", "thiserror", + "tracing", "utils", "vm-superio", ] @@ -829,6 +838,7 @@ dependencies = [ "serde_json", "snapshot", "thiserror", + "tracing", "utils", "versionize", "versionize_derive", @@ -902,6 +912,12 @@ version = "0.1.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "19b17cddbe7ec3f8bc800887bab5e717348c95ea2ca0b1bf0837fb964dc67099" +[[package]] +name = "pin-project-lite" +version = "0.2.12" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "12cc1b0bf1727a77a54b6654e7b5f1af8604923edc8b81885f8ec92f9e3f0a05" + [[package]] name = "pin-utils" version = "0.1.0" @@ -1016,6 +1032,7 @@ version = "1.5.0-dev" dependencies = [ "libc", "thiserror", + "tracing", "utils", ] @@ -1076,14 +1093,14 @@ dependencies = [ [[package]] name = "rustix" -version = "0.38.4" +version = "0.38.8" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0a962918ea88d644592894bc6dc55acc6c0956488adcebbfb6e273506b7fd6e5" +checksum = "19ed4fa021d81c8392ce04db050a3da9a60299050b7ae1cf482d862b54a7218f" dependencies = [ - "bitflags 2.3.3", + "bitflags 2.4.0", "errno", "libc", - "linux-raw-sys 0.4.3", + "linux-raw-sys 0.4.5", "windows-sys", ] @@ -1111,6 +1128,7 @@ dependencies = [ "serde", "serde_json", "thiserror", + "tracing", "utils", ] @@ -1163,6 +1181,15 @@ dependencies = [ "serde", ] +[[package]] +name = "sharded-slab" +version = "0.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "1.1.0" @@ -1176,6 +1203,7 @@ dependencies = [ "criterion", "libc", "thiserror", + "tracing", "versionize", "versionize_derive", ] @@ -1240,6 +1268,16 @@ dependencies = [ "syn 2.0.28", ] +[[package]] +name = "thread_local" +version = "1.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3fdd6f064ccff2d6567adcb3873ca630700f00b5ad3f060c25b5dcfd9a4ce152" +dependencies = [ + "cfg-if", + "once_cell", +] + [[package]] name = "timerfd" version = "1.5.0" @@ -1293,6 +1331,37 @@ dependencies = [ "winnow", ] +[[package]] +name = "tracing" +version = "0.1.37" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8ce8c33a8d48bd45d624a6e523445fd21ec13d3653cd51f681abf67418f54eb8" +dependencies = [ + "cfg-if", + "pin-project-lite", + "tracing-core", +] + +[[package]] +name = "tracing-core" +version = "0.1.31" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0955b8137a1df6f1a2e9a37d8a6656291ff0297c1a97c24e0d8425fe2312f79a" +dependencies = [ + "once_cell", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.17" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "30a651bc37f915e81f087d86e62a18eec5f79550c7faff886f7090b4ea757c77" +dependencies = [ + "sharded-slab", + "thread_local", + "tracing-core", +] + [[package]] name = "typenum" version = "1.16.0" @@ -1347,7 +1416,7 @@ version = "0.6.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0ec82f2a09c9279eb320bd9945f0df0232613d4621c093d8ba02edcb45624fd4" dependencies = [ - "bitflags 2.3.3", + "bitflags 2.4.0", "cfg-if", "libc", "nix", @@ -1382,6 +1451,7 @@ dependencies = [ "serde", "serde_json", "thiserror", + "tracing", "versionize", "versionize_derive", "vm-memory", @@ -1463,7 +1533,7 @@ name = "vmm" version = "0.1.0" dependencies = [ "aws-lc-rs", - "bitflags 2.3.3", + "bitflags 2.4.0", "criterion", "derive_more", "device_tree", @@ -1486,6 +1556,8 @@ dependencies = [ "snapshot", "thiserror", "timerfd", + "tracing", + "tracing-subscriber", "userfaultfd 0.5.1", "utils", "versionize", diff --git a/src/api_server/Cargo.toml b/src/api_server/Cargo.toml index cd29a75c58e..dd0c0afd104 100644 --- a/src/api_server/Cargo.toml +++ b/src/api_server/Cargo.toml @@ -21,6 +21,8 @@ mmds = { path = "../mmds" } seccompiler = { path = "../seccompiler" } utils = { path = "../utils" } vmm = { path = "../vmm" } +tracing = { version = "0.1.37", default-features = false } [dev-dependencies] libc = "0.2.117" +log = "0.4.19" \ No newline at end of file diff --git a/src/api_server/src/parsed_request.rs b/src/api_server/src/parsed_request.rs index 12eacb24bc0..038d4c8ad3b 100644 --- a/src/api_server/src/parsed_request.rs +++ b/src/api_server/src/parsed_request.rs @@ -3,7 +3,7 @@ use std::fmt::Debug; -use logger::{error, info, log_enabled, Level}; +use logger::{error, info, Level}; use micro_http::{Body, Method, Request, Response, StatusCode, Version}; use serde::ser::Serialize; use serde_json::Value; @@ -232,7 +232,7 @@ fn describe(method: Method, path: &str, body: Option<&Body>) -> String { ("/cpu-config", Some(payload_value)) => { // If the log level is at Debug or higher, include the CPU template in // the log line. - if log_enabled!(Level::Debug) { + if tracing::enabled!(Level::DEBUG) { describe_with_body(method, path, payload_value) } else { format!( diff --git a/src/api_server/src/request/logger.rs b/src/api_server/src/request/logger.rs index 9e386b00e81..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::LoggerLevel; + use vmm::vmm_config::logger::LevelFilter; use super::*; use crate::parsed_request::tests::vmm_action_from_request; @@ -37,10 +37,11 @@ mod tests { }"#; let mut expected_cfg = LoggerConfig { - log_path: PathBuf::from("log"), - level: LoggerLevel::Warning, - show_level: false, - show_log_origin: false, + log_path: Some(PathBuf::from("log")), + 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), @@ -55,10 +56,11 @@ mod tests { }"#; expected_cfg = LoggerConfig { - log_path: PathBuf::from("log"), - level: LoggerLevel::Debug, - show_level: false, - show_log_origin: false, + log_path: Some(PathBuf::from("log")), + 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/cpu-template-helper/Cargo.toml b/src/cpu-template-helper/Cargo.toml index 9be03d9c608..472c4b50bbb 100644 --- a/src/cpu-template-helper/Cargo.toml +++ b/src/cpu-template-helper/Cargo.toml @@ -17,6 +17,7 @@ libc = "0.2.147" serde = { version = "1.0.183", features = ["derive"] } serde_json = "1.0.104" thiserror = "1.0.44" +tracing = { version = "0.1.37", default-features = false } vmm = { path = "../vmm" } diff --git a/src/dumbo/Cargo.toml b/src/dumbo/Cargo.toml index 670bb37542c..decfe365510 100644 --- a/src/dumbo/Cargo.toml +++ b/src/dumbo/Cargo.toml @@ -11,6 +11,7 @@ bench = false [dependencies] bitflags = "1.3.2" derive_more = { version = "0.99.17", default-features = false, features = ["from"] } +tracing = { version = "0.1.37", default-features = false } logger = { path = "../logger" } micro_http = { git = "https://github.com/firecracker-microvm/micro-http", rev = "4b18a04" } diff --git a/src/firecracker/Cargo.toml b/src/firecracker/Cargo.toml index cd6b15d5fe6..d8f0036963f 100644 --- a/src/firecracker/Cargo.toml +++ b/src/firecracker/Cargo.toml @@ -15,9 +15,12 @@ bench = false [dependencies] event-manager = "0.3.0" libc = "0.2.147" +log = "0.4.19" serde_json = "1.0.104" thiserror = "1.0.44" timerfd = "1.5.0" +tracing = { version = "0.1.37", default-features = false } +tracing-subscriber = { version = "0.3.17", default-features = false, features = ["fmt"] } api_server = { path = "../api_server" } logger = { path = "../logger" } diff --git a/src/firecracker/src/api_server_adapter.rs b/src/firecracker/src/api_server_adapter.rs index f91d06cb041..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,6 +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, ) -> 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 @@ -211,6 +215,7 @@ pub(crate) fn run_with_api( boot_timer_enabled, mmds_size_limit, metadata_json, + logger_handles, ) .map_err(ApiServerError::MicroVMStoppedWithError), }; diff --git a/src/firecracker/src/main.rs b/src/firecracker/src/main.rs index 1a1d3f836d6..b98bf5101f1 100644 --- a/src/firecracker/src/main.rs +++ b/src/firecracker/src/main.rs @@ -8,12 +8,13 @@ mod seccomp; use std::fs::{self, File}; use std::path::PathBuf; use std::process::ExitCode; +use std::str::FromStr; use std::sync::{Arc, Mutex}; use std::{io, panic}; use api_server_adapter::ApiServerError; use event_manager::SubscriberOps; -use logger::{error, info, ProcessTimeReporter, StoreMetric, LOGGER, METRICS}; +use logger::{error, info, ProcessTimeReporter, StoreMetric, METRICS}; use seccomp::FilterError; use seccompiler::BpfThreadMap; use snapshot::{Error as SnapshotError, Snapshot}; @@ -25,8 +26,8 @@ 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::{init_logger, LoggerConfig, LoggerConfigError, LoggerLevel}; -use vmm::vmm_config::metrics::{init_metrics, MetricsConfig, MetricsConfigError}; +use vmm::vmm_config::logger::LevelFilter; +use vmm::vmm_config::metrics::{init_metrics, MetricsConfig}; use vmm::{EventManager, FcExitCode, HTTP_MAX_PAYLOAD_SIZE}; use crate::seccomp::SeccompConfig; @@ -35,7 +36,6 @@ use crate::seccomp::SeccompConfig; // runtime file. // see https://refspecs.linuxfoundation.org/FHS_3.0/fhs/ch03s15.html for more information. const DEFAULT_API_SOCK_PATH: &str = "/run/firecracker.socket"; -const DEFAULT_INSTANCE_ID: &str = "anonymous-instance"; const FIRECRACKER_VERSION: &str = env!("FIRECRACKER_VERSION"); const MMDS_CONTENT_ARG: &str = "metadata"; @@ -47,12 +47,17 @@ 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(LoggerConfigError), + #[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(LoggerConfigError), + LoggerInitialization(vmm::vmm_config::logger::InitLoggerError), #[error("Could not initialize metrics: {0:?}")] - MetricsInitialization(MetricsConfigError), + MetricsInitialization(vmm::vmm_config::metrics::MetricsConfigError), #[error("Seccomp error: {0}")] SeccompFilter(FilterError), #[error("RunWithApiError error: {0}")] @@ -87,10 +92,6 @@ fn main() -> ExitCode { } fn main_exec() -> Result<(), MainError> { - LOGGER - .configure(Some(DEFAULT_INSTANCE_ID.to_string())) - .expect("Failed to register logger"); - register_signal_handlers().map_err(MainError::RegisterSignalHandlers)?; #[cfg(target_arch = "aarch64")] @@ -124,124 +125,141 @@ fn main_exec() -> Result<(), MainError> { let http_max_payload_size_str = HTTP_MAX_PAYLOAD_SIZE.to_string(); - let mut arg_parser = ArgParser::new() - .arg( - Argument::new("api-sock") - .takes_value(true) - .default_value(DEFAULT_API_SOCK_PATH) - .help("Path to unix domain socket used by the API."), - ) - .arg( - Argument::new("id") - .takes_value(true) - .default_value(DEFAULT_INSTANCE_ID) - .help("MicroVM unique identifier."), - ) - .arg( - Argument::new("seccomp-filter") - .takes_value(true) - .forbids(vec!["no-seccomp"]) - .help( - "Optional parameter which allows specifying the path to a custom seccomp \ - filter. For advanced users.", + let mut arg_parser = + ArgParser::new() + .arg( + Argument::new("api-sock") + .takes_value(true) + .default_value(DEFAULT_API_SOCK_PATH) + .help("Path to unix domain socket used by the API."), + ) + .arg( + Argument::new("id") + .takes_value(true) + .default_value("anonymous-instance") + .help("MicroVM unique identifier."), + ) + .arg( + Argument::new("seccomp-filter") + .takes_value(true) + .forbids(vec!["no-seccomp"]) + .help( + "Optional parameter which allows specifying the path to a custom seccomp \ + filter. For advanced users.", + ), + ) + .arg( + Argument::new("no-seccomp") + .takes_value(false) + .forbids(vec!["seccomp-filter"]) + .help( + "Optional parameter which allows starting and using a microVM without \ + seccomp filtering. Not recommended.", + ), + ) + .arg( + Argument::new("start-time-us").takes_value(true).help( + "Process start time (wall clock, microseconds). This parameter is optional.", ), - ) - .arg( - Argument::new("no-seccomp") - .takes_value(false) - .forbids(vec!["seccomp-filter"]) - .help( - "Optional parameter which allows starting and using a microVM without seccomp \ - filtering. Not recommended.", - ), - ) - .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( + ) + .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) - .requires("config-file") - .help( - "Optional parameter which allows starting and using a microVM without an \ - active API socket.", + )) + .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("log-path") - .takes_value(true) - .help("Path to a fifo or a file used for configuring the logger on startup."), - ) - .arg( - Argument::new("level") - .takes_value(true) - .requires("log-path") - .default_value("Warning") - .help("Set the logger level."), - ) - .arg( - Argument::new("show-level") - .takes_value(false) - .requires("log-path") - .help("Whether or not to output the level in the logs."), - ) - .arg( - Argument::new("show-log-origin") - .takes_value(false) - .requires("log-path") - .help( - "Whether or not to include the file path and line number of the log's origin.", + ) + .arg( + Argument::new("start-time-us").takes_value(true).help( + "Process start time (wall clock, microseconds). This parameter is optional.", ), - ) - .arg( - Argument::new("metrics-path") - .takes_value(true) - .help("Path to a fifo or a file used for configuring the metrics on startup."), - ) - .arg(Argument::new("boot-timer").takes_value(false).help( - "Whether or not to load boot timer device for logging elapsed time since \ - InstanceStart command.", - )) - .arg(Argument::new("version").takes_value(false).help( - "Print the binary version number and a list of supported snapshot data format \ - versions.", - )) - .arg( - Argument::new("describe-snapshot") - .takes_value(true) - .help("Print the data format version of the provided snapshot state file."), - ) - .arg( - Argument::new("http-api-max-payload-size") - .takes_value(true) - .default_value(&http_max_payload_size_str) - .help("Http API request payload max size, in bytes."), - ) - .arg( - Argument::new("mmds-size-limit") - .takes_value(true) - .help("Mmds data store limit, in bytes."), - ); + ) + .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) + .requires("config-file") + .help( + "Optional parameter which allows starting and using a microVM without an \ + active API socket.", + ), + ) + .arg( + Argument::new("log-path") + .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) + .help("Set the logger level."), + ) + .arg( + Argument::new("show-level") + .takes_value(false) + .help("Whether or not to output the level in the logs."), + ) + .arg(Argument::new("show-log-origin").takes_value(false).help( + "Whether or not to include the file path and line number of the log's origin.", + )) + .arg( + Argument::new("metrics-path") + .takes_value(true) + .help("Path to a fifo or a file used for configuring the metrics on startup."), + ) + .arg(Argument::new("boot-timer").takes_value(false).help( + "Whether or not to load boot timer device for logging elapsed time since \ + InstanceStart command.", + )) + .arg(Argument::new("version").takes_value(false).help( + "Print the binary version number and a list of supported snapshot data format \ + versions.", + )) + .arg( + Argument::new("describe-snapshot") + .takes_value(true) + .help("Print the data format version of the provided snapshot state file."), + ) + .arg( + Argument::new("http-api-max-payload-size") + .takes_value(true) + .default_value(&http_max_payload_size_str) + .help("Http API request payload max size, in bytes."), + ) + .arg( + Argument::new("mmds-size-limit") + .takes_value(true) + .help("Mmds data store limit, in bytes."), + ); arg_parser.parse_from_cmdline()?; let arguments = arg_parser.arguments(); @@ -279,23 +297,30 @@ fn main_exec() -> Result<(), MainError> { app_name: "Firecracker".to_string(), }; - LOGGER.set_instance_id(instance_id.to_owned()); - - if let Some(log) = arguments.single_value("log-path") { - // It's safe to unwrap here because the field's been provided with a default value. - let level = arguments.single_value("level").unwrap().to_owned(); - let logger_level = LoggerLevel::from_string(level).map_err(MainError::InvalidLogLevel)?; - let show_level = arguments.flag_present("show-level"); - let show_log_origin = arguments.flag_present("show-log-origin"); - - let logger_config = LoggerConfig { - log_path: PathBuf::from(log), - level: logger_level, - show_level, - show_log_origin, + // Configure logger, the logger handles can be used to re-configure the logger with the API. + let logger_handles = { + let level_res = arguments + .single_value("level") + .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 }; - init_logger(logger_config, &instance_info).map_err(MainError::LoggerInitialization)?; - } + 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() + .map_err(MainError::LoggerInitialization)? + }; if let Some(metrics_path) = arguments.single_value("metrics-path") { let metrics_config = MetricsConfig { @@ -378,6 +403,7 @@ fn main_exec() -> Result<(), MainError> { api_payload_limit, mmds_size_limit, metadata_json.as_deref(), + logger_handles, ) .map_err(MainError::RunWithApi) } else { diff --git a/src/jailer/Cargo.toml b/src/jailer/Cargo.toml index 5280e99e831..023273886f1 100644 --- a/src/jailer/Cargo.toml +++ b/src/jailer/Cargo.toml @@ -17,5 +17,6 @@ libc = "0.2.147" nix = { version = "0.26.2", default-features = false, features = ["dir"] } regex = { version = "1.9.3", default-features = false, features = ["std"] } thiserror = "1.0.44" +tracing = { version = "0.1.37", default-features = false } utils = { path = "../utils" } diff --git a/src/logger/Cargo.toml b/src/logger/Cargo.toml index 908a508b931..ed8faec56df 100644 --- a/src/logger/Cargo.toml +++ b/src/logger/Cargo.toml @@ -16,4 +16,5 @@ serde = { version = "1.0.136", features = ["derive", "rc"] } serde_json = "1.0.78" thiserror = "1.0.32" vm-superio = "0.7.0" +tracing = { version = "0.1.37", default-features = false } utils = { path = "../utils" } diff --git a/src/logger/src/lib.rs b/src/logger/src/lib.rs index e9fe7d19d13..da92921fa9a 100644 --- a/src/logger/src/lib.rs +++ b/src/logger/src/lib.rs @@ -6,16 +6,10 @@ //! Crate that implements Firecracker specific functionality as far as logging and metrics //! collecting. -mod init; -mod logger; mod metrics; -use std::sync::LockResult; +pub use tracing::{debug, error, info, trace, warn, Level}; -pub use log::Level::*; -pub use log::{warn, *}; - -pub use crate::logger::{LoggerError, LOGGER}; #[cfg(target_arch = "aarch64")] pub use crate::metrics::RTCDeviceMetrics; pub use crate::metrics::{ @@ -41,15 +35,6 @@ pub fn log_dev_preview_warning(feature_name: &str, msg_opt: Option) { } } -fn extract_guard(lock_result: LockResult) -> G { - match lock_result { - Ok(guard) => guard, - // If a thread panics while holding this lock, the writer within should still be usable. - // (we might get an incomplete log line or something like that). - Err(poisoned) => poisoned.into_inner(), - } -} - /// Helper function for updating the value of a store metric with elapsed time since some time in a /// past. pub fn update_metric_with_elapsed_time(metric: &SharedStoreMetric, start_time_us: u64) -> u64 { diff --git a/src/logger/src/logger.rs b/src/logger/src/logger.rs deleted file mode 100644 index df82ea545c9..00000000000 --- a/src/logger/src/logger.rs +++ /dev/null @@ -1,776 +0,0 @@ -// Copyright 2020 Amazon.com, Inc. or its affiliates. All Rights Reserved. -// SPDX-License-Identifier: Apache-2.0 - -//! Utility for sending log related messages to a storing destination or simply to stdout/stderr. -//! The logging destination is specified upon the initialization of the logging system. -//! -//! # Enabling logging -//! There are 2 ways to enable the logging functionality: -//! -//! 1) Calling `LOGGER.configure()`. This will enable the logger to work in limited mode. -//! In this mode the logger can only write messages to stdout or stderr. - -//! The logger can be configured in this way any number of times before calling `LOGGER.init()`. -//! -//! 2) Calling `LOGGER.init()`. This will enable the logger to work in full mode. -//! In this mode the logger can write messages to arbitrary buffers. -//! The logger can be initialized only once. Any call to the `LOGGER.init()` following that will -//! fail with an explicit error. -//! -//! ## Example for logging to stdout/stderr -//! -//! ``` -//! use std::ops::Deref; -//! -//! use logger::{error, warn, LOGGER}; -//! -//! // Optionally do an initial configuration for the logger. -//! if let Err(err) = LOGGER.deref().configure(Some("MY-INSTANCE".to_string())) { -//! println!("Could not configure the log subsystem: {}", err); -//! return; -//! } -//! warn!("this is a warning"); -//! error!("this is an error"); -//! ``` -//! ## Example for logging to a `File`: -//! -//! ``` -//! use std::io::Cursor; -//! -//! use libc::c_char; -//! use logger::{error, warn, LOGGER}; -//! -//! let mut logs = Cursor::new(vec![0; 15]); -//! -//! // Initialize the logger to log to a FIFO that was created beforehand. -//! assert!(LOGGER -//! .init("Running Firecracker v.x".to_string(), Box::new(logs),) -//! .is_ok()); -//! // The following messages should appear in the in-memory buffer `logs`. -//! warn!("this is a warning"); -//! error!("this is an error"); -//! ``` - -//! # Plain log format -//! The current logging system is built upon the upstream crate 'log' and reexports the macros -//! provided by it for flushing plain log content. Log messages are printed through the use of five -//! macros: -//! * error!() -//! * warning!() -//! * info!() -//! * debug!() -//! * trace!() -//! -//! Each call to the desired macro will flush a line of the following format: -//! ``` [:::] ```. -//! The first component is always the timestamp which has the `%Y-%m-%dT%H:%M:%S.%f` format. -//! The level will depend on the macro used to flush a line and will be one of the following: -//! `ERROR`, `WARN`, `INFO`, `DEBUG`, `TRACE`. -//! The file path and the line provides the exact location of where the call to the macro was made. -//! ## Example of a log line: -//! ```bash -//! 2018-11-07T05:34:25.180751152 [anonymous-instance:ERROR:vmm/src/lib.rs:1173] Failed to write -//! metrics: Failed to write logs. Error: operation would block -//! ``` -//! # Limitations -//! Logs can be flushed either to stdout/stderr or to a byte-oriented sink (File, FIFO, Ring Buffer -//! etc). - -use std::fmt::{self, Debug}; -use std::io::{sink, stdout, Write}; -use std::sync::atomic::{AtomicBool, Ordering}; -use std::sync::{Mutex, RwLock}; -use std::{result, thread}; - -use lazy_static::lazy_static; -use log::{max_level, set_logger, set_max_level, LevelFilter, Log, Metadata, Record}; -use utils::time::LocalTime; - -use super::extract_guard; -use crate::init; -use crate::init::Init; -use crate::metrics::{IncMetric, METRICS}; - -/// Type for returning functions outcome. -pub type Result = result::Result; - -// Values used by the Logger. -const DEFAULT_MAX_LEVEL: LevelFilter = LevelFilter::Warn; - -lazy_static! { - static ref _LOGGER_INNER: Logger = Logger::new(); - - /// Static instance used for handling human-readable logs. - pub static ref LOGGER: &'static Logger = { - set_logger(_LOGGER_INNER.deref()).expect("Failed to set logger"); - _LOGGER_INNER.deref() - }; -} - -/// Logger representing the logging subsystem. -// All member fields have types which are Sync, and exhibit interior mutability, so -// we can call logging operations using a non-mut static global variable. -pub struct Logger { - init: Init, - // Human readable logs will be outputted here. - log_buf: Mutex>, - show_level: AtomicBool, - show_file_path: AtomicBool, - show_line_numbers: AtomicBool, - instance_id: RwLock, -} - -impl fmt::Debug for Logger { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - f.debug_struct("Logger") - .field("init", &self.init) - .field("log_buf", &"?") - .field("show_level", &self.show_level) - .field("show_file_path", &self.show_file_path) - .field("show_line_numbers", &self.show_line_numbers) - .field("instance_id", &self.instance_id) - .finish() - } -} - -impl Logger { - /// Creates a new instance of the current logger. - fn new() -> Logger { - Logger { - init: Init::new(), - log_buf: Mutex::new(Box::new(sink())), - show_level: AtomicBool::new(true), - show_line_numbers: AtomicBool::new(true), - show_file_path: AtomicBool::new(true), - instance_id: RwLock::new(String::new()), - } - } - - fn show_level(&self) -> bool { - self.show_level.load(Ordering::Relaxed) - } - - fn show_file_path(&self) -> bool { - self.show_file_path.load(Ordering::Relaxed) - } - - fn show_line_numbers(&self) -> bool { - self.show_line_numbers.load(Ordering::Relaxed) - } - - /// Enables or disables including the level in the log message's tag portion. - /// - /// # Arguments - /// - /// * `option` - Boolean deciding whether to include log level in log message. - /// - /// # Example - /// - /// ``` - /// use std::ops::Deref; - /// - /// use logger::{warn, LOGGER}; - /// - /// let l = LOGGER.deref(); - /// l.set_include_level(true); - /// assert!(l.configure(Some("MY-INSTANCE".to_string())).is_ok()); - /// warn!("A warning log message with level included"); - /// ``` - /// The code above will more or less print: - /// ```bash - /// 2018-11-07T05:34:25.180751152 [MY-INSTANCE:WARN:logger/src/lib.rs:290] A warning log - /// message with level included - /// ``` - pub fn set_include_level(&self, option: bool) -> &Self { - self.show_level.store(option, Ordering::Relaxed); - self - } - - /// Enables or disables including the file path and the line numbers in the tag of - /// the log message. Not including the file path will also hide the line numbers from the tag. - /// - /// # Arguments - /// - /// * `file_path` - Boolean deciding whether to include file path of the log message's origin. - /// * `line_numbers` - Boolean deciding whether to include the line number of the file where the - /// log message orginated. - /// - /// # Example - /// - /// ``` - /// use std::ops::Deref; - /// - /// use logger::{warn, LOGGER}; - /// - /// let l = LOGGER.deref(); - /// l.set_include_origin(false, false); - /// assert!(l.configure(Some("MY-INSTANCE".to_string())).is_ok()); - /// - /// warn!("A warning log message with log origin disabled"); - /// ``` - /// The code above will more or less print: - /// ```bash - /// 2018-11-07T05:34:25.180751152 [MY-INSTANCE:WARN] A warning log message with log origin - /// disabled - /// ``` - pub fn set_include_origin(&self, file_path: bool, line_numbers: bool) -> &Self { - self.show_file_path.store(file_path, Ordering::Relaxed); - // If the file path is not shown, do not show line numbers either. - self.show_line_numbers - .store(file_path && line_numbers, Ordering::Relaxed); - self - } - - /// Sets the ID for this logger session. - pub fn set_instance_id(&self, instance_id: String) -> &Self { - let mut guard = extract_guard(self.instance_id.write()); - *guard = instance_id; - self - } - - /// Explicitly sets the max log level for the Logger. - /// The default level is WARN. So, ERROR and WARN statements will be shown (i.e. all that is - /// bigger than the level code). - /// - /// # Arguments - /// - /// * `level` - Set the highest log level. - /// # Example - /// - /// ``` - /// use std::ops::Deref; - /// - /// use logger::{info, warn, LOGGER}; - /// - /// let l = LOGGER.deref(); - /// l.set_max_level(log::LevelFilter::Warn); - /// assert!(l.configure(Some("MY-INSTANCE".to_string())).is_ok()); - /// info!("An informational log message"); - /// warn!("A test warning message"); - /// ``` - /// The code above will more or less print: - /// ```bash - /// 2018-11-07T05:34:25.180751152 [MY-INSTANCE:INFO:logger/src/lib.rs:389] A test warning - /// message - /// ``` - pub fn set_max_level(&self, level: LevelFilter) -> &Self { - set_max_level(level); - self - } - - /// Get the current thread's name. - fn get_thread_name(&self) -> String { - thread::current().name().unwrap_or("-").to_string() - } - - /// Creates the first portion (to the left of the separator) - /// of the log statement based on the logger settings. - fn create_prefix(&self, record: &Record) -> String { - let mut prefix: Vec = vec![]; - - let instance_id = extract_guard(self.instance_id.read()); - if !instance_id.is_empty() { - prefix.push(instance_id.to_string()); - } - - // Attach current thread name to prefix. - prefix.push(self.get_thread_name()); - - if self.show_level() { - prefix.push(record.level().to_string()); - }; - - if self.show_file_path() { - prefix.push(record.file().unwrap_or("unknown").to_string()); - }; - - if self.show_line_numbers() { - if let Some(line) = record.line() { - prefix.push(line.to_string()); - } - } - - format!("[{}]", prefix.join(":")) - } - - /// if the max level hasn't been configured yet, set it to default - fn try_init_max_level(&self) { - // if the max level hasn't been configured yet, set it to default - if max_level() == LevelFilter::Off { - self.set_max_level(DEFAULT_MAX_LEVEL); - } - } - - /// Preconfigure the logger prior to initialization. - /// Performs the most basic steps in order to enable the logger to write to stdout or stderr - /// even before calling LOGGER.init(). Calling this method is optional. - /// This function can be called any number of times before the initialization. - /// Any calls made after the initialization will result in `Err()`. - /// - /// # Arguments - /// - /// * `instance_id` - Unique string identifying this logger session. This id is temporary and - /// will be overwritten upon initialization. - /// - /// # Example - /// - /// ``` - /// use std::ops::Deref; - /// - /// use logger::LOGGER; - /// - /// LOGGER - /// .deref() - /// .configure(Some("MY-INSTANCE".to_string())) - /// .unwrap(); - /// ``` - pub fn configure(&self, instance_id: Option) -> Result<()> { - self.init - .call_init(|| { - if let Some(some_instance_id) = instance_id { - self.set_instance_id(some_instance_id); - } - - self.try_init_max_level(); - - // don't finish the initialization - false - }) - .map_err(LoggerError::Init) - } - - /// Initialize log system (once and only once). - /// Every call made after the first will have no effect besides returning `Ok` or `Err`. - /// - /// # Arguments - /// - /// * `header` - Info about the app that uses the logger. - /// * `log_dest` - Buffer for plain text logs. Needs to implements `Write` and `Send`. - /// - /// # Example - /// - /// ``` - /// use std::io::Cursor; - /// - /// use logger::LOGGER; - /// - /// let mut logs = Cursor::new(vec![0; 15]); - /// - /// LOGGER.init("Running Firecracker v.x".to_string(), Box::new(logs)); - /// ``` - pub fn init(&self, header: String, log_dest: Box) -> Result<()> { - self.init - .call_init(|| { - let mut g = extract_guard(self.log_buf.lock()); - *g = log_dest; - - self.try_init_max_level(); - - // finish init - true - }) - .map_err(LoggerError::Init)?; - - self.write_log(&header); - - Ok(()) - } - - /// Handles the common logic of writing regular log messages. - /// - /// Writes `msg` followed by a newline to the destination, flushing afterwards. - fn write_log(&self, msg: &str) { - let mut guard; - let mut writer: Box = if self.init.is_initialized() { - guard = extract_guard(self.log_buf.lock()); - Box::new(guard.as_mut()) - } else { - Box::new(stdout()) - }; - // Writes `msg` followed by newline and flushes, if either operation returns an error, - // increment missed log count. - // This approach is preferable over `Result::and` as if `write!` returns an error it then - // does not attempt to flush. - if writeln!(writer, "{msg}") - .and_then(|_| writer.flush()) - .is_err() - { - // No reason to log the error to stderr here, just increment the metric. - METRICS.logger.missed_log_count.inc(); - } - } -} - -/// Describes the errors which may occur while handling logging scenarios. -#[derive(Debug, thiserror::Error)] -pub enum LoggerError { - /// Initialization Error. - #[error("Logger initialization failure: {0}")] - Init(init::Error), -} - -/// Implements the "Log" trait from the externally used "log" crate. -impl Log for Logger { - fn enabled(&self, _metadata: &Metadata) -> bool { - // No filtering beyond what the log crate already does based on level. - true - } - - fn log(&self, record: &Record) { - let msg = format!( - "{} {} {}", - LocalTime::now(), - self.create_prefix(record), - record.args() - ); - self.write_log(&msg); - } - - // This is currently not used. - fn flush(&self) { - unreachable!(); - } -} - -#[cfg(test)] -mod tests { - use std::fs::{create_dir, read_to_string, remove_dir, remove_file, OpenOptions}; - use std::io::{BufWriter, Read, Write}; - use std::sync::Arc; - - use log::{info, Level}; - - use super::*; - - const TEST_INSTANCE_ID: &str = "TEST-INSTANCE-ID"; - const TEST_APP_HEADER: &str = "App header"; - - const LOG_SOURCE: &str = "logger.rs"; - const LOG_LINE: u32 = 0; - - struct LogWriter { - buf: Arc>>, - } - - impl Write for LogWriter { - fn write(&mut self, buf: &[u8]) -> std::io::Result { - let mut data = self.buf.lock().unwrap(); - data.append(&mut buf.to_vec()); - - Ok(buf.len()) - } - - fn flush(&mut self) -> std::io::Result<()> { - Ok(()) - } - } - - struct LogReader { - buf: Arc>>, - } - - impl Read for LogReader { - fn read(&mut self, buf: &mut [u8]) -> std::io::Result { - let mut data = self.buf.lock().unwrap(); - - let len = std::cmp::min(data.len(), buf.len()); - buf[..len].copy_from_slice(&data[..len]); - - data.drain(..len); - - Ok(len) - } - } - - fn log_channel() -> (LogWriter, LogReader) { - let buf = Arc::new(Mutex::new(vec![])); - (LogWriter { buf: buf.clone() }, LogReader { buf }) - } - - impl Logger { - fn mock_new() -> Logger { - let logger = Logger::new(); - logger.set_instance_id(TEST_INSTANCE_ID.to_string()); - - logger - } - - fn mock_log(&self, level: Level, msg: &str) { - self.log( - &log::Record::builder() - .level(level) - .args(format_args!("{}", msg)) - .file(Some(LOG_SOURCE)) - .line(Some(LOG_LINE)) - .build(), - ); - } - - fn mock_init(&self) -> LogReader { - let (writer, mut reader) = log_channel(); - assert!(self - .init(TEST_APP_HEADER.to_string(), Box::new(writer)) - .is_ok()); - validate_log( - &mut Box::new(&mut reader), - &format!("{}\n", TEST_APP_HEADER), - ); - - reader - } - } - - fn validate_log(log_reader: &mut dyn Read, expected: &str) { - let mut log = Vec::new(); - log_reader.read_to_end(&mut log).unwrap(); - - assert!(log.len() >= expected.len()); - assert_eq!( - expected, - std::str::from_utf8(&log[log.len() - expected.len()..]).unwrap() - ); - } - - #[test] - fn test_default_values() { - let l = Logger::new(); - assert!(l.show_line_numbers()); - assert!(l.show_level()); - } - - #[test] - fn test_write_log() { - // Data to log to file for test. - const TEST_HEADER: &str = "test_log"; - const TEST_STR: &str = "testing flushing"; - // File to use for test. - const TEST_DIR: &str = "./tmp"; - const TEST_FILE: &str = "test.txt"; - let test_path = format!("{}/{}", TEST_DIR, TEST_FILE); - - // Creates ./tmp directory - create_dir(TEST_DIR).unwrap(); - // A buffered writer to a file - let file = OpenOptions::new() - .create(true) - .write(true) - .truncate(true) - .open(&test_path) - .unwrap(); - let writer = Box::new(BufWriter::new(file)); - // Create a logger with this buffered writer as the `dest`. - let logger = Logger::new(); - logger.init(String::from(TEST_HEADER), writer).unwrap(); - // Log some generic data - logger.write_log(TEST_STR); - // To drop the logger without calling its destructor, or to `forget` it - // (https://doc.rust-lang.org/stable/std/mem/fn.forget.html) will lead - // to a memory leak, so for this test I do not do this. - // As such this test simply illustrates the `write_log` function will - // always flush such that in the occurrence of the crash the expected - // behavior that all temporally distant logs from a crash are flushed. - - // Read from the log file. - let file_contents = read_to_string(&test_path).unwrap(); - // Asserts the contents of the log file are as expected. - assert_eq!(file_contents, format!("{}\n{}\n", TEST_HEADER, TEST_STR)); - // Removes the log file. - remove_file(&test_path).unwrap(); - // Removes /tmp directory - remove_dir(TEST_DIR).unwrap(); - } - - #[test] - fn test_configure() { - let logger = Logger::new(); - let crnt_thread_name = logger.get_thread_name(); - - // Assert that `configure()` can be called successfully any number of times. - assert!(logger.configure(Some(TEST_INSTANCE_ID.to_string())).is_ok()); - assert!(logger.configure(None).is_ok()); - assert!(logger.configure(Some(TEST_INSTANCE_ID.to_string())).is_ok()); - - // Assert that `init()` works after `configure()` - let (writer, mut reader) = log_channel(); - assert!(logger - .init(TEST_APP_HEADER.to_string(), Box::new(writer)) - .is_ok()); - validate_log( - &mut Box::new(&mut reader), - &format!("{}\n", TEST_APP_HEADER), - ); - // Check that the logs are written to the configured writer. - logger.mock_log(Level::Info, "info"); - validate_log( - &mut Box::new(&mut reader), - &format!( - "[TEST-INSTANCE-ID:{}:INFO:logger.rs:0] info\n", - crnt_thread_name - ), - ); - } - - #[test] - fn test_init() { - let logger = Logger::new(); - let crnt_thread_name = logger.get_thread_name(); - // Assert that the first call to `init()` is successful. - let (writer, mut reader) = log_channel(); - logger.set_instance_id(TEST_INSTANCE_ID.to_string()); - assert!(logger - .init(TEST_APP_HEADER.to_string(), Box::new(writer)) - .is_ok()); - validate_log( - &mut Box::new(&mut reader), - &format!("{}\n", TEST_APP_HEADER), - ); - // Check that the logs are written to the configured writer. - logger.mock_log(Level::Info, "info"); - validate_log( - &mut Box::new(&mut reader), - &format!( - "[TEST-INSTANCE-ID:{}:INFO:logger.rs:0] info\n", - crnt_thread_name - ), - ); - - // Assert that initialization works only once. - let (writer_2, mut reader_2) = log_channel(); - assert!(logger - .init(TEST_APP_HEADER.to_string(), Box::new(writer_2)) - .is_err()); - // Check that the logs are written only to the first writer. - logger.mock_log(Level::Info, "info"); - validate_log( - &mut Box::new(&mut reader), - &format!( - "[TEST-INSTANCE-ID:{}:INFO:logger.rs:0] info\n", - crnt_thread_name - ), - ); - validate_log(&mut Box::new(&mut reader_2), ""); - } - - #[test] - fn test_create_prefix() { - let logger = Logger::mock_new(); - let mut reader = logger.mock_init(); - let crnt_thread_name = logger.get_thread_name(); - // Test with empty instance id. - logger.set_instance_id("".to_string()); - - // Check that the prefix is empty when `show_level` and `show_origin` are false. - logger - .set_include_level(false) - .set_include_origin(false, true); - logger.mock_log(Level::Info, "msg"); - validate_log( - &mut Box::new(&mut reader), - &format!("[{}] msg\n", crnt_thread_name), - ); - - // Check that the prefix is correctly shown when all flags are true. - logger - .set_include_level(true) - .set_include_origin(true, true); - logger.mock_log(Level::Info, "msg"); - validate_log( - &mut Box::new(&mut reader), - &format!("[{}:INFO:logger.rs:0] msg\n", crnt_thread_name), - ); - - // Check show_line_numbers=false. - logger - .set_include_level(true) - .set_include_origin(true, false); - logger.mock_log(Level::Debug, "msg"); - validate_log( - &mut Box::new(&mut reader), - &format!("[{}:DEBUG:logger.rs] msg\n", crnt_thread_name), - ); - - // Check show_file_path=false. - logger - .set_include_level(true) - .set_include_origin(false, true); - logger.mock_log(Level::Error, "msg"); - validate_log( - &mut Box::new(&mut reader), - &format!("[{}:ERROR] msg\n", crnt_thread_name), - ); - - // Check show_level=false. - logger - .set_include_level(false) - .set_include_origin(true, true); - logger.mock_log(Level::Info, "msg"); - validate_log( - &mut Box::new(&mut reader), - &format!("[{}:logger.rs:0] msg\n", crnt_thread_name), - ); - - // Test with a mock instance id. - logger.set_instance_id(TEST_INSTANCE_ID.to_string()); - - // Check that the prefix contains only the instance id when all flags are false. - logger - .set_include_level(false) - .set_include_origin(false, false); - logger.mock_log(Level::Info, "msg"); - validate_log( - &mut Box::new(&mut reader), - &format!("[TEST-INSTANCE-ID:{}] msg\n", crnt_thread_name), - ); - - // Check that the prefix is correctly shown when all flags are true. - logger - .set_include_level(true) - .set_include_origin(true, true); - logger.mock_log(Level::Warn, "msg"); - validate_log( - &mut Box::new(&mut reader), - &format!( - "[TEST-INSTANCE-ID:{}:WARN:logger.rs:0] msg\n", - crnt_thread_name - ), - ); - } - - #[test] - fn test_thread_name_custom() { - let custom_thread = thread::Builder::new() - .name("custom-thread".to_string()) - .spawn(move || { - let logger = Logger::mock_new(); - let mut reader = logger.mock_init(); - logger - .set_include_level(false) - .set_include_origin(false, false); - logger.set_instance_id("".to_string()); - logger.mock_log(Level::Info, "thread-msg"); - validate_log(&mut Box::new(&mut reader), "[custom-thread] thread-msg\n"); - }) - .unwrap(); - let r = custom_thread.join(); - assert!(r.is_ok()); - } - - #[test] - fn test_static_logger() { - log::set_max_level(log::LevelFilter::Info); - LOGGER.set_instance_id(TEST_INSTANCE_ID.to_string()); - - let mut reader = LOGGER.mock_init(); - - info!("info"); - validate_log(&mut Box::new(&mut reader), "info\n"); - } - - #[test] - fn test_error_messages() { - assert_eq!( - format!("{}", LoggerError::Init(init::Error::AlreadyInitialized)), - "Logger initialization failure: The component is already initialized." - ); - } -} diff --git a/src/logger/src/metrics.rs b/src/logger/src/metrics.rs index 0a3884935d5..60d0d08c641 100644 --- a/src/logger/src/metrics.rs +++ b/src/logger/src/metrics.rs @@ -67,13 +67,13 @@ use std::ops::Deref; use std::sync::atomic::{AtomicUsize, Ordering}; use std::sync::{Mutex, OnceLock}; -#[cfg(target_arch = "aarch64")] -use log::warn; use serde::{Serialize, Serializer}; #[cfg(target_arch = "aarch64")] use vm_superio::rtc_pl031::RtcEvents; use super::FcLineWriter; +#[cfg(target_arch = "aarch64")] +use crate::warn; /// Static instance used for handling metrics. pub static METRICS: Metrics = diff --git a/src/mmds/Cargo.toml b/src/mmds/Cargo.toml index 1ba82482356..02896e6b227 100644 --- a/src/mmds/Cargo.toml +++ b/src/mmds/Cargo.toml @@ -23,4 +23,5 @@ dumbo = { path = "../dumbo" } logger = { path = "../logger" } micro_http = { git = "https://github.com/firecracker-microvm/micro-http", rev = "4b18a04" } snapshot = { path = "../snapshot" } -utils = { path = "../utils" } \ No newline at end of file +utils = { path = "../utils" } +tracing = { version = "0.1.37", default-features = false } \ No newline at end of file diff --git a/src/rebase-snap/Cargo.toml b/src/rebase-snap/Cargo.toml index f4f1032820d..9f5c1beefe3 100644 --- a/src/rebase-snap/Cargo.toml +++ b/src/rebase-snap/Cargo.toml @@ -13,5 +13,6 @@ bench = false [dependencies] libc = "0.2.147" thiserror = "1.0.40" +tracing = { version = "0.1.37", default-features = false } utils = { path = "../utils" } diff --git a/src/seccompiler/Cargo.toml b/src/seccompiler/Cargo.toml index 9f9a76b639e..bd1b9f9797e 100644 --- a/src/seccompiler/Cargo.toml +++ b/src/seccompiler/Cargo.toml @@ -22,5 +22,6 @@ libc = "0.2.147" serde = { version = "1.0.183", features = ["derive"] } serde_json = "1.0.104" thiserror = "1.0.44" +tracing = { version = "0.1.37", default-features = false } utils = { path = "../utils" } diff --git a/src/snapshot/Cargo.toml b/src/snapshot/Cargo.toml index 058efa139d8..cf57515f170 100644 --- a/src/snapshot/Cargo.toml +++ b/src/snapshot/Cargo.toml @@ -14,6 +14,7 @@ libc = "0.2.117" versionize = "0.1.10" versionize_derive = "0.1.5" thiserror = "1.0.32" +tracing = { version = "0.1.37", default-features = false } [dev-dependencies] criterion = { version = "0.5.0", default-features = false } diff --git a/src/utils/Cargo.toml b/src/utils/Cargo.toml index 8730af0ab49..0730ef97a54 100644 --- a/src/utils/Cargo.toml +++ b/src/utils/Cargo.toml @@ -17,6 +17,7 @@ versionize = "0.1.10" versionize_derive = "0.1.5" vmm-sys-util = "0.11.0" vm-memory = { version = "0.11.0", features = ["backend-mmap", "backend-bitmap"] } +tracing = { version = "0.1.37", default-features = false } net_gen = { path = "../net_gen" } diff --git a/src/vmm/Cargo.toml b/src/vmm/Cargo.toml index 11601b4914f..8a159cb11d0 100644 --- a/src/vmm/Cargo.toml +++ b/src/vmm/Cargo.toml @@ -29,6 +29,8 @@ versionize_derive = "0.1.5" vm-allocator = "0.1.0" vm-fdt = "0.2.0" vm-superio = "0.7.0" +tracing = { version = "0.1.37", default-features = false } +tracing-subscriber = { version = "0.3.17", default-features = false, features = ["fmt"] } log = { version = "0.4.17", features = ["serde"] } dumbo = { path = "../dumbo" } diff --git a/src/vmm/src/arch/aarch64/cache_info.rs b/src/vmm/src/arch/aarch64/cache_info.rs index 8d61b63a8d3..7faa98a4797 100644 --- a/src/vmm/src/arch/aarch64/cache_info.rs +++ b/src/vmm/src/arch/aarch64/cache_info.rs @@ -4,7 +4,7 @@ use std::path::{Path, PathBuf}; use std::{fs, io}; -use log::warn; +use logger::warn; // Based on https://elixir.free-electrons.com/linux/v4.9.62/source/arch/arm64/kernel/cacheinfo.c#L29. const MAX_CACHE_LEVEL: u8 = 7; diff --git a/src/vmm/src/builder.rs b/src/vmm/src/builder.rs index 5e63d95e004..ffe650b6e69 100644 --- a/src/vmm/src/builder.rs +++ b/src/vmm/src/builder.rs @@ -17,7 +17,7 @@ use linux_loader::loader::elf::Elf as Loader; #[cfg(target_arch = "aarch64")] use linux_loader::loader::pe::PE as Loader; use linux_loader::loader::KernelLoader; -use log::error; +use logger::error; use seccompiler::BpfThreadMap; use snapshot::Persist; use userfaultfd::Uffd; diff --git a/src/vmm/src/device_manager/mmio.rs b/src/vmm/src/device_manager/mmio.rs index 87a6811e098..f5700139011 100644 --- a/src/vmm/src/device_manager/mmio.rs +++ b/src/vmm/src/device_manager/mmio.rs @@ -11,7 +11,7 @@ use std::sync::{Arc, Mutex}; use kvm_ioctls::{IoEventAddress, VmFd}; use linux_loader::cmdline as kernel_cmdline; -use log::info; +use logger::info; #[cfg(target_arch = "x86_64")] use utils::vm_memory::GuestAddress; use versionize::{VersionMap, Versionize, VersionizeResult}; diff --git a/src/vmm/src/device_manager/persist.rs b/src/vmm/src/device_manager/persist.rs index 42564ffaa82..79da37f2052 100644 --- a/src/vmm/src/device_manager/persist.rs +++ b/src/vmm/src/device_manager/persist.rs @@ -8,7 +8,7 @@ use std::sync::{Arc, Mutex}; use event_manager::{MutEventSubscriber, SubscriberOps}; use kvm_ioctls::VmFd; -use log::{error, warn}; +use logger::{error, warn}; use mmds::data_store::MmdsVersion; use snapshot::Persist; use utils::vm_memory::GuestMemoryMmap; diff --git a/src/vmm/src/devices/legacy/i8042.rs b/src/vmm/src/devices/legacy/i8042.rs index 2524386ef0e..249827d9f1f 100644 --- a/src/vmm/src/devices/legacy/i8042.rs +++ b/src/vmm/src/devices/legacy/i8042.rs @@ -8,8 +8,7 @@ use std::io; use std::num::Wrapping; -use log::warn; -use logger::{IncMetric, METRICS}; +use logger::{warn, IncMetric, METRICS}; use utils::eventfd::EventFd; /// Errors thrown by the i8042 device. @@ -228,7 +227,7 @@ impl I8042Device { // our exit event fd. Meaning Firecracker will be exiting as soon as the VMM // thread wakes up to handle this event. if let Err(err) = self.reset_evt.write(1) { - log::error!("Failed to trigger i8042 reset event: {:?}", err); + logger::error!("Failed to trigger i8042 reset event: {:?}", err); METRICS.i8042.error_count.inc(); } METRICS.i8042.reset_count.inc(); diff --git a/src/vmm/src/devices/legacy/serial.rs b/src/vmm/src/devices/legacy/serial.rs index ff67817093d..14f0225f07d 100644 --- a/src/vmm/src/devices/legacy/serial.rs +++ b/src/vmm/src/devices/legacy/serial.rs @@ -12,8 +12,7 @@ use std::io::{Read, Write}; use std::os::unix::io::{AsRawFd, RawFd}; use event_manager::{EventOps, Events, MutEventSubscriber}; -use log::{error, warn}; -use logger::{IncMetric, METRICS}; +use logger::{error, warn, IncMetric, METRICS}; use utils::epoll::EventSet; use vm_superio::serial::{Error as SerialError, SerialEvents}; use vm_superio::{Serial, Trigger}; diff --git a/src/vmm/src/devices/mod.rs b/src/vmm/src/devices/mod.rs index b4e46743db7..5ce07e678f0 100644 --- a/src/vmm/src/devices/mod.rs +++ b/src/vmm/src/devices/mod.rs @@ -15,8 +15,7 @@ pub mod pseudo; pub mod virtio; pub use bus::{Bus, BusDevice, BusError}; -use log::error; -use logger::{IncMetric, METRICS}; +use logger::{error, IncMetric, METRICS}; use crate::devices::virtio::{QueueError, VsockError}; diff --git a/src/vmm/src/devices/pseudo/boot_timer.rs b/src/vmm/src/devices/pseudo/boot_timer.rs index 2551483ea53..9a599cd2939 100644 --- a/src/vmm/src/devices/pseudo/boot_timer.rs +++ b/src/vmm/src/devices/pseudo/boot_timer.rs @@ -23,7 +23,7 @@ impl BootTimer { let boot_time_us = now_tm_us.time_us - self.start_ts.time_us; let boot_time_cpu_us = now_tm_us.cputime_us - self.start_ts.cputime_us; - log::info!( + logger::info!( "Guest-boot-time = {:>6} us {} ms, {:>6} CPU us {} CPU ms", boot_time_us, boot_time_us / 1000, diff --git a/src/vmm/src/devices/virtio/balloon/device.rs b/src/vmm/src/devices/virtio/balloon/device.rs index 727c11d0e7a..0a8f8a56b1b 100644 --- a/src/vmm/src/devices/virtio/balloon/device.rs +++ b/src/vmm/src/devices/virtio/balloon/device.rs @@ -7,8 +7,7 @@ use std::sync::Arc; use std::time::Duration; use std::{cmp, fmt}; -use log::error; -use logger::{IncMetric, METRICS}; +use logger::{error, IncMetric, METRICS}; use serde::Serialize; use timerfd::{ClockId, SetTimeFlags, TimerFd, TimerState}; use utils::eventfd::EventFd; diff --git a/src/vmm/src/devices/virtio/balloon/event_handler.rs b/src/vmm/src/devices/virtio/balloon/event_handler.rs index 869cf0eb657..595071df2fd 100644 --- a/src/vmm/src/devices/virtio/balloon/event_handler.rs +++ b/src/vmm/src/devices/virtio/balloon/event_handler.rs @@ -4,7 +4,7 @@ use std::os::unix::io::AsRawFd; use event_manager::{EventOps, Events, MutEventSubscriber}; -use log::{error, warn}; +use logger::{error, warn}; use utils::epoll::EventSet; use crate::devices::report_balloon_event_fail; @@ -36,7 +36,7 @@ impl Balloon { } fn process_activate_event(&self, ops: &mut EventOps) { - log::debug!("balloon: activate event"); + logger::debug!("balloon: activate event"); if let Err(err) = self.activate_evt.read() { error!("Failed to consume balloon activate event: {:?}", err); } diff --git a/src/vmm/src/devices/virtio/balloon/util.rs b/src/vmm/src/devices/virtio/balloon/util.rs index 490c9960af8..b8bdd74109e 100644 --- a/src/vmm/src/devices/virtio/balloon/util.rs +++ b/src/vmm/src/devices/virtio/balloon/util.rs @@ -35,7 +35,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] { - log::error!("Skipping duplicate PFN {}.", page_frame_number); + logger::error!("Skipping duplicate PFN {}.", page_frame_number); continue; } diff --git a/src/vmm/src/devices/virtio/block/event_handler.rs b/src/vmm/src/devices/virtio/block/event_handler.rs index a766471bf9f..400e3e79dcb 100644 --- a/src/vmm/src/devices/virtio/block/event_handler.rs +++ b/src/vmm/src/devices/virtio/block/event_handler.rs @@ -3,7 +3,7 @@ use std::os::unix::io::AsRawFd; use event_manager::{EventOps, Events, MutEventSubscriber}; -use log::{error, warn}; +use logger::{error, warn}; use utils::epoll::EventSet; use super::io::FileEngine; @@ -32,7 +32,7 @@ impl Block { } fn process_activate_event(&self, ops: &mut EventOps) { - log::debug!("block: activate event"); + logger::debug!("block: activate event"); if let Err(err) = self.activate_evt.read() { error!("Failed to consume block activate event: {:?}", err); } diff --git a/src/vmm/src/devices/virtio/device.rs b/src/vmm/src/devices/virtio/device.rs index 2b68df2530f..c5264ee970e 100644 --- a/src/vmm/src/devices/virtio/device.rs +++ b/src/vmm/src/devices/virtio/device.rs @@ -9,7 +9,7 @@ use std::fmt; use std::sync::atomic::{AtomicUsize, Ordering}; use std::sync::Arc; -use log::warn; +use logger::warn; use utils::eventfd::EventFd; use utils::vm_memory::GuestMemoryMmap; @@ -74,7 +74,7 @@ impl IrqTrigger { self.irq_status.fetch_or(irq as usize, Ordering::SeqCst); self.irq_evt.write(1).map_err(|err| { - log::error!("Failed to send irq to the guest: {:?}", err); + logger::error!("Failed to send irq to the guest: {:?}", err); err })?; diff --git a/src/vmm/src/devices/virtio/mmio.rs b/src/vmm/src/devices/virtio/mmio.rs index b7632f88a1f..b0b68981ee8 100644 --- a/src/vmm/src/devices/virtio/mmio.rs +++ b/src/vmm/src/devices/virtio/mmio.rs @@ -9,7 +9,7 @@ use std::fmt::Debug; use std::sync::atomic::{AtomicUsize, Ordering}; use std::sync::{Arc, Mutex, MutexGuard}; -use log::warn; +use logger::warn; use utils::byte_order; use utils::vm_memory::{GuestAddress, GuestMemoryMmap}; diff --git a/src/vmm/src/devices/virtio/net/device.rs b/src/vmm/src/devices/virtio/net/device.rs index 22abe4dd80b..9e4afbc543e 100755 --- a/src/vmm/src/devices/virtio/net/device.rs +++ b/src/vmm/src/devices/virtio/net/device.rs @@ -14,8 +14,7 @@ use std::{cmp, mem}; use dumbo::pdu::arp::ETH_IPV4_FRAME_LEN; use dumbo::pdu::ethernet::{EthernetFrame, PAYLOAD_OFFSET}; use libc::EAGAIN; -use log::{error, warn}; -use logger::{IncMetric, METRICS}; +use logger::{error, warn, IncMetric, METRICS}; use mmds::data_store::Mmds; use mmds::ns::MmdsNetworkStack; use utils::eventfd::EventFd; diff --git a/src/vmm/src/devices/virtio/net/event_handler.rs b/src/vmm/src/devices/virtio/net/event_handler.rs index b5ed3dfa7b7..24428526b88 100644 --- a/src/vmm/src/devices/virtio/net/event_handler.rs +++ b/src/vmm/src/devices/virtio/net/event_handler.rs @@ -4,8 +4,7 @@ use std::os::unix::io::AsRawFd; use event_manager::{EventOps, Events, MutEventSubscriber}; -use log::{error, warn}; -use logger::{IncMetric, METRICS}; +use logger::{error, warn, IncMetric, METRICS}; use utils::epoll::EventSet; use crate::devices::virtio::net::device::Net; @@ -40,7 +39,7 @@ impl Net { } fn process_activate_event(&self, ops: &mut EventOps) { - log::debug!("net: activate event"); + logger::debug!("net: activate event"); if let Err(err) = self.activate_evt.read() { error!("Failed to consume net activate event: {:?}", err); } diff --git a/src/vmm/src/devices/virtio/net/persist.rs b/src/vmm/src/devices/virtio/net/persist.rs index 8fd4c14d322..9f39404b84c 100644 --- a/src/vmm/src/devices/virtio/net/persist.rs +++ b/src/vmm/src/devices/virtio/net/persist.rs @@ -7,7 +7,7 @@ use std::io; use std::sync::atomic::AtomicUsize; use std::sync::{Arc, Mutex}; -use log::warn; +use logger::warn; use mmds::data_store::Mmds; use mmds::ns::MmdsNetworkStack; use mmds::persist::MmdsNetworkStackState; diff --git a/src/vmm/src/devices/virtio/queue.rs b/src/vmm/src/devices/virtio/queue.rs index 0f45ec41dd5..d6ae64fc178 100644 --- a/src/vmm/src/devices/virtio/queue.rs +++ b/src/vmm/src/devices/virtio/queue.rs @@ -9,7 +9,7 @@ use std::cmp::min; use std::num::Wrapping; use std::sync::atomic::{fence, Ordering}; -use log::error; +use logger::error; use utils::vm_memory::{ Address, ByteValued, Bytes, GuestAddress, GuestMemory, GuestMemoryError, GuestMemoryMmap, }; diff --git a/src/vmm/src/devices/virtio/rng/event_handler.rs b/src/vmm/src/devices/virtio/rng/event_handler.rs index 1186901c136..ddcc2f7409e 100644 --- a/src/vmm/src/devices/virtio/rng/event_handler.rs +++ b/src/vmm/src/devices/virtio/rng/event_handler.rs @@ -4,7 +4,7 @@ use std::os::unix::io::AsRawFd; use event_manager::{EventOps, Events, MutEventSubscriber}; -use log::{error, warn}; +use logger::{error, warn}; use utils::epoll::EventSet; use super::{Entropy, RNG_QUEUE}; diff --git a/src/vmm/src/devices/virtio/vsock/csm/connection.rs b/src/vmm/src/devices/virtio/vsock/csm/connection.rs index 2eb056aa06f..d60759a7440 100644 --- a/src/vmm/src/devices/virtio/vsock/csm/connection.rs +++ b/src/vmm/src/devices/virtio/vsock/csm/connection.rs @@ -84,8 +84,7 @@ use std::num::Wrapping; use std::os::unix::io::{AsRawFd, RawFd}; use std::time::{Duration, Instant}; -use log::{debug, error, info, warn}; -use logger::{IncMetric, METRICS}; +use logger::{debug, error, info, warn, IncMetric, METRICS}; use utils::epoll::EventSet; use utils::vm_memory::{GuestMemoryError, GuestMemoryMmap, ReadVolatile, WriteVolatile}; diff --git a/src/vmm/src/devices/virtio/vsock/device.rs b/src/vmm/src/devices/virtio/vsock/device.rs index 8ca98d92644..bdcc49dfe11 100644 --- a/src/vmm/src/devices/virtio/vsock/device.rs +++ b/src/vmm/src/devices/virtio/vsock/device.rs @@ -23,8 +23,7 @@ use std::fmt::Debug; use std::sync::atomic::AtomicUsize; use std::sync::Arc; -use log::{debug, error, warn}; -use logger::{IncMetric, METRICS}; +use logger::{debug, error, warn, IncMetric, METRICS}; use utils::byte_order; use utils::eventfd::EventFd; use utils::vm_memory::{Bytes, GuestMemoryMmap}; diff --git a/src/vmm/src/devices/virtio/vsock/event_handler.rs b/src/vmm/src/devices/virtio/vsock/event_handler.rs index b2e539ee101..abedf223abf 100755 --- a/src/vmm/src/devices/virtio/vsock/event_handler.rs +++ b/src/vmm/src/devices/virtio/vsock/event_handler.rs @@ -28,8 +28,7 @@ use std::fmt::Debug; use std::os::unix::io::AsRawFd; use event_manager::{EventOps, Events, MutEventSubscriber}; -use log::{debug, error, warn}; -use logger::{IncMetric, METRICS}; +use logger::{debug, error, warn, IncMetric, METRICS}; use utils::epoll::EventSet; use super::device::{Vsock, EVQ_INDEX, RXQ_INDEX, TXQ_INDEX}; diff --git a/src/vmm/src/devices/virtio/vsock/unix/muxer.rs b/src/vmm/src/devices/virtio/vsock/unix/muxer.rs index 005df93a7f0..1699aa7a897 100644 --- a/src/vmm/src/devices/virtio/vsock/unix/muxer.rs +++ b/src/vmm/src/devices/virtio/vsock/unix/muxer.rs @@ -36,8 +36,7 @@ use std::io::Read; use std::os::unix::io::{AsRawFd, RawFd}; use std::os::unix::net::{UnixListener, UnixStream}; -use log::{debug, error, info, warn}; -use logger::{IncMetric, METRICS}; +use logger::{debug, error, info, warn, IncMetric, METRICS}; use utils::epoll::{ControlOperation, Epoll, EpollEvent, EventSet}; use utils::vm_memory::GuestMemoryMmap; diff --git a/src/vmm/src/persist.rs b/src/vmm/src/persist.rs index 6763874c0c1..6048992aba9 100644 --- a/src/vmm/src/persist.rs +++ b/src/vmm/src/persist.rs @@ -11,7 +11,7 @@ use std::os::unix::net::UnixStream; use std::path::Path; use std::sync::{Arc, Mutex}; -use log::{error, info, warn}; +use logger::{error, info, warn}; use seccompiler::BpfThreadMap; use semver::Version; use serde::Serialize; diff --git a/src/vmm/src/resources.rs b/src/vmm/src/resources.rs index 0cede36b6a2..4f1fe248270 100644 --- a/src/vmm/src/resources.rs +++ b/src/vmm/src/resources.rs @@ -19,7 +19,7 @@ use crate::vmm_config::boot_source::{ use crate::vmm_config::drive::*; use crate::vmm_config::entropy::*; use crate::vmm_config::instance_info::InstanceInfo; -use crate::vmm_config::logger::{init_logger, LoggerConfig, LoggerConfigError}; +use crate::vmm_config::logger::{InitLoggerError, LoggerConfig}; use crate::vmm_config::machine_config::{ MachineConfig, MachineConfigUpdate, VmConfig, VmConfigError, }; @@ -48,7 +48,7 @@ pub enum ResourcesError { InvalidJson(serde_json::Error), /// Logger configuration error. #[error("Logger error: {0}")] - Logger(LoggerConfigError), + Logger(InitLoggerError), /// Metrics system configuration error. #[error("Metrics error: {0}")] Metrics(MetricsConfigError), @@ -138,7 +138,7 @@ impl VmResources { let vmm_config = serde_json::from_str::(config_json)?; if let Some(logger) = vmm_config.logger { - init_logger(logger, instance_info)?; + logger.init()?; } if let Some(metrics) = vmm_config.metrics { @@ -184,7 +184,7 @@ impl VmResources { resources.locked_mmds_or_default().put_data( serde_json::from_str(data).expect("MMDS error: metadata provided not valid json"), )?; - log::info!("Successfully added metadata to mmds from file"); + logger::info!("Successfully added metadata to mmds from file"); } if let Some(mmds_config) = vmm_config.mmds_config { @@ -482,7 +482,6 @@ mod tests { use std::os::linux::fs::MetadataExt; use std::str::FromStr; - use logger::{LevelFilter, LOGGER}; use serde_json::{Map, Value}; use utils::net::mac::MacAddr; use utils::tempfile::TempFile; @@ -856,18 +855,15 @@ mod tests { rootfs_file.as_path().to_str().unwrap() ); - match VmResources::from_json( - json.as_str(), - &default_instance_info, - HTTP_MAX_PAYLOAD_SIZE, - None, - ) { - Err(ResourcesError::Logger(LoggerConfigError::InitializationFailure { .. })) => (), - _ => unreachable!(), - } - - // The previous call enables the logger. We need to disable it. - LOGGER.set_max_level(LevelFilter::Off); + assert!(matches!( + VmResources::from_json( + json.as_str(), + &default_instance_info, + HTTP_MAX_PAYLOAD_SIZE, + None, + ), + Err(ResourcesError::Logger(InitLoggerError::File(_))), + )); // Invalid path for metrics pipe. json = format!( diff --git a/src/vmm/src/rpc_interface.rs b/src/vmm/src/rpc_interface.rs index 255aa8242e8..3e72e509886 100644 --- a/src/vmm/src/rpc_interface.rs +++ b/src/vmm/src/rpc_interface.rs @@ -4,8 +4,7 @@ use std::fmt::{self, Debug}; use std::sync::{Arc, Mutex, MutexGuard}; -use log::{error, info, warn}; -use logger::*; +use logger::{error, info, warn, *}; use mmds::data_store::{self, Mmds}; use seccompiler::BpfThreadMap; use serde_json::Value; @@ -34,7 +33,7 @@ use crate::vmm_config::boot_source::{BootSourceConfig, BootSourceConfigError}; use crate::vmm_config::drive::{BlockDeviceConfig, BlockDeviceUpdateConfig, DriveError}; use crate::vmm_config::entropy::{EntropyDeviceConfig, EntropyDeviceError}; use crate::vmm_config::instance_info::InstanceInfo; -use crate::vmm_config::logger::{LoggerConfig, LoggerConfigError}; +use crate::vmm_config::logger::{LoggerConfig, LoggerHandles}; use crate::vmm_config::machine_config::{MachineConfig, MachineConfigUpdate, VmConfigError}; use crate::vmm_config::metrics::{MetricsConfig, MetricsConfigError}; use crate::vmm_config::mmds::{MmdsConfig, MmdsConfigError}; @@ -162,7 +161,7 @@ pub enum VmmActionError { LoadSnapshot(LoadSnapshotError), /// The action `ConfigureLogger` failed because of bad user input. #[error("{0}")] - Logger(LoggerConfigError), + Logger(crate::vmm_config::logger::UpdateLoggerError), /// One of the actions `GetVmConfiguration` or `UpdateVmConfiguration` failed because of bad /// input. #[error("{0}")] @@ -260,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,10 +271,12 @@ pub struct PrebootApiController<'a> { // Some PrebootApiRequest errors are irrecoverable and Firecracker // should cleanly teardown if they occur. fatal_error: Option, + /// Handles that allow re-configuring the logger. + 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) @@ -289,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() } @@ -314,13 +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, ) -> Self { Self { seccomp_filters, @@ -330,6 +334,7 @@ impl<'a> PrebootApiController<'a> { built_vmm: None, boot_path: false, fatal_error: None, + logger_handles, } } @@ -347,6 +352,7 @@ impl<'a> PrebootApiController<'a> { boot_timer_enabled: bool, mmds_size_limit: usize, metadata_json: Option<&str>, + logger_handles: LoggerHandles, ) -> Result<(VmResources, Arc>), FcExitCode> { let mut vm_resources = VmResources::default(); // Silence false clippy warning. Clippy suggests using @@ -379,6 +385,7 @@ impl<'a> PrebootApiController<'a> { instance_info, &mut vm_resources, event_manager, + logger_handles, ); // Configure and start microVM through successive API calls. @@ -424,11 +431,10 @@ impl<'a> PrebootApiController<'a> { match request { // Supported operations allowed pre-boot. ConfigureBootSource(config) => self.set_boot_source(config), - ConfigureLogger(logger_cfg) => { - vmm_config::logger::init_logger(logger_cfg, &self.instance_info) - .map(|()| VmmData::Empty) - .map_err(VmmActionError::Logger) - } + ConfigureLogger(logger_cfg) => logger_cfg + .update(&self.logger_handles) + .map(|()| VmmData::Empty) + .map_err(VmmActionError::Logger), ConfigureMetrics(metrics_cfg) => vmm_config::metrics::init_metrics(metrics_cfg) .map(|()| VmmData::Empty) .map_err(VmmActionError::Metrics), @@ -880,24 +886,17 @@ impl RuntimeApiController { #[cfg(test)] mod tests { use std::io; - use std::path::PathBuf; - use mmds::data_store::MmdsVersion; use seccompiler::BpfThreadMap; use super::*; - use crate::cpu_config::templates::test_utils::build_test_template; - use crate::cpu_config::templates::{CpuTemplateType, StaticCpuTemplate}; + use crate::cpu_config::templates::StaticCpuTemplate; use crate::devices::virtio::balloon::{BalloonConfig, BalloonError}; use crate::devices::virtio::rng::EntropyError; use crate::devices::virtio::VsockError; use crate::vmm_config::balloon::BalloonBuilder; - use crate::vmm_config::drive::{CacheType, FileEngineType}; - use crate::vmm_config::logger::LoggerLevel; use crate::vmm_config::machine_config::VmConfig; - use crate::vmm_config::snapshot::{MemBackendConfig, MemBackendType}; use crate::vmm_config::vsock::VsockBuilder; - use crate::HTTP_MAX_PAYLOAD_SIZE; impl PartialEq for VmmActionError { fn eq(&self, other: &VmmActionError) -> bool { @@ -1257,277 +1256,6 @@ mod tests { Ok(Arc::new(Mutex::new(MockVmm::default()))) } - fn default_preboot<'a>( - vm_resources: &'a mut VmResources, - event_manager: &'a mut EventManager, - seccomp_filters: &'a BpfThreadMap, - ) -> PrebootApiController<'a> { - let instance_info = InstanceInfo::default(); - PrebootApiController::new(seccomp_filters, instance_info, vm_resources, event_manager) - } - - fn check_preboot_request(request: VmmAction, check_success: F) - where - F: FnOnce(Result, &MockVmRes), - { - let mut vm_resources = MockVmRes::default(); - let mut evmgr = EventManager::new().unwrap(); - let seccomp_filters = BpfThreadMap::new(); - let mut preboot = default_preboot(&mut vm_resources, &mut evmgr, &seccomp_filters); - let res = preboot.handle_preboot_request(request); - check_success(res, &vm_resources); - } - - fn check_preboot_request_with_mmds( - request: VmmAction, - mmds: Arc>, - check_success: F, - ) where - F: FnOnce(Result, &MockVmRes), - { - let mut vm_resources = MockVmRes { - mmds: Some(mmds), - mmds_size_limit: HTTP_MAX_PAYLOAD_SIZE, - ..Default::default() - }; - let mut evmgr = EventManager::new().unwrap(); - let seccomp_filters = BpfThreadMap::new(); - let mut preboot = default_preboot(&mut vm_resources, &mut evmgr, &seccomp_filters); - let res = preboot.handle_preboot_request(request); - check_success(res, &vm_resources); - } - - // Forces error and validates error kind against expected. - fn check_preboot_request_err(request: VmmAction, expected_err: VmmActionError) { - let mut vm_resources = MockVmRes { - force_errors: true, - ..Default::default() - }; - let mut evmgr = EventManager::new().unwrap(); - let seccomp_filters = BpfThreadMap::new(); - let mut preboot = default_preboot(&mut vm_resources, &mut evmgr, &seccomp_filters); - let err = preboot.handle_preboot_request(request).unwrap_err(); - assert_eq!(err, expected_err); - } - - #[test] - fn test_preboot_config_boot_src() { - let req = VmmAction::ConfigureBootSource(BootSourceConfig::default()); - check_preboot_request(req, |result, vm_res| { - assert_eq!(result, Ok(VmmData::Empty)); - assert!(vm_res.boot_cfg_set) - }); - - let req = VmmAction::ConfigureBootSource(BootSourceConfig::default()); - check_preboot_request_err( - req, - VmmActionError::BootSource(BootSourceConfigError::InvalidKernelCommandLine( - String::new(), - )), - ); - } - - #[test] - fn test_preboot_get_vm_config() { - let req = VmmAction::GetVmMachineConfig; - let expected_cfg = MachineConfig::default(); - check_preboot_request(req, |result, _| { - assert_eq!(result, Ok(VmmData::MachineConfiguration(expected_cfg))) - }); - - let req = VmmAction::ConfigureBootSource(BootSourceConfig::default()); - check_preboot_request_err( - req, - VmmActionError::BootSource(BootSourceConfigError::InvalidKernelCommandLine( - String::new(), - )), - ); - } - - #[test] - fn test_preboot_get_balloon_config() { - let req = VmmAction::GetBalloonConfig; - let expected_cfg = BalloonDeviceConfig::default(); - check_preboot_request(req, |result, _| { - assert_eq!(result, Ok(VmmData::BalloonConfig(expected_cfg))) - }); - } - - #[test] - fn test_preboot_put_cpu_config() { - // Start testing - Provide VMM vCPU configuration in preparation for `InstanceStart` - let req = VmmAction::PutCpuConfiguration(build_test_template()); - check_preboot_request(req, |result, vm_res| { - assert_eq!(result, Ok(VmmData::Empty)); - assert_eq!( - vm_res.vm_config.cpu_template, - Some(CpuTemplateType::Custom(build_test_template())) - ); - }); - } - - #[test] - fn test_preboot_set_vm_config() { - let req = - VmmAction::UpdateVmConfiguration(MachineConfigUpdate::from(MachineConfig::default())); - let expected_cfg = MachineConfig::default(); - check_preboot_request(req, |result, vm_res| { - assert_eq!(result, Ok(VmmData::Empty)); - assert_eq!(MachineConfig::from(&vm_res.vm_config), expected_cfg); - }); - - let req = - VmmAction::UpdateVmConfiguration(MachineConfigUpdate::from(MachineConfig::default())); - check_preboot_request_err( - req, - VmmActionError::MachineConfig(VmConfigError::InvalidVcpuCount), - ); - } - - #[test] - fn test_preboot_set_balloon_dev() { - let req = VmmAction::SetBalloonDevice(BalloonDeviceConfig::default()); - check_preboot_request(req, |result, vm_res| { - assert_eq!(result, Ok(VmmData::Empty)); - assert!(vm_res.balloon_set) - }); - - let req = VmmAction::SetBalloonDevice(BalloonDeviceConfig::default()); - check_preboot_request_err( - req, - VmmActionError::BalloonConfig(BalloonConfigError::DeviceNotFound), - ); - } - - #[test] - fn test_preboot_insert_block_dev() { - let req = VmmAction::InsertBlockDevice(BlockDeviceConfig { - path_on_host: String::new(), - is_root_device: false, - partuuid: None, - cache_type: CacheType::Unsafe, - is_read_only: false, - drive_id: String::new(), - rate_limiter: None, - file_engine_type: FileEngineType::default(), - }); - check_preboot_request(req, |result, vm_res| { - assert_eq!(result, Ok(VmmData::Empty)); - assert!(vm_res.block_set) - }); - - let req = VmmAction::InsertBlockDevice(BlockDeviceConfig { - path_on_host: String::new(), - is_root_device: false, - partuuid: None, - cache_type: CacheType::Unsafe, - is_read_only: false, - drive_id: String::new(), - rate_limiter: None, - file_engine_type: FileEngineType::default(), - }); - check_preboot_request_err( - req, - VmmActionError::DriveConfig(DriveError::RootBlockDeviceAlreadyAdded), - ); - } - - #[test] - fn test_preboot_insert_net_dev() { - let req = VmmAction::InsertNetworkDevice(NetworkInterfaceConfig { - iface_id: String::new(), - host_dev_name: String::new(), - guest_mac: None, - rx_rate_limiter: None, - tx_rate_limiter: None, - }); - check_preboot_request(req, |result, vm_res| { - assert_eq!(result, Ok(VmmData::Empty)); - assert!(vm_res.net_set) - }); - - let req = VmmAction::InsertNetworkDevice(NetworkInterfaceConfig { - iface_id: String::new(), - host_dev_name: String::new(), - guest_mac: None, - rx_rate_limiter: None, - tx_rate_limiter: None, - }); - check_preboot_request_err( - req, - VmmActionError::NetworkConfig(NetworkInterfaceError::GuestMacAddressInUse( - String::new(), - )), - ); - } - - #[test] - fn test_preboot_set_vsock_dev() { - let req = VmmAction::SetVsockDevice(VsockDeviceConfig { - vsock_id: Some(String::new()), - guest_cid: 0, - uds_path: String::new(), - }); - check_preboot_request(req, |result, vm_res| { - assert_eq!(result, Ok(VmmData::Empty)); - assert!(vm_res.vsock_set) - }); - - let req = VmmAction::SetVsockDevice(VsockDeviceConfig { - vsock_id: Some(String::new()), - guest_cid: 0, - uds_path: String::new(), - }); - check_preboot_request_err( - req, - VmmActionError::VsockConfig(VsockConfigError::CreateVsockDevice( - VsockError::BufDescMissing, - )), - ); - } - - #[test] - fn test_preboot_set_entropy_device() { - let req = VmmAction::SetEntropyDevice(EntropyDeviceConfig::default()); - check_preboot_request(req, |result, vm_res| { - assert_eq!(result, Ok(VmmData::Empty)); - assert!(vm_res.entropy_set); - }); - } - - #[test] - fn test_preboot_set_mmds_config() { - let req = VmmAction::SetMmdsConfiguration(MmdsConfig { - ipv4_address: None, - version: MmdsVersion::V2, - network_interfaces: Vec::new(), - }); - check_preboot_request(req, |result, vm_res| { - assert_eq!(result, Ok(VmmData::Empty)); - assert_eq!( - vm_res.mmds.as_ref().unwrap().lock().unwrap().version(), - MmdsVersion::V2 - ); - }); - - let req = VmmAction::SetMmdsConfiguration(MmdsConfig { - ipv4_address: None, - version: MmdsVersion::default(), - network_interfaces: Vec::new(), - }); - check_preboot_request_err( - req, - VmmActionError::MmdsConfig(MmdsConfigError::InvalidIpv4Addr), - ); - } - - #[test] - fn test_preboot_get_mmds() { - check_preboot_request(VmmAction::GetMMDS, |result, _| { - assert_eq!(result, Ok(VmmData::MmdsValue(Value::Null))); - }); - } - #[test] fn test_runtime_get_mmds() { check_runtime_request(VmmAction::GetMMDS, |result, _| { @@ -1535,42 +1263,6 @@ mod tests { }); } - #[test] - fn test_preboot_put_mmds() { - let mmds = Arc::new(Mutex::new(Mmds::default())); - - check_preboot_request_with_mmds( - VmmAction::PutMMDS(Value::String("string".to_string())), - mmds.clone(), - |result, _| { - assert_eq!(result, Ok(VmmData::Empty)); - }, - ); - check_preboot_request_with_mmds(VmmAction::GetMMDS, mmds.clone(), |result, _| { - assert_eq!( - result, - Ok(VmmData::MmdsValue(Value::String("string".to_string()))) - ); - }); - - let filling = (0..51300).map(|_| "X").collect::(); - let data = "{\"key\": \"".to_string() + &filling + "\"}"; - - check_preboot_request_with_mmds( - VmmAction::PutMMDS(serde_json::from_str(&data).unwrap()), - mmds.clone(), - |result, _| { - assert!(matches!(result, Err(VmmActionError::MmdsLimitExceeded(_)))); - }, - ); - check_preboot_request_with_mmds(VmmAction::GetMMDS, mmds, |result, _| { - assert_eq!( - result, - Ok(VmmData::MmdsValue(Value::String("string".to_string()))) - ); - }); - } - #[test] fn test_runtime_put_mmds() { let mmds = Arc::new(Mutex::new(Mmds::default())); @@ -1607,236 +1299,6 @@ mod tests { }); } - #[test] - fn test_preboot_patch_mmds() { - let mmds = Arc::new(Mutex::new(Mmds::default())); - // MMDS data store is not yet initialized. - check_preboot_request_err( - VmmAction::PatchMMDS(Value::String("string".to_string())), - VmmActionError::Mmds(data_store::Error::NotInitialized), - ); - - check_preboot_request_with_mmds( - VmmAction::PutMMDS( - serde_json::from_str(r#"{"key1": "value1", "key2": "val2"}"#).unwrap(), - ), - mmds.clone(), - |result, _| { - assert_eq!(result, Ok(VmmData::Empty)); - }, - ); - check_preboot_request_with_mmds(VmmAction::GetMMDS, mmds.clone(), |result, _| { - assert_eq!( - result, - Ok(VmmData::MmdsValue( - serde_json::from_str(r#"{"key1": "value1", "key2": "val2"}"#).unwrap() - )) - ); - }); - - check_preboot_request_with_mmds( - VmmAction::PatchMMDS( - serde_json::from_str(r#"{"key1": null, "key2": "value2"}"#).unwrap(), - ), - mmds.clone(), - |result, _| { - assert_eq!(result, Ok(VmmData::Empty)); - }, - ); - - check_preboot_request_with_mmds(VmmAction::GetMMDS, mmds.clone(), |result, _| { - assert_eq!( - result, - Ok(VmmData::MmdsValue( - serde_json::from_str(r#"{"key2": "value2"}"#).unwrap() - )) - ); - }); - - let filling = (0..HTTP_MAX_PAYLOAD_SIZE).map(|_| "X").collect::(); - let data = "{\"key\": \"".to_string() + &filling + "\"}"; - - check_preboot_request_with_mmds( - VmmAction::PatchMMDS(serde_json::from_str(&data).unwrap()), - mmds.clone(), - |result, _| { - assert!(matches!(result, Err(VmmActionError::MmdsLimitExceeded(_)))); - }, - ); - check_preboot_request_with_mmds(VmmAction::GetMMDS, mmds, |result, _| { - assert_eq!( - result, - Ok(VmmData::MmdsValue( - serde_json::from_str(r#"{"key2": "value2"}"#).unwrap() - )) - ); - }); - } - - #[test] - fn test_runtime_patch_mmds() { - let mmds = Arc::new(Mutex::new(Mmds::default())); - // MMDS data store is not yet initialized. - check_runtime_request_err( - VmmAction::PatchMMDS(Value::String("string".to_string())), - VmmActionError::Mmds(data_store::Error::NotInitialized), - ); - - check_runtime_request_with_mmds( - VmmAction::PutMMDS( - serde_json::from_str(r#"{"key1": "value1", "key2": "val2"}"#).unwrap(), - ), - mmds.clone(), - |result, _| { - assert_eq!(result, Ok(VmmData::Empty)); - }, - ); - check_runtime_request_with_mmds(VmmAction::GetMMDS, mmds.clone(), |result, _| { - assert_eq!( - result, - Ok(VmmData::MmdsValue( - serde_json::from_str(r#"{"key1": "value1", "key2": "val2"}"#).unwrap() - )) - ); - }); - - check_runtime_request_with_mmds( - VmmAction::PatchMMDS( - serde_json::from_str(r#"{"key1": null, "key2": "value2"}"#).unwrap(), - ), - mmds.clone(), - |result, _| { - assert_eq!(result, Ok(VmmData::Empty)); - }, - ); - - check_runtime_request_with_mmds(VmmAction::GetMMDS, mmds.clone(), |result, _| { - assert_eq!( - result, - Ok(VmmData::MmdsValue( - serde_json::from_str(r#"{"key2": "value2"}"#).unwrap() - )) - ); - }); - - let filling = (0..HTTP_MAX_PAYLOAD_SIZE).map(|_| "X").collect::(); - let data = "{\"key\": \"".to_string() + &filling + "\"}"; - - check_runtime_request_with_mmds( - VmmAction::PatchMMDS(serde_json::from_str(&data).unwrap()), - mmds.clone(), - |result, _| { - assert!(matches!(result, Err(VmmActionError::MmdsLimitExceeded(_)))); - }, - ); - check_runtime_request_with_mmds(VmmAction::GetMMDS, mmds, |result, _| { - assert_eq!( - result, - Ok(VmmData::MmdsValue( - serde_json::from_str(r#"{"key2": "value2"}"#).unwrap() - )) - ); - }); - } - - #[test] - fn test_preboot_load_snapshot() { - let mut vm_resources = MockVmRes::default(); - let mut evmgr = EventManager::new().unwrap(); - let seccomp_filters = BpfThreadMap::new(); - let mut preboot = default_preboot(&mut vm_resources, &mut evmgr, &seccomp_filters); - - // Without resume. - let req = VmmAction::LoadSnapshot(LoadSnapshotParams { - snapshot_path: PathBuf::new(), - mem_backend: MemBackendConfig { - backend_type: MemBackendType::File, - backend_path: PathBuf::new(), - }, - enable_diff_snapshots: false, - resume_vm: false, - }); - // Request should succeed. - preboot.handle_preboot_request(req).unwrap(); - // Should have built default mock vmm. - let vmm = preboot.built_vmm.take().unwrap(); - assert_eq!(*vmm.lock().unwrap(), MockVmm::default()); - - // With resume. - let req = VmmAction::LoadSnapshot(LoadSnapshotParams { - snapshot_path: PathBuf::new(), - mem_backend: MemBackendConfig { - backend_type: MemBackendType::File, - backend_path: PathBuf::new(), - }, - enable_diff_snapshots: false, - resume_vm: true, - }); - // Request should succeed. - preboot.handle_preboot_request(req).unwrap(); - let vmm = preboot.built_vmm.as_ref().unwrap().lock().unwrap(); - // Should have built mock vmm then called resume on it. - assert!(vmm.resume_called); - // Extra sanity check - pause was never called. - assert!(!vmm.pause_called); - } - - #[test] - fn test_preboot_disallowed() { - check_preboot_request_err( - VmmAction::FlushMetrics, - VmmActionError::OperationNotSupportedPreBoot, - ); - check_preboot_request_err( - VmmAction::Pause, - VmmActionError::OperationNotSupportedPreBoot, - ); - check_preboot_request_err( - VmmAction::Resume, - VmmActionError::OperationNotSupportedPreBoot, - ); - check_preboot_request_err( - VmmAction::GetBalloonStats, - VmmActionError::OperationNotSupportedPreBoot, - ); - check_preboot_request_err( - VmmAction::UpdateBalloon(BalloonUpdateConfig { amount_mib: 0 }), - VmmActionError::OperationNotSupportedPreBoot, - ); - check_preboot_request_err( - VmmAction::UpdateBalloonStatistics(BalloonUpdateStatsConfig { - stats_polling_interval_s: 0, - }), - VmmActionError::OperationNotSupportedPreBoot, - ); - check_preboot_request_err( - VmmAction::UpdateBlockDevice(BlockDeviceUpdateConfig::default()), - VmmActionError::OperationNotSupportedPreBoot, - ); - check_preboot_request_err( - VmmAction::UpdateNetworkInterface(NetworkInterfaceUpdateConfig { - iface_id: String::new(), - rx_rate_limiter: None, - tx_rate_limiter: None, - }), - VmmActionError::OperationNotSupportedPreBoot, - ); - check_preboot_request_err( - VmmAction::CreateSnapshot(CreateSnapshotParams { - snapshot_type: SnapshotType::Full, - snapshot_path: PathBuf::new(), - mem_file_path: PathBuf::new(), - version: None, - }), - VmmActionError::OperationNotSupportedPreBoot, - ); - #[cfg(target_arch = "x86_64")] - check_preboot_request_err( - VmmAction::SendCtrlAltDel, - VmmActionError::OperationNotSupportedPreBoot, - ); - } - fn check_runtime_request(request: VmmAction, check_success: F) where F: FnOnce(Result, &MockVmm), @@ -1864,17 +1326,6 @@ mod tests { check_success(res, &vmm.lock().unwrap()); } - // Forces error and validates error kind against expected. - fn check_runtime_request_err(request: VmmAction, expected_err: VmmActionError) { - let vmm = Arc::new(Mutex::new(MockVmm { - force_errors: true, - ..Default::default() - })); - let mut runtime = RuntimeApiController::new(MockVmRes::default(), vmm); - let err = runtime.handle_request(request).unwrap_err(); - assert_eq!(err, expected_err); - } - #[test] fn test_runtime_get_vm_config() { let req = VmmAction::GetVmMachineConfig; @@ -1885,333 +1336,4 @@ mod tests { ); }); } - - #[test] - fn test_runtime_pause() { - let req = VmmAction::Pause; - check_runtime_request(req, |result, vmm| { - assert_eq!(result, Ok(VmmData::Empty)); - assert!(vmm.pause_called) - }); - - let req = VmmAction::Pause; - check_runtime_request_err(req, VmmActionError::InternalVmm(VmmError::VcpuPause)); - } - - #[test] - fn test_runtime_resume() { - let req = VmmAction::Resume; - check_runtime_request(req, |result, vmm| { - assert_eq!(result, Ok(VmmData::Empty)); - assert!(vmm.resume_called) - }); - - let req = VmmAction::Resume; - check_runtime_request_err(req, VmmActionError::InternalVmm(VmmError::VcpuResume)); - } - - #[cfg(target_arch = "x86_64")] - #[test] - fn test_runtime_ctrl_alt_del() { - let req = VmmAction::SendCtrlAltDel; - check_runtime_request(req, |result, vmm| { - assert_eq!(result, Ok(VmmData::Empty)); - assert!(vmm.send_ctrl_alt_del_called) - }); - - let req = VmmAction::SendCtrlAltDel; - check_runtime_request_err( - req, - VmmActionError::InternalVmm(VmmError::I8042Error( - crate::devices::legacy::I8042DeviceError::InternalBufferFull, - )), - ); - } - - #[test] - fn test_runtime_balloon_config() { - let req = VmmAction::GetBalloonConfig; - check_runtime_request(req, |result, vmm| { - assert_eq!( - result, - Ok(VmmData::BalloonConfig(BalloonDeviceConfig::default())) - ); - assert!(vmm.balloon_config_called) - }); - - let req = VmmAction::GetBalloonConfig; - check_runtime_request_err( - req, - VmmActionError::BalloonConfig(BalloonConfigError::DeviceNotFound), - ); - } - - #[test] - fn test_runtime_latest_balloon_stats() { - let req = VmmAction::GetBalloonStats; - check_runtime_request(req, |result, vmm| { - assert_eq!(result, Ok(VmmData::BalloonStats(BalloonStats::default()))); - assert!(vmm.latest_balloon_stats_called) - }); - - let req = VmmAction::GetBalloonStats; - check_runtime_request_err( - req, - VmmActionError::BalloonConfig(BalloonConfigError::DeviceNotFound), - ); - } - - #[test] - fn test_runtime_update_balloon_config() { - let req = VmmAction::UpdateBalloon(BalloonUpdateConfig { amount_mib: 0 }); - check_runtime_request(req, |result, vmm| { - assert_eq!(result, Ok(VmmData::Empty)); - assert!(vmm.update_balloon_config_called) - }); - - let req = VmmAction::UpdateBalloon(BalloonUpdateConfig { amount_mib: 0 }); - check_runtime_request_err( - req, - VmmActionError::BalloonConfig(BalloonConfigError::DeviceNotFound), - ); - } - - #[test] - fn test_runtime_update_balloon_stats_config() { - let req = VmmAction::UpdateBalloonStatistics(BalloonUpdateStatsConfig { - stats_polling_interval_s: 0, - }); - check_runtime_request(req, |result, vmm| { - assert_eq!(result, Ok(VmmData::Empty)); - assert!(vmm.update_balloon_stats_config_called) - }); - - let req = VmmAction::UpdateBalloonStatistics(BalloonUpdateStatsConfig { - stats_polling_interval_s: 0, - }); - check_runtime_request_err( - req, - VmmActionError::BalloonConfig(BalloonConfigError::DeviceNotFound), - ); - } - - #[test] - fn test_runtime_update_block_device_path() { - let req = VmmAction::UpdateBlockDevice(BlockDeviceUpdateConfig { - path_on_host: Some(String::new()), - ..Default::default() - }); - check_runtime_request(req, |result, vmm| { - assert_eq!(result, Ok(VmmData::Empty)); - assert!(vmm.update_block_device_path_called) - }); - - let req = VmmAction::UpdateBlockDevice(BlockDeviceUpdateConfig { - path_on_host: Some(String::new()), - ..Default::default() - }); - check_runtime_request_err( - req, - VmmActionError::DriveConfig(DriveError::DeviceUpdate(VmmError::DeviceManager( - crate::device_manager::mmio::MmioError::InvalidDeviceType, - ))), - ); - } - - #[test] - fn test_runtime_update_net_rate_limiters() { - let req = VmmAction::UpdateNetworkInterface(NetworkInterfaceUpdateConfig { - iface_id: String::new(), - rx_rate_limiter: None, - tx_rate_limiter: None, - }); - check_runtime_request(req, |result, vmm| { - assert_eq!(result, Ok(VmmData::Empty)); - assert!(vmm.update_net_rate_limiters_called) - }); - - let req = VmmAction::UpdateNetworkInterface(NetworkInterfaceUpdateConfig { - iface_id: String::new(), - rx_rate_limiter: None, - tx_rate_limiter: None, - }); - check_runtime_request_err( - req, - VmmActionError::NetworkConfig(NetworkInterfaceError::DeviceUpdate( - VmmError::DeviceManager(crate::device_manager::mmio::MmioError::InvalidDeviceType), - )), - ); - } - - #[test] - fn test_runtime_disallowed() { - check_runtime_request_err( - VmmAction::ConfigureBootSource(BootSourceConfig::default()), - VmmActionError::OperationNotSupportedPostBoot, - ); - check_runtime_request_err( - VmmAction::ConfigureLogger(LoggerConfig { - log_path: PathBuf::new(), - level: LoggerLevel::Debug, - show_level: false, - show_log_origin: false, - }), - VmmActionError::OperationNotSupportedPostBoot, - ); - check_runtime_request_err( - VmmAction::ConfigureMetrics(MetricsConfig { - metrics_path: PathBuf::new(), - }), - VmmActionError::OperationNotSupportedPostBoot, - ); - check_runtime_request_err( - VmmAction::InsertBlockDevice(BlockDeviceConfig { - path_on_host: String::new(), - is_root_device: false, - partuuid: None, - cache_type: CacheType::Unsafe, - is_read_only: false, - drive_id: String::new(), - rate_limiter: None, - file_engine_type: FileEngineType::default(), - }), - VmmActionError::OperationNotSupportedPostBoot, - ); - check_runtime_request_err( - VmmAction::InsertNetworkDevice(NetworkInterfaceConfig { - iface_id: String::new(), - host_dev_name: String::new(), - guest_mac: None, - rx_rate_limiter: None, - tx_rate_limiter: None, - }), - VmmActionError::OperationNotSupportedPostBoot, - ); - check_runtime_request_err( - VmmAction::SetVsockDevice(VsockDeviceConfig { - vsock_id: Some(String::new()), - guest_cid: 0, - uds_path: String::new(), - }), - VmmActionError::OperationNotSupportedPostBoot, - ); - check_runtime_request_err( - VmmAction::SetBalloonDevice(BalloonDeviceConfig::default()), - VmmActionError::OperationNotSupportedPostBoot, - ); - check_runtime_request_err( - VmmAction::SetVsockDevice(VsockDeviceConfig { - vsock_id: Some(String::new()), - guest_cid: 0, - uds_path: String::new(), - }), - VmmActionError::OperationNotSupportedPostBoot, - ); - check_runtime_request_err( - VmmAction::SetMmdsConfiguration(MmdsConfig { - ipv4_address: None, - version: MmdsVersion::default(), - network_interfaces: Vec::new(), - }), - VmmActionError::OperationNotSupportedPostBoot, - ); - check_runtime_request_err( - VmmAction::UpdateVmConfiguration(MachineConfigUpdate::from(MachineConfig::default())), - VmmActionError::OperationNotSupportedPostBoot, - ); - check_runtime_request_err( - VmmAction::LoadSnapshot(LoadSnapshotParams { - snapshot_path: PathBuf::new(), - mem_backend: MemBackendConfig { - backend_type: MemBackendType::File, - backend_path: PathBuf::new(), - }, - enable_diff_snapshots: false, - resume_vm: false, - }), - VmmActionError::OperationNotSupportedPostBoot, - ); - check_runtime_request_err( - VmmAction::SetEntropyDevice(EntropyDeviceConfig::default()), - VmmActionError::OperationNotSupportedPostBoot, - ); - } - - fn verify_load_snap_disallowed_after_boot_resources(res: VmmAction, res_name: &str) { - let mut vm_resources = MockVmRes::default(); - let mut evmgr = EventManager::new().unwrap(); - let seccomp_filters = BpfThreadMap::new(); - let mut preboot = default_preboot(&mut vm_resources, &mut evmgr, &seccomp_filters); - - preboot.handle_preboot_request(res).unwrap(); - - // Load snapshot should no longer be allowed. - let req = VmmAction::LoadSnapshot(LoadSnapshotParams { - snapshot_path: PathBuf::new(), - mem_backend: MemBackendConfig { - backend_type: MemBackendType::File, - backend_path: PathBuf::new(), - }, - enable_diff_snapshots: false, - resume_vm: false, - }); - let err = preboot.handle_preboot_request(req); - assert_eq!( - err, - Err(VmmActionError::LoadSnapshot( - LoadSnapshotError::LoadSnapshotNotAllowed - )), - "LoadSnapshot should be disallowed after {}", - res_name - ); - } - - #[test] - fn test_preboot_load_snap_disallowed_after_boot_resources() { - // Verify LoadSnapshot not allowed after configuring various boot-specific resources. - let req = VmmAction::ConfigureBootSource(BootSourceConfig::default()); - verify_load_snap_disallowed_after_boot_resources(req, "ConfigureBootSource"); - - let req = VmmAction::InsertBlockDevice(BlockDeviceConfig { - path_on_host: String::new(), - is_root_device: false, - partuuid: None, - cache_type: CacheType::Unsafe, - is_read_only: false, - drive_id: String::new(), - rate_limiter: None, - file_engine_type: FileEngineType::default(), - }); - verify_load_snap_disallowed_after_boot_resources(req, "InsertBlockDevice"); - - let req = VmmAction::InsertNetworkDevice(NetworkInterfaceConfig { - iface_id: String::new(), - host_dev_name: String::new(), - guest_mac: None, - rx_rate_limiter: None, - tx_rate_limiter: None, - }); - verify_load_snap_disallowed_after_boot_resources(req, "InsertNetworkDevice"); - - let req = VmmAction::SetBalloonDevice(BalloonDeviceConfig::default()); - verify_load_snap_disallowed_after_boot_resources(req, "SetBalloonDevice"); - - let req = VmmAction::SetVsockDevice(VsockDeviceConfig { - vsock_id: Some(String::new()), - guest_cid: 0, - uds_path: String::new(), - }); - verify_load_snap_disallowed_after_boot_resources(req, "SetVsockDevice"); - - let req = - VmmAction::UpdateVmConfiguration(MachineConfigUpdate::from(MachineConfig::default())); - verify_load_snap_disallowed_after_boot_resources(req, "SetVmConfiguration"); - - let req = VmmAction::SetMmdsConfiguration(MmdsConfig { - ipv4_address: None, - version: MmdsVersion::default(), - network_interfaces: Vec::new(), - }); - verify_load_snap_disallowed_after_boot_resources(req, "SetMmdsConfiguration"); - } } diff --git a/src/vmm/src/signal_handler.rs b/src/vmm/src/signal_handler.rs index 9c4f4f04009..156e2de51d9 100644 --- a/src/vmm/src/signal_handler.rs +++ b/src/vmm/src/signal_handler.rs @@ -4,8 +4,7 @@ use libc::{ c_int, c_void, siginfo_t, SIGBUS, SIGHUP, SIGILL, SIGPIPE, SIGSEGV, SIGSYS, SIGXCPU, SIGXFSZ, }; -use log::error; -use logger::{IncMetric, StoreMetric, METRICS}; +use logger::{error, IncMetric, StoreMetric, METRICS}; use utils::signal::register_signal_handler; use crate::FcExitCode; diff --git a/src/vmm/src/vmm_config/logger.rs b/src/vmm/src/vmm_config/logger.rs index 4c108c14bf7..de9dffd7625 100644 --- a/src/vmm/src/vmm_config/logger.rs +++ b/src/vmm/src/vmm_config/logger.rs @@ -1,70 +1,105 @@ // Copyright 2018 Amazon.com, Inc. or its affiliates. All Rights Reserved. // SPDX-License-Identifier: Apache-2.0 -//! Auxiliary module for configuring the logger. -use std::path::PathBuf; +use std::convert::From; +use std::fmt; +use std::io::LineWriter; +use std::os::unix::fs::OpenOptionsExt; +use std::str::FromStr; +use std::sync::atomic::AtomicBool; +use std::sync::atomic::Ordering::SeqCst; +use std::sync::Mutex; -use logger::{FcLineWriter, LevelFilter, LOGGER}; -use serde::{de, Deserialize, Deserializer, Serialize}; +use serde::{Deserialize, Serialize}; +use tracing::Event; +use tracing_subscriber::fmt::format::{self, FormatEvent, FormatFields}; +use tracing_subscriber::fmt::writer::BoxMakeWriter; +use tracing_subscriber::fmt::{FmtContext, Layer as FmtLayer}; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::registry::{LookupSpan, Registry}; +use tracing_subscriber::reload::Layer as ReloadLayer; +use tracing_subscriber::util::SubscriberInitExt; -use super::open_file_nonblock; -use crate::vmm_config::instance_info::InstanceInfo; +type ReloadError = tracing_subscriber::reload::Error; -/// Enum used for setting the log level. -#[derive(Clone, Debug, Default, PartialEq, Eq, Deserialize, Serialize)] -pub enum LoggerLevel { - /// When the level is set to `Error`, the logger will only contain entries - /// that come from the `error` macro. +// TODO: See below doc comment. +/// Mimic of `log::LevelFilter`. +/// +/// 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 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 LevelFilter { + /// A level lower than all log levels. + Off, + /// Corresponds to the `Error` log level. + #[serde(alias = "ERROR")] Error, - /// When the level is set to `Warning`, the logger will only contain entries - /// that come from the `error` and `warn` macros. - #[default] - Warning, - /// When the level is set to `Info`, the logger will only contain entries - /// that come from the `error`, `warn` and `info` macros. + /// Corresponds to the `Warn` log level. + #[serde(alias = "WARNING", alias = "Warning")] + Warn, + /// Corresponds to the `Info` log level. + #[serde(alias = "INFO")] Info, - /// The most verbose log level. + /// Corresponds to the `Debug` log level. + #[serde(alias = "DEBUG")] Debug, + /// Corresponds to the `Trace` log level. + #[serde(alias = "TRACE")] + Trace, } -impl LoggerLevel { - /// Converts from a logger level value of type String to the corresponding LoggerLevel variant - /// or returns an error if the parsing failed. - pub fn from_string(level: String) -> Result { - match level.to_ascii_lowercase().as_str() { - "error" => Ok(LoggerLevel::Error), - "warning" => Ok(LoggerLevel::Warning), - "info" => Ok(LoggerLevel::Info), - "debug" => Ok(LoggerLevel::Debug), - _ => Err(LoggerConfigError::InitializationFailure(level)), - } +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 LevelFilter { - fn from(logger_level: LoggerLevel) -> Self { - match logger_level { - LoggerLevel::Error => LevelFilter::Error, - LoggerLevel::Warning => LevelFilter::Warn, - LoggerLevel::Info => LevelFilter::Info, - LoggerLevel::Debug => LevelFilter::Debug, +impl From for log::LevelFilter { + fn from(level: LevelFilter) -> log::LevelFilter { + match level { + 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, } } } - -// This allows `level` field, which is an enum, to be case-insensitive. -fn case_insensitive<'de, D>(deserializer: D) -> Result -where - D: Deserializer<'de>, -{ - let level = String::deserialize(deserializer).map_err(de::Error::custom)?; - LoggerLevel::from_string(level).or_else(|err| { - Err(format!( - "unknown variant `{}`, expected one of `Error`, `Warning`, `Info`, `Debug`", - err - )) - .map_err(de::Error::custom) - }) +impl From for LevelFilter { + fn from(level: log::LevelFilter) -> LevelFilter { + match level { + 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 LevelFilter { + type Err = ::Err; + fn from_str(s: &str) -> std::result::Result { + // This is required to avoid a breaking change. + match s { + "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), + } + } } /// Strongly typed structure used to describe the logger. @@ -72,186 +107,261 @@ where #[serde(deny_unknown_fields)] pub struct LoggerConfig { /// Named pipe or file used as output for logs. - pub log_path: PathBuf, + pub log_path: Option, + // TODO Deprecate this API argument. /// The level of the Logger. - #[serde( - default = "LoggerLevel::default", - deserialize_with = "case_insensitive" - )] - pub level: LoggerLevel, + pub level: Option, /// When enabled, the logger will append to the output the severity of the log entry. - #[serde(default)] - pub show_level: bool, + pub show_level: Option, /// When enabled, the logger will append the origin of the log entry. - #[serde(default)] - pub show_log_origin: bool, + pub show_log_origin: Option, + /// Filter components. If this is `Some` it overrides `self.level`. + pub filter: Option, } -impl LoggerConfig { - /// Creates a new LoggerConfig. - pub fn new( - log_path: PathBuf, - level: LoggerLevel, - show_level: bool, - show_log_origin: bool, - ) -> LoggerConfig { - LoggerConfig { - log_path, - level, - show_level, - show_log_origin, - } - } +/// Error type for [`LoggerConfig::init`]. +#[derive(Debug, thiserror::Error)] +pub enum InitLoggerError { + /// Failed to initialize logger. + #[error("Failed to initialize logger: {0}")] + Init(tracing_subscriber::util::TryInitError), + /// Failed to open target file. + #[error("Failed to open target file: {0}")] + File(std::io::Error), } -/// Errors associated with actions on the `LoggerConfig`. +/// Error type for [`LoggerConfig::update`]. #[derive(Debug, thiserror::Error)] -pub enum LoggerConfigError { - /// Cannot initialize the logger due to bad user input. - #[error("{}", format!("{:?}", .0).replace('\"', ""))] - InitializationFailure(String), +pub enum UpdateLoggerError { + /// Failed to open target file. + #[error("Failed to open target file: {0}")] + File(std::io::Error), + /// Failed to modify format layer writer. + #[error("Failed to modify format layer writer: {0}")] + Fmt(ReloadError), + /// Failed to modify level filter. + #[error("Failed to modify level filter: {0}")] + Level(ReloadError), } -/// Configures the logger as described in `logger_cfg`. -pub fn init_logger( - logger_cfg: LoggerConfig, - instance_info: &InstanceInfo, -) -> Result<(), LoggerConfigError> { - LOGGER - .set_max_level(logger_cfg.level.into()) - .set_include_origin(logger_cfg.show_log_origin, logger_cfg.show_log_origin) - .set_include_level(logger_cfg.show_level); - - let writer = FcLineWriter::new( - open_file_nonblock(&logger_cfg.log_path) - .map_err(|err| LoggerConfigError::InitializationFailure(err.to_string()))?, - ); - LOGGER - .init( - format!( - "Running {} v{}", - instance_info.app_name, instance_info.vmm_version - ), - Box::new(writer), - ) - .map_err(|err| LoggerConfigError::InitializationFailure(err.to_string())) +/// 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, } -#[cfg(test)] -mod tests { - use std::io::{BufRead, BufReader}; +// Initialize filter to default. +static FILTER: Mutex = Mutex::new(FilterArgs { + file: None, + module: None, + level: Some(log::LevelFilter::Warn), +}); - use logger::warn; - use utils::tempfile::TempFile; - use utils::time::TimestampUs; +// `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, +} - use super::*; - use crate::devices::pseudo::BootTimer; +type FmtHandle = tracing_subscriber::reload::Handle< + tracing_subscriber::fmt::Layer< + tracing_subscriber::layer::Layered< + tracing_subscriber::filter::FilterFn, + tracing_subscriber::registry::Registry, + >, + tracing_subscriber::fmt::format::DefaultFields, + LoggerFormatter, + tracing_subscriber::fmt::writer::BoxMakeWriter, + >, + tracing_subscriber::layer::Layered< + tracing_subscriber::filter::FilterFn, + tracing_subscriber::registry::Registry, + >, +>; - #[test] - fn test_init_logger() { - let default_instance_info = InstanceInfo::default(); +impl LoggerConfig { + /// Initializes the logger. + /// + /// Returns handles that can be used to dynamically re-configure the logger. + 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) => {} + } - // Error case: initializing logger with invalid pipe returns error. - let desc = LoggerConfig { - log_path: PathBuf::from("not_found_file_log"), - level: LoggerLevel::Debug, - show_level: false, - show_log_origin: false, - }; - assert!(init_logger(desc, &default_instance_info).is_err()); + // 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 + }); - // Initializing logger with valid pipe is ok. - let log_file = TempFile::new().unwrap(); - let desc = LoggerConfig { - log_path: log_file.as_path().to_path_buf(), - level: LoggerLevel::Info, - show_level: true, - show_log_origin: true, + // Setup fmt layer + let (fmt, fmt_handle) = { + let fmt_writer = match &self.log_path { + Some(path) => { + // In case we open a FIFO, in order to not block the instance if nobody is + // consuming the message that is flushed to the two pipes, we are opening it + // with `O_NONBLOCK` flag. In this case, writing to a pipe will start failing + // when reaching 64K of unconsumed content. + let file = std::fs::OpenOptions::new() + .custom_flags(libc::O_NONBLOCK) + .read(true) + .write(true) + .open(path) + .map_err(InitLoggerError::File)?; + // Wrap file to satisfy `tracing_subscriber::fmt::MakeWriter`. + let writer = Mutex::new(LineWriter::new(file)); + BoxMakeWriter::new(writer) + } + None => BoxMakeWriter::new(std::io::stdout), + }; + let fmt_subscriber = FmtLayer::new() + .event_format(LoggerFormatter::new( + self.show_level.unwrap_or_default(), + self.show_log_origin.unwrap_or_default(), + )) + .with_writer(fmt_writer); + ReloadLayer::new(fmt_subscriber) }; - assert!(init_logger(desc.clone(), &default_instance_info).is_ok()); - assert!(init_logger(desc, &default_instance_info).is_err()); + Registry::default() + .with(filter) + .with(fmt) + .try_init() + .map_err(InitLoggerError::Init)?; - // Validate logfile works. - warn!("this is a test"); + tracing::error!("Error level logs enabled."); + tracing::warn!("Warn level logs enabled."); + tracing::info!("Info level logs enabled."); + tracing::debug!("Debug level logs enabled."); + tracing::trace!("Trace level logs enabled."); - let mut reader = BufReader::new(log_file.into_file()); + Ok(LoggerHandles { fmt: fmt_handle }) + } + /// Updates the logger using the given handles. + pub fn update( + 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 { + // In case we open a FIFO, in order to not block the instance if nobody is consuming the + // message that is flushed to the two pipes, we are opening it with `O_NONBLOCK` flag. + // In this case, writing to a pipe will start failing when reaching 64K of unconsumed + // content. + let file = std::fs::OpenOptions::new() + .custom_flags(libc::O_NONBLOCK) + .read(true) + .write(true) + .open(log_path) + .map_err(UpdateLoggerError::File)?; + + fmt.modify(|f| *f.writer_mut() = BoxMakeWriter::new(Mutex::new(LineWriter::new(file)))) + .map_err(UpdateLoggerError::Fmt)?; + } - let mut line = String::new(); - loop { - if line.contains("this is a test") { - break; + // Update the filter + match (self.level, self.filter) { + (_, Some(filter)) => { + *FILTER.lock().unwrap() = filter; } - if reader.read_line(&mut line).unwrap() == 0 { - // If it ever gets here, this assert will fail. - assert!(line.contains("this is a test")); + (Some(level), None) => { + *FILTER.lock().unwrap() = FilterArgs { + file: None, + module: None, + level: Some(log::LevelFilter::from(level)), + }; } + (None, None) => {} } - // Validate logging the boot time works. - let mut boot_timer = BootTimer::new(TimestampUs::default()); - boot_timer.bus_write(0, &[123]); + // Update if the logger shows the level + if let Some(show_level) = self.show_level { + SHOW_LEVEL.store(show_level, SeqCst); + } - let mut line = String::new(); - loop { - if line.contains("Guest-boot-time =") { - break; - } - if reader.read_line(&mut line).unwrap() == 0 { - // If it ever gets here, this assert will fail. - assert!(line.contains("Guest-boot-time =")); - } + // Updates if the logger shows the origin + if let Some(show_log_origin) = self.show_log_origin { + SHOW_LOG_ORIGIN.store(show_log_origin, SeqCst); } + + Ok(()) } +} - #[test] - fn test_new_logger_config() { - let logger_config = - LoggerConfig::new(PathBuf::from("log"), LoggerLevel::Debug, false, true); - assert_eq!(logger_config.log_path, PathBuf::from("log")); - assert_eq!(logger_config.level, LoggerLevel::Debug); - assert!(!logger_config.show_level); - assert!(logger_config.show_log_origin); +#[derive(Debug)] +struct LoggerFormatter; +impl LoggerFormatter { + pub fn new(show_level: bool, show_log_origin: bool) -> Self { + SHOW_LEVEL.store(show_level, SeqCst); + SHOW_LOG_ORIGIN.store(show_log_origin, SeqCst); + Self } +} + +static SHOW_LEVEL: AtomicBool = AtomicBool::new(false); +static SHOW_LOG_ORIGIN: AtomicBool = AtomicBool::new(false); - #[test] - fn test_parse_level() { - // Check `from_string()` behaviour for different scenarios. - assert_eq!( - format!( - "{}", - LoggerLevel::from_string("random_value".to_string()).unwrap_err() - ), - "random_value" - ); - assert_eq!( - LoggerLevel::from_string("Error".to_string()).unwrap(), - LoggerLevel::Error - ); - assert_eq!( - LoggerLevel::from_string("Warning".to_string()).unwrap(), - LoggerLevel::Warning - ); - assert_eq!( - LoggerLevel::from_string("Info".to_string()).unwrap(), - LoggerLevel::Info - ); - assert_eq!( - LoggerLevel::from_string("Debug".to_string()).unwrap(), - LoggerLevel::Debug - ); - assert_eq!( - LoggerLevel::from_string("error".to_string()).unwrap(), - LoggerLevel::Error - ); - assert_eq!( - LoggerLevel::from_string("WaRnIng".to_string()).unwrap(), - LoggerLevel::Warning - ); - assert_eq!( - LoggerLevel::from_string("DEBUG".to_string()).unwrap(), - LoggerLevel::Debug - ); +impl FormatEvent for LoggerFormatter +where + S: tracing::Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event( + &self, + ctx: &FmtContext<'_, S, N>, + writer: format::Writer<'_>, + event: &Event<'_>, + ) -> fmt::Result { + tracing_subscriber::fmt::format::Format::default() + .with_thread_names(true) + .with_ansi(false) + .with_level(SHOW_LEVEL.load(SeqCst)) + .with_file(SHOW_LOG_ORIGIN.load(SeqCst)) + .with_line_number(SHOW_LOG_ORIGIN.load(SeqCst)) + .format_event(ctx, writer, event) } } diff --git a/src/vmm/src/vstate/vcpu/mod.rs b/src/vmm/src/vstate/vcpu/mod.rs index e0b3ae94c81..fcd3defc7e8 100644 --- a/src/vmm/src/vstate/vcpu/mod.rs +++ b/src/vmm/src/vstate/vcpu/mod.rs @@ -16,8 +16,7 @@ use std::{fmt, io, thread}; use kvm_bindings::{KVM_SYSTEM_EVENT_RESET, KVM_SYSTEM_EVENT_SHUTDOWN}; use kvm_ioctls::VcpuExit; use libc::{c_int, c_void, siginfo_t}; -use log::{error, info}; -use logger::{IncMetric, METRICS}; +use logger::{error, info, IncMetric, METRICS}; use seccompiler::{BpfProgram, BpfProgramRef}; use utils::errno; use utils::eventfd::EventFd; diff --git a/src/vmm/src/vstate/vcpu/x86_64.rs b/src/vmm/src/vstate/vcpu/x86_64.rs index cb9e3ba351c..163972fc2b1 100644 --- a/src/vmm/src/vstate/vcpu/x86_64.rs +++ b/src/vmm/src/vstate/vcpu/x86_64.rs @@ -12,8 +12,7 @@ use kvm_bindings::{ kvm_xsave, CpuId, Msrs, KVM_MAX_CPUID_ENTRIES, KVM_MAX_MSR_ENTRIES, }; use kvm_ioctls::{VcpuExit, VcpuFd}; -use log::{error, warn}; -use logger::{IncMetric, METRICS}; +use logger::{error, warn, IncMetric, METRICS}; use utils::vm_memory::{Address, GuestAddress, GuestMemoryMmap}; use versionize::{VersionMap, Versionize, VersionizeError, VersionizeResult}; use versionize_derive::Versionize; diff --git a/tests/framework/microvm.py b/tests/framework/microvm.py index 04b7aff145d..fcfe6780a08 100644 --- a/tests/framework/microvm.py +++ b/tests/framework/microvm.py @@ -628,8 +628,6 @@ def spawn( # and leave 0.2 delay between them. if "no-api" not in self.jailer.extra_args: self._wait_create() - if create_logger: - self.check_log_message("Running Firecracker") @retry(delay=0.2, tries=5) def _wait_create(self): diff --git a/tests/integration_tests/functional/test_logging.py b/tests/integration_tests/functional/test_logging.py index 520c44361f0..c26f947686a 100644 --- a/tests/integration_tests/functional/test_logging.py +++ b/tests/integration_tests/functional/test_logging.py @@ -5,69 +5,85 @@ It checks the response of the API configuration calls and the logs that show up in the configured logging FIFO. """ + +import datetime import os -import re -from time import strptime import host_tools.logging as log_tools -# Array of supported log levels of the current logging system. -# Do not change order of values inside this array as logic depends on this. -LOG_LEVELS = ["ERROR", "WARN", "INFO", "DEBUG"] - -def to_formal_log_level(log_level): - """Convert a pretty-print log level into the related log level code. +def level_int(level): + """Converts a log level string to an integer representation""" - Turns a pretty formatted log level (i.e Warning) into the one actually - being logged (i.e WARN). - :param log_level: pretty formatted log level - :return: actual level being logged - """ - if log_level == "Error": - return LOG_LEVELS[0] - if log_level == "Warning": - return LOG_LEVELS[1] - if log_level == "Info": - return LOG_LEVELS[2] - if log_level == "Debug": - return LOG_LEVELS[3] - return "" + if level == "ERROR": + return 0 + if level == "WARN": + return 1 + if level == "INFO": + return 2 + if level == "DEBUG": + return 3 + if level == "TRACE": + return 4 + raise Exception("Invalid level") -def check_log_message_format(log_str, instance_id, level, show_level, show_origin): +# pylint: disable=anomalous-backslash-in-string +def check_log_message_format(log_str, log_level, show_level, show_origin): """Ensure correctness of the logged message. Parse the string representing the logs and look for the parts that should be there. - The log line should look lie this: - YYYY-MM-DDTHH:MM:SS.NNNNNNNNN [ID:THREAD:LEVEL:FILE:LINE] MESSAGE - where LEVEL and FILE:LINE are both optional. - e.g. with THREAD NAME as TN - `2018-09-09T12:52:00.123456789 [MYID:TN:WARN:/path/to/file.rs:52] warning` - """ - timestamp, tag_and_msg = log_str.split(" ", maxsplit=1) - timestamp = timestamp[:-10] - strptime(timestamp, "%Y-%m-%dT%H:%M:%S") - - pattern = "\\[(" + instance_id + ")" - pattern += ":(.*)" + The log line should look like: + > {year}-{month}-{day}T{hour}:{minute}:{second}.{microsecond}Z {level} {thread name} + > {process name}: {file}:{line number} {message} + where `level`, `file` and `line number` are optional e.g. + > 2023-07-19T12:10:54.608814Z INFO main test_bin_3: src\main.rs:18: yak shaving completed. + """ + split = iter(log_str.split()) + now = datetime.datetime.now() + + timestamp = next(split) + date, time = timestamp.split("T") + year, month, day = date.split("-") + assert len(month) == 2 + assert len(day) == 2 + + assert time[-1] == "Z" + hour, minute, secs = time[:-1].split(":") + second, microsecond = secs.split(".") + assert len(hour) == 2 + assert len(minute) == 2 + assert len(second) == 2 + assert len(microsecond) == 6 + + # Assert the time in the logs is less than or equal to the current time + log_time = datetime.datetime( + year=int(year), + month=int(month), + day=int(day), + hour=int(hour), + minute=int(minute), + second=int(second), + microsecond=int(microsecond), + ) + assert log_time <= now + if show_level: - pattern += ":(" + "|".join(LOG_LEVELS) + ")" - if show_origin: - pattern += ":([^:]+/[^:]+):([0-9]+)" - pattern += "\\].*" + level = next(split) + assert level in ("ERROR", "WARN", "INFO", "DEBUG", "TRACE") + assert level_int(level) <= level_int(log_level.upper()) - mo = re.match(pattern, tag_and_msg) - assert ( - mo is not None - ), f"Log message ({tag_and_msg}) does not match pattern ({pattern})." + # Thread names are not optional. + _thread_name = next(split) + # Process names are not optional. + _process_name = next(split) - if show_level: - tag_level = mo.group(3) - tag_level_no = LOG_LEVELS.index(tag_level) - configured_level_no = LOG_LEVELS.index(to_formal_log_level(level)) - assert tag_level_no <= configured_level_no + if show_origin: + origin = next(split) + assert origin[-1] == ":" + _path, line = origin[:-1].split(":") + assert line.isnumeric() def test_no_origin_logs(test_microvm_with_api): @@ -102,7 +118,7 @@ def test_warn_logs(test_microvm_with_api): """ Check output of logs when minimum level to be displayed is warning. """ - _test_log_config(microvm=test_microvm_with_api, log_level="Warning") + _test_log_config(microvm=test_microvm_with_api, log_level="Warn") def test_error_logs(test_microvm_with_api): @@ -232,8 +248,5 @@ def _test_log_config(microvm, log_level="Info", show_level=True, show_origin=Tru microvm.start() lines = microvm.log_data.splitlines() - for idx, line in enumerate(lines): - if idx == 0: - assert line.startswith("Running Firecracker") - continue - check_log_message_format(line, microvm.id, log_level, show_level, show_origin) + for line in lines: + check_log_message_format(line, log_level, show_level, show_origin)