Merge pull request #121 from nix-community/tool-configurable-logging

tool: init configurable logging

flake.nix

@@ -138,7 +138,6 @@
             # tell lanzatool where to find our UEFI binaries.
             makeWrapper ${tool}/bin/lzbt $out/bin/lzbt \
               --set PATH ${lib.makeBinPath [ pkgs.binutils-unwrapped pkgs.sbsigntool ]} \
-              --set RUST_BACKTRACE full \
               --set LANZABOOTE_STUB ${stub}/bin/lanzaboote_stub.efi
           '';
         in

rust/tool/Cargo.lock

@@ -2,6 +2,15 @@
 # It is not intended for manual editing.
 version = 3
 
+[[package]]
+name = "android_system_properties"
+version = "0.1.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "819e7219dbd41043ac279b19830f2efc897156490d7fd6ea916720117ee66311"
+dependencies = [
+ "libc",
+]
+
 [[package]]
 name = "anyhow"
 version = "1.0.69"
@@ -22,6 +31,23 @@ dependencies = [
  "wait-timeout",
 ]
 
+[[package]]
+name = "atty"
+version = "0.2.14"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d9b39be18770d11421cdb1b9947a45dd3f37e93092cbf377614828a319d5fee8"
+dependencies = [
+ "hermit-abi 0.1.19",
+ "libc",
+ "winapi",
+]
+
+[[package]]
+name = "autocfg"
+version = "1.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d468802bab17cbc0cc575e9b053f41e72aa36bfa6b7f55e3529ffa43161b97fa"
+
 [[package]]
 name = "bitflags"
 version = "1.3.2"
@@ -58,6 +84,12 @@ dependencies = [
  "serde",
 ]
 
+[[package]]
+name = "bumpalo"
+version = "3.12.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "0d261e256854913907f67ed06efbc3338dfe6179796deefc1ff763fc1aee5535"
+
 [[package]]
 name = "cc"
 version = "1.0.79"
@@ -70,6 +102,20 @@ version = "1.0.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd"
 
+[[package]]
+name = "chrono"
+version = "0.4.23"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "16b0a3d9ed01224b22057780a37bb8c5dbfe1be8ba48678e7bf57ec4b385411f"
+dependencies = [
+ "iana-time-zone",
+ "js-sys",
+ "num-integer",
+ "num-traits",
+ "wasm-bindgen",
+ "winapi",
+]
+
 [[package]]
 name = "clap"
 version = "4.1.6"
@@ -107,6 +153,22 @@ dependencies = [
  "os_str_bytes",
 ]
 
+[[package]]
+name = "codespan-reporting"
+version = "0.11.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "3538270d33cc669650c4b093848450d380def10c331d38c768e34cac80576e6e"
+dependencies = [
+ "termcolor",
+ "unicode-width",
+]
+
+[[package]]
+name = "core-foundation-sys"
+version = "0.8.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "5827cebf4670468b8772dd191856768aedcb1b0278a04f989f7766351917b9dc"
+
 [[package]]
 name = "cpufeatures"
 version = "0.2.5"
@@ -126,6 +188,50 @@ dependencies = [
  "typenum",
 ]
 
+[[package]]
+name = "cxx"
+version = "1.0.91"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "86d3488e7665a7a483b57e25bdd90d0aeb2bc7608c8d0346acf2ad3f1caf1d62"
+dependencies = [
+ "cc",
+ "cxxbridge-flags",
+ "cxxbridge-macro",
+ "link-cplusplus",
+]
+
+[[package]]
+name = "cxx-build"
+version = "1.0.91"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "48fcaf066a053a41a81dfb14d57d99738b767febb8b735c3016e469fac5da690"
+dependencies = [
+ "cc",
+ "codespan-reporting",
+ "once_cell",
+ "proc-macro2",
+ "quote",
+ "scratch",
+ "syn",
+]
+
+[[package]]
+name = "cxxbridge-flags"
+version = "1.0.91"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "a2ef98b8b717a829ca5603af80e1f9e2e48013ab227b68ef37872ef84ee479bf"
+
+[[package]]
+name = "cxxbridge-macro"
+version = "1.0.91"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "086c685979a698443656e5cf7856c95c642295a38599f12fb1ff76fb28d19892"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
 [[package]]
 name = "difflib"
 version = "0.4.0"
@@ -250,12 +356,45 @@ version = "0.4.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "2540771e65fc8cb83cd6e8a237f70c319bd5c29f78ed1084ba5d50eeac86f7f9"
 
+[[package]]
+name = "hermit-abi"
+version = "0.1.19"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "62b467343b94ba476dcb2500d242dadbb39557df889310ac77c5d99100aaac33"
+dependencies = [
+ "libc",
+]
+
 [[package]]
 name = "hermit-abi"
 version = "0.3.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "fed44880c466736ef9a5c5b5facefb5ed0785676d0c02d612db14e54f0d84286"
 
+[[package]]
+name = "iana-time-zone"
+version = "0.1.53"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "64c122667b287044802d6ce17ee2ddf13207ed924c712de9a66a5814d5b64765"
+dependencies = [
+ "android_system_properties",
+ "core-foundation-sys",
+ "iana-time-zone-haiku",
+ "js-sys",
+ "wasm-bindgen",
+ "winapi",
+]
+
+[[package]]
+name = "iana-time-zone-haiku"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "0703ae284fc167426161c2e3f1da3ea71d94b21bedbcc9494e92b28e334e3dca"
+dependencies = [
+ "cxx",
+ "cxx-build",
+]
+
 [[package]]
 name = "instant"
 version = "0.1.12"
@@ -281,7 +420,7 @@ version = "0.4.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "21b6b32576413a8e69b90e952e4a026476040d81017b80445deda5f2d3921857"
 dependencies = [
- "hermit-abi",
+ "hermit-abi 0.3.1",
  "io-lifetimes",
  "rustix",
  "windows-sys 0.45.0",
@@ -302,6 +441,15 @@ version = "1.0.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "4217ad341ebadf8d8e724e264f13e593e0648f5b3e94b3896a5df283be015ecc"
 
+[[package]]
+name = "js-sys"
+version = "0.3.61"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "445dde2150c55e483f3d8416706b97ec8e8237c307e5b7b4b8dd15e6af2a0730"
+dependencies = [
+ "wasm-bindgen",
+]
+
 [[package]]
 name = "lanzaboote_tool"
 version = "0.1.0"
@@ -314,11 +462,13 @@ dependencies = [
  "fastrand",
  "filetime",
  "goblin",
+ "log",
  "nix",
  "rand",
  "serde",
  "serde_json",
  "sha2",
+ "stderrlog",
  "tempfile",
  "time",
  "walkdir",
@@ -330,6 +480,15 @@ version = "0.2.137"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "fc7fcc620a3bff7cdd7a365be3376c97191aeaccc2a603e600951e452615bf89"
 
+[[package]]
+name = "link-cplusplus"
+version = "1.0.8"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ecd207c9c713c34f95a097a5b029ac2ce6010530c7b49d7fea24d977dede04f5"
+dependencies = [
+ "cc",
+]
+
 [[package]]
 name = "linux-raw-sys"
 version = "0.1.4"
@@ -363,6 +522,25 @@ dependencies = [
  "static_assertions",
 ]
 
+[[package]]
+name = "num-integer"
+version = "0.1.45"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "225d3389fb3509a24c93f5c29eb6bde2586b98d9f016636dff58d7c6f7569cd9"
+dependencies = [
+ "autocfg",
+ "num-traits",
+]
+
+[[package]]
+name = "num-traits"
+version = "0.2.15"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "578ede34cf02f8924ab9447f50c28075b4d3e5b269972345e7e0372b38c6cdcd"
+dependencies = [
+ "autocfg",
+]
+
 [[package]]
 name = "once_cell"
 version = "1.16.0"
@@ -530,6 +708,12 @@ dependencies = [
  "winapi-util",
 ]
 
+[[package]]
+name = "scratch"
+version = "1.0.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ddccb15bcce173023b3fedd9436f882a0739b8dfb45e4f6b6002bee5929f61b2"
+
 [[package]]
 name = "scroll"
 version = "0.11.0"
@@ -598,6 +782,19 @@ version = "1.1.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "a2eb9349b6444b326872e140eb1cf5e7c522154d69e7a0ffb0fb81c06b37543f"
 
+[[package]]
+name = "stderrlog"
+version = "0.5.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "69a26bbf6de627d389164afa9783739b56746c6c72c4ed16539f4ff54170327b"
+dependencies = [
+ "atty",
+ "chrono",
+ "log",
+ "termcolor",
+ "thread_local",
+]
+
 [[package]]
 name = "strsim"
 version = "0.10.0"
@@ -643,6 +840,16 @@ version = "0.4.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "95059e91184749cb66be6dc994f67f182b6d897cb3df74a5bf66b5e709295fd8"
 
+[[package]]
+name = "thread_local"
+version = "1.1.7"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "3fdd6f064ccff2d6567adcb3873ca630700f00b5ad3f060c25b5dcfd9a4ce152"
+dependencies = [
+ "cfg-if",
+ "once_cell",
+]
+
 [[package]]
 name = "time"
 version = "0.3.20"
@@ -671,6 +878,12 @@ version = "1.0.5"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "6ceab39d59e4c9499d4e5a8ee0e2735b891bb7308ac83dfb4e80cad195c9f6f3"
 
+[[package]]
+name = "unicode-width"
+version = "0.1.10"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c0edd1e5b14653f783770bce4a4dabb4a5108a5370a5f5d8cfe8710c361f6c8b"
+
 [[package]]
 name = "version_check"
 version = "0.9.4"
@@ -703,6 +916,60 @@ version = "0.11.0+wasi-snapshot-preview1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "9c8d87e72b64a3b4db28d11ce29237c246188f4f51057d65a7eab63b7987e423"
 
+[[package]]
+name = "wasm-bindgen"
+version = "0.2.84"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "31f8dcbc21f30d9b8f2ea926ecb58f6b91192c17e9d33594b3df58b2007ca53b"
+dependencies = [
+ "cfg-if",
+ "wasm-bindgen-macro",
+]
+
+[[package]]
+name = "wasm-bindgen-backend"
+version = "0.2.84"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "95ce90fd5bcc06af55a641a86428ee4229e44e07033963a2290a8e241607ccb9"
+dependencies = [
+ "bumpalo",
+ "log",
+ "once_cell",
+ "proc-macro2",
+ "quote",
+ "syn",
+ "wasm-bindgen-shared",
+]
+
+[[package]]
+name = "wasm-bindgen-macro"
+version = "0.2.84"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "4c21f77c0bedc37fd5dc21f897894a5ca01e7bb159884559461862ae90c0b4c5"
+dependencies = [
+ "quote",
+ "wasm-bindgen-macro-support",
+]
+
+[[package]]
+name = "wasm-bindgen-macro-support"
+version = "0.2.84"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "2aff81306fcac3c7515ad4e177f521b5c9a15f2b08f4e32d823066102f35a5f6"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+ "wasm-bindgen-backend",
+ "wasm-bindgen-shared",
+]
+
+[[package]]
+name = "wasm-bindgen-shared"
+version = "0.2.84"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "0046fef7e28c3804e5e38bfa31ea2a0f73905319b677e57ebe37e49358989b5d"
+
 [[package]]
 name = "winapi"
 version = "0.3.9"

rust/tool/Cargo.toml

@@ -25,6 +25,8 @@ sha2 = "0.10.6"
 # Keep the fastrand version aligned with the one from tempfile to avoid two
 # different versions.
 fastrand = "1.9.0"
+log = { version = "0.4.17", features = ["std"] }
+stderrlog = "0.5.4"
 
 [dev-dependencies]
 assert_cmd = "2.0.8"

rust/tool/src/cli.rs

@@ -6,8 +6,19 @@ use clap::{Parser, Subcommand};
 use crate::install;
 use crate::signature::KeyPair;
 
+/// The default log level.
+///
+/// 2 corresponds to the level INFO.
+const DEFAULT_LOG_LEVEL: usize = 2;
+
 #[derive(Parser)]
 pub struct Cli {
+    /// Silence all output
+    #[arg(short, long)]
+    quiet: bool,
+    /// Verbose mode (-v, -vv, etc.)
+    #[arg(short, long, action = clap::ArgAction::Count)]
+    verbose: u8,
     #[clap(subcommand)]
     commands: Commands,
 }
@@ -47,8 +58,19 @@ struct InstallCommand {
 }
 
 impl Cli {
-    pub fn call(self) -> Result<()> {
+    pub fn call(self, module: &str) {
-        self.commands.call()
+        stderrlog::new()
+            .module(module)
+            .show_level(false)
+            .quiet(self.quiet)
+            .verbosity(DEFAULT_LOG_LEVEL + usize::from(self.verbose))
+            .init()
+            .expect("Failed to setup logger.");
+
+        if let Err(e) = self.commands.call() {
+            log::error!("{e:#}");
+            std::process::exit(1);
+        };
     }
 }
 

rust/tool/src/gc.rs

@@ -64,7 +64,7 @@ impl Roots {
         for e in entries_not_in_use {
             let entry = e?;
             let path = entry.path();
-            println!("'{}' not in use anymore. Removing...", path.display());
+            log::debug!("Garbage collecting {path:?}...");
 
             if path.is_dir() {
                 // If a directory is marked as unused all its children can be deleted too.

rust/tool/src/install.rs

@@ -55,6 +55,8 @@ impl Installer {
     }
 
     pub fn install(&mut self) -> Result<()> {
+        log::info!("Installing Lanzaboote to {:?}...", self.esp_paths.esp);
+
         let mut links = self
             .generation_links
             .iter()
@@ -83,6 +85,7 @@ impl Installer {
 
         self.install_systemd_boot()?;
 
+        log::info!("Collecting garbage...");
         // Only collect garbage in these two directories. This way, no files that do not belong to
         // the NixOS installation are deleted. Lanzatool takes full control over the esp/EFI/nixos
         // directory and deletes ALL files that it doesn't know about. Dual- or multiboot setups
@@ -98,6 +101,7 @@ impl Installer {
                     .map_or(false, |n| n.starts_with("nixos-"))
             })?;
 
+        log::info!("Successfully installed Lanzaboote.");
         Ok(())
     }
 
@@ -164,11 +168,15 @@ impl Installer {
                 .with_context(|| format!("Failed to build generation from link: {link:?}"));
 
             // Ignore failing to read a generation so that old malformed generations do not stop
-            // lanzatool from working.
+            // lzbt from working.
             let generation = match generation_result {
                 Ok(generation) => generation,
                 Err(e) => {
-                    println!("Malformed generation: {:?}", e);
+                    log::info!(
+                        "Ignoring generation {} because it's malformed.",
+                        link.version
+                    );
+                    log::debug!("{e:#}");
                     continue;
                 }
             };
@@ -307,7 +315,16 @@ impl Installer {
         ];
 
         for (from, to) in paths {
-            if newer_systemd_boot(from, to)? || !&self.key_pair.verify(to) {
+            let newer_systemd_boot_available = newer_systemd_boot(from, to)?;
+            if newer_systemd_boot_available {
+                log::info!("Updating systemd-boot...")
+            };
+            let systemd_boot_is_signed = &self.key_pair.verify(to);
+            if !systemd_boot_is_signed {
+                log::warn!("systemd-boot is not signed. Replacing it with a signed binary...")
+            };
+
+            if newer_systemd_boot_available || !systemd_boot_is_signed {
                 force_install_signed(&self.key_pair, from, to)
                     .with_context(|| format!("Failed to install systemd-boot binary to: {to:?}"))?;
             }
@@ -434,7 +451,7 @@ fn install_signed(key_pair: &KeyPair, from: &Path, to: &Path) -> Result<()> {
 /// `.tmp` suffix and then renamed to its final name. This is atomic, because a rename is an atomic
 /// operation on POSIX platforms.
 fn force_install_signed(key_pair: &KeyPair, from: &Path, to: &Path) -> Result<()> {
-    println!("Signing and installing {}...", to.display());
+    log::debug!("Signing and installing {to:?}...");
     let to_tmp = to.with_extension(".tmp");
     ensure_parent_dir(&to_tmp);
     key_pair
@@ -466,7 +483,7 @@ fn install(from: &Path, to: &Path) -> Result<()> {
 /// file at the destination to 0o755, the expected permissions for a vfat ESP. This is useful for
 /// producing file systems trees which can then be converted to a file system image.
 fn force_install(from: &Path, to: &Path) -> Result<()> {
-    println!("Installing {}...", to.display());
+    log::debug!("Installing {to:?}...");
     ensure_parent_dir(to);
     atomic_copy(from, to)?;
     set_permission_bits(to, 0o755)

rust/tool/src/main.rs

@@ -9,11 +9,10 @@ mod signature;
 mod systemd;
 mod utils;
 
-use anyhow::Result;
 use clap::Parser;
 
 use cli::Cli;
 
-fn main() -> Result<()> {
+fn main() {
-    Cli::parse().call()
+    Cli::parse().call(module_path!())
 }

rust/tool/src/signature.rs

@@ -34,11 +34,9 @@ impl KeyPair {
         if !output.status.success() {
             std::io::stderr()
                 .write_all(&output.stderr)
-                .context("Failed to write output of sbsign to stderr")?;
+                .context("Failed to write output of sbsign to stderr.")?;
-            return Err(anyhow::anyhow!(
+            log::debug!("sbsign failed with args: `{args:?}`.");
-                "Failed to sign file using sbsign with args `{:?}`",
+            return Err(anyhow::anyhow!("Failed to sign {to:?}."));
-                &args
-            ));
         }
 
         Ok(())
@@ -61,10 +59,7 @@ impl KeyPair {
             if std::io::stderr().write_all(&output.stderr).is_err() {
                 return false;
             };
-            println!(
+            log::debug!("sbverify failed with args: `{args:?}`.");
-                "Failed to verify signature using sbverify with args `{:?}`",
-                &args
-            );
             return false;
         }
         true

rust/tool/tests/common/mod.rs

@@ -132,6 +132,7 @@ pub fn lanzaboote_install(
     let mut cmd = Command::cargo_bin("lzbt")?;
     let output = cmd
         .env("LANZABOOTE_STUB", test_systemd_stub)
+        .arg("-vv")
         .arg("install")
         .arg("--systemd")
         .arg(test_systemd)