FS operations performed by blender yield confusing order of events from the debouncer

[Sorseg]

System details

• OS/Platform name and version:
  Linux host 6.8.0-76060800daily20240311-generic #202403110203~1713206908~22.04~3a62479 SMP PREEMPT_DYNAMIC Mon A x86_64 x86_64 x86_64 GNU/Linux
• Rust version (if building from source): rustc --version: rustc 1.77.2 (25ef9e3d8 2024-04-09)
• Notify version (or commit hash if building from git): notify-debouncer-full v0.3.1

Cargo tree

notify-debouncer-full v0.3.1
    ├── crossbeam-channel v0.5.12
    │   └── crossbeam-utils v0.8.19
    ├── file-id v0.2.1
    ├── log v0.4.21
    ├── notify v6.1.1
    │   ├── crossbeam-channel v0.5.12 (*)
    │   ├── filetime v0.2.23
    │   │   ├── cfg-if v1.0.0
    │   │   └── libc v0.2.153
    │   ├── inotify v0.9.6
    │   │   ├── bitflags v1.3.2
    │   │   ├── inotify-sys v0.1.5
    │   │   │   └── libc v0.2.153
    │   │   └── libc v0.2.153
    │   ├── libc v0.2.153
    │   ├── log v0.4.21
    │   ├── mio v0.8.11
    │   │   ├── libc v0.2.153
    │   │   └── log v0.4.21
    │   └── walkdir v2.5.0
    │       └── same-file v1.0.6
    ├── parking_lot v0.12.1
    │   ├── lock_api v0.4.11
    │   │   └── scopeguard v1.2.0
    │   │   [build-dependencies]
    │   │   └── autocfg v1.2.0
    │   └── parking_lot_core v0.9.9
    │       ├── cfg-if v1.0.0
    │       ├── libc v0.2.153
    │       └── smallvec v1.13.2
    └── walkdir v2.5.0 (*)

• If you're coming from a project that makes use of Notify, what it is, and a link to the downstream issue if there is one:
  Bevy asset system File watcher + asset processor get confused when blender saves a new file version bevyengine/bevy#13053
• Filesystem type and options: ext4 (rw,relatime)
• If you're running as a privileged user (root, System): running as user

What you did (as detailed as you can)

Run the example code, then open an existing file test.blend in blender and overwrite it with a new version.

What I ran

use std::path::Path;
use std::time::Duration;
use notify_debouncer_full::{DebounceEventResult, new_debouncer};
use notify_debouncer_full::notify::{RecursiveMode, Watcher};

fn main() {
    println!("Hello, world!");
    // Select recommended watcher for debouncer.
// Using a callback here, could also be a channel.
    let mut debouncer = new_debouncer(Duration::from_secs(2), None, |result: DebounceEventResult| {
        match result {
            Ok(events) => events.iter().for_each(|event| println!("{event:?}")),
            Err(errors) => errors.iter().for_each(|error| println!("{error:?}")),
        }
    }).unwrap();

// Add a path to be watched. All files and directories at that path and
// below will be monitored for changes.
    debouncer.watcher().watch(Path::new("."), RecursiveMode::Recursive).unwrap();

// Add the same path to the file ID cache. The cache uses unique file IDs
// provided by the file system and is used to stich together rename events
// in case the notification back-end doesn't emit rename cookies.
    debouncer.cache().add_root(Path::new("."), RecursiveMode::Recursive);
    std::thread::sleep(Duration::from_secs(100000000));
}

What you expected

I expected to read a series of events that would indicate that the test.blend now contains the new data,
as this is what bevy relies upon to reload the assets.

What happened

strace of blender saving a file

20:45:43.021143 openat(AT_FDCWD, "<...>/test.blend@", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 28
20:45:43.023758 unlink("<...>/test.blend1") = 0
20:45:43.024196 rename("<...>/test.blend", "<...>/test.blend1") = 0
20:45:43.024412 rename("<...>/test.blend@", "<...>/test.blend") = 0

Result

DebouncedEvent { event: Event { kind: Create(File), paths: ["<...>/./test.blend"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 28469, tv_nsec: 182994437 } }
DebouncedEvent { event: Event { kind: Access(Close(Write)), paths: ["<...>/./test.blend"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 28469, tv_nsec: 185258534 } }
DebouncedEvent { event: Event { kind: Remove(Any), paths: ["<...>/./test.blend1"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 28469, tv_nsec: 185991873 } }
DebouncedEvent { event: Event { kind: Modify(Name(Both)), paths: ["<...>/./test.blend", "<...>/./test.blend1"], attr:tracker: Some(10280), attr:flag: None, attr:info: None, attr:source: None }, time: Instant { tv_sec: 28469, tv_nsec: 185991873 } }

The resulting list of events confuses bevy into thinking there is only the .blend1 file, as the last event returned is the rename. Which is not what actually happens to the filesystem.

Thank you for maintaining this ❤️ !

[0xpr03]

Maybe @dfaust has a faster answer what the debouncer logic does here. Would have to dig around first how we flatten this joyride of renames to have backups, especially with the timing here.

create test.blend@ (new content)
delete test.blend1 (delete backup)
rename test.blend -> test.blend1 (move current to backup)
rename test.blend@ -> test.blend (move new to current)

Hard to say what you would even want to get reported here. Delete test.blend1, Rename test.blend -> test.blend1, Modify test.blend in that succession would probably be the closest to the truth. Even though modify test.blend, test.blend1 would be true too - in the spirit of what blender really does at the end for the asset recompilation.

[dfaust]

I'll have a look at it. My first thought is that the reported events should be:

(maybe) delete test.blend1
rename test.blend -> test.blend1
create test.blend

[dfaust]

Looks like the problem here is the order in which the events are emitted. The create event happens at first, but must be emitted after the rename event.

@Sorseg can you please try #590 and tell me if it fixes your problem?

[Sorseg]

Thank you! I'll be able to test it next week

[Sorseg]

Unfortunately it does not seem to help. Here's the output with the patched version
(save happened around 08:28:27)
https://gist.github.com/Sorseg/47563fa04552fe11a9f2dd31aef26b6a
I cannot say if this is an issue on bevy or notify side. I am also worried about the lack of these log lines. I wonder if it has something to do with it being run in a different thread.

My repro repo

[dfaust]

@Sorseg It has been a while, but if you are still interested in this issue, I would like to get your feedback.

I updated the PR, but it should not change the previous behavior.

In my experiment I'm getting:

inotify:
Create(File)            "blend@"
Access(Open(Any))       "blend@"
Modify(Data(Any)) (4x)  "blend@"
Access(Close(Write))    "blend@"
Modify(Name(Both))      "blend" -> "blend1"
Modify(Name(Both))      "blend@" -> "blend"

debounced:
Modify(Name(Both))      "blend" -> "blend1"
Create(File)            "blend"
Access(Open(Any))       "blend"
Access(Close(Write))    "blend"

bevy:
RenamedAsset            "blend" -> "blend1"
AddedAsset              "blend"
ModifiedAsset           "blend"

https://gist.github.com/dfaust/de7b228e54147490587d4203ac2f9dd9

And I think this is "correct". Bevy receives a rename event that informs it that the old file has been moved. Then the new file is created. I have only looked at the events, not what bevy does with them. But I'm afraid we can't do better than this without guessing too much and potentially causing problems elsewhere.