From ae031a97d2d865db0df2616b45dab3ef8fb0cd01 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Pablo=20Barb=C3=A1chano?= Date: Thu, 12 Oct 2023 18:12:31 +0200 Subject: [PATCH 1/2] fix: move the logging message where it's effective MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Move the message after the logger has been configured, so it actually gets printed. Eliminate redundant message that outputs internal vmm crate version 0.1.0. Fixes: 96ed4576, 332f218 Signed-off-by: Pablo Barbáchano --- src/firecracker/src/main.rs | 52 ++++++------- src/vmm/src/logger/logging.rs | 12 +-- tests/framework/microvm.py | 12 ++- .../functional/test_logging.py | 76 ++++--------------- 4 files changed, 52 insertions(+), 100 deletions(-) diff --git a/src/firecracker/src/main.rs b/src/firecracker/src/main.rs index cf95ff1f995..09bba69fd3e 100644 --- a/src/firecracker/src/main.rs +++ b/src/firecracker/src/main.rs @@ -263,6 +263,32 @@ fn main_exec() -> Result<(), MainError> { return Ok(()); } + // It's safe to unwrap here because the field's been provided with a default value. + let instance_id = arguments.single_value("id").unwrap(); + validate_instance_id(instance_id.as_str()).expect("Invalid instance ID"); + + // Apply the logger configuration. + vmm::logger::INSTANCE_ID + .set(String::from(instance_id)) + .unwrap(); + 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, + }) + .map_err(MainError::LoggerInitialization)?; + info!("Running Firecracker v{FIRECRACKER_VERSION}"); + register_signal_handlers().map_err(MainError::RegisterSignalHandlers)?; #[cfg(target_arch = "aarch64")] @@ -286,10 +312,6 @@ fn main_exec() -> Result<(), MainError> { // deprecating one. // warn_deprecated_parameters(&arguments); - // It's safe to unwrap here because the field's been provided with a default value. - let instance_id = arguments.single_value("id").unwrap(); - validate_instance_id(instance_id.as_str()).expect("Invalid instance ID"); - let instance_info = InstanceInfo { id: instance_id.clone(), state: VmState::NotStarted, @@ -297,28 +319,6 @@ fn main_exec() -> Result<(), MainError> { app_name: "Firecracker".to_string(), }; - let id = arguments.single_value("id").map(|s| s.as_str()).unwrap(); - vmm::logger::INSTANCE_ID.set(String::from(id)).unwrap(); - info!("Running Firecracker v{FIRECRACKER_VERSION}"); - - // 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, - }) - .map_err(MainError::LoggerInitialization)?; - if let Some(metrics_path) = arguments.single_value("metrics-path") { let metrics_config = MetricsConfig { metrics_path: PathBuf::from(metrics_path), diff --git a/src/vmm/src/logger/logging.rs b/src/vmm/src/logger/logging.rs index fb9a27eacc1..58177a84ffb 100644 --- a/src/vmm/src/logger/logging.rs +++ b/src/vmm/src/logger/logging.rs @@ -22,8 +22,6 @@ pub const DEFAULT_LEVEL: log::LevelFilter = log::LevelFilter::Info; 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. /// @@ -62,7 +60,7 @@ impl Logger { .unwrap_or(DEFAULT_LEVEL), ); - let target_changed = if let Some(log_path) = config.log_path { + if let Some(log_path) = config.log_path { let file = std::fs::OpenOptions::new() .custom_flags(libc::O_NONBLOCK) .read(true) @@ -71,9 +69,6 @@ impl Logger { .map_err(LoggerUpdateError)?; guard.target = Some(file); - true - } else { - false }; if let Some(show_level) = config.show_level { @@ -87,11 +82,6 @@ impl Logger { // 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(()) } diff --git a/tests/framework/microvm.py b/tests/framework/microvm.py index 4174c15869c..3de4056a611 100644 --- a/tests/framework/microvm.py +++ b/tests/framework/microvm.py @@ -450,6 +450,8 @@ def spawn( self, log_file="fc.log", log_level="Debug", + log_show_level=False, + log_show_origin=False, metrics_path="fc.ndjson", ): """Start a microVM as a daemon or in a screen session.""" @@ -461,10 +463,14 @@ def spawn( self.log_file = Path(self.path) / log_file self.log_file.touch() self.create_jailed_resource(self.log_file) - # The default value for `level`, when configuring the - # logger via cmd line, is `Warning`. We set the level - # to `Debug` to also have the boot time printed in fifo. + # The default value for `level`, when configuring the logger via cmd + # line, is `Info`. We set the level to `Debug` to also have the boot + # time printed in the log. self.jailer.extra_args.update({"log-path": log_file, "level": log_level}) + if log_show_level: + self.jailer.extra_args["show-level"] = None + if log_show_origin: + self.jailer.extra_args["show-log-origin"] = None if metrics_path is not None: self.metrics_file = Path(self.path) / metrics_path diff --git a/tests/integration_tests/functional/test_logging.py b/tests/integration_tests/functional/test_logging.py index 04674930594..d3520a51424 100644 --- a/tests/integration_tests/functional/test_logging.py +++ b/tests/integration_tests/functional/test_logging.py @@ -3,7 +3,7 @@ """Tests the format of human readable logs. It checks the response of the API configuration calls and the logs that show -up in the configured logging FIFO. +up in the configured logging file. """ import re @@ -71,48 +71,6 @@ def check_log_message_format(log_str, instance_id, level, show_level, show_origi assert tag_level_no <= configured_level_no -def test_no_origin_logs(test_microvm_with_api): - """ - Check that logs do not contain the origin (i.e file and line number). - """ - _test_log_config(microvm=test_microvm_with_api, show_level=True, show_origin=False) - - -def test_no_level_logs(test_microvm_with_api): - """ - Check that logs do not contain the level. - """ - _test_log_config(microvm=test_microvm_with_api, show_level=False, show_origin=True) - - -def test_no_nada_logs(test_microvm_with_api): - """ - Check that logs do not contain either level or origin. - """ - _test_log_config(microvm=test_microvm_with_api, show_level=False, show_origin=False) - - -def test_info_logs(test_microvm_with_api): - """ - Check output of logs when minimum level to be displayed is info. - """ - _test_log_config(microvm=test_microvm_with_api) - - -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") - - -def test_error_logs(test_microvm_with_api): - """ - Check output of logs when minimum level of logs displayed is error. - """ - _test_log_config(microvm=test_microvm_with_api, log_level="Error") - - def test_log_config_failure(test_microvm_with_api): """ Check passing invalid FIFOs is detected and reported as an error. @@ -212,27 +170,25 @@ def test_api_requests_logs(test_microvm_with_api): ) -# pylint: disable=W0102 -def _test_log_config(microvm, log_level="Info", show_level=True, show_origin=True): +@pytest.mark.parametrize( + "log_level,show_level,show_origin", + [ + ("Info", True, True), + ("Info", False, True), + ("Info", True, False), + ("Info", False, False), + ("Error", False, False), + ("Warning", False, False), + ], +) +def test_log_config(uvm_plain, log_level, show_level, show_origin): """Exercises different scenarios for testing the logging config.""" - microvm.spawn(log_file=None) - # only works if log level is Debug - microvm.time_api_requests = False - - # Configure logging. - log_path = Path(microvm.path) / "log" - log_path.touch() - microvm.api.logger.put( - log_path=microvm.create_jailed_resource(log_path), - level=log_level, - show_level=show_level, - show_log_origin=show_origin, + microvm = uvm_plain + microvm.spawn( + log_level=log_level, log_show_level=show_level, log_show_origin=show_origin ) - microvm.log_file = log_path - microvm.basic_config() microvm.start() - lines = microvm.log_data.splitlines() # Check for `Running Firecracker` message. From efbd227b6c55a700a4da0cada152b1b7976468ed Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Pablo=20Barb=C3=A1chano?= Date: Mon, 16 Oct 2023 16:53:07 +0200 Subject: [PATCH 2/2] fix: option --show-log-origin has no effect MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit show-log-origin was turned on by the --show-level option. Use the correct flag to enable it. Fixes: 332f2184 Signed-off-by: Pablo Barbáchano --- CHANGELOG.md | 3 +++ src/firecracker/src/main.rs | 2 +- 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 9eca11f5f79..bb56ed533a6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,9 @@ ### Fixed +- Fixed a bug that ignored the `--show-log-origin` option, preventing it from + printing the source code file of the log messages. + ## [1.5.0] ### Added diff --git a/src/firecracker/src/main.rs b/src/firecracker/src/main.rs index 09bba69fd3e..8c62461c2f3 100644 --- a/src/firecracker/src/main.rs +++ b/src/firecracker/src/main.rs @@ -278,7 +278,7 @@ fn main_exec() -> Result<(), MainError> { .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); + let show_log_origin = arguments.flag_present("show-log-origin").then_some(true); LOGGER .update(LoggerConfig { log_path,