cargo watch triggering on file that hasn't changed (only read)

[edmorley]

Hi! Thank you for a great tool :-)

I'm currently experiencing cargo watch -x test looping indefinitely, with --why reporting that the cause is a file that hasn't been modified (the file is read during cargo test and copied to a temp dir, but the original isn't modified itself).

I was wondering if you might have some insight?

Steps to reproduce:

1. git clone https://github.com/Malax/libcnb.rs (currently at fd1686f8d0fe07aca5e0b9592fbdee1919591fdb)
2. cd libcnb.rs/examples/example-02-ruby-sample/
3. cargo watch -x test --why

Expected:

Test command is run only once, and waits for next modification to the project source before being re-run.

Actual:

Test command is run repeatedly in a loop.

Output says:

2022-02-02T23:27:19.085+00:00 - INFO - Paths updated: [PathOp { path: "/Users/emorley/src/libcnb.rs/examples/example-02-ruby-sample/test-fixtures/simple-ruby-app/app.rb", op: Some((empty)), cookie: None }, PathOp { path: "/Users/emorley/src/libcnb.rs/examples/example-02-ruby-sample/test-fixtures/simple-ruby-app/Gemfile", op: Some((empty)), cookie: None }, PathOp { path: "/Users/emorley/src/libcnb.rs/examples/example-02-ruby-sample/test-fixtures/simple-ruby-app/Gemfile.lock", op: Some((empty)), cookie: None }]

Stating the files before/after shows nothing has changed:

$ stat test-fixtures/simple-ruby-app/app.rb  File: test-fixtures/simple-ruby-app/app.rb
  Size: 150             Blocks: 8          IO Block: 4096   regular file
Device: 1,8     Inode: 112878460   Links: 1
Access: (0644/-rw-r--r--)  Uid: (  503/ emorley)   Gid: (   20/   staff)
Access: 2022-02-02 14:49:13.822279666 +0000
Modify: 2022-02-02 14:49:13.762440366 +0000
Change: 2022-02-02 14:49:13.762440366 +0000
 Birth: 2022-02-02 14:49:13.760673662 +0000

$ cargo watch -x test --why
...
<Ctrl+C>

$ stat test-fixtures/simple-ruby-app/app.rb  File: test-fixtures/simple-ruby-app/app.rb
  Size: 150             Blocks: 8          IO Block: 4096   regular file
Device: 1,8     Inode: 112878460   Links: 1
Access: (0644/-rw-r--r--)  Uid: (  503/ emorley)   Gid: (   20/   staff)
Access: 2022-02-02 14:49:13.822279666 +0000
Modify: 2022-02-02 14:49:13.762440366 +0000
Change: 2022-02-02 14:49:13.762440366 +0000
 Birth: 2022-02-02 14:49:13.760673662 +0000

During the test setup, the files in question are copied to a temporary directory here using fs_extra::dir::copy():
https://github.com/Malax/libcnb.rs/blob/fd1686f8d0fe07aca5e0b9592fbdee1919591fdb/libcnb-test/src/app.rs#L5-L21

...but the target directory is in TMP and so not watched, and the source file was never modified.

Additional information

Cargo watch was installed using cargo install cargo-watch (I reinstalled just now using --force to ensure it was recently compiled, given not using --locked).

Versions:

$ rustc --version
rustc 1.59.0-beta.5 (28c8a34e1 2022-01-27)
$ cargo watch --version
cargo-watch 8.1.1

(though this also repros on Rust stable)

This is on macOS 12.2.

[passcod]

I can't really tell. The macos infrastructure for for changes used in cargo watch so far (it's due to change next version) is a black box.

However, from knowledge of how other platforms work, for example inotify on Linux, it's possible that a mere file read access is triggering the change.

[passcod]

Is the lockfile changing?

[edmorley]

Thank you for replying :-)

The workspace Cargo.lock is up to date, checked into the repo (not in .gitignore) and the output from stat doesn't change after running cargo test. It's also in the directories above the working directory in the steps to reproduce (so presumably not watched), and wasn't mentioned in the --why output.

[passcod]

No, I mean in the output you gave, there's --why entries for the gemfile and gemfile.lock

[schneems]

No, I mean in the output you gave, there's --why entries for the gemfile and gemfile.lock

In those tests Gemfile and Gemfile.lock are not modified

Here's another output with the same thing happening (repo not yet open sourced).

$ cargo watch -x test --why  
[Running 'cargo test']
    Finished test [unoptimized + debuginfo] target(s) in 0.13s
     Running unittests (target/debug/deps/procfile_buildpack-202d655ed7e5c570)

running 16 tests
test launch::test::test_no_processes ... ok
test procfile::tests::test_empty_parse_procfile ... ok
test procfile::tests::test_cannot_parse_procfile ... ok
test procfile::tests::test_missing_name_parse_procfile ... ok
test procfile::tests::test_missing_command_parse_procfile ... ok
test tests::test_empty_names_from_processes ... ok
test procfile::tests::test_valid_parse_procfile ... ok
test procfile::tests::test_multiple_valid_parse_procfile ... ok
test tests::test_valid_process_names_from_processes ... ok
test tests::test_missing_procfile_detect ... ok
test tests::test_valid_detect ... ok
test launch::test::test_single_non_web_process ... ok
test launch::test::test_single_web_process ... ok
test launch::test::test_web_and_additional_process ... ok
test launch::test::test_multiple_non_web_processes ... ok
test launch::test::test_process_order ... ok

test result: ok. 16 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Running tests/integration_test.rs (target/debug/deps/integration_test-b6d324553c0598e7)

running 1 test
    Finished dev [unoptimized + debuginfo] target(s) in 0.08s
2022-02-02T20:03:19.123-06:00 - INFO - Paths updated: [PathOp { path: "/Users/rschneeman/Documents/projects/work/procfile-cnb-rust/tests/fixtures/app_with_procfile/Procfile", op: Some((empty)), cookie: None }, PathOp { path: "/Users/rschneeman/Documents/projects/work/procfile-cnb-rust/buildpack.toml", op: Some((empty)), cookie: None }]
[Running 'cargo test']
    Finished test [unoptimized + debuginfo] target(s) in 0.15s
     Running unittests (target/debug/deps/procfile_buildpack-202d655ed7e5c570)

running 16 tests
test launch::test::test_no_processes ... ok
test procfile::tests::test_empty_parse_procfile ... ok
test tests::test_empty_names_from_processes ... ok
test procfile::tests::test_cannot_parse_procfile ... ok
test procfile::tests::test_valid_parse_procfile ... ok
test procfile::tests::test_missing_name_parse_procfile ... ok
test procfile::tests::test_multiple_valid_parse_procfile ... ok
test procfile::tests::test_missing_command_parse_procfile ... ok
test tests::test_valid_process_names_from_processes ... ok
test tests::test_missing_procfile_detect ... ok
test tests::test_valid_detect ... ok
test launch::test::test_single_web_process ... ok
test launch::test::test_single_non_web_process ... ok
test launch::test::test_web_and_additional_process ... ok
test launch::test::test_multiple_non_web_processes ... ok
test launch::test::test_process_order ... ok

test result: ok. 16 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Running tests/integration_test.rs (target/debug/deps/integration_test-b6d324553c0598e7)

running 1 test
    Finished dev [unoptimized + debuginfo] target(s) in 0.10s
2022-02-02T20:03:20.825-06:00 - INFO - Paths updated: [PathOp { path: "/Users/rschneeman/Documents/projects/work/procfile-cnb-rust/tests/fixtures/app_with_procfile/Procfile", op: Some((empty)), cookie: None }, PathOp { path: "/Users/rschneeman/Documents/projects/work/procfile-cnb-rust/buildpack.toml", op: Some((empty)), cookie: None }]
[Running 'cargo test']
    Finished test [unoptimized + debuginfo] target(s) in 0.13s
     Running unittests (target/debug/deps/procfile_buildpack-202d655ed7e5c570)

In this case it's saying:

2022-02-02T20:03:19.123-06:00 - INFO - Paths updated: [PathOp { path: "/Users/rschneeman/Documents/projects/work/procfile-cnb-rust/tests/fixtures/app_with_procfile/Procfile", op: Some((empty)), cookie: None }, PathOp { path: "/Users/rschneeman/Documents/projects/work/procfile-cnb-rust/buildpack.toml", op: Some((empty)), cookie: None }]

We're not modifying the Procfile or the buildpack.toml, though as Ed has mentioned they're being copied to a different directory (outside of the current dir, shouldn't trigger cargo watch).

[passcod]

That will probably need a bit of tweaking, but could you use the latest watchexec and see if it's an issue?

$ watchexec --print-events -- cargo test

Also any chance to run on e.g. Linux?

Want to clarify if it's an issue with FSEvents (macos, cargo watch <=8 only) or with cargo watch itself.

[edmorley]

Ah so it doesn't reproduce if I use watchexec v1.18.5 (using the pre-built binaries via brew install watchexec), and run watchexec --print-events -- cargo test instead of step 3, in the OP's steps to reproduce.

Thank you for the suggestion to try that :-)

[passcod]

Right, so it's an FSEvents thing. Unfortunately I can't really mitigate that. However, it will be fixed next release, when upstream watchexec is used here: the backend changes away from FSEvent to the more precise/appropriate kqueue.

[edmorley]

That makes sense - thank you for your help! We will use watchexec directly in the meantime :-)

[passcod]

Okay, so it's not actually an FSEvent thing, because Watchexec was using FSEvent all along too. It might be a Notify 4 vs 5 thing, or it might be something else that Watchexec 1.18 fixes. Hopefully it will still be fixed when I merge upstream Watchexec into cargo watch!

[edmorley]

Fingers crossed that will fix it! :-)

[tekacs]

Hullo, still running into this issue at the moment. I get the same op: Some((empty)), am running on macOS Sonoma, cargo-watch 8.4.1 and this triggers when I simply restart my editor -- a random Rust file in my project triggers this, perhaps the most recently used.

Happy to help with a fix here or deeper in, though I'm unclear given the above: is the op: Some((empty)) a valid state that should trigger on valid writes too?

[passcod]

@tekacs Does this happen with watchexec?

[oclyke]

@passcod I just did a little investigation between cargo-watch and watchexec.

I've got a static site generator. It has an example application and basic web sources. My hope was to set up a watcher to respond to changes in the source dir. Critically, site-content is read-only. The generator can and does walk through those dirs and copies files from site-content into site-out.

Seems to me like there is probably an issue with OSX triggering these tools on file reads.

My cargo-watch command was like this (okay, I tried a lot of variations, here are two):
cargo watch -x 'run --example basic' --ignore '**/{site-out}/**'
cargo watch -x 'run --example basic' --watch **/examples/basic/site-content

My watchexec command looked like this:
watchexec -w examples/basic/site-content -r cargo run --example basic

In both cases I got an infinite loop. I was able to shut down the loop by ignoring the site-content directory as well as the site-out (but of course that defeats the purpose in my case).

Thanks!

[passcod]

@oclyke Sorry for the late answer, but if you could run with --print-events (in watchexec), and then show the events that are triggering your loop, that would help!

[oclyke]

@passcod No worries! Okay, here's what I am seeing.

Upon a first-run I am not getting a loop. In this case the site-out directory is removed entirely (using std::fs::remove_dir_all) and then it is regenerated from the contents of site-content. The input / output is unchanged in this case.

oclyke@Owens-MacBook-Pro blanket-rs % watchexec --print-events -w examples/basic/site-content -r cargo run --example basic
[EVENT 0] Event
[Running: cargo run --example basic]
    Finished dev [unoptimized + debuginfo] target(s) in 0.00s
     Running `target/debug/examples/basic`
program start
removing output directory... done.
Root::generate
program end
[Command was successful]

Now the command is waiting to observe changes in the filesystem (within site-content ideally). If I introduce a change, say by editing and saving site-content/index.html, then a loop begins. Here are the complete logs:

oclyke@Owens-MacBook-Pro blanket-rs % watchexec --print-events -w examples/basic/site-content -r cargo run --example basic
[EVENT 0] Event
[Running: cargo run --example basic]
    Finished dev [unoptimized + debuginfo] target(s) in 0.00s
     Running `target/debug/examples/basic`
program start
removing output directory... done.
Root::generate
program end
[Command was successful]
[EVENT 0] Event source=Filesystem kind=Modify(Metadata(Any)) path=/Users/oclyke/Documents/oclyke/blanket-rs/examples/basic/site-content/index.html filetype=file
[EVENT 1] Event source=Filesystem kind=Modify(Data(Content)) path=/Users/oclyke/Documents/oclyke/blanket-rs/examples/basic/site-content/index.html filetype=file
[Running: cargo run --example basic]
    Finished dev [unoptimized + debuginfo] target(s) in 0.00s
     Running `target/debug/examples/basic`
program start
removing output directory... done.
Root::generate
program end
[Command was successful]
[EVENT 0] Event source=Filesystem kind=Modify(Metadata(Any)) path=/Users/oclyke/Documents/oclyke/blanket-rs/examples/basic/site-content/index.html filetype=file
[EVENT 1] Event source=Filesystem kind=Modify(Data(Content)) path=/Users/oclyke/Documents/oclyke/blanket-rs/examples/basic/site-content/index.html filetype=file
[Running: cargo run --example basic]
    Finished dev [unoptimized + debuginfo] target(s) in 0.00s
     Running `target/debug/examples/basic`
 ...
^C[EVENT 0] Event source=Keyboard signal=Interrupt
[Waiting 60s for processes to exit before stopping...]

Relevant code which seemingly triggers the watcher is like this:

• A CopyFile resource is registered into the build tree for index.html (No action yet)
• The builder eventually runs the generate()

There's not really much here. Maybe I can make a gist about it - one sec.

[oclyke]

@passcod Here's a gist which reproduces the problem on my M1 Mac. (macOS Sonoma 14.2.1)

https://gist.github.com/oclyke/bb9e59af565cafb06651330628c04c47

[passcod]

Right, I see what you mean. I think that's an inherent limitation of fsevents (something like "a modify event happened that concerned this file, but i'm not telling you if it was the copied or the copy"); you may have better luck with polling. Out of curiosity, what events do you get with:

• --only-emit-events --emit-events-to=json-stdio, running the generator manually
• the above and watching site-out as well

I haven't been able to replicate using the ancient macbook air I have myself.

[tekacs]

Hey, I'm sorry I missed this earlier! I've since switched to watchexec and have managed to sidestep these issues.

I've split my build process from my run process and I'm doing this (simplified) now:

backend-build: watchexec --on-busy-update=queue --print-events -w common -w backend -- cargo build -p backend
backend: watchexec --on-busy-update=restart --print-events -w ./target/debug/backend --no-vcs-ignore -- ./target/debug/backend

With this setup I don't see any op: Some((empty)) restarts, so I think that the events aren't present in a watchexec setup, although I do appreciate that there are multiple differences. I am watching the same folders and think that I'm otherwise the same except on-busy-update.

I'm happy to test things to evaluate if there's something I can do to help this effort.

[passcod]

Thanks @tekacs! I think that @oclyke's issue is a subtly different one; in any case I'll keep this bug open until I get cargo watch updated to the latest watchexec.

[oclyke]

Thanks for all the attention you're giving this one @passcod!

Okay, I dove into this a little bit with a bunch of scattered testing. I'll do a TLDR here and dump more notes below.

TLDR
Rust's std::fs::copy() seems to be a root cause here, and watchexec's behaviour appears to be correct. A workaround can be had by using std::io::copy() with File objects instead.

Detail
Looking at the logs above it really bugged me that the source file site-content/index.html was getting Modify() events when running the generator – by design the generator does not modify sources. The only code that even remotely makes sense to cause this issue is the line used to copy the source to the destination. Upon inspection it appears that std::fs::copy() copies permissions bits as well as content. On Mac this copy operation is achieved using fclonefileat and fcopyfile.

On a hunch I changed the method of copying files to use the io copy. I thought this might get rid of the Modify(Metadata(Any)) event (spoiler, it didn't – but it did work for reasons unknown to me).

    // std::fs::copy(source, path)?;
    let mut source = std::fs::File::open(source)?;
    let mut dest = std::fs::File::create(path)?;
    std::io::copy(&mut source, &mut dest)?;

With this modification the generator is able to be driven by changes in the source directory as expected.

oclyke@Owens-MacBook-Pro blanket-rs % watchexec --print-events -w examples/basic/site-content -r cargo run --example basic
[EVENT 0] Event
[Running: cargo run --example basic]
    Finished dev [unoptimized + debuginfo] target(s) in 0.02s
     Running `target/debug/examples/basic`
program start
removing output directory... done.
Root::generate
program end
[Command was successful]
[EVENT 0] Event source=Filesystem kind=Modify(Metadata(Any)) path=/Users/oclyke/Documents/oclyke/blanket-rs/examples/basic/site-content/index.html filetype=file
[EVENT 1] Event source=Filesystem kind=Modify(Data(Content)) path=/Users/oclyke/Documents/oclyke/blanket-rs/examples/basic/site-content/index.html filetype=file
[Running: cargo run --example basic]
    Finished dev [unoptimized + debuginfo] target(s) in 0.00s
     Running `target/debug/examples/basic`
program start
removing output directory... done.
Root::generate
program end
[Command was successful]

Using a separate process I recorded the events in JSON, as @passcod suggested. (Formatted for easy reading) [p.s. I realized that events in site-out were discarded thanks to .gitignore, and that it worked as expected detecting changes to the output directory when this was resolved.]

oclyke@Owens-MacBook-Pro blanket-rs % watchexec --print-events --only-emit-events --emit-events-to=json-stdio -w examples/basic/site-content -w examples/basic/site-out
{
  "tags": [
    {
      "kind": "source",
      "source": "filesystem"
    },
    {
      "kind": "fs",
      "simple": "modify",
      "full": "Modify(Metadata(Any))"
    },
    {
      "kind": "path",
      "absolute": "/Users/oclyke/Documents/oclyke/blanket-rs/examples/basic/site-content/index.html",
      "filetype": "file"
    }
  ]
}
{
  "tags": [
    {
      "kind": "source",
      "source": "filesystem"
    },
    {
      "kind": "fs",
      "simple": "modify",
      "full": "Modify(Data(Content))"
    },
    {
      "kind": "path",
      "absolute": "/Users/oclyke/Documents/oclyke/blanket-rs/examples/basic/site-content/index.html",
      "filetype": "file"
    }
  ]
}

As you can see the same events appear to be happening and I didn't really have the time to dive deep into how these system calls interact with FSEvents. It seems really odd to me that the received events (Content and Metadata modifications) did not change between the two cases. Eventually if I get some free time I think it would be neat to understand what is going on here.

Thanks again for all the help everyone!