fix: filter file watcher duplicate events (#200)

* refactor: log millis and added logging

* fix: use notify-debouncer-full to filter multiple events

* chore: fmt

* Send notifications for file creation too

* Use `inlyne=trace` instead of debug for tests

* Fix renames

* Drain any initial notifications

---------

Co-authored-by: Cosmic Horror <[email protected]>

Cargo.toml

@@ -67,6 +67,7 @@ two-face = "0.3.0"
 # Required for WGPU to work properly with Vulkan
 fontdb = { version = "0.13.1", features = ["fontconfig"] }
 human-panic = "1.2.2"
+notify-debouncer-full = { version = "0.3.1", default-features = false }
 
 [dependencies.glyphon]
 version = "0.2"

src/file_watcher/mod.rs

@@ -8,7 +8,10 @@ use std::time::Duration;
 use crate::InlyneEvent;
 
 use notify::event::{EventKind, ModifyKind};
-use notify::{Event, EventHandler, RecommendedWatcher, RecursiveMode, Watcher as _};
+use notify::{Event, RecommendedWatcher, RecursiveMode, Watcher as _};
+use notify_debouncer_full::{
+    new_debouncer, DebounceEventHandler, DebounceEventResult, Debouncer, FileIdMap,
+};
 use winit::event_loop::EventLoopProxy;
 
 trait Callback: Send + 'static {
@@ -35,10 +38,43 @@ enum WatcherMsg {
 
 struct MsgHandler(mpsc::Sender<WatcherMsg>);
 
-impl EventHandler for MsgHandler {
-    fn handle_event(&mut self, event: notify::Result<Event>) {
-        let msg = WatcherMsg::Notify(event);
-        let _ = self.0.send(msg);
+impl DebounceEventHandler for MsgHandler {
+    fn handle_event(&mut self, debounced_event: DebounceEventResult) {
+        log::debug!("Received debounced file events: {:#?}", debounced_event);
+
+        match debounced_event {
+            Ok(events) => {
+                let mut selected_event: Option<Event> = None;
+
+                // select the most interesting event
+                // Rename/Remove is more interesting than changing the contents
+                for ev in events {
+                    match ev.event.kind {
+                        EventKind::Modify(ModifyKind::Name(_)) | EventKind::Remove(_) => {
+                            let _ = selected_event.insert(ev.event);
+                        }
+                        EventKind::Create(_) | EventKind::Modify(_) => {
+                            let _ = selected_event.get_or_insert(ev.event);
+                        }
+                        _ => {}
+                    }
+                }
+
+                if let Some(event) = selected_event {
+                    let msg = WatcherMsg::Notify(Ok(event));
+                    let _ = self.0.send(msg);
+                } else {
+                    log::trace!("Ignoring events")
+                }
+            }
+            Err(err) => {
+                // log all errors
+                for e in err {
+                    let msg = WatcherMsg::Notify(Err(e));
+                    let _ = self.0.send(msg);
+                }
+            }
+        }
     }
 }
 
@@ -54,7 +90,7 @@ impl Watcher {
         let watcher = Self(msg_tx.clone());
 
         let notify_watcher =
-            RecommendedWatcher::new(MsgHandler(msg_tx), notify::Config::default()).unwrap();
+            new_debouncer(Duration::from_millis(10), None, MsgHandler(msg_tx)).unwrap();
 
         std::thread::spawn(move || {
             endlessly_handle_messages(notify_watcher, msg_rx, reload_callback, file_path);
@@ -73,11 +109,12 @@ impl Watcher {
 }
 
 fn endlessly_handle_messages<C: Callback>(
-    mut watcher: RecommendedWatcher,
+    mut watcher: Debouncer<RecommendedWatcher, FileIdMap>,
     msg_rx: mpsc::Receiver<WatcherMsg>,
     reload_callback: C,
     mut file_path: PathBuf,
 ) {
+    let watcher = watcher.watcher();
     watcher
         .watch(&file_path, RecursiveMode::NonRecursive)
         .unwrap();
@@ -97,17 +134,17 @@ fn endlessly_handle_messages<C: Callback>(
     while let Ok(msg) = msg_rx.recv() {
         match msg {
             WatcherMsg::Notify(Ok(event)) => {
-                log::trace!("File event: {:#?}", event);
+                log::debug!("Processing file event: {:#?}", event);
 
                 if matches!(
                     event.kind,
                     EventKind::Remove(_) | EventKind::Modify(ModifyKind::Name(_))
                 ) {
                     log::debug!("File may have been renamed/removed. Falling back to polling");
-                    poll_registering_watcher(&mut watcher, &file_path);
+                    poll_registering_watcher(watcher, &file_path);
                     log::debug!("Successfully re-registered file watcher");
                     reload_callback.file_reload();
-                } else if matches!(event.kind, EventKind::Modify(_)) {
+                } else if matches!(event.kind, EventKind::Create(_) | EventKind::Modify(_)) {
                     log::debug!("Reloading file");
                     reload_callback.file_reload();
                 }
@@ -116,7 +153,7 @@ fn endlessly_handle_messages<C: Callback>(
             WatcherMsg::FileChange { new_path, contents } => {
                 log::info!("Updating file watcher path: {}", new_path.display());
                 let _ = watcher.unwatch(&file_path);
-                poll_registering_watcher(&mut watcher, &new_path);
+                poll_registering_watcher(watcher, &new_path);
                 file_path = new_path;
                 reload_callback.file_change(contents);
             }

src/file_watcher/tests.rs

@@ -61,6 +61,8 @@ impl Delays {
 }
 
 struct TestEnv {
+    // TODO: no need to pass this into the test env. Keep it external and limit what gets passed to
+    // tests
     temp_dir: TempDir,
     main_file: PathBuf,
     rel_file: PathBuf,
@@ -108,8 +110,13 @@ macro_rules! gen_watcher_test {
                 for _ in 0..4 {
                     let result = std::panic::catch_unwind(|| {
                         let test_dir = TestEnv::init();
-    // Give the watcher time to get comfy :)
-    delays.delay();
+                        // Give the watcher time to get comfy :)
+                        delays.delay();
+
+                        // For some reason it looks like MacOS gets a create event even though the
+                        // watcher gets registered after the file is already created. Drain any
+                        // initial notifications to start
+                        while test_dir.callback_rx.recv_timeout(delays.short_timeout).is_ok() {}
 
                         $test_fn(test_dir, delays.clone())
                     });

src/interpreter/mod.rs

@@ -166,6 +166,11 @@ impl HtmlInterpreter {
         let mut tok = Tokenizer::new(self, TokenizerOpts::default());
 
         for md_string in receiver {
+            log::debug!(
+                "Recieved markdown for interpretation: {} bytes",
+                md_string.len()
+            );
+
             if tok
                 .sink
                 .should_queue

src/main.rs

@@ -756,6 +756,7 @@ fn main() -> anyhow::Result<()> {
     human_panic::setup_panic!();
 
     env_logger::Builder::new()
+        .format_timestamp_millis()
         .filter_level(log::LevelFilter::Error)
         .filter_module("inlyne", log::LevelFilter::Info)
         .parse_env("INLYNE_LOG")

src/test_utils.rs

@@ -3,7 +3,7 @@ use log::LevelFilter;
 pub fn init_test_log() {
     // Ignore errors because other tests in the same binary may have already initialized the logger
     let _ = env_logger::Builder::new()
-        .filter(Some("inlyne"), LevelFilter::Debug)
+        .filter(Some("inlyne"), LevelFilter::Trace)
         .filter(None, LevelFilter::Warn)
         .is_test(true)
         .try_init();