refactor: improve logging for build action

crates/cargo-wdk/src/actions/build/build_task.rs

@@ -9,7 +9,7 @@ use std::path::{Path, PathBuf};
 
 use anyhow::Result;
 use mockall_double::double;
-use tracing::{debug, info};
+use tracing::debug;
 
 #[double]
 use crate::providers::exec::CommandExec;
@@ -77,7 +77,7 @@ impl<'a> BuildTask<'a> {
     /// * `BuildTaskError::CargoBuild` - If there is an error running the cargo
     ///   build command
     pub fn run(&self) -> Result<(), BuildTaskError> {
-        info!("Running cargo build for package: {}", self.package_name);
+        debug!("Running cargo build");
         let mut args = vec!["build".to_string()];
         args.push("-p".to_string());
         args.push(self.package_name.to_string());
@@ -102,11 +102,12 @@ impl<'a> BuildTask<'a> {
             .iter()
             .map(std::string::String::as_str)
             .collect::<Vec<&str>>();
+
         // Run cargo build from the provided working directory so that config.toml
         // is respected
         self.command_exec
             .run("cargo", &args, None, Some(self.working_dir))?;
-        debug!("Done");
+        debug!("cargo build done");
         Ok(())
     }
 }

crates/cargo-wdk/src/actions/build/error.rs

@@ -31,10 +31,7 @@ pub enum BuildActionError {
     PackageTask(#[from] PackageTaskError),
     #[error("No valid rust projects in the current working directory: {0}")]
     NoValidRustProjectsInTheDirectory(PathBuf),
-    #[error(
-        "One or more rust (possibly driver) projects failed to build in the emulated workspace: \
-         {0}"
-    )]
+    #[error("One or more packages failed to build in the emulated workspace: {0}")]
     OneOrMoreRustProjectsFailedToBuild(PathBuf),
     #[error("One or more workspace members failed to build in the workspace: {0}")]
     OneOrMoreWorkspaceMembersFailedToBuild(PathBuf),

crates/cargo-wdk/src/actions/build/mod.rs

@@ -141,7 +141,7 @@ impl<'a> BuildAction<'a> {
 
         // Emulated workspaces support
         let dirs = self.fs.read_dir_entries(&self.working_dir)?;
-        info!(
+        debug!(
             "Checking for valid Rust projects in the working directory: {}",
             self.working_dir.display()
         );
@@ -172,55 +172,49 @@ impl<'a> BuildAction<'a> {
             ));
         }
 
-        debug!("Iterating over each dir entry and process valid Rust(possibly driver) projects");
+        info!("Building packages in {}", self.working_dir.display());
+
         let mut failed_atleast_one_project = false;
         for dir in dirs {
-            debug!(
-                "Verifying the dir entry if it is a valid Rust project: {}",
-                dir.path().display()
-            );
+            debug!("Checking dir entry: {}", dir.path().display());
             if !self.fs.dir_file_type(&dir)?.is_dir()
                 || !self.fs.exists(&dir.path().join("Cargo.toml"))
             {
-                debug!("Skipping the dir entry as it is not a valid Rust project");
+                debug!("Dir entry is not a valid Rust package");
                 continue;
             }
 
-            info!(
-                "Processing Rust(possibly driver) project: {}",
-                dir.path()
-                    .file_name()
-                    .expect("package sub directory name ended with \"..\" which is not expected")
-                    .to_string_lossy()
-            );
+            let working_dir_path = dir.path(); // Avoids a short-lived temporary
+            let sub_dir = working_dir_path
+                .file_name()
+                .expect("package sub directory name ended with \"..\" which is not expected")
+                .to_string_lossy();
+
+            debug!("Building package(s) in dir {sub_dir}");
             if let Err(e) = self.run_from_workspace_root(&dir.path()) {
                 failed_atleast_one_project = true;
                 err!(
-                    "Error building the child project: {}, error: {:?}",
-                    dir.path()
-                        .file_name()
-                        .expect(
-                            "package sub directory name ended with \"..\" which is not expected"
-                        )
-                        .to_string_lossy(),
+                    "Error building project: {sub_dir}, error: {:?}",
                     anyhow::Error::new(e)
                 );
             }
         }
 
-        debug!("Done checking for valid Rust(possibly driver) projects in the working directory");
+        debug!("Done building projects in {}", self.working_dir.display());
         if failed_atleast_one_project {
             return Err(BuildActionError::OneOrMoreRustProjectsFailedToBuild(
                 self.working_dir.clone(),
             ));
         }
 
-        info!("Build completed successfully");
+        info!(
+            "Build completed successfully for projects in {}",
+            self.working_dir.display()
+        );
         Ok(())
     }
 
-    // Method to initiate the build and package tasks for the given working
-    // directory and the cargo metadata
+    // Runs build for the given working directory and the cargo metadata
     fn run_from_workspace_root(&self, working_dir: &Path) -> Result<(), BuildActionError> {
         let cargo_metadata = &self.get_cargo_metadata(working_dir)?;
         let wdk_metadata = Wdk::try_from(cargo_metadata);
@@ -251,9 +245,10 @@ impl<'a> BuildAction<'a> {
                 let package_root_path = absolute(package_root_path.as_path())
                     .map_err(|e| BuildActionError::NotAbsolute(package_root_path.clone(), e))?;
                 debug!(
-                    "Processing workspace member package: {}",
+                    "Building workspace member package: {}",
                     package_root_path.display()
                 );
+
                 if let Err(e) = self.build_and_package(
                     &package_root_path,
                     &wdk_metadata,
@@ -318,7 +313,7 @@ impl<'a> BuildAction<'a> {
             }
         }
 
-        info!(
+        debug!(
             "Build completed successfully for path: {}",
             working_dir.display()
         );
@@ -346,7 +341,7 @@ impl<'a> BuildAction<'a> {
         package_name: &str,
         target_dir: &Path,
     ) -> Result<(), BuildActionError> {
-        info!("Processing package: {}", package_name);
+        info!("Building package {package_name}");
         BuildTask::new(
             package_name,
             working_dir,
@@ -361,20 +356,13 @@ impl<'a> BuildAction<'a> {
             debug!("Found wdk metadata in package: {}", package_name);
             wdk_metadata
         } else {
-            warn!(
-                "WDK metadata is not available. Skipping driver build workflow for package: {}",
-                package_name
-            );
+            debug!("Invalid WDK metadata. Skipping package task");
             return Ok(());
         };
 
-        // TODO: Do we need this check anymore?
+        // Identifying non driver packages
         if package.metadata.get("wdk").is_none() {
-            warn!(
-                "No package.metadata.wdk section found. Skipping driver build workflow for \
-                 package: {}",
-                package_name
-            );
+            debug!("Packaging task skipped for non-driver package");
             return Ok(());
         }
 
@@ -383,10 +371,7 @@ impl<'a> BuildAction<'a> {
             .iter()
             .any(|t| t.kind.contains(&TargetKind::CDyLib))
         {
-            warn!(
-                "No cdylib target found. Skipping driver build workflow for package: {}",
-                package_name
-            );
+            warn!("No cdylib target found. Skipping package task");
             return Ok(());
         }
 
@@ -395,10 +380,7 @@ impl<'a> BuildAction<'a> {
         let target_arch = match self.target_arch {
             TargetArch::Default(arch) | TargetArch::Selected(arch) => arch,
         };
-        debug!(
-            "Target architecture for package: {} is: {}",
-            package_name, target_arch
-        );
+        debug!("Target architecture for package: {package_name} is: {target_arch}");
         let mut target_dir = target_dir.to_path_buf();
         if let TargetArch::Selected(arch) = self.target_arch {
             target_dir = target_dir.join(to_target_triple(arch));
@@ -429,7 +411,7 @@ impl<'a> BuildAction<'a> {
         )
         .run()?;
 
-        info!("Processing completed for package: {}", package_name);
+        info!("Finished building {package_name}");
         Ok(())
     }
 }

crates/cargo-wdk/src/actions/build/package_task.rs

@@ -14,7 +14,7 @@ use std::{
 };
 
 use mockall_double::double;
-use tracing::{debug, info};
+use tracing::{debug, info, warn};
 use wdk_build::{CpuArchitecture, DriverConfig};
 
 #[double]
@@ -279,7 +279,7 @@ impl<'a> PackageTask<'a> {
     }
 
     fn run_stampinf(&self) -> Result<(), PackageTaskError> {
-        info!("Running stampinf command.");
+        info!("Running stampinf");
         let wdf_version_flags = match self.driver_model {
             DriverConfig::Kmdf(kmdf_config) => {
                 vec![
@@ -326,7 +326,7 @@ impl<'a> PackageTask<'a> {
     }
 
     fn run_inf2cat(&self) -> Result<(), PackageTaskError> {
-        info!("Running inf2cat command.");
+        info!("Running inf2cat");
         let args = [
             &format!(
                 "/driver:{}",
@@ -346,7 +346,7 @@ impl<'a> PackageTask<'a> {
     }
 
     fn generate_certificate(&self) -> Result<(), PackageTaskError> {
-        debug!("Generating certificate.");
+        debug!("Generating certificate");
         if self.fs.exists(&self.src_cert_file_path) {
             return Ok(());
         }
@@ -359,7 +359,7 @@ impl<'a> PackageTask<'a> {
     }
 
     fn is_self_signed_certificate_in_store(&self) -> Result<bool, PackageTaskError> {
-        debug!("Checking if self signed certificate exists in WDRTestCertStore store.");
+        debug!("Checking if self signed certificate exists in WDRTestCertStore store");
         let args = ["-s", WDR_TEST_CERT_STORE];
 
         match self.command_exec.run("certmgr.exe", &args, None, None) {
@@ -373,7 +373,7 @@ impl<'a> PackageTask<'a> {
     }
 
     fn create_self_signed_cert_in_store(&self) -> Result<(), PackageTaskError> {
-        info!("Creating self signed certificate in WDRTestCertStore store using makecert.");
+        info!("Creating self signed certificate in WDRTestCertStore store using makecert");
         let cert_path = self.src_cert_file_path.to_string_lossy();
         let args = [
             "-r",
@@ -395,7 +395,7 @@ impl<'a> PackageTask<'a> {
     }
 
     fn create_cert_file_from_store(&self) -> Result<(), PackageTaskError> {
-        info!("Creating certificate file from WDRTestCertStore store using certmgr.");
+        info!("Creating certificate file from WDRTestCertStore store using certmgr");
         let cert_path = self.src_cert_file_path.to_string_lossy();
         let args = [
             "-put",
@@ -428,7 +428,7 @@ impl<'a> PackageTask<'a> {
         cert_name: &str,
     ) -> Result<(), PackageTaskError> {
         info!(
-            "Signing {} using signtool.",
+            "Signing {} using signtool",
             file_path
                 .file_name()
                 .expect("Unable to read file name from the path")
@@ -456,7 +456,7 @@ impl<'a> PackageTask<'a> {
 
     fn run_signtool_verify(&self, file_path: &Path) -> Result<(), PackageTaskError> {
         info!(
-            "Verifying {} using signtool.",
+            "Verifying {} using signtool",
             file_path
                 .file_name()
                 .expect("Unable to read file name from the path")
@@ -473,21 +473,22 @@ impl<'a> PackageTask<'a> {
     }
 
     fn run_infverif(&self) -> Result<(), PackageTaskError> {
-        info!("Running infverif command.");
         let additional_args = if self.sample_class {
             let wdk_build_number = self.wdk_build.detect_wdk_build_number()?;
             if MISSING_SAMPLE_FLAG_WDK_BUILD_NUMBER_RANGE.contains(&wdk_build_number) {
                 debug!(
                     "InfVerif in WDK Build {wdk_build_number} is bugged and does not contain the \
                      /samples flag."
                 );
-                info!("Skipping InfVerif for samples class. WDK Build: {wdk_build_number}");
+                warn!("InfVerif skipped for samples class. WDK Build: {wdk_build_number}");
                 return Ok(());
             }
             "/msft"
         } else {
             ""
         };
+
+        info!("Running infverif");
         let mut args = vec![
             "/v",
             match self.driver_model {

crates/cargo-wdk/tests/build_command_test.rs

@@ -16,12 +16,9 @@ fn mixed_package_kmdf_workspace_builds_successfully() {
     with_file_lock(|| {
         let stdout = run_build_cmd("tests/mixed-package-kmdf-workspace");
 
-        assert!(stdout.contains("Processing completed for package: driver"));
-        assert!(stdout.contains(
-            "No package.metadata.wdk section found. Skipping driver build workflow for package: \
-             non_driver_crate"
-        ));
-
+        assert!(stdout.contains("Building package driver"));
+        assert!(stdout.contains("Building package non_driver_crate"));
+        assert!(stdout.contains("Build completed successfully"));
         verify_driver_package_files("tests/mixed-package-kmdf-workspace", "driver", "sys");
     });
 }
@@ -77,16 +74,13 @@ fn emulated_workspace_builds_successfully() {
         let emulated_workspace_path = "tests/emulated-workspace";
         let stdout = run_build_cmd(emulated_workspace_path);
 
+        assert!(stdout.contains("Building package driver_1"));
+        assert!(stdout.contains("Building package driver_2"));
         // Matches warning about WDK metadata not being available for non driver project
         // but a valid rust project
-        assert!(stdout.contains(
-            "WDK metadata is not available. Skipping driver build workflow for package: \
-             rust-project"
-        ));
+        assert!(stdout.contains("Invalid WDK metadata. Skipping package task"));
 
-        assert!(stdout.contains("Processing completed for package: driver_1"));
-        assert!(stdout.contains("Processing completed for package: driver_2"));
-        assert!(stdout.contains(r"Build completed successfully"));
+        assert!(stdout.contains("Build completed successfully"));
 
         let umdf_driver_workspace_path = format!("{emulated_workspace_path}/umdf-driver-workspace");
         verify_driver_package_files(&umdf_driver_workspace_path, "driver_1", "dll");
@@ -100,7 +94,8 @@ fn build_driver_project(driver_type: &str) {
 
     let stdout = run_build_cmd(&driver_path);
 
-    assert!(stdout.contains(&format!("Processing completed for package: {driver_name}")));
+    assert!(stdout.contains(&format!("Building package {driver_name}")));
+    assert!(stdout.contains("Build completed successfully"));
 
     let driver_binary_extension = match driver_type {
         "kmdf" | "wdm" => "sys",