feat(core): enhance native cache operations with comprehensive logging (#31652)

## Current Behavior

The native cache system has minimal logging, making it difficult to
debug issues or understand what's happening during cache operations.
When problems occur, there's insufficient visibility into:
- File copying operations and their progress
- Output expansion and glob pattern matching
- Cache PUT operation timing and success/failure details
- Directory creation and cleanup processes

## Expected Behavior

With these changes, the native cache system provides comprehensive
logging that:
- Tracks all file operations with sizes and timing
- Provides detailed visibility into glob pattern expansion
- Logs cache PUT operations with performance metrics
- Includes trace-level debugging for troubleshooting
- Makes it easier to diagnose cache-related issues

## Related Issue(s)

This enhancement improves the observability and debugging capabilities
of the native cache system without changing its core functionality.

## Changes Made

- **Enhanced cache PUT operations**: Added timing metrics and detailed
logging for each step
- **Improved file copying**: Added progress tracking, size reporting,
and detailed trace logs
- **Better output expansion**: Added comprehensive logging for glob
pattern analysis and path validation
- **Fixed borrow checker error**: Resolved compilation issue in file_ops
copy function
- **Comprehensive tracing**: Added trace and debug logging throughout
the cache operations

The logging follows a structured approach:
- `trace\!()` for detailed step-by-step operations
- `debug\!()` for summary information and timing metrics
- Proper error context for debugging issues

This makes the native cache system much more observable and easier to
debug when issues arise.

(cherry picked from commit fca5650)

Author: FrozenPandaz

packages/nx/src/native/cache/cache.rs

@@ -1,13 +1,13 @@
 use std::fs::{create_dir_all, read_to_string, write};
 use std::path::{Path, PathBuf};
 use std::time::Instant;
+use tracing::{debug, trace};
 
 use fs_extra::remove_items;
 use napi::bindgen_prelude::*;
 use regex::Regex;
 use rusqlite::params;
 use sysinfo::Disks;
-use tracing::trace;
 
 use crate::native::cache::expand_outputs::_expand_outputs;
 use crate::native::cache::file_ops::_copy;
@@ -136,37 +136,55 @@ impl NxCache {
         outputs: Vec<String>,
         code: i16,
     ) -> anyhow::Result<()> {
+        let start = Instant::now();
         trace!("PUT {}", &hash);
         let task_dir = self.cache_path.join(&hash);
 
         // Remove the task directory
         //
         trace!("Removing task directory: {:?}", &task_dir);
         remove_items(&[&task_dir])?;
+        trace!("Successfully removed task directory: {:?}", &task_dir);
+
         // Create the task directory again
         trace!("Creating task directory: {:?}", &task_dir);
         create_dir_all(&task_dir)?;
+        trace!("Successfully created task directory: {:?}", &task_dir);
 
         // Write the terminal outputs into a file
         let task_outputs_path = self.get_task_outputs_path_internal(&hash);
         trace!("Writing terminal outputs to: {:?}", &task_outputs_path);
         let mut total_size: i64 = terminal_output.len() as i64;
         write(task_outputs_path, terminal_output)?;
+        trace!("Successfully wrote terminal outputs ({} bytes)", total_size);
 
         // Expand the outputs
         let expanded_outputs = _expand_outputs(&self.workspace_root, outputs)?;
+        trace!("Successfully expanded {} outputs", expanded_outputs.len());
 
         // Copy the outputs to the cache
+        let mut copied_files = 0;
         for expanded_output in expanded_outputs.iter() {
             let p = self.workspace_root.join(expanded_output);
             if p.exists() {
                 let cached_outputs_dir = task_dir.join(expanded_output);
                 trace!("Copying {:?} -> {:?}", &p, &cached_outputs_dir);
-                total_size += _copy(p, cached_outputs_dir)?;
+                let copied_size = _copy(p, cached_outputs_dir)?;
+                total_size += copied_size;
+                copied_files += 1;
+                trace!(
+                    "Successfully copied {} ({} bytes)",
+                    expanded_output, copied_size
+                );
             }
         }
+        trace!(
+            "Successfully copied {} files, total cache size: {} bytes",
+            copied_files, total_size
+        );
 
-        self.record_to_cache(hash, code, total_size)?;
+        self.record_to_cache(hash.clone(), code, total_size)?;
+        debug!("PUT {} {:?}", &hash, start.elapsed());
         Ok(())
     }
 

packages/nx/src/native/cache/expand_outputs.rs

@@ -1,6 +1,6 @@
 use hashbrown::HashMap;
 use std::path::{Path, PathBuf};
-use tracing::trace;
+use tracing::{debug, trace};
 
 use crate::native::glob::{build_glob_set, contains_glob_pattern, glob_transform::partition_glob};
 use crate::native::logger::enable_logger;
@@ -19,18 +19,36 @@ where
     P: AsRef<Path>,
 {
     let directory: PathBuf = directory.as_ref().into();
+    trace!(
+        "Expanding {} output entries in directory: {:?}",
+        entries.len(),
+        &directory
+    );
 
     let has_glob_pattern = entries.iter().any(|entry| contains_glob_pattern(entry));
 
     if !has_glob_pattern {
         trace!("No glob patterns found, checking if entries exist");
+        let mut existing_count = 0;
         let existing_directories = entries
             .into_iter()
             .filter(|entry| {
                 let path = directory.join(entry);
-                path.exists()
+                let exists = path.exists();
+                if exists {
+                    existing_count += 1;
+                    trace!("Found existing entry: {}", entry);
+                } else {
+                    trace!("Entry does not exist: {}", entry);
+                }
+                exists
             })
-            .collect();
+            .collect::<Vec<_>>();
+        debug!(
+            "Expanded outputs: found {} existing entries out of {} total",
+            existing_count,
+            existing_directories.len()
+        );
         return Ok(existing_directories);
     }
 
@@ -57,18 +75,33 @@ where
         .collect::<Vec<_>>();
 
     trace!(?negated_globs, ?regular_globs, "Expanding globs");
+    trace!(
+        "Building glob set for {} regular globs",
+        regular_globs.len()
+    );
 
     let glob_set = build_glob_set(&regular_globs)?;
-    let found_paths = nx_walker_sync(directory, Some(&negated_globs))
+    trace!("Successfully built glob set");
+
+    trace!(
+        "Walking directory with {} negated globs",
+        negated_globs.len()
+    );
+    let found_paths = nx_walker_sync(&directory, Some(&negated_globs))
         .filter_map(|path| {
             if glob_set.is_match(&path) {
+                trace!("Glob match found: {}", path.to_normalized_string());
                 Some(path.to_normalized_string())
             } else {
                 None
             }
         })
-        .collect();
+        .collect::<Vec<_>>();
 
+    debug!(
+        "Expanded outputs: found {} paths matching glob patterns",
+        found_paths.len()
+    );
     Ok(found_paths)
 }
 

packages/nx/src/native/cache/file_ops.rs

@@ -2,7 +2,7 @@ use std::path::{Path, PathBuf};
 use std::{fs, io};
 
 use fs_extra::error::ErrorKind;
-use tracing::trace;
+use tracing::{debug, trace};
 
 #[napi]
 pub fn remove(src: String) -> anyhow::Result<()> {
@@ -22,24 +22,41 @@ where
     P: AsRef<Path>,
 {
     let dest: PathBuf = remove_trailing_single_dot(dest);
-
     let dest_parent = dest.parent().unwrap_or(&dest);
-
     let src: PathBuf = src.as_ref().into();
 
+    trace!("Copying {:?} -> {:?}", &src, &dest);
+
     if !dest_parent.exists() {
+        trace!("Creating parent directory: {:?}", dest_parent);
         fs::create_dir_all(dest_parent)?;
+        trace!("Successfully created parent directory: {:?}", dest_parent);
     }
 
     let size = if src.is_dir() {
-        copy_dir_all(&src, dest).map_err(anyhow::Error::new)?
+        trace!("Copying directory: {:?}", &src);
+        let copied_size = copy_dir_all(&src, &dest).map_err(anyhow::Error::new)?;
+        trace!(
+            "Successfully copied directory: {:?} ({} bytes)",
+            &src, copied_size
+        );
+        copied_size
     } else if src.is_symlink() {
-        symlink(fs::read_link(src)?, dest)?;
+        trace!("Copying symlink: {:?}", &src);
+        symlink(fs::read_link(&src)?, &dest)?;
+        trace!("Successfully copied symlink: {:?}", &src);
         0
     } else {
-        fs::copy(src, dest)?
+        trace!("Copying file: {:?}", &src);
+        let copied_size = fs::copy(&src, &dest)?;
+        trace!(
+            "Successfully copied file: {:?} ({} bytes)",
+            &src, copied_size
+        );
+        copied_size
     };
 
+    debug!("Copy completed: {:?} -> {:?} ({} bytes)", &src, &dest, size);
     Ok(size as i64)
 }
 
@@ -71,27 +88,59 @@ fn symlink<P: AsRef<Path>, Q: AsRef<Path>>(original: P, link: Q) -> io::Result<(
 }
 
 fn copy_dir_all(src: impl AsRef<Path>, dst: impl AsRef<Path>) -> io::Result<u64> {
-    trace!("creating directory: {:?}", dst.as_ref());
+    trace!("Creating directory: {:?}", dst.as_ref());
     fs::create_dir_all(&dst)?;
-    trace!("reading source directory: {:?}", src.as_ref());
+    trace!("Successfully created directory: {:?}", dst.as_ref());
+
+    trace!("Reading source directory: {:?}", src.as_ref());
     let mut total_size = 0;
-    for entry in fs::read_dir(src)? {
+    let mut files_copied = 0;
+    let mut dirs_copied = 0;
+    let mut symlinks_copied = 0;
+
+    for entry in fs::read_dir(&src)? {
         let entry = entry?;
         let ty = entry.file_type()?;
+        let entry_name = entry.file_name();
+        let dest_path = dst.as_ref().join(&entry_name);
+
         let size: u64 = if ty.is_dir() {
-            copy_dir_all(entry.path(), dst.as_ref().join(entry.file_name()))?
+            trace!("Copying subdirectory: {:?}", entry.path());
+            let subdir_size = copy_dir_all(entry.path(), dest_path)?;
+            dirs_copied += 1;
+            trace!(
+                "Successfully copied subdirectory: {:?} ({} bytes)",
+                entry_name, subdir_size
+            );
+            subdir_size
         } else if ty.is_symlink() {
-            symlink(
-                fs::read_link(entry.path())?,
-                dst.as_ref().join(entry.file_name()),
-            )?;
-            // Handle this
+            trace!("Copying symlink: {:?}", entry.path());
+            symlink(fs::read_link(entry.path())?, dest_path)?;
+            symlinks_copied += 1;
+            trace!("Successfully copied symlink: {:?}", entry_name);
             0
         } else {
-            fs::copy(entry.path(), dst.as_ref().join(entry.file_name()))?
+            trace!("Copying file: {:?}", entry.path());
+            let file_size = fs::copy(entry.path(), dest_path)?;
+            files_copied += 1;
+            trace!(
+                "Successfully copied file: {:?} ({} bytes)",
+                entry_name, file_size
+            );
+            file_size
         };
         total_size += size;
     }
+
+    debug!(
+        "Directory copy completed: {:?} -> {:?} ({} files, {} dirs, {} symlinks, {} bytes total)",
+        src.as_ref(),
+        dst.as_ref(),
+        files_copied,
+        dirs_copied,
+        symlinks_copied,
+        total_size
+    );
     Ok(total_size)
 }