logging cleanup

Cargo.toml

@@ -30,6 +30,7 @@ nix = { version = "0.30.1", features = ["feature", "fs", "mount", "process", "te
 getrandom = { version = "0.2.15" }
 log = { version = "0.4.21", features = ["std"], default-features = false}
 json = { version = "0.12.4", optional = true }
+git-version = { version = "0.3.9" }
 
 [features]
 default = ["systemd", "dmverity", "usb9pfs", "reboot-on-failure"]

src/dmverity.rs

@@ -7,7 +7,7 @@ use std::os::fd::IntoRawFd;
 use std::path::Path;
 
 use getrandom::getrandom;
-use log::debug;
+use log::{debug, info};
 use nix::ioctl_readwrite;
 use nix::libc::dev_t;
 use nix::sys::stat::minor;
@@ -246,7 +246,7 @@ pub fn prepare_dmverity(options: &mut CmdlineOptions) -> Result<bool> {
     let param_data = read_file("/verity-params")?;
     let params = VerityParams::from_string(&param_data)?;
 
-    debug!(
+    info!(
         "Configuring dm-verity rootfs with root-hash = {}",
         params.root_hash
     );

src/init.rs

@@ -12,7 +12,8 @@ use std::os::fd::AsFd;
 use std::os::unix::ffi::OsStrExt;
 use std::panic::set_hook;
 
-use log::{debug, error, LevelFilter};
+use git_version::git_version;
+use log::{error, info};
 #[cfg(feature = "reboot-on-failure")]
 use nix::sys::reboot::{reboot, RebootMode};
 use nix::sys::termios::tcdrain;
@@ -53,12 +54,6 @@ fn setup_console() -> Result<()> {
     Ok(())
 }
 
-pub fn setup_log() -> Result<()> {
-    let logger = Logger::new()?;
-    log::set_boxed_logger(Box::new(logger)).map(|()| log::set_max_level(LevelFilter::Trace))?;
-    Ok(())
-}
-
 fn finalize() {
     /* Make sure all output is written before exiting */
     let _ = tcdrain(io::stdout().as_fd());
@@ -182,7 +177,11 @@ impl<'a> InitContext<'a> {
     pub fn setup(&mut self) -> Result<()> {
         mount_special()?;
 
-        setup_log()?;
+        Logger::enable()?;
+        info!(
+            concat!(env!("CARGO_PKG_NAME"), " version {}"),
+            git_version!(fallback = env!("CARGO_PKG_VERSION"))
+        );
 
         self.options = self.parser.parse_file("/proc/cmdline")?;
 
@@ -260,7 +259,7 @@ impl<'a> InitContext<'a> {
             write!(buf, "{} ", arg.to_bytes().escape_ascii())?;
         }
         writeln!(buf, "...")?;
-        debug!("{}", &buf);
+        info!("{}", &buf);
 
         execv(&args[0], &args)?;
 

src/integration.rs

@@ -7,7 +7,7 @@ use std::fs::{File, OpenOptions};
 use std::io::Write as _;
 use std::path::Path;
 
-use log::{Metadata, Record};
+use log::{LevelFilter, Metadata, Record};
 
 use crate::kmsg::KmsgLogger;
 use crate::util::Result;
@@ -38,6 +38,11 @@ impl IntegrationLogger {
         let kmsg = KmsgLogger::new()?;
         Ok(IntegrationLogger { next: kmsg, vport })
     }
+    pub fn enable() -> Result<()> {
+        let logger = IntegrationLogger::new()?;
+        log::set_boxed_logger(Box::new(logger)).map(|()| log::set_max_level(LevelFilter::Trace))?;
+        Ok(())
+    }
 }
 
 impl log::Log for IntegrationLogger {

src/kmsg.rs

@@ -5,7 +5,7 @@ use std::borrow::Borrow;
 use std::fs::{File, OpenOptions};
 use std::io::Write as _;
 
-use log::{Level, Metadata, Record};
+use log::{Level, LevelFilter, Metadata, Record};
 
 use crate::util::Result;
 
@@ -38,4 +38,9 @@ impl KmsgLogger {
         let kmsg = OpenOptions::new().write(true).open("/dev/kmsg")?;
         Ok(KmsgLogger { kmsg })
     }
+    pub fn enable() -> Result<()> {
+        let logger = KmsgLogger::new()?;
+        log::set_boxed_logger(Box::new(logger)).map(|()| log::set_max_level(LevelFilter::Trace))?;
+        Ok(())
+    }
 }

src/mount.rs

@@ -4,7 +4,7 @@
 use std::fs::{self, remove_dir};
 use std::path::{Path, PathBuf};
 
-use log::{debug, warn};
+use log::{info, warn};
 use nix::{
     mount::{mount, umount, MsFlags},
     sys::utsname::uname,
@@ -23,7 +23,7 @@ pub fn do_mount(
 
     mount(src, dst, fstype, flags, data).map_err(|e| {
         format!(
-            "Failed to mount {} -> {} as {} with flags = {:#x}, data = '{}'): {e}",
+            "Failed to mount {} -> {} as '{}' with flags = {:#x}, data = '{}'): {e}",
             src.unwrap_or_default(),
             dst,
             fstype.unwrap_or_default(),
@@ -75,8 +75,8 @@ pub fn mount_root(
     }
     mkdir("/root")?;
 
-    debug!(
-        "Mounting rootfs {} -> /root as {} with flags = {:#x}, data = '{}'",
+    info!(
+        "Mounting rootfs {} -> /root as '{}' with flags = {:#x}, data = '{}'",
         device.ok_or("No root device argument")?,
         fstype.unwrap_or_default(),
         fsflags.bits(),

src/usbg_9pfs.rs

@@ -5,7 +5,7 @@ use std::fs::{read_dir, write};
 use std::os::unix::fs::symlink;
 use std::{thread, time};
 
-use log::debug;
+use log::info;
 use nix::mount::MsFlags;
 
 use crate::cmdline::CmdlineOptions;
@@ -17,7 +17,7 @@ fn write_file<C: AsRef<[u8]>>(path: &str, content: C) -> Result<()> {
 }
 
 fn setup_9pfs_gadget(options: &mut CmdlineOptions) -> Result<()> {
-    debug!("Initializing USB 9pfs gadget ...");
+    info!("Initializing USB 9pfs gadget ...");
 
     let device = if let Some(root) = &mut options.root {
         if let Some(index) = root.find('/') {
@@ -71,7 +71,7 @@ fn setup_9pfs_gadget(options: &mut CmdlineOptions) -> Result<()> {
     mkdir(&function)?;
     symlink(&function, &link)?;
 
-    debug!("Attaching 9pfs gatget to UDC {device}");
+    info!("Attaching 9pfs gatget to UDC {device}");
     write_file("/sys/kernel/config/usb_gadget/9pfs/UDC", device)?;
 
     let d = time::Duration::new(1, 0);

test/qemu.py

@@ -107,7 +107,7 @@ def __ensure_kernel(self, url, file, sha256):
 
     def run(self):
         args = [f"qemu-system-{self.__arch}"]
-        cmdline = "loglevel=8 panic=-1"
+        cmdline = "loglevel=7 panic=-1"
         match self.__arch:
             case "x86_64":
                 args += ["-machine", "q35"]

test/test_basic.py

@@ -92,9 +92,9 @@ def test_missing_root(genimage, qemu):
     qemu.set_initramfs(genimage.get_initramfs())
     qemu.set_cmdline("root=/dev/vda1")
     result = qemu.run()
-    assert result.rsinit_messages == [
-        {"message": "Timeout reached while waiting for the device"}
-    ]
+    assert result.rsinit_messages[-1] == {
+        "message": "Timeout reached while waiting for the device"
+    }
     assert not result.mountinfo