Proc-macro dependencies being rebuilt in dev mode

[dpc]

I've recently upgraded Rust from 1.67.0 to 1.71.0, and noticed that in our "build workspace" derivation, some dependencies are being re-compiled, even though they were compiled in "build workspace deps only" derivation.

I confirmed that just switching between 1.67.0 and 1.71.0 fixes/introduces the problem.

It looks like only build.rs (and deps that depend on them) are being rebuilt, and from the initial debugging session I suspect something about tracking which deps require rebuild changed between these two toolchain (well... probably cargo) versions.

Notably the files restored in /build/source/target/ from zstd (I use the zstd mode) archive produced by deps-only have different timestamps than originals: they are all reset to the default unix timestamp, while the original ones had the original timestamps. I suspect something about how cargo tracks these changed.

[dpc]

1.68.0 is unaffected, and 1.69 is affected.

And indeed some freshness work was done rust-lang/cargo@0.68.0...0.69.0

[dpc]

Ironically the change was done there to display reasons for rebuilds, but the reason for rebuilding affected crates is not being displayed.

rust-lang/cargo#11407

[ipetkov]

Do you have a minimal repro I can take a look at?

What does cargo say about which files have changed specifically?

[dpc]

Do you have a minimal repro I can take a look at?

Will try to minimize when I find some time.

What does cargo say about which files have changed specifically?

I can't get it to tell me anything, even with -vv. It just prints the Compiling proc-macros2 etc., and executes the build script.

[ipetkov]

You can also try running it with CARGO_LOG=cargo::core::compiler::fingerprint=trace and see if that shows anything interesting

[dpc]

I created a quick-start example based project where I've added syn as a depdency (which brings also proc-macro2), and couldn't reprod, even bringing more and more little details of the affected project.

CARGO_LOG of affected vs example shows a important difference:

Affected:

[2023-08-23T18:58:43Z DEBUG cargo::core::compiler::fingerprint] old local fingerprints deps "/nix/store/8xlxixbffyyra5w4xv8fabyfcwynfdh0-vendor-cargo-deps/c19b7c6f923b580ac259164a89f2577984ad5ab09ee9d583b888f934adbbe8d0/proc-macro2-1.0.66" precalculated="1.0.66"

Not affected:

quick-start-build> [2023-08-23T19:18:54Z DEBUG cargo::core::compiler::fingerprint] new local fingerprints deps "/nix/store/wzs1f02h3xw6i0ql0a12r6kbla1savr2-vendor-cargo-deps/c19b7c6f923b580ac259164a89f2577984ad5ab09ee9d583b888f934adbbe8d0/proc-macro2-1.0.66"

which reading the code suggests that in the affected build cargo somehow lost the information proc-macro2 does output rerun-if-changed=build.rs every time and is thus 'new-style' custom build.

[dpc]

I see that it affects another projects, so maybe I'm not just crazy. I reported it on cargo issue tracker, maybe I can get some help.

[dpc]

Important observation: I have 3 stages of building

• deps only
• build workspace
• run tests

The "run tests" internally, very early runs the same command that "build workspace" runs (in case this script is invoked from a dev shell). And there there is no rebuilds. Which I just realized, rules out the storing&restoring of target directory itself being an issue.

[dpc]

Not doing .cargo copying in self.mkDummySrc didn't seem to change anything.

[dpc]

Getting rid of installCargoArtifactsMode = true; does not remove the problem.

Getting rid of any differences between args passed to buildDepsOnly and building workspace does not remove the problem.

(I'm basically stripping improvements/optimizations and see if any fixes it).

[dpc]

The problem did not happen in release build!

[dpc]

We have an extra ci profile (inheriting from dev), so I tried all 3, and for some reason release doesn't have the issue. Erasing the extra settings for these profiles in Cargo.toml doesn't change anything, so I don't think it's about the customizations itself.

@Radvendii since you seem to experience same issues, and I don't know the exact details, if you could verify that, it would be very valuable.

[Radvendii]

I'm not sure where I'm supposed to set that profile. If I add --release to cargoExtraArgs, it complains about not being allowed to set it twice, so it seems like it's already getting set somewhere but I'm not actually sure where.

[dpc]

I'm not sure where I'm supposed to set that profile. If I add --release to cargoExtraArgs, it complains about not being allowed to set it twice, so it seems like it's already getting set somewhere but I'm not actually sure where.

CARGO_PROFILE is introduced on on crane level. If CARGO_PROFILE is set crane will run cargo ... command with --profile $CARGO_PROFILE instead of --release.

If you ever build your own cargo ... command you need to take care of $CARGO_PROFILE itself if you want it to be compatible with crane.

@Radvendii

[Radvendii]

So I set CARGO_PROFILE = "release"; on the deps only build and one of the main builds, and it still rebuilt the build.rs-using dependencies

[ipetkov]

If you ever build your own cargo ... command you need to take care of $CARGO_PROFILE itself if you want it to be compatible with crane.

There's also the cargoWithProfile helper which will automatically inject --profile ... or --release based on the value of CARGO_PROFILE

---

@Radvendii you can set CARGO_LOG = "cargo::core::compiler::fingerprint=trace"; and look through the logs to see why the build is being invalidated

[Radvendii]

first i get a bunch of logs like

[2023-09-13T01:19:34Z DEBUG cargo::core::compiler::fingerprint] fingerprint at: /build/source/target/release/.fingerprint/nickel-lang-core-c6da6289b4897f33/lib-nickel-lang-core
[2023-09-13T01:19:34Z DEBUG cargo::core::compiler::fingerprint] max output mtime for "/nix/store/bhyli42jac57wn36n7sl24n14m3ryynz-vendor-cargo-deps/c19b7c6f923b580ac259164a89f2577984ad5ab09ee9d583b888f934adbbe8d0/ansi_term-0.12.1" is "/build/source/target/release/deps/libansi_term-0948ac557423c31e.rmeta" 1.000000000s
[2023-09-13T01:19:34Z DEBUG cargo::core::compiler::fingerprint] all paths up-to-date relative to "/build/source/target/release/.fingerprint/ansi_term-0948ac557423c31e/dep-lib-ansi_term" mtime=1.000000000s
[2023-09-13T01:19:34Z DEBUG cargo::core::compiler::fingerprint] filesystem up-to-date "/nix/store/bhyli42jac57wn36n7sl24n14m3ryynz-vendor-cargo-deps/c19b7c6f923b580ac259164a89f2577984ad5ab09ee9d583b888f934adbbe8d0/ansi_term-0.12.1"

Then i get a bunch of logs like

[2023-09-13T01:19:34Z INFO  cargo::core::compiler::fingerprint] fingerprint error for nickel-lang-core v0.1.0 (/build/source/core)/Build/TargetInner { benched: false, ..: lib_target("nickel-lang-core", ["lib"], "/build/source/core/src/lib.rs", Edition2021) }
[2023-09-13T01:19:34Z INFO  cargo::core::compiler::fingerprint]     err: failed to read `/build/source/target/release/.fingerprint/nickel-lang-core-c6da6289b4897f33/lib-nickel-lang-core`
    
    Caused by:
        No such file or directory (os error 2)

Then a bunch of normal-looking logs e.g.

[2023-09-13T01:19:34Z DEBUG cargo::core::compiler::fingerprint] fingerprint at: /build/source/target/release/.fingerprint/itertools-52f884d0b248894f/lib-itertools

And only after a ton of logs does it actually start compiling the dependencies. I'm not seeing any of the "fingerprint mismatch" logs and nothing of note immediately before the dependencies get re-compiled

The most suspicious looking thing is the "no such file or directory" errors

[dpc]

Since I know that release works fine, and other profiles are affected I ran a binary search changing options to dev build to ones that release use and with:

[profile.dev]
debug = false

the problem disappears.

[dpc]

TODO

Try a fork of crane that does not mess with timestamps etc. in the compressed files. Logic: what else could it be? It has to be it. And really, other then some purity, there's no point. Everything is tared anyway, so Nix can't see these timestamps, and any derivation running later will be necessity have time in the future. cargo doesn't care if these files were built 1 minute or 1 month in the past, as long as they're in the past, right?

Edit: Nvmd. That's not it. It has something to do with deps-only minimization, and I forgot about it.

[dpc]

Found it!!!

rust-lang/cargo#12457

Fix/workaround: https://github.com/fedimint/fedimint/pull/3212/files

@ipetkov I don't know if there's anything crane could do about it. Probably not. Maybe it's worth pointing out somewhere. Or at least it's good to be aware of it.

[ISibboI]

The workaround means you cannot have debug info anymore? That is quite of a bummer, as I use crane also for building binaries for integration tests.

[dpc]

The workaround means you cannot have debug info anymore? That is quite of a bummer, as I use crane also for building binaries for integration tests.

The workaround is profile.dev.build-override, which means it affects only building build.rs script. The chance you'll really need debug symbols in build script is virtually 0. Everything else stays unaffected.

[ISibboI]

I see, thanks!

[dpc]

@Radvendii You should give it a try. I'm curious if it fixes it for you as well.

Since you were getting rebuilds in release mode, you either have a different problem, or you were using debug = true or something in the release build profile.

[ipetkov]

I don't know if there's anything crane could do about it. Probably not. Maybe it's worth pointing out somewhere. Or at least it's good to be aware of it.

@dpc I'm very glad you found the issue! I've opened #388 to document the workaround in case anyone else runs into it!