fix: Outdated/wrong git status

Resolved internal error cause by our FS notifier backend which caused
outdated git status in the picker. This should eliminate the process
completely also improved the logging of errors and improved the
perfromance and logic around the handling background events

Cargo.toml

@@ -22,7 +22,6 @@ path = "src/bin/search_profiler.rs"
 name = "bench_search_only"
 path = "src/bin/bench_search_only.rs"
 
-
 [dependencies]
 blake3 = "1.8.2"
 chrono = { version = "0.4", features = ["serde"] }

lua/fff/rust/background_watcher.rs

@@ -2,9 +2,13 @@ use crate::FILE_PICKER;
 use crate::error::Error;
 use crate::file_picker::FilePicker;
 use crate::git::GitStatusCache;
+use crate::sort_buffer::sort_with_buffer;
 use git2::Repository;
-use notify::{EventKind, RecursiveMode};
-use notify_debouncer_full::{DebounceEventResult, DebouncedEvent, RecommendedCache, new_debouncer};
+use notify::event::{AccessKind, AccessMode};
+use notify::{Config, EventKind, RecursiveMode};
+use notify_debouncer_full::{
+    DebounceEventResult, DebouncedEvent, RecommendedCache, new_debouncer_opt,
+};
 use std::path::{Path, PathBuf};
 use std::sync::{Arc, Mutex};
 use std::time::Duration;
@@ -16,8 +20,8 @@ pub struct BackgroundWatcher {
     debouncer: Arc<Mutex<Option<Debouncer>>>,
 }
 
-const DEBOUNCE_TIMEOUT: Duration = Duration::from_millis(500);
-const MAX_PATHS_THRESHOLD: usize = 50;
+const DEBOUNCE_TIMEOUT: Duration = Duration::from_millis(250);
+const MAX_PATHS_THRESHOLD: usize = 1024;
 
 impl BackgroundWatcher {
     pub fn new(base_path: PathBuf, git_workdir: Option<PathBuf>) -> Result<Self, Error> {
@@ -38,21 +42,26 @@ impl BackgroundWatcher {
         base_path: PathBuf,
         git_workdir: Option<PathBuf>,
     ) -> Result<Debouncer, Error> {
-        let mut debouncer = new_debouncer(
+        // do not follow symlinks as then notifiers spawns a bunch of events for symlinked
+        // files that could be git ignored, we have to property differentiate those and if
+        // the file was edited through a
+        let config = Config::default().with_follow_symlinks(false);
+
+        let mut debouncer = new_debouncer_opt(
             DEBOUNCE_TIMEOUT,
-            Some(DEBOUNCE_TIMEOUT / 4), // tick rate for the event span
+            Some(DEBOUNCE_TIMEOUT / 2), // tick rate for the event span
             {
                 move |result: DebounceEventResult| match result {
                     Ok(events) => {
-                        if !events.is_empty() {
-                            handle_debounced_events(events, &git_workdir);
-                        }
+                        handle_debounced_events(events, &git_workdir);
                     }
                     Err(errors) => {
                         error!("File watcher errors: {:?}", errors);
                     }
                 }
             },
+            RecommendedCache::new(),
+            config,
         )?;
 
         debouncer.watch(base_path.as_path(), RecursiveMode::Recursive)?;
@@ -83,7 +92,7 @@ impl Drop for BackgroundWatcher {
     }
 }
 
-#[tracing::instrument(skip(events), level = Level::DEBUG)]
+#[tracing::instrument(name = "fs_events", skip(events), level = Level::DEBUG)]
 fn handle_debounced_events(events: Vec<DebouncedEvent>, git_workdir: &Option<PathBuf>) {
     // this will be called very often, we have to minimiy the lock time for file picker
     let repo = git_workdir.as_ref().and_then(|p| Repository::open(p).ok());
@@ -95,11 +104,19 @@ fn handle_debounced_events(events: Vec<DebouncedEvent>, git_workdir: &Option<Pat
 
     for debounced_event in &events {
         // It is very important to not react to the access errors because we inevitably
-        // gonna trigger the sync by our own preview
-        if matches!(debounced_event.event.kind, EventKind::Access(_)) {
+        // gonna trigger the sync by our own preview or other unnecessary noise
+        if matches!(
+            debounced_event.event.kind,
+            EventKind::Access(
+                AccessKind::Read
+                    | AccessKind::Open(_)
+                    | AccessKind::Close(AccessMode::Read | AccessMode::Execute)
+            )
+        ) {
             continue;
         }
 
+        tracing::debug!(event = ?debounced_event.event, "Processing FS event");
         for path in &debounced_event.event.paths {
             if is_ignore_definition_path(path) {
                 info!(
@@ -142,16 +159,30 @@ fn handle_debounced_events(events: Vec<DebouncedEvent>, git_workdir: &Option<Pat
     }
 
     if need_full_rescan {
-        error!("NEED A FULL RESCAN");
+        info!(?affected_paths_count, "Triggering full rescan");
+        trigger_full_rescan();
         return;
     }
 
+    // It's important to get the allocated sort
+    sort_with_buffer(paths_to_add_or_modify.as_mut_slice(), |a, b| {
+        a.as_os_str().cmp(b.as_os_str())
+    });
+    paths_to_add_or_modify.dedup_by(|a, b| a.as_os_str().eq(b.as_os_str()));
+
+    info!(
+        "Event processing summary: {} to remove, {} to add/modify",
+        paths_to_remove.len(),
+        paths_to_add_or_modify.len()
+    );
+
     let Some(repo) = repo.as_ref() else {
+        info!("No git repo, skipping git status updates");
         return;
     };
 
     if need_full_git_rescan {
-        info!("Triggering full git rescan by the notification results");
+        info!("Triggering full git rescan");
 
         if let Err(e) = FilePicker::refresh_git_status_global() {
             error!("Failed to refresh git status: {:?}", e);
@@ -160,6 +191,10 @@ fn handle_debounced_events(events: Vec<DebouncedEvent>, git_workdir: &Option<Pat
         return;
     }
 
+    if paths_to_remove.is_empty() && paths_to_add_or_modify.is_empty() {
+        return;
+    }
+
     let files_to_update_git_status = {
         let Ok(mut file_picker_guard) = FILE_PICKER.write() else {
             error!("Failed to acquire file picker write lock");
@@ -180,20 +215,57 @@ fn handle_debounced_events(events: Vec<DebouncedEvent>, git_workdir: &Option<Pat
         let mut files_to_update_git_status = Vec::with_capacity(paths_to_add_or_modify.len());
         for path in paths_to_add_or_modify {
             if let Some(file) = picker.on_create_or_modify(path) {
-                files_to_update_git_status.push(file.relative_path.clone());
+                files_to_update_git_status.push(file.path.clone());
             }
         }
 
         files_to_update_git_status
     };
 
-    let status = GitStatusCache::git_status_for_paths(repo, &files_to_update_git_status);
+    info!(
+        "Fetching git status for {} files",
+        files_to_update_git_status.len()
+    );
+
+    let status = match GitStatusCache::git_status_for_paths(repo, &files_to_update_git_status) {
+        Ok(status) => status,
+        Err(e) => {
+            tracing::error!(?e, "Failed to query git statue");
+            return;
+        }
+    };
+
     // only lock the picker for theshortest possitble time
     if let Ok(mut file_picker_guard) = FILE_PICKER.write()
         && let Some(ref mut picker) = *file_picker_guard
-        && let Err(e) = picker.update_git_statuses(status)
     {
-        error!("Failed to update git statuses: {:?}", e);
+        if let Err(e) = picker.update_git_statuses(status) {
+            error!("Failed to update git statuses: {:?}", e);
+        } else {
+            info!("Successfully updated git statuses in picker");
+        }
+    } else {
+        error!("Failed to acquire picker lock for git status update");
+    }
+}
+
+fn trigger_full_rescan() {
+    info!("Triggering full filesystem rescan");
+
+    let Ok(mut file_picker_guard) = FILE_PICKER.write() else {
+        error!("Failed to acquire file picker write lock for full rescan");
+        return;
+    };
+
+    let Some(ref mut picker) = *file_picker_guard else {
+        error!("File picker not initialized, cannot trigger rescan");
+        return;
+    };
+
+    if let Err(e) = picker.trigger_rescan() {
+        error!("Failed to trigger full rescan: {:?}", e);
+    } else {
+        info!("Full filesystem rescan completed successfully");
     }
 }
 

lua/fff/rust/error.rs

@@ -1,3 +1,5 @@
+use std::path::StripPrefixError;
+
 #[derive(thiserror::Error, Debug)]
 #[non_exhaustive]
 pub enum Error {
@@ -33,6 +35,12 @@ pub enum Error {
     DbCommit(#[source] heed::Error),
     #[error("Failed to start file system watcher: {0}")]
     FileSystemWatch(#[from] notify::Error),
+
+    #[error("Expected a path to be child of another path: {0}")]
+    StripPrefixError(#[from] StripPrefixError),
+
+    #[error("libgit2 error occurred: {0}")]
+    Git(#[from] git2::Error),
 }
 
 impl From<Error> for mlua::Error {
@@ -43,3 +51,5 @@ impl From<Error> for mlua::Error {
         mlua::Error::RuntimeError(string_value)
     }
 }
+
+pub type Result<T> = std::result::Result<T, Error>;

lua/fff/rust/file_picker.rs

@@ -7,13 +7,14 @@ use crate::score::match_and_score_files;
 use crate::types::{FileItem, ScoringContext, SearchResult};
 use git2::{Repository, Status, StatusOptions};
 use rayon::prelude::*;
+use std::fmt::Debug;
 use std::path::{Path, PathBuf};
 use std::sync::{
     Arc,
     atomic::{AtomicBool, AtomicUsize, Ordering},
 };
 use std::time::SystemTime;
-use tracing::{debug, error, info, warn};
+use tracing::{Level, debug, error, info, warn};
 
 use crate::{FILE_PICKER, FRECENCY};
 
@@ -33,7 +34,7 @@ impl FileSync {
 
     fn find_file_index(&self, path: &Path) -> Result<usize, usize> {
         self.files
-            .binary_search_by(|file| file.path.as_path().cmp(path))
+            .binary_search_by(|file| file.path.as_os_str().cmp(path.as_os_str()))
     }
 }
 
@@ -217,14 +218,7 @@ impl FilePicker {
         }
     }
 
-    pub fn update_git_statuses(
-        &mut self,
-        status_cache: Option<GitStatusCache>,
-    ) -> Result<(), Error> {
-        let Some(status_cache) = status_cache else {
-            return Ok(());
-        };
-
+    pub fn update_git_statuses(&mut self, status_cache: GitStatusCache) -> Result<(), Error> {
         debug!(
             statuses_count = status_cache.statuses_len(),
             "Updating git status",
@@ -240,6 +234,8 @@ impl FilePicker {
                     if let Some(frecency) = frecency.as_ref() {
                         file.update_frecency_scores(frecency)?;
                     }
+                } else {
+                    error!(?path, "Couldn't update the git status for path");
                 }
 
                 Ok(())
@@ -280,8 +276,14 @@ impl FilePicker {
             .as_mut()
             .ok_or_else(|| Error::FilePickerMissing)?;
 
-        let statuses_count = git_status.as_ref().map_or(0, |cache| cache.statuses_len());
-        picker.update_git_statuses(git_status)?;
+        let statuses_count = if let Some(git_status) = git_status {
+            let count = git_status.statuses_len();
+            picker.update_git_statuses(git_status)?;
+
+            count
+        } else {
+            0
+        };
 
         Ok(statuses_count)
     }
@@ -336,7 +338,8 @@ impl FilePicker {
         }
     }
 
-    pub fn on_create_or_modify(&mut self, path: impl AsRef<Path>) -> Option<&FileItem> {
+    #[tracing::instrument(skip(self), name = "timing_update", level = Level::DEBUG)]
+    pub fn on_create_or_modify(&mut self, path: impl AsRef<Path> + Debug) -> Option<&FileItem> {
         let path = path.as_ref();
         match self.sync_data.find_file_index(path) {
             Ok(pos) => {
@@ -409,14 +412,17 @@ impl FilePicker {
         self.is_scanning.store(true, Ordering::Relaxed);
         self.scanned_files_count.store(0, Ordering::Relaxed);
 
-        if let Ok(sync) = scan_filesystem(&self.base_path, &self.scanned_files_count) {
-            info!(
-                "Filesystem scan completed: found {} files",
-                sync.files.len()
-            );
-            self.sync_data = sync
-        } else {
-            warn!("Filesystem scan failed");
+        let scan_result = scan_filesystem(&self.base_path, &self.scanned_files_count);
+        match scan_result {
+            Ok(sync) => {
+                info!(
+                    "Filesystem scan completed: found {} files",
+                    sync.files.len()
+                );
+
+                self.sync_data = sync
+            }
+            Err(error) => error!(?error, "Failed to scan file system"),
         }
 
         self.is_scanning.store(false, Ordering::Relaxed);
@@ -517,6 +523,7 @@ fn scan_filesystem(
                     .recurse_untracked_dirs(true)
                     .exclude_submodules(true),
             );
+
             (git_workdir, status_cache)
         });
 

lua/fff/rust/git.rs

@@ -1,9 +1,10 @@
+use crate::error::Result;
 use git2::{Repository, Status, StatusOptions};
 use std::{
     fmt::Debug,
     path::{Path, PathBuf},
 };
-use tracing::{debug, error, info};
+use tracing::debug;
 
 /// Represents a cache of a single git status query, if there is no
 /// status aka file is clear but it was specifically requested to updated
@@ -32,19 +33,12 @@ impl GitStatusCache {
             .and_then(|idx| self.0.get(idx).map(|(_, status)| *status))
     }
 
-    fn read_status_impl(repo: &Repository, status_options: &mut StatusOptions) -> Option<Self> {
-        let status_start = std::time::Instant::now();
-        info!("GIT: Reading git status");
-        let statuses = repo
-            .statuses(Some(status_options))
-            .map_err(|e| {
-                error!("Failed to get git statuses: {}", e);
-                e
-            })
-            .ok()?;
-        let status_time = status_start.elapsed();
-        let repo_path = repo.path().parent()?;
-        info!("GIT: Status query completed in {:?}", status_time);
+    #[tracing::instrument(skip(repo, status_options))]
+    fn read_status_impl(repo: &Repository, status_options: &mut StatusOptions) -> Result<Self> {
+        let statuses = repo.statuses(Some(status_options))?;
+        let Some(repo_path) = repo.workdir() else {
+            return Ok(Self(vec![])); // repo is bare
+        };
 
         let mut entries = Vec::with_capacity(statuses.len());
         for entry in &statuses {
@@ -54,7 +48,7 @@ impl GitStatusCache {
             }
         }
 
-        Some(Self(entries))
+        Ok(Self(entries))
     }
 
     pub fn read_git_status(
@@ -64,20 +58,42 @@ impl GitStatusCache {
         let git_workdir = git_workdir.as_ref()?;
         let repository = Repository::open(git_workdir).ok()?;
 
-        Self::read_status_impl(&repository, status_options)
+        let status = Self::read_status_impl(&repository, status_options);
+
+        match status {
+            Ok(status) => Some(status),
+            Err(e) => {
+                tracing::error!(?e, "Failed to read git status");
+
+                None
+            }
+        }
     }
 
+    #[tracing::instrument(skip(repo), level = tracing::Level::DEBUG)]
     pub fn git_status_for_paths<TPath: AsRef<Path> + Debug>(
         repo: &Repository,
         paths: &[TPath],
-    ) -> Option<Self> {
+    ) -> Result<Self> {
         if paths.is_empty() {
-            return None;
+            return Ok(Self(vec![]));
         }
 
-        debug!(?paths, "Git partial git status for paths");
-        let mut status_options = StatusOptions::new();
+        let Some(workdir) = repo.workdir() else {
+            return Ok(Self(vec![]));
+        };
 
+        // git pathspec is pretty slow and requires to walk the whole directory
+        // so for a single file which is the most general use case we query directly the file
+        if paths.len() == 1 {
+            let full_path = paths[0].as_ref();
+            let relative_path = full_path.strip_prefix(workdir)?;
+            let status = repo.status_file(relative_path)?;
+
+            return Ok(Self(vec![(full_path.to_path_buf(), status)]));
+        }
+
+        let mut status_options = StatusOptions::new();
         status_options
             .include_untracked(true)
             .recurse_untracked_dirs(true)
@@ -85,17 +101,16 @@ impl GitStatusCache {
             .include_unmodified(true);
 
         for path in paths {
-            status_options.pathspec(path.as_ref());
+            status_options.pathspec(path.as_ref().strip_prefix(workdir)?);
         }
 
-        let statuses = Self::read_status_impl(repo, &mut status_options)?;
+        let git_status_cache = Self::read_status_impl(repo, &mut status_options)?;
         debug!(
-            "Git partial status for paths {:?} returned {} entries",
-            statuses,
-            statuses.statuses_len()
+            status_len = git_status_cache.statuses_len(),
+            "Multiple files git status"
         );
 
-        Some(statuses)
+        Ok(git_status_cache)
     }
 }
 

lua/fff/rust/lib.rs

@@ -15,7 +15,7 @@ pub mod git;
 mod location;
 mod path_utils;
 pub mod score;
-mod sort_buffer;
+pub mod sort_buffer;
 mod tracing;
 pub mod types;
 use mimalloc::MiMalloc;

lua/fff/rust/tracing.rs

@@ -1,6 +1,7 @@
 use crate::error::Error;
 use std::path::Path;
 use tracing_appender::non_blocking;
+use tracing_subscriber::fmt::format::FmtSpan;
 use tracing_subscriber::{EnvFilter, fmt, prelude::*};
 
 static TRACING_INITIALIZED: std::sync::OnceLock<tracing_appender::non_blocking::WorkerGuard> =
@@ -51,7 +52,8 @@ pub fn init_tracing(log_file_path: &str, log_level: Option<&str>) -> Result<Stri
                     .with_thread_names(false)
                     .with_file(true)
                     .with_line_number(true)
-                    .with_ansi(false),
+                    .with_ansi(false)
+                    .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE),
             )
             .with(
                 EnvFilter::builder()