File watcher + asset processor get confused when blender saves a new file version

Sorseg commented 6 months ago

Bevy version

from the lock file:

[[package]]
name = "bevy_asset"
version = "0.13.2"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "50028e0d4f28a9f6aab48f61b688ba2793141188f88cdc9aa6c2bca2cc02ad35"

Relevant system information

Linux with an ext4 volume

What you did

I've setup an AssetProcessor for blender files and run a game with RUST_LOG=bevy_asset=trace and bevy features asset_processor,file_watcher,dynamic_linking enabled.

What went wrong

When starting up the game, I see

2024-04-21T18:03:48.881955Z DEBUG bevy_asset::processor: Listening for changes to source assets
2024-04-21T18:04:06.509932Z TRACE bevy_asset::processor: AddedAsset("levels/experiment1.blend")
2024-04-21T18:04:06.509957Z DEBUG bevy_asset::processor: Processing levels/experiment1.blend
2024-04-21T18:04:07.258200Z DEBUG bevy_asset::processor: Finished processing "levels/experiment1.blend"

then I save the blend file in blender this happens:

2024-04-21T18:09:49.539919Z TRACE bevy_asset::processor: AddedAsset("levels/experiment1.blend")
2024-04-21T18:09:49.539940Z DEBUG bevy_asset::processor: Processing levels/experiment1.blend
2024-04-21T18:09:49.963173Z DEBUG bevy_asset::processor: Finished processing "levels/experiment1.blend"
2024-04-21T18:09:49.963193Z TRACE bevy_asset::processor: ModifiedAsset("levels/experiment1.blend")
2024-04-21T18:09:49.963199Z DEBUG bevy_asset::processor: Processing levels/experiment1.blend
2024-04-21T18:09:49.964035Z DEBUG bevy_asset::processor: Skipping processing (unchanged) "levels/experiment1.blend"
2024-04-21T18:09:49.964041Z TRACE bevy_asset::processor: RemovedUnknown { path: "levels/experiment1.blend1", is_meta: false }
2024-04-21T18:09:49.964054Z DEBUG bevy_asset::processor: Removing processed levels/experiment1.blend1 because source was removed
2024-04-21T18:09:49.964388Z TRACE bevy_asset::processor: RenamedAsset { old: "levels/experiment1.blend", new: "levels/experiment1.blend1" }
2024-04-21T18:09:49.964490Z DEBUG bevy_asset::processor: Processing levels/experiment1.blend1
2024-04-21T18:09:49.967089Z DEBUG bevy_asset::processor: Finished processing "levels/experiment1.blend1"
2024-04-21T18:09:50.286670Z  INFO bevy_asset::server: Reloading levels/experiment1.blend1 because it has changed

I was expecting bevy to notice the new experiment1.blend right away (the file does appear in the unprocessed directory and gets picked up if I restart my bevy app).

One important detail is that blender on save creates a backup with a blend1 extension. Strace of blender file operations:

openat(AT_FDCWD, "sources/levels/experiment1.blend@", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 28
stat("sources/levels/experiment1.blend", {st_mode=S_IFREG|0664, st_size=1135904, ...}) = 0
stat("sources/levels/experiment1.blend", {st_mode=S_IFREG|0664, st_size=1135904, ...}) = 0
stat("sources/levels/experiment1.blend1", {st_mode=S_IFREG|0664, st_size=1135904, ...}) = 0
unlink("sources/levels/experiment1.blend1") = 0
rename("sources/levels/experiment1.blend", "sources/levels/experiment1.blend1") = 0
stat("sources/levels/experiment1.blend@", {st_mode=S_IFREG|0664, st_size=1135904, ...}) = 0
stat("sources/levels/experiment1.blend", 0x7ffc51d516c0) = -1 ENOENT (No such file or directory)
rename("sources/levels/experiment1.blend@", "sources/levels/experiment1.blend") = 0
stat("sources/levels/experiment1.blend", {st_mode=S_IFREG|0664, st_size=1135904, ...}) = 0

Additional information

I think there in an issue in how file watcher handles what blender does to the file system, for some reason it does not pick up the creation and renaming of experiment1.blend@, which I assume is the temporary file blender creates for the save.

the log might also indicate that if messages from the fs event notify system are received in batches, then they are processed in reverse order (bevy first notices the blend1 file appears, and then sees the rename)

Thank you for maintaining this project, it is the greatest game engine I had the honor to work with! :heart:

Sorseg commented 6 months ago

I'll try to debug this myself a little bit tomorrow and if I fail I'll try to set up a repository with an easy reproduction

Sorseg commented 6 months ago

Looks like the issue is with notify-debouncer-full, the example code has the same behavior. I'll make an issue there and close this one for now. For anyone running into this, I suggest a workaround of disabling the blend1 file creation backup Edit -> Preferences -> Save&Load -> Save Versions -> 0

Sorseg commented 6 months ago

Forwarded https://github.com/notify-rs/notify/issues/587

bevyengine / bevy