diff --git a/CHANGELOG.md b/CHANGELOG.md index aadf78b45c2..610452c90c8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -57,7 +57,10 @@ v1.4.0 are available as an improved iteration of the static CPU templates. For more information about the transition from static CPU templates to custom CPU templates, please refer to [this GitHub discussion](https://github.com/firecracker-microvm/firecracker/discussions/4135). - +- Changed default log level from + [`Warn`](https://docs.rs/log/latest/log/enum.Level.html#variant.Warn) to + [`Info`](https://docs.rs/log/latest/log/enum.Level.html#variant.Info). This + results in more logs being output by default. ### Fixed - Fixed a change in behavior of normalize host brand string that breaks diff --git a/Cargo.lock b/Cargo.lock index ba2ea6c69e2..059bbe5127c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -538,6 +538,7 @@ dependencies = [ "displaydoc", "event-manager", "libc", + "log", "regex", "seccompiler", "serde", diff --git a/src/api_server/src/request/logger.rs b/src/api_server/src/request/logger.rs index 1fcb1a51808..ad16246bc14 100644 --- a/src/api_server/src/request/logger.rs +++ b/src/api_server/src/request/logger.rs @@ -2,7 +2,6 @@ // SPDX-License-Identifier: Apache-2.0 use vmm::logger::{IncMetric, METRICS}; -use vmm::vmm_config::logger_config::LoggerConfig; use super::super::VmmAction; use crate::parsed_request::{Error, ParsedRequest}; @@ -10,7 +9,7 @@ use crate::request::Body; pub(crate) fn parse_put_logger(body: &Body) -> Result { METRICS.put_api_requests.logger_count.inc(); - let res = serde_json::from_slice::(body.raw()); + let res = serde_json::from_slice::(body.raw()); let config = res.map_err(|err| { METRICS.put_api_requests.logger_fails.inc(); err @@ -22,7 +21,7 @@ pub(crate) fn parse_put_logger(body: &Body) -> Result { mod tests { use std::path::PathBuf; - use vmm::vmm_config::logger_config::LoggerLevel; + use vmm::logger::{LevelFilter, LoggerConfig}; use super::*; use crate::parsed_request::tests::vmm_action_from_request; @@ -30,16 +29,17 @@ mod tests { #[test] fn test_parse_put_logger_request() { let body = r#"{ - "log_path": "log", - "level": "Warning", - "show_level": false, - "show_log_origin": false - }"#; + "log_path": "log", + "level": "Warning", + "show_level": false, + "show_log_origin": false + }"#; + let expected_config = 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), }; assert_eq!( vmm_action_from_request(parse_put_logger(&Body::new(body)).unwrap()), @@ -47,16 +47,17 @@ mod tests { ); let body = r#"{ - "log_path": "log", - "level": "DEBUG", - "show_level": false, - "show_log_origin": false - }"#; + "log_path": "log", + "level": "DEBUG", + "show_level": false, + "show_log_origin": false + }"#; + let expected_config = 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), }; assert_eq!( vmm_action_from_request(parse_put_logger(&Body::new(body)).unwrap()), diff --git a/src/api_server/swagger/firecracker.yaml b/src/api_server/swagger/firecracker.yaml index 8b515a12c69..9be57c05017 100644 --- a/src/api_server/swagger/firecracker.yaml +++ b/src/api_server/swagger/firecracker.yaml @@ -983,8 +983,8 @@ definitions: level: type: string description: Set the level. The possible values are case-insensitive. - enum: [Error, Warning, Info, Debug] - default: Warning + enum: [Error, Warning, Info, Debug, Trace, Off] + default: Info log_path: type: string description: Path to the named pipe or file for the human readable log output. diff --git a/src/firecracker/Cargo.toml b/src/firecracker/Cargo.toml index 105ff1b2f95..c3e5e9092e6 100644 --- a/src/firecracker/Cargo.toml +++ b/src/firecracker/Cargo.toml @@ -16,6 +16,7 @@ bench = false displaydoc = "0.2.4" event-manager = "0.3.0" libc = "0.2.148" +log = "0.4.20" serde_json = "1.0.107" thiserror = "1.0.49" timerfd = "1.5.0" diff --git a/src/firecracker/src/main.rs b/src/firecracker/src/main.rs index 3ae46e6aa8f..2539ae50b52 100644 --- a/src/firecracker/src/main.rs +++ b/src/firecracker/src/main.rs @@ -8,6 +8,7 @@ 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}; @@ -20,12 +21,13 @@ use utils::arg_parser::{ArgParser, Argument}; use utils::terminal::Terminal; use utils::validators::validate_instance_id; use vmm::builder::StartMicrovmError; -use vmm::logger::{error, info, ProcessTimeReporter, StoreMetric, LOGGER, METRICS}; +use vmm::logger::{ + debug, error, info, LoggerConfig, ProcessTimeReporter, StoreMetric, LOGGER, METRICS, +}; 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_config::{init_logger, LoggerConfig, LoggerConfigError, LoggerLevel}; use vmm::vmm_config::metrics::{init_metrics, MetricsConfig, MetricsConfigError}; use vmm::{EventManager, FcExitCode, HTTP_MAX_PAYLOAD_SIZE}; @@ -35,12 +37,13 @@ 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!("CARGO_PKG_VERSION"); const MMDS_CONTENT_ARG: &str = "metadata"; #[derive(Debug, thiserror::Error, displaydoc::Display)] enum MainError { + /// Failed to set the logger: {0} + SetLogger(log::SetLoggerError), /// Failed to register signal handlers: {0} RegisterSignalHandlers(#[source] utils::errno::Error), /// Arguments parsing error: {0} \n\nFor more information try --help. @@ -48,9 +51,9 @@ enum MainError { /// When printing Snapshot Data format: {0} PrintSnapshotDataFormat(#[from] SnapshotVersionError), /// Invalid value for logger level: {0}.Possible values: [Error, Warning, Info, Debug] - InvalidLogLevel(LoggerConfigError), + InvalidLogLevel(vmm::logger::LevelFilterFromStrError), /// Could not initialize logger: {0} - LoggerInitialization(LoggerConfigError), + LoggerInitialization(vmm::logger::LoggerUpdateError), /// Could not initialize metrics: {0:?} MetricsInitialization(MetricsConfigError), /// Seccomp error: {0} @@ -99,9 +102,10 @@ fn main() -> ExitCode { } fn main_exec() -> Result<(), MainError> { - LOGGER - .configure(Some(DEFAULT_INSTANCE_ID.to_string())) - .expect("Failed to register logger"); + // Initialize the logger. + log::set_logger(&LOGGER).map_err(MainError::SetLogger)?; + log::set_max_level(vmm::logger::DEFAULT_LEVEL); + info!("Running Firecracker v{FIRECRACKER_VERSION}"); register_signal_handlers().map_err(MainError::RegisterSignalHandlers)?; @@ -113,7 +117,7 @@ fn main_exec() -> Result<(), MainError> { // These errors are non-critical: In the worst case we have worse snapshot restore // performance. ResizeFdTableError::GetRlimit | ResizeFdTableError::Dup2(_) => { - vmm::logger::debug!("Failed to resize fdtable: {err}") + debug!("Failed to resize fdtable: {err}") } // This error means that we now have a random file descriptor lying around, abort to be // cautious. @@ -149,124 +153,114 @@ 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) + .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("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("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("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(); @@ -304,23 +298,29 @@ 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, + let id = arguments + .single_value("id") + .map(|s| s.as_str()) + .unwrap_or(vmm::logger::DEFAULT_INSTANCE_ID); + vmm::logger::INSTANCE_ID.set(String::from(id)).unwrap(); + + // Apply the logger configuration. + let log_path = arguments.single_value("log-path").map(PathBuf::from); + let level = arguments + .single_value("level") + .map(|s| vmm::logger::LevelFilter::from_str(s)) + .transpose() + .map_err(MainError::InvalidLogLevel)?; + let show_level = arguments.flag_present("show-level").then_some(true); + let show_log_origin = arguments.flag_present("show-level").then_some(true); + LOGGER + .update(LoggerConfig { + log_path, + level, show_level, show_log_origin, - }; - init_logger(logger_config, &instance_info).map_err(MainError::LoggerInitialization)?; - } + }) + .map_err(MainError::LoggerInitialization)?; if let Some(metrics_path) = arguments.single_value("metrics-path") { let metrics_config = MetricsConfig { diff --git a/src/vmm/src/logger/init.rs b/src/vmm/src/logger/init.rs deleted file mode 100644 index d27906bed40..00000000000 --- a/src/vmm/src/logger/init.rs +++ /dev/null @@ -1,117 +0,0 @@ -// Copyright 2020 Amazon.com, Inc. or its affiliates. All Rights Reserved. -// SPDX-License-Identifier: Apache-2.0 - -use std::sync::atomic::{AtomicUsize, Ordering}; - -/// Errors associated with the `Init` struct. -#[derive(Debug, thiserror::Error, displaydoc::Display)] -pub enum Error { - /// The component is already initialized. - AlreadyInitialized, - /// The component is initializing. Can't perform the requested action right now. - InitializationInProgress, -} - -/// A helper structure which can be used to run a one-time initialization. -#[derive(Debug)] -pub struct Init { - state: AtomicUsize, -} - -impl Init { - const UNINITIALIZED: usize = 0; - const INITIALIZING: usize = 1; - const INITIALIZED: usize = 2; - - /// Creates a new instance of `Init`. - pub const fn new() -> Self { - Self { - state: AtomicUsize::new(Self::UNINITIALIZED), - } - } - - /// Performs an initialization routine. - /// - /// The given closure will be executed if the current state is `UNINITIALIZED`. - /// Otherwise an Error will be returned. - /// - /// If the closure returns `true`, the state will be changed to `INITIALIZED`. - /// If the closure returns `false`, the state will remain `UNINITIALIZED`. - pub fn call_init(&self, f: F) -> Result<(), Error> - where - F: FnOnce() -> bool, - { - match self.state.compare_exchange( - Self::UNINITIALIZED, - Self::INITIALIZING, - Ordering::SeqCst, - Ordering::SeqCst, - ) { - Err(Self::INITIALIZING) => { - return Err(Error::InitializationInProgress); - } - Err(Self::INITIALIZED) => { - return Err(Error::AlreadyInitialized); - } - _ => {} - } - - let state = if f() { - Self::INITIALIZED - } else { - Self::UNINITIALIZED - }; - - self.state.store(state, Ordering::SeqCst); - - Ok(()) - } - - /// Checks if the current state is `INITIALIZED`. - #[inline] - pub fn is_initialized(&self) -> bool { - self.state.load(Ordering::Relaxed) == Self::INITIALIZED - } -} - -#[cfg(test)] -mod tests { - use super::*; - - #[test] - fn test_call_init_with_true() { - let init = Init::new(); - assert!(init.call_init(|| { true }).is_ok()); - assert!(init.state.load(Ordering::Relaxed) == Init::INITIALIZED); - } - - #[test] - fn test_call_init_with_false() { - let init = Init::new(); - assert!(init.call_init(|| { false }).is_ok()); - assert!(init.state.load(Ordering::Relaxed) == Init::UNINITIALIZED); - } - - #[test] - fn test_call_init_errors() { - let init = Init::new(); - - init.state.store(Init::INITIALIZED, Ordering::SeqCst); - assert!(init.call_init(|| { true }).is_err()); - - init.state.store(Init::INITIALIZING, Ordering::SeqCst); - assert!(init.call_init(|| { true }).is_err()); - } - - #[test] - fn test_error_messages() { - assert_eq!( - format!("{}", Error::InitializationInProgress), - "The component is initializing. Can't perform the requested action right now." - ); - assert_eq!( - format!("{}", Error::AlreadyInitialized), - "The component is already initialized." - ); - } -} diff --git a/src/vmm/src/logger/logging.rs b/src/vmm/src/logger/logging.rs index 2cf28bdbe66..04f6fb61181 100644 --- a/src/vmm/src/logger/logging.rs +++ b/src/vmm/src/logger/logging.rs @@ -1,428 +1,157 @@ // 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 vmm::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 vmm::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 std::fmt::Debug; +use std::io::Write; +use std::os::unix::fs::OpenOptionsExt; +use std::path::PathBuf; +use std::str::FromStr; +use std::sync::{Mutex, OnceLock}; +use std::thread; + +use log::{Log, Metadata, Record}; +use serde::{Deserialize, Serialize}; use utils::time::LocalTime; -use super::extract_guard; -use crate::logger::init; -use crate::logger::init::Init; -use crate::logger::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() - } -} +use super::metrics::{IncMetric, METRICS}; + +/// Default level filter for logger matching the swagger specification +/// (`src/api_server/swagger/firecracker.yaml`). +pub const DEFAULT_LEVEL: log::LevelFilter = log::LevelFilter::Info; +/// Default instance id. +pub const DEFAULT_INSTANCE_ID: &str = "anonymous-instance"; +/// Instance id. +pub static INSTANCE_ID: OnceLock = OnceLock::new(); +/// Semver version of Firecracker. +const FIRECRACKER_VERSION: &str = env!("CARGO_PKG_VERSION"); + +/// The logger. +/// +/// Default values matching the swagger specification (`src/api_server/swagger/firecracker.yaml`). +pub static LOGGER: Logger = Logger(Mutex::new(LoggerConfiguration { + target: None, + format: LogFormat { + show_level: false, + show_log_origin: false, + }, +})); + +/// Error type for [`Logger::update`]. +#[derive(Debug, thiserror::Error)] +#[error("Failed to open target file: {0}")] +pub struct LoggerUpdateError(pub std::io::Error); 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 vmm::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 vmm::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 vmm::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()); + /// Applies the given logger configuration the logger. + pub fn update(&self, config: LoggerConfig) -> Result<(), LoggerUpdateError> { + let mut guard = self.0.lock().unwrap(); + log::set_max_level( + config + .level + .map(log::LevelFilter::from) + .unwrap_or(DEFAULT_LEVEL), + ); - if self.show_level() { - prefix.push(record.level().to_string()); - }; + let target_changed = if let Some(log_path) = config.log_path { + let file = std::fs::OpenOptions::new() + .custom_flags(libc::O_NONBLOCK) + .read(true) + .write(true) + .open(log_path) + .map_err(LoggerUpdateError)?; - if self.show_file_path() { - prefix.push(record.file().unwrap_or("unknown").to_string()); + guard.target = Some(file); + true + } else { + false }; - if self.show_line_numbers() { - if let Some(line) = record.line() { - prefix.push(line.to_string()); - } + if let Some(show_level) = config.show_level { + guard.format.show_level = show_level; } - 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); + if let Some(show_log_origin) = config.show_log_origin { + guard.format.show_log_origin = show_log_origin; } - } - - /// 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 vmm::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 vmm::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); + // Ensure we drop the guard before attempting to log, otherwise this + // would deadlock. + drop(guard); + if target_changed { + // We log this when a target is changed so it is always the 1st line logged, this + // maintains some previous behavior to minimize a breaking change. + log::info!("Running Firecracker v{FIRECRACKER_VERSION}"); + } 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, displaydoc::Display)] -pub enum LoggerError { - /// Logger initialization failure: {0} - Init(init::Error), +#[derive(Debug)] +pub struct LogFormat { + pub show_level: bool, + pub show_log_origin: bool, +} +#[derive(Debug)] +pub struct LoggerConfiguration { + pub target: Option, + pub format: LogFormat, } +#[derive(Debug)] +pub struct Logger(pub Mutex); -/// Implements the "Log" trait from the externally used "log" crate. impl Log for Logger { + // No additional filters to . 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); + // Lock the logger. + let mut guard = self.0.lock().unwrap(); + + // Prints log message + { + let thread = thread::current().name().unwrap_or("-").to_string(); + let level = match guard.format.show_level { + true => format!(":{}", record.level()), + false => String::new(), + }; + + let origin = match guard.format.show_log_origin { + true => { + let file = record.file().unwrap_or("?"); + let line = match record.line() { + Some(x) => x.to_string(), + None => String::from("?"), + }; + format!(":{file}:{line}") + } + false => String::new(), + }; + + let message = format!( + "{} [{}:{thread}{level}{origin}] {}\n", + LocalTime::now(), + INSTANCE_ID + .get() + .map(|s| s.as_str()) + .unwrap_or(DEFAULT_INSTANCE_ID), + record.args() + ); + + let result = if let Some(file) = &mut guard.target { + file.write_all(message.as_bytes()) + } else { + std::io::stdout().write_all(message.as_bytes()) + }; + + // If the write returns an error, increment missed log count. + // No reason to log the error to stderr here, just increment the metric. + if result.is_err() { + METRICS.logger.missed_log_count.inc(); + } + } } // This is currently not used. @@ -431,343 +160,189 @@ impl Log for Logger { } } -#[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::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()) - } +/// Strongly typed structure used to describe the logger. +#[derive(Clone, Debug, PartialEq, Eq, Deserialize, Serialize)] +#[serde(deny_unknown_fields)] +pub struct LoggerConfig { + /// Named pipe or file used as output for logs. + pub log_path: Option, + /// The level of the Logger. + pub level: Option, + /// Whether to show the log level in the log. + pub show_level: Option, + /// Whether to show the log origin in the log. + pub show_log_origin: Option, +} - fn flush(&mut self) -> std::io::Result<()> { - Ok(()) +/// This is required since we originally supported `Warning` and uppercase variants being used as +/// the log level filter. It would be a breaking change to no longer support this. In the next +/// breaking release this should be removed (replaced with `log::LevelFilter` and only supporting +/// its default deserialization). +#[derive(Clone, Debug, PartialEq, Eq, Deserialize, Serialize)] +pub enum LevelFilter { + /// [`log::LevelFilter:Off`] + #[serde(alias = "OFF")] + Off, + /// [`log::LevelFilter:Trace`] + #[serde(alias = "TRACE")] + Trace, + /// [`log::LevelFilter:Debug`] + #[serde(alias = "DEBUG")] + Debug, + /// [`log::LevelFilter:Info`] + #[serde(alias = "INFO")] + Info, + /// [`log::LevelFilter:Warn`] + #[serde(alias = "WARN", alias = "WARNING", alias = "Warning")] + Warn, + /// [`log::LevelFilter:Error`] + #[serde(alias = "ERROR")] + Error, +} +impl From for log::LevelFilter { + fn from(filter: LevelFilter) -> log::LevelFilter { + match filter { + LevelFilter::Off => log::LevelFilter::Off, + LevelFilter::Trace => log::LevelFilter::Trace, + LevelFilter::Debug => log::LevelFilter::Debug, + LevelFilter::Info => log::LevelFilter::Info, + LevelFilter::Warn => log::LevelFilter::Warn, + LevelFilter::Error => log::LevelFilter::Error, } } +} - 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) +/// Error type for [`::from_str`]. +#[derive(Debug, PartialEq, Eq, thiserror::Error)] +#[error("Failed to parse string to level filter: {0}")] +pub struct LevelFilterFromStrError(String); + +impl FromStr for LevelFilter { + type Err = LevelFilterFromStrError; + fn from_str(s: &str) -> Result { + match s { + "Off" | "OFF" => Ok(Self::Off), + "Trace" | "TRACE" => Ok(Self::Trace), + "Debug" | "DEBUG" => Ok(Self::Debug), + "Info" | "INFO" => Ok(Self::Info), + "Warn" | "WARN" | "Warning" | "WARNING" => Ok(Self::Warn), + "Error" | "ERROR" => Ok(Self::Error), + _ => Err(LevelFilterFromStrError(String::from(s))), } } +} - 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 - } - } +#[cfg(test)] +mod tests { + use log::Level; - fn validate_log(log_reader: &mut dyn Read, expected: &str) { - let mut log = Vec::new(); - log_reader.read_to_end(&mut log).unwrap(); + use super::*; - assert!(log.len() >= expected.len()); + #[test] + fn levelfilter_from_levelfilter() { assert_eq!( - expected, - std::str::from_utf8(&log[log.len() - expected.len()..]).unwrap() + log::LevelFilter::from(LevelFilter::Off), + log::LevelFilter::Off ); - } - - #[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), + assert_eq!( + log::LevelFilter::from(LevelFilter::Trace), + log::LevelFilter::Trace ); - // 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_eq!( + log::LevelFilter::from(LevelFilter::Debug), + log::LevelFilter::Debug ); - } - - #[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), + assert_eq!( + log::LevelFilter::from(LevelFilter::Info), + log::LevelFilter::Info ); - // 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_eq!( + log::LevelFilter::from(LevelFilter::Warn), + log::LevelFilter::Warn ); - - // 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 - ), + assert_eq!( + log::LevelFilter::from(LevelFilter::Error), + log::LevelFilter::Error ); - 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), + fn levelfilter_from_str() { + assert_eq!( + LevelFilter::from_str("bad"), + Err(LevelFilterFromStrError(String::from("bad"))) ); - // 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), - ); + assert_eq!(LevelFilter::from_str("Off"), Ok(LevelFilter::Off)); + assert_eq!(LevelFilter::from_str("Trace"), Ok(LevelFilter::Trace)); + assert_eq!(LevelFilter::from_str("Debug"), Ok(LevelFilter::Debug)); + assert_eq!(LevelFilter::from_str("Info"), Ok(LevelFilter::Info)); + assert_eq!(LevelFilter::from_str("Warn"), Ok(LevelFilter::Warn)); + assert_eq!(LevelFilter::from_str("Error"), Ok(LevelFilter::Error)); - // 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), - ); + assert_eq!(LevelFilter::from_str("OFF"), Ok(LevelFilter::Off)); + assert_eq!(LevelFilter::from_str("TRACE"), Ok(LevelFilter::Trace)); + assert_eq!(LevelFilter::from_str("DEBUG"), Ok(LevelFilter::Debug)); + assert_eq!(LevelFilter::from_str("INFO"), Ok(LevelFilter::Info)); + assert_eq!(LevelFilter::from_str("WARN"), Ok(LevelFilter::Warn)); + assert_eq!(LevelFilter::from_str("ERROR"), Ok(LevelFilter::Error)); - // 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 - ), - ); + assert_eq!(LevelFilter::from_str("Warning"), Ok(LevelFilter::Warn)); + assert_eq!(LevelFilter::from_str("WARNING"), Ok(LevelFilter::Warn)); } #[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"); - }) + fn logger() { + // Get temp file path. + let file = utils::tempfile::TempFile::new().unwrap(); + let path = file.as_path().to_str().unwrap().to_string(); + drop(file); + + // Create temp file. + let target = std::fs::OpenOptions::new() + .create(true) + .write(true) + .open(&path) .unwrap(); - let r = custom_thread.join(); - assert!(r.is_ok()); - } - - // There was a test `test_static_logger` to cover LOGGER however, - // it had conflict with `vmm_config::test::test_itest_init_logger` - // which also uses tries to initialize logger and fail with an - // already initialized error. - // Since vmm_config::test_init_logger() cover the logger init test - // with more parameters, test_static_logger() was removed. - // This comment is kept here so that we don't try to implement - // test_static_logger() again in the future. - #[test] - fn test_error_messages() { + // Create logger. + let logger = Logger(Mutex::new(LoggerConfiguration { + target: Some(target), + format: LogFormat { + show_level: true, + show_log_origin: true, + }, + })); + + // Assert results of enabled given specific metadata. + assert!(logger.enabled(&Metadata::builder().level(Level::Warn).build())); + assert!(logger.enabled(&Metadata::builder().level(Level::Debug).build())); + + // Log + let metadata = Metadata::builder().level(Level::Error).build(); + let record = Record::builder() + .args(format_args!("Error!")) + .metadata(metadata) + .file(Some("dir/app.rs")) + .line(Some(200)) + .module_path(Some("module::server")) + .build(); + logger.log(&record); + + // Assert calling flush panics. + std::panic::catch_unwind(|| { + logger.flush(); + }) + .unwrap_err(); + + // Asserts result of log. + let contents = std::fs::read_to_string(&path).unwrap(); + let (_time, rest) = contents.split_once(' ').unwrap(); + let thread = thread::current().name().unwrap_or("-").to_string(); assert_eq!( - format!("{}", LoggerError::Init(init::Error::AlreadyInitialized)), - "Logger initialization failure: The component is already initialized." + rest, + format!("[{DEFAULT_INSTANCE_ID}:{thread}:ERROR:dir/app.rs:200] Error!\n") ); + + std::fs::remove_file(path).unwrap(); } } diff --git a/src/vmm/src/logger/mod.rs b/src/vmm/src/logger/mod.rs index 83119a821e7..31272585e32 100644 --- a/src/vmm/src/logger/mod.rs +++ b/src/vmm/src/logger/mod.rs @@ -6,18 +6,17 @@ //! Crate that implements Firecracker specific functionality as far as logging and metrics //! collecting. -mod init; mod logging; mod metrics; -use std::sync::LockResult; - -pub use log::{debug, error, info, log_enabled, trace, warn, Level, LevelFilter}; - -pub use crate::logger::logging::{LoggerError, LOGGER}; +pub use log::{debug, error, info, log_enabled, trace, warn, Level}; +pub use logging::{ + LevelFilter, LevelFilterFromStrError, LoggerConfig, LoggerUpdateError, DEFAULT_INSTANCE_ID, + DEFAULT_LEVEL, INSTANCE_ID, LOGGER, +}; #[cfg(target_arch = "aarch64")] -pub use crate::logger::metrics::RTCDeviceMetrics; -pub use crate::logger::metrics::{ +pub use metrics::RTCDeviceMetrics; +pub use metrics::{ IncMetric, MetricsError, ProcessTimeReporter, SerialDeviceMetrics, SharedIncMetric, SharedStoreMetric, StoreMetric, METRICS, }; @@ -40,15 +39,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/vmm/src/resources.rs b/src/vmm/src/resources.rs index f06bc6d8de4..125db7e6cc2 100644 --- a/src/vmm/src/resources.rs +++ b/src/vmm/src/resources.rs @@ -21,7 +21,6 @@ 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_config::{init_logger, LoggerConfig, LoggerConfigError}; use crate::vmm_config::machine_config::{ MachineConfig, MachineConfigUpdate, VmConfig, VmConfigError, }; @@ -44,7 +43,7 @@ pub enum ResourcesError { /// Invalid JSON: {0} InvalidJson(serde_json::Error), /// Logger error: {0} - Logger(LoggerConfigError), + Logger(crate::logger::LoggerUpdateError), /// Metrics error: {0} Metrics(MetricsConfigError), /// MMDS error: {0} @@ -73,7 +72,7 @@ pub struct VmmConfig { #[serde(rename = "cpu-config")] cpu_config: Option, #[serde(rename = "logger")] - logger: Option, + logger: Option, #[serde(rename = "machine-config")] machine_config: Option, #[serde(rename = "metrics")] @@ -126,8 +125,8 @@ impl VmResources { ) -> Result { let vmm_config = serde_json::from_str::(config_json)?; - if let Some(logger) = vmm_config.logger { - init_logger(logger, instance_info)?; + if let Some(logger_config) = vmm_config.logger { + crate::logger::LOGGER.update(logger_config)?; } if let Some(metrics) = vmm_config.metrics { @@ -478,7 +477,6 @@ mod tests { use super::*; use crate::cpu_config::templates::{CpuTemplateType, StaticCpuTemplate}; use crate::devices::virtio::vsock::VSOCK_DEV_ID; - use crate::logger::{LevelFilter, LOGGER}; use crate::resources::VmResources; use crate::vmm_config::boot_source::{ BootConfig, BootSource, BootSourceConfig, DEFAULT_KERNEL_CMDLINE, @@ -851,13 +849,10 @@ mod tests { HTTP_MAX_PAYLOAD_SIZE, None, ) { - Err(ResourcesError::Logger(LoggerConfigError::InitializationFailure { .. })) => (), + Err(ResourcesError::Logger(crate::logger::LoggerUpdateError(_))) => (), _ => unreachable!(), } - // The previous call enables the logger. We need to disable it. - LOGGER.set_max_level(LevelFilter::Off); - // Invalid path for metrics pipe. json = format!( r#"{{ diff --git a/src/vmm/src/rpc_interface.rs b/src/vmm/src/rpc_interface.rs index 5054cd85609..d7ee989d4ff 100644 --- a/src/vmm/src/rpc_interface.rs +++ b/src/vmm/src/rpc_interface.rs @@ -4,7 +4,6 @@ use std::fmt::{self, Debug}; use std::sync::{Arc, Mutex, MutexGuard}; -use log::{error, info, warn}; use seccompiler::BpfThreadMap; use serde_json::Value; #[cfg(test)] @@ -21,7 +20,7 @@ use super::{ }; use crate::builder::StartMicrovmError; use crate::cpu_config::templates::{CustomCpuTemplate, GuestConfigError}; -use crate::logger::*; +use crate::logger::{error, info, warn, LoggerConfig, *}; use crate::mmds::data_store::{self, Mmds}; use crate::persist::{CreateSnapshotError, RestoreFromSnapshotError, VmInfo}; use crate::resources::VmmConfig; @@ -34,7 +33,6 @@ 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_config::{LoggerConfig, LoggerConfigError}; use crate::vmm_config::machine_config::{MachineConfig, MachineConfigUpdate, VmConfigError}; use crate::vmm_config::metrics::{MetricsConfig, MetricsConfigError}; use crate::vmm_config::mmds::{MmdsConfig, MmdsConfigError}; @@ -152,7 +150,7 @@ pub enum VmmActionError { /// Load microVM snapshot error: {0} LoadSnapshot(LoadSnapshotError), /// {0} - Logger(LoggerConfigError), + Logger(crate::logger::LoggerUpdateError), /// {0} MachineConfig(VmConfigError), /// {0} @@ -399,11 +397,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_config::init_logger(logger_cfg, &self.instance_info) - .map(|()| VmmData::Empty) - .map_err(VmmActionError::Logger) - } + ConfigureLogger(logger_cfg) => crate::logger::LOGGER + .update(logger_cfg) + .map(|()| VmmData::Empty) + .map_err(VmmActionError::Logger), ConfigureMetrics(metrics_cfg) => vmm_config::metrics::init_metrics(metrics_cfg) .map(|()| VmmData::Empty) .map_err(VmmActionError::Metrics), @@ -868,7 +865,6 @@ mod tests { use crate::mmds::data_store::MmdsVersion; use crate::vmm_config::balloon::BalloonBuilder; use crate::vmm_config::drive::{CacheType, FileEngineType}; - use crate::vmm_config::logger_config::LoggerLevel; use crate::vmm_config::machine_config::VmConfig; use crate::vmm_config::snapshot::{MemBackendConfig, MemBackendType}; use crate::vmm_config::vsock::VsockBuilder; @@ -2026,10 +2022,10 @@ mod tests { ); check_runtime_request_err( VmmAction::ConfigureLogger(LoggerConfig { - log_path: PathBuf::new(), - level: LoggerLevel::Debug, - show_level: false, - show_log_origin: false, + log_path: Some(PathBuf::new()), + level: Some(crate::logger::LevelFilter::Debug), + show_level: Some(false), + show_log_origin: Some(false), }), VmmActionError::OperationNotSupportedPostBoot, ); diff --git a/src/vmm/src/vmm_config/logger_config.rs b/src/vmm/src/vmm_config/logger_config.rs deleted file mode 100644 index 9994d3b35ae..00000000000 --- a/src/vmm/src/vmm_config/logger_config.rs +++ /dev/null @@ -1,257 +0,0 @@ -// 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 serde::{de, Deserialize, Deserializer, Serialize}; - -use super::open_file_nonblock; -use crate::logger::{FcLineWriter, LevelFilter, LOGGER}; -use crate::vmm_config::instance_info::InstanceInfo; - -/// 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. - 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. - Info, - /// The most verbose log level. - Debug, -} - -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)), - } - } -} - -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, - } - } -} - -// 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) - }) -} - -/// Strongly typed structure used to describe the logger. -#[derive(Clone, Debug, PartialEq, Eq, Deserialize, Serialize)] -#[serde(deny_unknown_fields)] -pub struct LoggerConfig { - /// Named pipe or file used as output for logs. - pub log_path: PathBuf, - /// The level of the Logger. - #[serde( - default = "LoggerLevel::default", - deserialize_with = "case_insensitive" - )] - pub level: LoggerLevel, - /// When enabled, the logger will append to the output the severity of the log entry. - #[serde(default)] - pub show_level: bool, - /// When enabled, the logger will append the origin of the log entry. - #[serde(default)] - pub show_log_origin: bool, -} - -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, - } - } -} - -/// Errors associated with actions on the `LoggerConfig`. -#[derive(Debug, thiserror::Error)] -pub enum LoggerConfigError { - /// Cannot initialize the logger due to bad user input. - #[error("{}", format!("{:?}", .0).replace('\"', ""))] - InitializationFailure(String), -} - -/// 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())) -} - -#[cfg(test)] -mod tests { - use std::io::{BufRead, BufReader}; - - use utils::tempfile::TempFile; - use utils::time::TimestampUs; - - use super::*; - use crate::devices::pseudo::BootTimer; - use crate::logger::warn; - - #[test] - fn test_init_logger() { - let default_instance_info = InstanceInfo::default(); - - // 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()); - - // 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, - }; - - assert!(init_logger(desc.clone(), &default_instance_info).is_ok()); - assert!(init_logger(desc, &default_instance_info).is_err()); - - // Validate logfile works. - warn!("this is a test"); - - let mut reader = BufReader::new(log_file.into_file()); - - let mut line = String::new(); - loop { - if line.contains("this is a test") { - break; - } - if reader.read_line(&mut line).unwrap() == 0 { - // If it ever gets here, this assert will fail. - assert!(line.contains("this is a test")); - } - } - - // Validate logging the boot time works. - let mut boot_timer = BootTimer::new(TimestampUs::default()); - boot_timer.bus_write(0, &[123]); - - 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 =")); - } - } - } - - #[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); - } - - #[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 - ); - } -} diff --git a/src/vmm/src/vmm_config/mod.rs b/src/vmm/src/vmm_config/mod.rs index 182f61d0033..28c889886b9 100644 --- a/src/vmm/src/vmm_config/mod.rs +++ b/src/vmm/src/vmm_config/mod.rs @@ -22,8 +22,6 @@ pub mod drive; pub mod entropy; /// Wrapper over the microVM general information attached to the microVM. pub mod instance_info; -/// Wrapper for configuring the logger. -pub mod logger_config; /// Wrapper for configuring the memory and CPU of the microVM. pub mod machine_config; /// Wrapper for configuring the metrics. diff --git a/tests/framework/microvm.py b/tests/framework/microvm.py index 493e3ea02b5..979214b294d 100644 --- a/tests/framework/microvm.py +++ b/tests/framework/microvm.py @@ -516,7 +516,7 @@ def spawn( # and leave 0.2 delay between them. if "no-api" not in self.jailer.extra_args: self._wait_create() - if self.log_file: + if self.log_file and log_level in ("Trace", "Debug", "Info"): self.check_log_message("Running Firecracker") @retry(delay=0.2, tries=5, logger=None) diff --git a/tests/integration_tests/functional/test_logging.py b/tests/integration_tests/functional/test_logging.py index 70ae42be2f4..04674930594 100644 --- a/tests/integration_tests/functional/test_logging.py +++ b/tests/integration_tests/functional/test_logging.py @@ -176,6 +176,17 @@ def test_api_requests_logs(test_microvm_with_api): "The API server received a Get request " 'on "/machine-config".' ) + # Re-configure logging. + log_path = Path(microvm.path) / "new_log" + log_path.touch() + microvm.api.logger.put( + log_path=microvm.create_jailed_resource(log_path), + level="Info", + show_level=True, + show_log_origin=True, + ) + microvm.log_file = log_path + # Check that all requests on /mmds are logged without the body. dummy_json = {"latest": {"meta-data": {"ami-id": "dummy"}}} microvm.api.mmds.put(json=dummy_json) @@ -223,8 +234,13 @@ 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 for `Running Firecracker` message. + configured_level_no = LOG_LEVELS.index(to_formal_log_level(log_level)) + info_level_no = LOG_LEVELS.index("INFO") + if info_level_no <= configured_level_no: + assert "Running Firecracker" in lines[0] + + # Check format of messages + for line in lines: check_log_message_format(line, microvm.id, log_level, show_level, show_origin)