"can't find crate for..." proc-macro crates when the crate is clearly present and is passed to rustc

[NoraCodes]

Problem

When compiling some crates (poem 3.1.10, salvo 0.78.0), I expect them to build; they fail to build with errors like:

error[E0463]: can't find crate for `salvo_macros`
  --> /home/nora/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/salvo_core-0.78.0/src/lib.rs:31:9
   |
31 | pub use salvo_macros::handler;
   |         ^^^^^^^^^^^^ can't find crate

error[E0463]: can't find crate for `salvo_macros`
  --> /home/nora/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/salvo_core-0.78.0/src/lib.rs:33:9
   |
33 | pub use salvo_macros as macros;
   |         ^^^^^^^^^^^^ can't find crate

error[E0463]: can't find crate for `salvo_macros`
  --> /home/nora/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/salvo_core-0.78.0/src/lib.rs:85:13
   |
85 |     pub use salvo_macros::{Extractible, handler};
   |             ^^^^^^^^^^^^ can't find crate

For more information about this error, try `rustc --explain E0463`.
error: could not compile `salvo_core` (lib) due to 3 previous errors

Steps

1. cargo new whatever && cd whatever
2. cargo add poem (or salvo)
3. cargo build

However, I tried this on a new VM and wasn't able to reproduce it. It's something to do with my system, and I haven't yet figured out what.

Possible Solution(s)

I tried uninstalling (rustup self uninstall) and reinstalling Rust, as well as cargo clean and rm -r ~/.cargo/registry/cache.

This appears not to happen under rust 1.80 but does happen under 1.81.

Notes

I ran cargo build --verbose and can see that the "missing" crates are indeed being passed to rustc:

/home/nora/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc 
--crate-name salvo_core 
--edition=2024 /home/nora/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/salvo_core-0.78.0/src/lib.rs 
# ...
--extern salvo_macros=/tmp/salvotest/target/debug/deps/libsalvo_macros-2d16cc326ba6665d.so 
# ...
--cap-lints allow`

Version

cargo 1.86.0 (adf9b6ad1 2025-02-28)
release: 1.86.0
commit-hash: adf9b6ad14cfa10ff680d5806741a144f7163698
commit-date: 2025-02-28
host: x86_64-unknown-linux-gnu
libgit2: 1.9.0 (sys:0.20.0 vendored)
libcurl: 8.12.0-DEV (sys:0.4.79+curl-8.12.0 vendored ssl:OpenSSL/1.1.1w)
ssl: OpenSSL 1.1.1w  11 Sep 2023
os: Debian 12.0.0 (bookworm) [64-bit]

[jyn514]

nora ran cargo bisect-rustc and found this:

Regression in nightly-2024-07-13

...

looking for regression commit between 2024-07-12 and 2024-07-13
fetching (via remote github) commits from max(5315cbe15b79533f380bbb6685aa5480d5ff4ef5, 2024-07-10) to c6727fc9b5c64cefa7263486497ee95e529bd0f8
ending github query because we found starting sha: 5315cbe15b79533f380bbb6685aa5480d5ff4ef5
get_commits_between returning commits, len: 8
  commit[0] 2024-07-11: Auto merge of #127609 - flip1995:clippy-subtree-update, r=Manishearth
  commit[1] 2024-07-11: Auto merge of #127614 - matthiaskrgr:rollup-8geziwi, r=matthiaskrgr
  commit[2] 2024-07-12: Auto merge of #127382 - estebank:const-let, r=compiler-errors
  commit[3] 2024-07-12: Auto merge of #127635 - matthiaskrgr:rollup-foopajr, r=matthiaskrgr
  commit[4] 2024-07-12: Auto merge of #127479 - Urgau:rustc-stable-hash, r=michaelwoerister
  commit[5] 2024-07-12: Auto merge of #127653 - matthiaskrgr:rollup-72bqgvp, r=matthiaskrgr
  commit[6] 2024-07-12: Auto merge of #127636 - nnethercote:fix-Parser-look_ahead, r=oli-obk
  commit[7] 2024-07-12: Auto merge of #123351 - beetrees:x86-ret-snan-rust, r=nikic,workingjubilee

so a) this is a rustc bug, and b) i suspect it is related to rustc-stable-hash somehow.

we also ran RUSTC_LOG=rustc_metadata=info and found this mismatch between the working and non-working builds:

# working
 INFO rustc_metadata::creader resolving crate `poem_derive`
 INFO rustc_metadata::creader library for `poem_derive` was loaded previously

# non-working
 INFO rustc_metadata::creader resolving crate `poem_derive`
 INFO rustc_metadata::creader falling back to a load
 INFO rustc_metadata::locator dylib reading metadata from: /tmp/whatever/target/debug/deps/libpoem_derive-a4fba4f212f1e51d.so
 INFO rustc_metadata::locator Rejecting via proc macro: expected false got true
 INFO rustc_metadata::locator metadata mismatch
 INFO rustc_metadata::creader falling back to loading proc_macro
 INFO rustc_metadata::locator dylib reading metadata from: /tmp/whatever/target/debug/deps/libpoem_derive-a4fba4f212f1e51d.so
 INFO rustc_metadata::creader register newly loaded library for `poem_derive`
 INFO rustc_metadata::creader register crate `poem_derive` (cnum = 84. private_dep = false)

[jyn514]

this bit here: https://github.com/rust-lang/rust/blob/c9f690a1e3d42f80788e9e4f2aa25547b1d8df58/compiler/rustc_metadata/src/creader.rs#L516-L535
is rejecting a previously loaded crate, but i'm not sure why

[jyn514]

there is additional logging in the non-working case that i didn't post at first; here it is:

 INFO rustc_metadata::creader resolving crate `poem_derive`
 INFO rustc_metadata::creader falling back to a load
 INFO rustc_metadata::locator dylib reading metadata from: /tmp/whatever/target/debug/deps/libpoem_derive-a4fba4f212f1e51d.so
 INFO rustc_metadata::locator Rejecting via proc macro: expected false got true
 INFO rustc_metadata::locator metadata mismatch
 INFO rustc_metadata::creader falling back to loading proc_macro
 INFO rustc_metadata::locator dylib reading metadata from: /tmp/whatever/target/debug/deps/libpoem_derive-a4fba4f212f1e51d.so
 INFO rustc_metadata::creader register newly loaded library for `poem_derive`
 INFO rustc_metadata::creader resolving crate `poem_derive`

in particular note those last two lines. "register newly loaded library" should always be followed by "register crate"; the only way it can go wrong is if intern_stable_crate_id returns an error.

my working theory:

1. existing_match, for some reason, incorrectly thinks it needs to reload the crate because of a mismatch.
2. CrateLocator successfully finds the crate and passes it to register_crate
3. register_crate fails to reregister it, because it is the same crate and it rejects duplicate StableCrateIds.

cc @petrochenkov @Urgau i suspect this is related to rust-lang/rust#127479 somehow but i'm not sure how. do you have ideas on what could be going wrong in existing_match?

[jyn514]

i think there is a secondary issue which is that this should have reported E0519 instead of "crate not found". the last code to touch that was rust-lang/rust#111461 but that says it was just readding existing logic.

[jyn514]

ok yeah rust-lang/rust#109213 really should not have removed the bug!; cc @oli-obk

[Urgau]

I re-examine rust-lang/rust#127479 and I don't see anything that would explain the behavior seen here.

I also re-compared the extracted code with the code inside rustc-stable-hash and didn't find any meaningful difference.

@jyn514 Are you able to confirm that the crate hash are not the same? Does reverting the PR fixes the issue?

[jyn514]

@Urgau i'm not able to replicate this locally, so i can't confirm anything about the hashes one way or another. but i don't see anything else in the range bisect-rustc shows that could possible affect metadata loading. and the error seems related to hashing somehow, because the issue is that rustc_resolve thinks the .so file doesn't match the already loaded cnum, even though later it errors because file has the same StableCrateId.

[Urgau]

I tried locally and on a VM and I'm also unable to reproduce it, with both poem and salvo.

[shunby]

Do you have the Nix package manager installed? I am using Nix on Ubuntu and ran into a similar issue with wasmtime. Removing gcc that was installed via the Nix Home Manager solved it for me. Someone else on the Rust user forums seems to have encountered the same problem.

[weihanglo]

I bumped into this a couple of times with nixpkgs but never remembered how I fixed it. Guess it might be nix patch-elf at sometimes patching rustc wrongly, or my rust toolchain frkm nixpkgs was missing some dependencies.