Cargo occasionally fails to detect changed source code files

[icy-ux]

Normally when I run cargo build, test, etc then any changes I've made to the code are picked up as expected & it re-compiles those parts of the binary.

Occasionally it does not do so, and I need to run cargo clean, then recompile to have my changes recognised.

This seems very similar to #2426 and would probably be solved by #6529

Meta

rustc --version --verbose:

$ rustc --version --verbose
rustc 1.42.0 (b8cedc004 2020-03-09)
binary: rustc
commit-hash: b8cedc00407a4c56a3bda1ed605c6fc166655447
commit-date: 2020-03-09
host: x86_64-unknown-linux-gnu
release: 1.42.0
LLVM version: 9.0

Checking whether it happens in nightly isn't currently possible as it's an intermittent issue. I will have to remember to check the next time the issue appears.

[alexcrichton]

Do you have a reproducible set of steps we could investigate to try to figure out what's going on?

[ehuss]

I would be surprised if it is #2426, there is specific protection so that Cargo will detect if a file is modified during a build.

Running with the CARGO_LOG=cargo::core::compiler::fingerprint=trace environment variable will log some details about why cargo thinks something is out of date or not. Starting with beta (1.43), it logs additional information like the mtime it is detecting.

[icy-ux]

On Mon, Apr 13, 2020 at 07:48:35AM -0700, Alex Crichton wrote: Do you have a reproducible set of steps we could investigate to try to figure out what's going on?

I wish I did! Then I would have been able to make a much more thorough bug report :(

[icy-ux]

On Mon, Apr 13, 2020 at 09:26:42AM -0700, Eric Huss wrote: Running with the `CARGO_LOG=cargo::core::compiler::fingerprint=trace` environment variable will log some details about why cargo thinks something is out of date or not. Starting with beta (1.43), it logs additional information like the mtime it is detecting.

Thanks, I've noted this and will try it next time the issue appears.

[icy-ux]

On Mon, Apr 13, 2020 at 07:48:35AM -0700, Alex Crichton wrote: Do you have a reproducible set of steps we could investigate to try to figure out what's going on?

If it's any help, these issues mostly crop up on a build server where the source code files (e.g any recent changes) are synced to the server with rsync. Then cargo (occasionally) fails to detect the updated files until I do `cargo clean`.

[ehuss]

If you are syncing with rsync, you have to be very careful with filesystem mtimes (such as dealing with the preserve-times feature). The two machines should have their time synced. Additionally, you should avoid this pattern:

1. rsync -a
2. Modify source file
3. Build on server (from step 1)
4. rsync -a
5. Build on server (will not detect updates because build output from step 3 is newer than the changed source files from step 2).

[icy-ux]

On Mon, Apr 13, 2020 at 11:22:53AM -0700, Eric Huss wrote: If you are syncing with rsync, you have to be very careful with filesystem mtimes (such as dealing with the preserve-times feature). The two machines should have their time synced. Additionally, you should avoid this pattern: 1. rsync -a 2. Modify source file 3. Build on server (from step 1) 4. rsync -a 5. Build on server (will not detect updates because build output from step 3 is newer than the changed source files from step 2).

The two machines' clocks are not locked together but they both get their time from NTP and (checking now) right now the clocks are exactly synced. The pattern referenced above does not apply. A common example would be: 1. `rsync --recursive --times --links --progress --chmod=ugo=rwX --checksum` 2. Build on server 3. Tests fail (on server) 4. Fix code locally 5. rsync as #1 6. Build on server 7. Tests fail again ("but I just fixed that")

[icy-ux]

I would be surprised if it is #2426, there is specific protection so that Cargo will detect if a file is modified during a build.

Running with the CARGO_LOG=cargo::core::compiler::fingerprint=trace environment variable will log some details about why cargo thinks something is out of date or not. Starting with beta (1.43), it logs additional information like the mtime it is detecting.

This problem cropped again today. I tried prepending the above CARGO_LOG to the command line when running cargo test but no new information was logged. Adding a RUST_LOG=cargo to tell envlogger to handle those messages didn't help either.

Sadly I am deep in a project so I will need to destroy my wonderful little test case by running cargo clean, but I welcome additional suggestions for what to try the next time this appears.

[icy-ux]

Looks like the trick is to do:

export CARGO_LOG=cargo::core::compiler::fingerprint=trace

before running anything else, just passing CARGO_LOG doesn't seem to do it.

The issue has cropped up again despite running cargo clean so I have the cargo log output for the case where the error occurs. What should I be looking at? All I see are a lot of lines like:

[2020-05-10T11:43:53Z DEBUG cargo::core::compiler::fingerprint] fingerprint at: /home/user/myproject/target/debug/.fingerprint/myproject-1971e1bd56c8af85/test-bin-mything-1971e1bd56c8af85           
[2020-05-10T11:43:53Z DEBUG cargo::core::compiler::fingerprint] old local fingerprints deps                                                                                               
[2020-05-10T11:43:53Z DEBUG cargo::core::compiler::fingerprint] old local fingerprints deps                                                                                                               
[2020-05-10T11:43:53Z DEBUG cargo::core::compiler::fingerprint] old local fingerprints deps                                                                                                           
[2020-05-10T11:43:53Z DEBUG cargo::core::compiler::fingerprint] old local fingerprints deps                                                                                                          
[2020-05-10T11:43:53Z DEBUG cargo::core::compiler::fingerprint] old local fingerprints deps                                                                                                               
[2020-05-10T11:43:53Z DEBUG cargo::core::compiler::fingerprint] new local fingerprints deps 

[icy-ux]

Looks like my local machine's time had got out of sync with the server's. It's too early to say whether this is enough to resolve the problem. I've also removed the --times option from the Rsync sync script, in the event that was contributing to the issue.

[icy-ux]

Now too many things are coming back as outdated: the Cargo logging data shows it's identifying as outdated files that I haven't changed.

[icy-ux]

Making a small change, re-uploading, and running tests shows that everything works now. The fix was therefore either:
a) syncing times on local machine and server, or
b) running rsync without the --times option

[tal-zvon]

Not sure if I should open a new issue for this, but I can still reproduce this with these steps using cargo 1.50.0 (f04e7fa 2021-02-04), rustc 1.50.0 (cb75ad5db 2021-02-10):

• Start a new project on my MacOS Catalina with cargo new bug_test
• mv src/main.rs src/main.orig.rs
• vim src/main.rs
  • fn main() { let s = String::from("hello"); }
• cargo build
  • warning: unused variable: 's'
• rm src/main.rs
• mv src/main.orig.rs src/main.rs
• cargo build
  • warning: unused variable: 's'

To clarify, what I end up with is a main.rs that looks like this:

fn main() {
    println!("Hello, world!");
}

Which is the default main.rs that cargo builds for new projects, but cargo build complains about a warning that has nothing to do with the source code.

Is this expected?

[ehuss]

Is this expected?

Unfortunately, yes. Cargo only tracks mtimes, and the "orig" main has an mtime older than the last build. Using alternate change-tracking techniques such as content hashing is tracked in #6529.

[tal-zvon]

@ehuss Ok - I figured it was possibly a minor design flaw more than just a bug. I'm sure this isn't the place to discuss, but a combination of mtime/file_size, OR hashing, just like rsync does it, might be a good solution. Looks like devs are already working on it. Thanks for clearing that up.

[txtyash]

I encountered this bug today on:

 > rustup --version
rustup 1.26.0 (5af9b9484 2023-04-05)
info: This is the version for the rustup toolchain manager, not the rustc compiler.
info: The currently active `rustc` version is `rustc 1.72.0 (5680fa18f 2023-08-23)`
[I] [1] /home/zim/github/mewe/src
 > cargo --version
cargo 1.72.0 (103a7ff2e 2023-08-15)
[I] [1] /home/zim/github/mewe/src
 > uname -a
Linux arch 6.5.3-arch1-1 #1 SMP PREEMPT_DYNAMIC Wed, 13 Sep 2023 08:37:40 +0000 x86_64 GNU/Linux

Can't reproduce after I ran cargo clean