fix: move the logging message where it's effective

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

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-log-origin").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,39 +312,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.