Rebuild on mid build file modification

[dwijnand]

Fixes #2426

---

original

Trying to create a test for #2426, as described by @alexcrichton in #2426 (comment).

Alex, what am I doing wrong? Why isn't my test failing as it should be?

?r @alexcrichton

[rust-highfive]

r? @alexcrichton

(rust_highfive has picked a reviewer for you, use r? to override)

[alexcrichton]

I think that these may help, but if they don't I can keep poking too!

[alexcrichton]

After you connect here you'll want to read_to_end to block waiting for the disconnect to happen

[alexcrichton]

You'll want to defer dropping this socket until after the file has been modified

[dwijnand]

Still passes :(

[alexcrichton]

Hm it's interesting that the test failed on Windows but succeeded on Unix? I wonder if the file needs to be closed? This may also have to do with weird trickery around timestamp resolution. I'll take a closer look tomorrow at Cargo's code here to try to pinpoint the bug

[ehuss]

If you add drop(file); just before drop(socket);, then it reliably passes on my Windows system. I suspect it has to do with threading differences between the platforms.

This test fails about half the time on my Mac. It's because my filesystem only has 1s resolution. So if the fingerprint is saved at 1234.1 and you modify the file at time 1234.2, the file is considered fresh because 1234 == 1234.

To make this reliably fail on all platforms, you want to modify root/src/lib.rs, not the proc-macro. Modifying the proc-macro is modifying the thing that was just built, not the thing that is currently building.

[dwijnand]

You're right, @ehuss. Thank you. This is now consistently failing on me. 🎉

[dwijnand]

I have a fix for my test.

Please review - I'm probably doing something silly (design wise, or just Rust-wise).

[alexcrichton]

Hm it looks like some other tests may have started failing? I think the main fix here is that we'll basically want to record the mtime of the start of the build rather than the end of the build, and I think that should fix issue where files are modified during the build?

[dwijnand]

Do you mean by changing LocalFingerprint's structure to not reference a path?

[alexcrichton]

Something like that yeah. The current mtime we base everything off is the dep-info mtime which the compiler emits (I think?), but the relevant mtime is rather when the build started.

[dwijnand]

OK.

Note that there's also a code path that re-checks and updates the fingerprint's mtime: https://github.com/rust-lang/cargo/blob/0.26.0/src/cargo/ops/cargo_rustc/fingerprint.rs#L206-L212. What should happen in that case?

(Side note: let me know if this is growing to be more work than it's worth. I'm perfectly happy to persevere, or drop the PR. I've learnt either way.)

[alexcrichton]

@dwijnand that's what's called after the build is completed and it just updates with the mtime of the path mentioned (as the path may not have existed before the build started). I think that method would basically go away and we'd just record what time the build started, then we'd record that.

[dwijnand]

@alexcrichton how do I avoid spurious recompiles? I have an implementation that just uses the build start time, but it breaks my test because now the second compile recompiles proc_macro_dep when it needn't.

(edit: wip impl: dwijnand@eeea737)

[alexcrichton]

Hm I'm not entirely sure! Want to set RUST_LOG=cargo::core::compiler::fingerprint and see why Cargo is recompiling?

[dwijnand]

It's recompiling because the fingerprints, which now hold the build start time, don't match..

running `/d/cargo/target/debug/cargo build`
running `/d/cargo/target/debug/cargo build`
DEBUG 2018-04-27T14:33:22Z: cargo::core::compiler::fingerprint: fingerprint at: /d/cargo/target/cit/t0/p/target/debug/.fingerprint/root-819987bee50907ec/lib-root-819987bee50907ec
 INFO 2018-04-27T14:33:22Z: cargo::core::compiler::fingerprint: fingerprint error for root v0.1.0 (file:///d/cargo/target/cit/t0/p/root): mtime based components have changed: previously Some(FileTime { seconds: 1524839602, nanos: 146249000 }) now Some(FileTime { seconds: 1524839602, nanos: 283090000 })
DEBUG 2018-04-27T14:33:22Z: cargo::core::compiler::fingerprint: fingerprint at: /d/cargo/target/cit/t0/p/target/debug/.fingerprint/proc_macro_dep-aae81e26f117d294/lib-proc_macro_dep-aae81e26f117d294
 INFO 2018-04-27T14:33:22Z: cargo::core::compiler::fingerprint: fingerprint error for proc_macro_dep v0.1.0 (file:///d/cargo/target/cit/t0/p/proc_macro_dep): mtime based components have changed: previously Some(FileTime { seconds: 1524839601, nanos: 867084000 }) now Some(FileTime { seconds: 1524839602, nanos: 282926000 })
   Compiling proc_macro_dep v0.1.0 (file:///d/cargo/target/cit/t0/p/proc_macro_dep)
DEBUG 2018-04-27T14:33:23Z: cargo::core::compiler::fingerprint: write fingerprint: /d/cargo/target/cit/t0/p/target/debug/.fingerprint/proc_macro_dep-aae81e26f117d294/lib-proc_macro_dep-aae81e26f117d294
   Compiling root v0.1.0 (file:///d/cargo/target/cit/t0/p/root)
DEBUG 2018-04-27T14:33:23Z: cargo::core::compiler::fingerprint: write fingerprint: /d/cargo/target/cit/t0/p/target/debug/.fingerprint/root-819987bee50907ec/lib-root-819987bee50907ec
    Finished dev [unoptimized + debuginfo] target(s) in 1.13 secs

[alexcrichton]

Hm sorry I'm not immediately sure what's going on. The fingerprint module is pretty finnicky and fixing this issue may be exposing existing bugs that otherwise need to be explored :(

[dwijnand]

I fear I've misunderstood your build start time idea, and therefore implemented something that could never work. If you have time and spot any issue there, that might unblock this path. Meanwhile I'm thinking of looking at why my newest_output_file solution broke other tests.

[alexcrichton]

I believe (trying to remember right) the way things work today is something like:

• If no output artifacts exist, we do a compilation.
• Otherwise we assume that the dep-info file (*.d) was an output artifact. We also assume that all files necessary for the compilation are listed.
• The mtime of all files listed previously are compared to the mtime of the *.d file, if any are newer then we recompile
• After a crate finishes compiling we update the *.d with Cargo's own internal format/serialization.

The last step there means that when we update the *.d file it's after the compilation so any modifications that happened during the compilation aren't tracked because they're considered older than the mtime of the *.d file, thend of compilation.

I think the fix here will basically be to tweak LocalFingerprint::MtimeBased slightly. Ideally when update_local is called it doesn't call mtime because that time is too far in the future. Rather it should update the mtime of the file listed (if it's a Cargo-internal file) to just before compilation started (perhaps an extra payload to the MtimeBased variant)

[dwijnand]

@alexcrichton I had a go implementing what you said (or at least the parts I understood and knew how to do). It's still failing my test, but I added some debug info to the commit message too. If you have time to review that would be great! 🙇

[dwijnand]

Actually I think I'm done. It was too difficult for me, at this time.

[alexcrichton]

Ah sorry for the misdiagnosed "easy issue" @dwijnand, that's definitely my bad! If you feel like continuing to poke around Cargo internals though please feel free to ask questions!

[dwijnand]

Thanks @alexcrichton. It was fun to learn to about proc macros and using TCP to test this behaviour. I guess that effort could be reused by the next person attacking #2426.

Actually: does Cargo's test suite have "pending until fixed" test facilities? By that I mean you can assert that a test doesn't pass because it's blocked on issue X being fixed? If so perhaps I could land my test in master.

Finally: If you (or @matklad) keep labeling things E-easy/E-help-wanted/E-mentor I'll keep an eye out for them. 😄

[alexcrichton]

I think we may have a test here or there for unfixed bugs but in-the-large we're only checking in working tests