fix: move the logging message where it's effective

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: 96ed457, 332f218

(cherry picked from commit 78c26af)

Signed-off-by: Pablo Barbáchano <[email protected]>

Author: pb8o

src/firecracker/src/main.rs

@@ -264,6 +264,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")]
@@ -287,39 +313,13 @@ 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,
         vmm_version: FIRECRACKER_VERSION.to_string(),
         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),

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<String> = 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(())
     }

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

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.