windows: Add some trace-level logging to help dig into missing FS update bugs (#40200)

Cole Miller created 3 weeks ago

Related to https://github.com/zed-industries/zed/issues/38109

Release Notes:

- N/A

Change summary

crates/fs/src/fs.rs             | 2 ++
crates/fs/src/fs_watcher.rs     | 8 ++++++++
crates/fs/src/mac_watcher.rs    | 4 ++++
crates/worktree/src/worktree.rs | 3 ++-
4 files changed, 16 insertions(+), 1 deletion(-)

Detailed changes

crates/fs/src/fs.rs

@@ -749,6 +749,7 @@ impl Fs for RealFs {
                         events
                             .into_iter()
                             .map(|event| {
+                                log::trace!("fs path event: {event:?}");
                                 let kind = if event.flags.contains(StreamFlags::ITEM_REMOVED) {
                                     Some(PathEventKind::Removed)
                                 } else if event.flags.contains(StreamFlags::ITEM_CREATED) {
@@ -806,6 +807,7 @@ impl Fs for RealFs {
 
         // Check if path is a symlink and follow the target parent
         if let Some(mut target) = self.read_link(path).await.ok() {
+            log::trace!("watch symlink {path:?} -> {target:?}");
             // Check if symlink target is relative path, if so make it absolute
             if target.is_relative()
                 && let Some(parent) = path.parent()

crates/fs/src/fs_watcher.rs

@@ -46,6 +46,7 @@ impl Drop for FsWatcher {
 
 impl Watcher for FsWatcher {
     fn add(&self, path: &std::path::Path) -> anyhow::Result<()> {
+        log::trace!("watcher add: {path:?}");
         let tx = self.tx.clone();
         let pending_paths = self.pending_path_events.clone();
 
@@ -63,11 +64,15 @@ impl Watcher for FsWatcher {
                 .next_back()
                 && path.starts_with(watched_path.as_ref())
             {
+                log::trace!(
+                    "path to watch is covered by existing registration: {path:?}, {watched_path:?}"
+                );
                 return Ok(());
             }
         }
         #[cfg(target_os = "linux")]
         {
+            log::trace!("path to watch is already watched: {path:?}");
             if self.registrations.lock().contains_key(path) {
                 return Ok(());
             }
@@ -85,6 +90,7 @@ impl Watcher for FsWatcher {
             let path = path.clone();
             |g| {
                 g.add(path, mode, move |event: &notify::Event| {
+                    log::trace!("watcher received event: {event:?}");
                     let kind = match event.kind {
                         EventKind::Create(_) => Some(PathEventKind::Created),
                         EventKind::Modify(_) => Some(PathEventKind::Changed),
@@ -126,6 +132,7 @@ impl Watcher for FsWatcher {
     }
 
     fn remove(&self, path: &std::path::Path) -> anyhow::Result<()> {
+        log::trace!("remove watched path: {path:?}");
         let Some(registration) = self.registrations.lock().remove(path) else {
             return Ok(());
         };
@@ -215,6 +222,7 @@ static FS_WATCHER_INSTANCE: OnceLock<anyhow::Result<GlobalWatcher, notify::Error
     OnceLock::new();
 
 fn handle_event(event: Result<notify::Event, notify::Error>) {
+    log::trace!("global handle event: {event:?}");
     // Filter out access events, which could lead to a weird bug on Linux after upgrading notify
     // https://github.com/zed-industries/zed/actions/runs/14085230504/job/39449448832
     let Some(event) = event

crates/fs/src/mac_watcher.rs

@@ -32,6 +32,7 @@ impl MacWatcher {
 
 impl Watcher for MacWatcher {
     fn add(&self, path: &Path) -> Result<()> {
+        log::trace!("mac watcher add: {:?}", path);
         let handles = self
             .handles
             .upgrade()
@@ -44,6 +45,9 @@ impl Watcher for MacWatcher {
             .next_back()
             && path.starts_with(watched_path)
         {
+            log::trace!(
+                "mac watched path starts with existing watched path: {watched_path:?}, {path:?}"
+            );
             return Ok(());
         }
 

crates/worktree/src/worktree.rs

@@ -2435,6 +2435,7 @@ impl LocalSnapshot {
     }
 
     fn insert_entry(&mut self, mut entry: Entry, fs: &dyn Fs) -> Entry {
+        log::trace!("insert entry {:?}", entry.path);
         if entry.is_file() && entry.path.file_name() == Some(&GITIGNORE) {
             let abs_path = self.absolutize(&entry.path);
             match smol::block_on(build_gitignore(&abs_path, fs)) {
@@ -3758,6 +3759,7 @@ impl BackgroundScanner {
     }
 
     async fn process_events(&self, mut abs_paths: Vec<PathBuf>) {
+        log::trace!("process events: {abs_paths:?}");
         let root_path = self.state.lock().snapshot.abs_path.clone();
         let root_canonical_path = self.fs.canonicalize(root_path.as_path()).await;
         let root_canonical_path = match &root_canonical_path {
@@ -4351,7 +4353,6 @@ impl BackgroundScanner {
         // detected regardless of the order of the paths.
         for (path, metadata) in relative_paths.iter().zip(metadata.iter()) {
             if matches!(metadata, Ok(None)) || doing_recursive_update {
-                log::trace!("remove path {:?}", path);
                 state.remove_path(path);
             }
         }