feat: Improve logging

crates/konfigkoll/src/fs_scan.rs

@@ -25,12 +25,14 @@ pub(crate) struct ScanResult {
     pub path_map: PathMap<'this>,
 }
 
+#[tracing::instrument(skip_all)]
 pub(crate) fn scan_fs(
     interner: &Arc<Interner>,
     backend: &Arc<dyn Files>,
     ignores: &[CompactString],
     trust_mtime: bool,
 ) -> anyhow::Result<(ScanResult, Vec<FsInstruction>)> {
+    tracing::debug!("Scanning filesystem");
     let mut fs_instructions_sys = vec![];
     let mut files = backend.files(interner).with_context(|| {
         format!(
@@ -39,17 +41,20 @@ pub(crate) fn scan_fs(
         )
     })?;
     if backend.may_need_canonicalization() {
+        tracing::debug!("Canonicalizing file entries");
         canonicalize_file_entries(&mut files);
     }
     // Drop mutability
     let files = files;
 
+    tracing::debug!("Building path map");
     let scan_result = ScanResultBuilder {
         files,
         path_map_builder: |files| create_path_map(files.as_slice()),
     }
     .build();
 
+    tracing::debug!("Checking for unexpected files");
     let common_config = CommonFileCheckConfiguration::builder()
         .trust_mtime(trust_mtime)
         .config_files(ConfigFiles::Include)

crates/konfigkoll/src/main.rs

@@ -153,7 +153,7 @@ async fn main() -> anyhow::Result<()> {
     // Script: Do early package phase
     script_engine.run_phase(Phase::ScriptDependencies).await?;
 
-    tracing::info!("Retriving package loading results");
+    tracing::info!("Waiting for package loading results...");
     let (pkgs_sys, package_maps) = package_loader.await??;
     tracing::info!("Got package loading results");
 
@@ -194,7 +194,7 @@ async fn main() -> anyhow::Result<()> {
     // Make sure FS actions are sorted
     script_engine.state_mut().commands_mut().fs_actions.sort();
 
-    tracing::info!("Retriving file system scan results...");
+    tracing::info!("Waiting for file system scan results...");
     let (fs_scan_result, fs_instructions_sys) = fs_instructions_sys.await??;
     tracing::info!("Got file system scan results");
 

crates/konfigkoll/src/pkgs.rs

@@ -11,6 +11,7 @@ use paketkoll_types::{
 };
 use rayon::prelude::*;
 
+#[tracing::instrument(skip_all)]
 pub(crate) fn load_packages(
     interner: &Arc<Interner>,
     backends_pkg: &PackageBackendMap,

crates/konfigkoll_core/src/conversion.rs

@@ -29,21 +29,29 @@ use crate::utils::{IdKey, NumericToNameResolveCache};
 pub fn convert_issues_to_fs_instructions(
     issues: Vec<(Option<PackageRef>, Issue)>,
 ) -> anyhow::Result<Vec<FsInstruction>> {
+    tracing::debug!("Starting conversion of {} issues", issues.len());
     let error_count = AtomicU32::new(0);
     let id_resolver = Mutex::new(NumericToNameResolveCache::new());
 
-    let converted: Vec<FsInstruction> = issues.into_par_iter().map(|issue| {
-        let mut results = vec![];
-        let (_pkg, issue) = issue;
-        match convert_issue(&issue, &mut results, &id_resolver) {
-            Ok(()) => (),
-            Err(err) => {
-                tracing::error!(target: "konfigkoll_core::conversion", "Error converting issue: {err:?} for {}", issue.path().display());
-                error_count.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
+    let converted: Vec<FsInstruction> = issues
+        .into_par_iter()
+        .map(|issue| {
+            let mut results = vec![];
+            let (_pkg, issue) = issue;
+            match convert_issue(&issue, &mut results, &id_resolver) {
+                Ok(()) => (),
+                Err(err) => {
+                    tracing::error!(
+                        "Error converting issue: {err:?} for {}",
+                        issue.path().display()
+                    );
+                    error_count.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
+                }
             }
-        }
-        results
-    }).flatten().collect();
+            results
+        })
+        .flatten()
+        .collect();
 
     tracing::debug!("Conversion done, length: {}", converted.len());
     let error_count = error_count.load(std::sync::atomic::Ordering::Relaxed);
@@ -242,7 +250,7 @@ fn from_fs(
     } else if metadata.file_type().is_socket() {
         // Socket files can only be created by a running program and gets
         // removed on program end. We can't do anything with them.
-        tracing::warn!(target: "konfigkoll_core::conversion", "Ignoring socket file: {:?}", path);
+        tracing::warn!("Ignoring socket file: {:?}", path);
         return Ok(results.into_iter());
     } else {
         anyhow::bail!("Unsupported file type: {:?}", path);

crates/paketkoll_core/src/backend/arch.rs

@@ -45,7 +45,7 @@ pub(crate) struct ArchLinuxBuilder {
 impl ArchLinuxBuilder {
     /// Load pacman config
     fn load_config(&mut self) -> anyhow::Result<pacman_conf::PacmanConfig> {
-        log::debug!(target: "paketkoll_core::backend::arch", "Loading pacman config");
+        log::debug!("Loading pacman config");
         let mut readable = BufReader::new(std::fs::File::open("/etc/pacman.conf")?);
         let pacman_config: pacman_conf::PacmanConfig =
             pacman_conf::PacmanConfig::new(&mut readable)?;
@@ -91,11 +91,11 @@ impl Files for ArchLinux {
         let db_path: &Path = Path::new(&self.pacman_config.db_path);
 
         // Load packages
-        log::debug!(target: "paketkoll_core::backend::arch", "Loading packages");
+        log::debug!("Loading packages");
         let pkgs_and_paths = get_mtree_paths(db_path, interner, self.package_filter)?;
 
         // Load mtrees
-        log::debug!(target: "paketkoll_core::backend::arch", "Loading mtrees");
+        log::debug!("Loading mtrees");
         // Directories are duplicated across packages, we deduplicate them here
         let seen_directories = DashSet::new();
         // It is counter-intuitive, but we are faster if we collect into a vec here and start
@@ -357,7 +357,7 @@ fn download_arch_pkg(pkg: &str) -> Result<(), anyhow::Error> {
         .args(["-Sw", "--noconfirm", pkg])
         .status()?;
     if !status.success() {
-        log::warn!(target: "paketkoll_core::backend::arch", "Failed to download package for {pkg}");
+        log::warn!("Failed to download package for {pkg}");
     };
     Ok(())
 }

crates/paketkoll_core/src/backend/deb.rs

@@ -88,30 +88,30 @@ impl Name for Debian {
 
 impl Files for Debian {
     fn files(&self, interner: &Interner) -> anyhow::Result<Vec<FileEntry>> {
-        log::debug!(target: "paketkoll_core::backend::deb", "Loading packages");
+        log::debug!("Loading packages");
         let packages_files: Vec<_> = get_package_files(interner)?.collect();
 
         // Handle diversions: (parse output of dpkg-divert --list)
-        log::debug!(target: "paketkoll_core::backend::deb", "Loading diversions");
+        log::debug!("Loading diversions");
         let diversions =
             divert::get_diverions(interner).context("Failed to get dpkg diversions")?;
 
         // Load config files.
-        log::debug!(target: "paketkoll_core::backend::deb", "Loading status to get config files");
+        log::debug!("Loading status to get config files");
         let (config_files, _) = {
             let mut status = BufReader::new(File::open(STATUS_PATH)?);
             parsers::parse_status(interner, &mut status, self.primary_architecture)
         }
         .context(format!("Failed to parse {}", STATUS_PATH))?;
 
-        log::debug!(target: "paketkoll_core::backend::deb", "Merging packages files into one map");
+        log::debug!("Merging packages files into one map");
         let merged = DashMap::with_hasher(ahash::RandomState::new());
         packages_files.into_par_iter().for_each(|files| {
             merge_deb_fileentries(&merged, files, &diversions);
         });
 
         // The config files must be merged into the results
-        log::debug!(target: "paketkoll_core::backend::deb", "Merging config files");
+        log::debug!("Merging config files");
         merge_deb_fileentries(&merged, config_files, &diversions);
 
         // For Debian we apply the filter here at the end, since multiple steps
@@ -356,15 +356,15 @@ fn process_file(interner: &Interner, entry: &DirEntry) -> anyhow::Result<Option<
 impl Packages for Debian {
     fn packages(&self, interner: &Interner) -> anyhow::Result<Vec<PackageInterned>> {
         // Parse status
-        log::debug!(target: "paketkoll_core::backend::deb", "Loading status to installed packages");
+        log::debug!("Loading status to installed packages");
         let (_, mut packages) = {
             let mut status = BufReader::new(File::open(STATUS_PATH)?);
             parsers::parse_status(interner, &mut status, self.primary_architecture)
         }
         .context(format!("Failed to parse {}", STATUS_PATH))?;
 
         // Parse extended status
-        log::debug!(target: "paketkoll_core::backend::deb", "Loading extended status to get auto installed packages");
+        log::debug!("Loading extended status to get auto installed packages");
         let extended_packages = {
             let mut status = BufReader::new(File::open(EXTENDED_STATUS_PATH)?);
             parsers::parse_extended_status(interner, &mut status)?
@@ -449,8 +449,7 @@ fn download_deb(pkg: &str) -> Result<(), anyhow::Error> {
         .args(["install", "--reinstall", "-d", pkg])
         .status()?;
     if !status.success() {
-        log::warn!(target: "paketkoll_core::backend::deb",
-                   "Failed to download package for {pkg}");
+        log::warn!("Failed to download package for {pkg}");
     };
     Ok(())
 }

crates/paketkoll_core/src/file_ops.rs

@@ -51,7 +51,7 @@ pub fn check_installed_files(
         .files(&interner)
         .with_context(|| format!("Failed to collect information from backend {backend}"))?;
 
-    log::debug!(target: "paketkoll_core::backend", "Checking file system");
+    log::debug!("Checking file system");
     // For all file entries, check on file system
     // Par-bridge is used here to avoid batching. We do too much work for
     // batching to be useful, and this way we avoid pathological cases with
@@ -96,11 +96,11 @@ pub fn check_all_files(
 
     // Possibly canonicalize paths
     if unexpected_cfg.canonicalize_paths {
-        log::debug!(target: "paketkoll_core::backend", "Canonicalizing paths");
+        log::debug!("Canonicalizing paths");
         canonicalize_file_entries(&mut expected_files);
     }
 
-    log::debug!(target: "paketkoll_core::backend", "Preparing data structures");
+    log::debug!("Preparing data structures");
     // We want a hashmap from path to data here.
     let path_map = create_path_map(&expected_files);
 
@@ -131,7 +131,7 @@ pub fn mismatching_and_unexpected_files<'a>(
     filecheck_config: &crate::config::CommonFileCheckConfiguration,
     unexpected_cfg: &crate::config::CheckAllFilesConfiguration,
 ) -> anyhow::Result<Vec<(Option<PackageRef>, Issue)>> {
-    log::debug!(target: "paketkoll_core::backend", "Building ignores");
+    log::debug!("Building ignores");
     // Build glob set of ignores
     let overrides = {
         let mut builder = OverrideBuilder::new("/");
@@ -146,7 +146,7 @@ pub fn mismatching_and_unexpected_files<'a>(
         builder.build()?
     };
 
-    log::debug!(target: "paketkoll_core::backend", "Walking file system");
+    log::debug!("Walking file system");
     let walker = WalkBuilder::new("/")
         .hidden(false)
         .parents(false)
@@ -217,6 +217,7 @@ pub fn mismatching_and_unexpected_files<'a>(
         })
     });
 
+    log::debug!("Identifying and processing missing files");
     // Identify missing files (we should have seen them walking through the file system)
     expected_files.par_iter().for_each(|file_entry| {
         if file_entry.seen.load(std::sync::atomic::Ordering::Relaxed) {
@@ -248,6 +249,7 @@ pub fn mismatching_and_unexpected_files<'a>(
             .expect("Unbounded queue");
     });
 
+    log::debug!("Collecting results");
     // Collect all items from queue into vec
     let mut mismatches = Vec::new();
     for item in collected_issues.drain() {

crates/paketkoll_core/src/utils.rs

@@ -145,9 +145,9 @@ pub(crate) fn locate_package_file(
 
         // Nothing found, try downloading the package
         if downloaded {
-            log::error!(target: "paketkoll_core::utils", "Failed to find package for {pkg}");
+            log::error!("Failed to find package for {pkg}");
         } else {
-            log::info!(target: "paketkoll_core::utils", "Downloading package for {pkg}");
+            log::info!("Downloading package for {pkg}");
             download_pkg(pkg)?;
         }
     }