Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Incompatibility with sccache on long builds #87

Closed
tofay opened this issue Nov 30, 2022 · 28 comments · Fixed by #88
Closed

Incompatibility with sccache on long builds #87

tofay opened this issue Nov 30, 2022 · 28 comments · Fixed by #88

Comments

@tofay
Copy link
Contributor

tofay commented Nov 30, 2022

When using cargo auditable with sccache, cargo auditable sometimes panics. We're seeing that panic on long (5> mins) builds:

sccache: error: failed to execute compile
sccache: caused by: Compiler not supported: "thread \'main\' panicked at \'called `Result::unwrap()` on an `Err` value: MissingOption(Keys([\"--crate-name\", \"\"]))\', cargo-auditable/src/rustc_wrapper.rs:13:50\nnote: run with `RUST_BACKTRACE=1` environment variable to display a backtrace\n"

Running under strace shows that sccache is running /path/to/cargo-auditable rustc -vV when compiling a workspace member. Normally sccache runs this when compiling a dependency, and caches the information. On larger builds that cache expires causing sccache to run that command when compiling a workspace member, causing the panic

The panic can trivially by reproduced with

CARGO_PRIMARY_PACKAGE=foo ~/.cargo/bin/cargo-auditable rustc -vV
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: MissingOption(Keys(["--crate-name", ""]))', cargo-auditable/src/rustc_wrapper.rs:13:50
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

or by creating a new project without any dependencies and building with sccache and cargo auditable:

tom [ ~ ]$ cargo init new
     Created binary (application) package
tom [ ~ ]$ cd new
tom [ ~/new ]$ RUSTC_WRAPPER=/home/tom/.cargo/bin/sccache cargo auditable build
   Compiling new v0.1.0 (/home/tom/new)
sccache: error: failed to execute compile
sccache: caused by: Compiler not supported: "thread \'main\' panicked at \'called `Result::unwrap()` on an `Err` value: MissingOption(Keys([\"--crate-name\", \"\"]))\', cargo-auditable/src/rustc_wrapper.rs:13:50\nnote: run with `RUST_BACKTRACE=1` environment variable to display a backtrace\n"
error: could not compile `new`
@tofay tofay mentioned this issue Nov 30, 2022
Merged
@Shnatsel
Copy link
Member

Shnatsel commented Dec 1, 2022

Fix released as v0.5.5

@Shnatsel Shnatsel reopened this Dec 7, 2022
@Shnatsel
Copy link
Member

Shnatsel commented Dec 7, 2022

@tofay could you test if commit d3f9454 works for you? That exact commit, and not any of the subsequent ones.

It made the test fail and I added a workaround in subsequent commits, but I suspect that the test is not representative of the real world.

@Shnatsel
Copy link
Member

Shnatsel commented Dec 7, 2022

I cannot reproduce the issue on actual sccache on older versions that are supposed to be broken. I cannot get any build failures. These are the steps I've tried:

cargo install sccache --version=0.3.1 # latest as of this writing
cargo install cargo-auditable --version=0.5.4 # latest version that's NOT fixed
git clone https://github.com/mozilla/sccache # a large Rust project
cd sccache
export RUSTC_WRAPPER="$(which sccache)"
cargo auditable build -j1 --release # because of -j1 this takes over 10 minutes with a cold cache

@Shnatsel
Copy link
Member

Shnatsel commented Dec 7, 2022

The real question I'm trying to answer is whether the workaround I've added in 1aef302 is actually necessary; that is, when sccache calls rustc -vV, does it do so with the environment variables it received, or does it clear them.

I suspect that it preserves the environment, so relying on the environment variables alone is sufficient, but I don't want to make any changes without testing them.

@tofay
Copy link
Contributor Author

tofay commented Dec 9, 2022

I can't reproduce when building sccache either... - strace shows that cargo also does a cached rustc call at https://github.com/rust-lang/cargo/blob/70898e522116f6c23971e2a554b2dc85fd4c84cd/src/cargo/core/compiler/build_context/target_info.rs#L214, and that affects the window condition too.
I'll try and reproduce next week when I have access to the work projects that we hit this on.

@NobodyXu
Copy link

NobodyXu commented Mar 18, 2023 •
edited

@Shnatsel I was able to reproduce this in cargo-quickinstall CI when compiling cargo-deny.

It still fails due to:

  sccache: error: failed to execute compile
  sccache: caused by: Compiler not supported: "thread \'main\' panicked at \'Failed to invoke rustc! Make sure it\'s in your $PATH: Os { code: 2, kind: NotFound, message: \"No such file or directory\" }\', /home/runner/.cargo/registry/src/github.com-1ecc6299db9ec823/cargo-auditable-0.6.1/src/rustc_wrapper.rs:90:10\nstack backtrace:\n   0: rust_begin_unwind\n             at ./rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/panicking.rs:575:5\n   1: core::panicking::panic_fmt\n             at ./rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/core/src/panicking.rs:64:14\n   2: core::result::unwrap_failed\n             at ./rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/core/src/result.rs:1791:5\n   3: cargo_auditable::main\nnote: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.\n"

@NobodyXu NobodyXu mentioned this issue Mar 18, 2023
Closed
4 tasks
@NobodyXu
Copy link

From this CI with backtrace:

    0:     0x5647c9208e30 - std::backtrace_rs::backtrace::libunwind::trace::h79937bc171ada62c
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x5647c9208e30 - std::backtrace_rs::backtrace::trace_unsynchronized::h2292bca8571cb919
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x5647c9208e30 - std::sys_common::backtrace::_print_fmt::h9c461f248e4ae90d
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/sys_common/backtrace.rs:65:5
   3:     0x5647c9208e30 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::he9fe6bf1a39182e1
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/sys_common/backtrace.rs:44:22
   4:     0x5647c91b93ae - core::fmt::write::h032658c119c720d7
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/core/src/fmt/mod.rs:1208:17
   5:     0x5647c91e1bf4 - std::io::Write::write_fmt::h299fc90dfae41c0d
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/io/mod.rs:1682:15
   6:     0x5647c920cd97 - std::sys_common::backtrace::_print::heb70d25df9937e3f
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/sys_common/backtrace.rs:47:5
   7:     0x5647c920cd97 - std::sys_common::backtrace::print::had745c0a76b8b521
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/sys_common/backtrace.rs:34:9
   8:     0x5647c920cb35 - std::panicking::default_hook::{{closure}}::h1ea782cdfa2fd097
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/panicking.rs:267:22
   9:     0x5647c920d27c - std::panicking::default_hook::h1cc3af63455a163c
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/panicking.rs:286:9
  10:     0x5647c920d27c - std::panicking::rust_panic_with_hook::h5cafdc4b3bfd5528
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/panicking.rs:688:13
  11:     0x5647c920cf54 - std::panicking::begin_panic_handler::{{closure}}::hf31c60f40775892c
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/panicking.rs:579:13
  12:     0x5647c920cebc - std::sys_common::backtrace::__rust_end_short_backtrace::h28a5c7be595826cd
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/sys_common/backtrace.rs:137:18
  13:     0x5647c920ce91 - rust_begin_unwind
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/std/src/panicking.rs:575:5
  14:     0x5647c917dfa2 - core::panicking::panic_fmt::h8fa27a0b37dd98b7
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/core/src/panicking.rs:64:14
  15:     0x5647c917e3e2 - core::result::unwrap_failed::h62abf61e411aaa08
                               at /rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/core/src/result.rs:1791:5
  16:     0x5647c91b0822 - cargo_auditable::main::hdd65ba2143273e12
  17:     0x5647c9187293 - std::sys_common::backtrace::__rust_begin_short_backtrace::h4d3b5a05e09ea3dc
  18:     0x5647c91b159c - main
  19:     0x7fbc814b3083 - __libc_start_main
  20:     0x5647c9181b0e - _start
  21:                0x0 - <unknown>

@NobodyXu
Copy link

Here is the cargo-auditable binaries we used in quickinstall.

@NobodyXu
Copy link

The process invocation:

  process didn't exit successfully: `sccache /home/runner/.cargo/bin/cargo-auditable-v0.6.1 rustc - --crate-name ___ --print=file-names --crate-type bin --crate-type rlib --crate-type dylib --crate-type cdylib --crate-type staticlib --crate-type proc-macro --print=sysroot --print=split-debuginfo --print=crate-name --print=cfg` (exit status: 2)

/home/runner/.cargo/bin/cargo-auditable-v0.6.1 is the path where cargo-auditable is installed by cargo-binstall.

@Shnatsel
Copy link
Member

Fun but probably unrelated fact: if I run rustc --print=sysroot --print=split-debuginfo --print=crate-name --print=cfg on Rust 1.68, rustc panics. But rustc 1.70.0-nightly (900c35403 2023-03-08) returns an error instead.

@Shnatsel
Copy link
Member

@NobodyXu the issue you're hitting seems to be a novel one. I admit I am confused by the "no such file or directory" error when invoking rustc. Could you run the build under strace --follow-forks --trace=%process --columns=200 and post the output?

@Shnatsel
Copy link
Member

Also, could you confirm that building without cargo auditable works? I've seen the sccache code and it's quite fragile. It's possible that cargo auditable is not the culprit here.

@Shnatsel
Copy link
Member

Ah, I think I know what the problem is. Based on this command, it seems that sccache just calls a bunch of --print commands and rustc isn't instructed to actually compile anything, but we try to inject the audit info regardless, which fails.

I'll have a branch with a fix up for testing shortly.

@Shnatsel Shnatsel mentioned this issue Mar 18, 2023
Merged
@Shnatsel
Copy link
Member

I've opened #111 which should fix it. I'd appreciate if you could test it and confirm that it indeed fixes the issue before I cut a release.

@Shnatsel
Copy link
Member

Okay, apparently #111 didn't help.

To make matters worse, it only fails on Mac - the Linux build works just fine. So I won't even be able to reproduce it because I don't have any Apple hardware.

I think the best way to proceed is to run dtruss on the build process, which should list the system calls performed. This will give us a long log with a complete picture of what's going on. Unfortunately I've never used Apple systems so I cannot advise on the exact flags to pass to dtruss.

@NobodyXu
Copy link

Okay, apparently #111 didn't help.

To make matters worse, it only fails on Mac - the Linux build works just fine. So I won't even be able to reproduce it because I don't have any Apple hardware.

@Shnatsel It actually fails on Linux CI

@NobodyXu
Copy link

NobodyXu commented Mar 19, 2023 •
edited

@Shnatsel I was able to use strace to collect list of syscalls invoked in Linux CI:

execve("/home/runner/.cargo/bin/cargo-auditable", ["cargo-auditable", "auditable", "install", "cargo-deny", "--version", "0.13.7", "--target", "x86_64-unknown-linux-gnu", "--root", "/tmp/tmp.8QnOBjIuAH", "cargo-deny", "--features", "vendored-openssl,vendored-libgit"...], 0x7ffffc79fb80 /* 123 vars */) = 0
brk(NULL)                               = 0x55bdc709e000
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffc04d38700) = -1 EINVAL (Invalid argument)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7faf70503000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/tls/haswell/avx512_1/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/tls/haswell/avx512_1/x86_64", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/tls/haswell/avx512_1/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/tls/haswell/avx512_1", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/tls/haswell/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/tls/haswell/x86_64", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/tls/haswell/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/tls/haswell", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/tls/avx512_1/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/tls/avx512_1/x86_64", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/tls/avx512_1/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/tls/avx512_1", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/tls/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/tls/x86_64", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/tls/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/tls", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/haswell/avx512_1/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/haswell/avx512_1/x86_64", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/haswell/avx512_1/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/haswell/avx512_1", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/haswell/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/haswell/x86_64", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/haswell/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/haswell", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/avx512_1/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/avx512_1/x86_64", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/avx512_1/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/avx512_1", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib/x86_64", 0x7ffc04d37950) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/usr/lib/llvm-15/lib", {st_mode=S_IFDIR|0755, st_size=16384, ...}) = 0
openat(AT_FDCWD, "tls/haswell/avx512_1/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/haswell/avx512_1/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/haswell/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/haswell/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/avx512_1/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/avx512_1/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/avx512_1/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/avx512_1/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "avx512_1/x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "avx512_1/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=61329, ...}) = 0
mmap(NULL, 61329, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7faf704f4000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\3405\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=104984, ...}) = 0
mmap(NULL, 107592, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7faf704d9000
mmap(0x7faf704dc000, 73728, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7faf704dc000
mmap(0x7faf704ee000, 16384, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) = 0x7faf704ee000
mmap(0x7faf704f2000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x18000) = 0x7faf704f2000
close(3)                                = 0
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/haswell/avx512_1/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/haswell/avx512_1/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/haswell/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/haswell/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/avx512_1/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/avx512_1/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/avx512_1/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/avx512_1/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "avx512_1/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "avx512_1/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\220q\0\0\0\0\0\0"..., 832) = 832
pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0{E6\364\34\332\245\210\204\10\350-\0106\343="..., 68, 824) = 68
fstat(3, {st_mode=S_IFREG|0755, st_size=157224, ...}) = 0
pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0{E6\364\34\332\245\210\204\10\350-\0106\343="..., 68, 824) = 68
mmap(NULL, 140408, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7faf704b6000
mmap(0x7faf704bc000, 69632, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7faf704bc000
mmap(0x7faf704cd000, 24576, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0x7faf704cd000
mmap(0x7faf704d3000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c000) = 0x7faf704d3000
mmap(0x7faf704d5000, 13432, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7faf704d5000
close(3)                                = 0
openat(AT_FDCWD, "/usr/lib/llvm-15/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/haswell/avx512_1/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/haswell/avx512_1/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/haswell/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/haswell/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/avx512_1/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/avx512_1/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/avx512_1/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/avx512_1/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "avx512_1/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "avx512_1/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300A\2\0\0\0\0\0"..., 832) = 832
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
pread64(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32, 848) = 32
pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\30x\346\264ur\f|Q\226\236i\253-'o"..., 68, 880) = 68
fstat(3, {st_mode=S_IFREG|0755, st_size=2029592, ...}) = 0
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
pread64(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32, 848) = 32
pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\30x\346\264ur\f|Q\226\236i\253-'o"..., 68, 880) = 68
mmap(NULL, 2037344, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7faf702c4000
mmap(0x7faf702e6000, 1540096, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) = 0x7faf702e6000
mmap(0x7faf7045e000, 319488, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x19a000) = 0x7faf7045e000
mmap(0x7faf704ac000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1e7000) = 0x7faf704ac000
mmap(0x7faf704b2000, 13920, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7faf704b2000
close(3)                                = 0
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7faf702c1000
arch_prctl(ARCH_SET_FS, 0x7faf702c1780) = 0
mprotect(0x7faf704ac000, 16384, PROT_READ) = 0
mprotect(0x7faf704d3000, 4096, PROT_READ) = 0
mprotect(0x7faf704f2000, 4096, PROT_READ) = 0
mprotect(0x55bdc61c2000, 24576, PROT_READ) = 0
mprotect(0x7faf70532000, 4096, PROT_READ) = 0
munmap(0x7faf704f4000, 61329)           = 0
set_tid_address(0x7faf702c1a50)         = 5465
set_robust_list(0x7faf702c1a60, 24)     = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7faf704bcbf0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7faf704ca420}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x7faf704bcc90, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7faf704ca420}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=16384*1024, rlim_max=RLIM64_INFINITY}) = 0
poll([{fd=0, events=0}, {fd=1, events=0}, {fd=2, events=0}], 3, 0) = 1 ([{fd=0, revents=POLLHUP}])
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7faf70307090}, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGSEGV, {sa_handler=0x55bdc61755c0, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7faf704ca420}, NULL, 8) = 0
rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGBUS, {sa_handler=0x55bdc61755c0, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7faf704ca420}, NULL, 8) = 0
sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7faf70500000
mprotect(0x7faf70500000, 4096, PROT_NONE) = 0
sigaltstack({ss_sp=0x7faf70501000, ss_flags=0, ss_size=8192}, NULL) = 0
brk(NULL)                               = 0x55bdc709e000
brk(0x55bdc70bf000)                     = 0x55bdc70bf000
openat(AT_FDCWD, "/proc/self/maps", O_RDONLY|O_CLOEXEC) = 3
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=16384*1024, rlim_max=RLIM64_INFINITY}) = 0
fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
read(3, "55bdc6104000-55bdc610d000 r--p 0"..., 1024) = 1024
read(3, "31.so\n7faf704ac000-7faf704b0000 "..., 1024) = 1024
read(3, "s.so.1\n7faf704dc000-7faf704ee000"..., 1024) = 1024
read(3, "w-p 0002d000 08:01 4702         "..., 1024) = 457
close(3)                                = 0
sched_getaffinity(5465, 32, [0, 1])     = 8
readlink("/proc/self/exe", "/home/runner/.cargo/bin/cargo-au"..., 256) = 39
mmap(NULL, 36864, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7faf704f7000
rt_sigprocmask(SIG_BLOCK, ~[], [], 8)   = 0
clone(child_stack=0x7faf704ffff0, flags=CLONE_VM|CLONE_VFORK|SIGCHLD) = 5466
munmap(0x7faf704f7000, 36864)           = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
wait4(5466,  [{WIFEXITED(s) && WEXITSTATUS(s) == 101}], 0, NULL) = 5466
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=5466, si_uid=1001, si_status=101, si_utime=6, si_stime=3} ---
sigaltstack({ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=8192}, NULL) = 0
munmap(0x7faf70500000, 12288)           = 0
exit_group(101)                         = ?
+++ exited with 101 +++

@Shnatsel
Copy link
Member

Thanks! I'm afraid it didn't follow forks, you'll need a more advanced command: strace --follow-forks --trace=%process --columns=200

That should follow subprocesses and capture only the relevant syscalls.

Thanks for all the help in debugging this, by the way!

@NobodyXu
Copy link

Somehow --follow-forks is unsupported by strace on ubuntu-20.04

strace: unrecognized option '--follow-forks'

@NobodyXu
Copy link

NobodyXu commented Mar 19, 2023 •
edited

@Shnatsel Ok I got the strace output for children from this CI:

execve("/home/runner/.cargo/bin/cargo-auditable", ["cargo-auditable", "auditable", "install", "cargo-deny", "--version", "0.13.7", "--target", "x86_64-unknown-linux-gnu", "--root", "/tmp/tmp.yJUPlxFOoD", "cargo-deny", "--features", "vendored-openssl,vendored-libgit"...], 0x7ffe94579598 /* 125 vars */) = 0
arch_prctl(0x3001 /* ARCH_??? */, 0x7fff325c0580)                                                                                                                                                       = -1 EINVAL (Invalid argument)
arch_prctl(ARCH_SET_FS, 0x7f483e8c6780)                                                                                                                                                                 = 0
clone(child_stack=0x7f483eb06ff0, flags=CLONE_VM|CLONE_VFORK|SIGCHLDstrace: Process 5387 attached
 <unfinished ...>
[pid  5387] execve("/usr/lib/llvm-15/bin/cargo", ["cargo", "install", "cargo-deny", "--version", "0.13.7", "--target", "x86_64-unknown-linux-gnu", "--root", "/tmp/tmp.yJUPlxFOoD", "cargo-deny", "--features", "vendored-openssl,vendored-libgit"...], 0x55c9151dc500 /* 127 vars */) = -1 ENOENT (No such file or directory)
[pid  5387] execve("/opt/hostedtoolcache/sccache/0.4.0-pre.10/x64/cargo", ["cargo", "install", "cargo-deny", "--version", "0.13.7", "--target", "x86_64-unknown-linux-gnu", "--root", "/tmp/tmp.yJUPlxFOoD", "cargo-deny", "--features", "vendored-openssl,vendored-libgit"...], 0x55c9151dc500 /* 127 vars */) = -1 ENOENT (No such file or directory)
[pid  5387] execve("/home/runner/.local/bin/cargo", ["cargo", "install", "cargo-deny", "--version", "0.13.7", "--target", "x86_64-unknown-linux-gnu", "--root", "/tmp/tmp.yJUPlxFOoD", "cargo-deny", "--features", "vendored-openssl,vendored-libgit"...], 0x55c9151dc500 /* 127 vars */) = -1 ENOENT (No such file or directory)
[pid  5387] execve("/opt/pipx_bin/cargo", ["cargo", "install", "cargo-deny", "--version", "0.13.7", "--target", "x86_64-unknown-linux-gnu", "--root", "/tmp/tmp.yJUPlxFOoD", "cargo-deny", "--features", "vendored-openssl,vendored-libgit"...], 0x55c9151dc500 /* 127 vars */) = -1 ENOENT (No such file or directory)
[pid  5387] execve("/home/runner/.cargo/bin/cargo", ["cargo", "install", "cargo-deny", "--version", "0.13.7", "--target", "x86_64-unknown-linux-gnu", "--root", "/tmp/tmp.yJUPlxFOoD", "cargo-deny", "--features", "vendored-openssl,vendored-libgit"...], 0x55c9151dc500 /* 127 vars */ <unfinished ...>
[pid  5386] <... clone resumed>)                                                                                                                                                                        = 5387
[pid  5387] <... execve resumed>)                                                                                                                                                                       = 0
[pid  5387] arch_prctl(0x3001 /* ARCH_??? */, 0x7fff56a015c0)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5386] wait4(5387,  <unfinished ...>
[pid  5387] arch_prctl(ARCH_SET_FS, 0x7faf578c5900)                                                                                                                                                     = 0
[pid  5387] execve("/home/runner/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/cargo", ["/home/runner/.rustup/toolchains/"..., "install", "cargo-deny", "--version", "0.13.7", "--target", "x86_64-unknown-linux-gnu", "--root", "/tmp/tmp.yJUPlxFOoD", "cargo-deny", "--features", "vendored-openssl,vendored-libgit"...], 0x560756948cb0 /* 131 vars */) = 0
[pid  5387] arch_prctl(0x3001 /* ARCH_??? */, 0x7ffd1474cdf0)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5387] arch_prctl(ARCH_SET_FS, 0x7f9caadef900)                                                                                                                                                     = 0
 Downloading crates ...
[pid  5387] clone(child_stack=0x7f9c9c492df0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTIDstrace: Process 5388 attached
, parent_tid=[5388], tls=0x7f9c9c493700, child_tidptr=0x7f9c9c4939d0) = 5388
[pid  5388] exit(0)                                                                                                                                                                                     = ?
[pid  5388] +++ exited with 0 +++
[pid  5387] clone(child_stack=0x7f9c9c492df0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTIDstrace: Process 5389 attached
, parent_tid=[5389], tls=0x7f9c9c493700, child_tidptr=0x7f9c9c4939d0) = 5389
[pid  5389] exit(0)                                                                                                                                                                                     = ?
[pid  5389] +++ exited with 0 +++
  Downloaded cargo-deny v0.13.7
[pid  5387] clone(child_stack=0x7f9c9c503ff0, flags=CLONE_VM|CLONE_VFORK|SIGCHLDstrace: Process 5390 attached
 <unfinished ...>
[pid  5390] execve("/usr/lib/llvm-15/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                       = -1 ENOENT (No such file or directory)
[pid  5390] execve("/opt/hostedtoolcache/sccache/0.4.0-pre.10/x64/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                              = -1 ENOENT (No such file or directory)
[pid  5390] execve("/home/runner/.local/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                    = -1 ENOENT (No such file or directory)
[pid  5390] execve("/opt/pipx_bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                              = -1 ENOENT (No such file or directory)
[pid  5390] execve("/home/runner/.cargo/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */ <unfinished ...>
[pid  5387] <... clone resumed>)                                                                                                                                                                        = 5390
[pid  5390] <... execve resumed>)                                                                                                                                                                       = 0
[pid  5390] arch_prctl(0x3001 /* ARCH_??? */, 0x7ffdc03dd4d0)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5390] arch_prctl(ARCH_SET_FS, 0x7f4b560df900)                                                                                                                                                     = 0
[pid  5390] execve("/home/runner/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc", ["/home/runner/.rustup/toolchains/"..., "-vV"], 0x5617348e2c00 /* 133 vars */)                          = 0
[pid  5390] arch_prctl(0x3001 /* ARCH_??? */, 0x7ffc5ea5e4a0)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5390] arch_prctl(ARCH_SET_FS, 0x7efc51a3b640)                                                                                                                                                     = 0
[pid  5390] exit_group(0)                                                                                                                                                                               = ?
[pid  5390] +++ exited with 0 +++
[pid  5387] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=5390, si_uid=1001, si_status=0, si_utime=6, si_stime=1} ---
[pid  5387] wait4(5390, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL)                                                                                                                               = 5390
    Updating crates.io index
[pid  5387] clone(child_stack=0x7f9c9c492df0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTIDstrace: Process 5391 attached
, parent_tid=[5391], tls=0x7f9c9c493700, child_tidptr=0x7f9c9c4939d0) = 5391
[pid  5391] exit(0)                                                                                                                                                                                     = ?
[pid  5391] +++ exited with 0 +++
[pid  5387] clone(child_stack=0x7f9caadeeff0, flags=CLONE_VM|CLONE_VFORK|SIGCHLDstrace: Process 5392 attached
 <unfinished ...>
[pid  5392] execve("/usr/lib/llvm-15/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                       = -1 ENOENT (No such file or directory)
[pid  5392] execve("/opt/hostedtoolcache/sccache/0.4.0-pre.10/x64/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                              = -1 ENOENT (No such file or directory)
[pid  5392] execve("/home/runner/.local/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                    = -1 ENOENT (No such file or directory)
[pid  5392] execve("/opt/pipx_bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                              = -1 ENOENT (No such file or directory)
[pid  5392] execve("/home/runner/.cargo/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */ <unfinished ...>
[pid  5387] <... clone resumed>)                                                                                                                                                                        = 5392
[pid  5392] <... execve resumed>)                                                                                                                                                                       = 0
[pid  5392] arch_prctl(0x3001 /* ARCH_??? */, 0x7fffeb414d90)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5392] arch_prctl(ARCH_SET_FS, 0x7f1bd4d01900)                                                                                                                                                     = 0
[pid  5392] execve("/home/runner/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc", ["/home/runner/.rustup/toolchains/"..., "-vV"], 0x55fd9f36fdf0 /* 133 vars */)                          = 0
[pid  5392] arch_prctl(0x3001 /* ARCH_??? */, 0x7fff7d659e30)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5392] arch_prctl(ARCH_SET_FS, 0x7f51b93c8640)                                                                                                                                                     = 0
[pid  5392] exit_group(0)                                                                                                                                                                               = ?
[pid  5392] +++ exited with 0 +++
[pid  5387] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=5392, si_uid=1001, si_status=0, si_utime=3, si_stime=2} ---
[pid  5387] wait4(5392, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL)                                                                                                                               = 5392
[pid  5387] clone(child_stack=0x7f9c9c541ff0, flags=CLONE_VM|CLONE_VFORK|SIGCHLDstrace: Process 5393 attached
 <unfinished ...>
[pid  5393] execve("/usr/lib/llvm-15/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                       = -1 ENOENT (No such file or directory)
[pid  5393] execve("/opt/hostedtoolcache/sccache/0.4.0-pre.10/x64/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                              = -1 ENOENT (No such file or directory)
[pid  5393] execve("/home/runner/.local/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                    = -1 ENOENT (No such file or directory)
[pid  5393] execve("/opt/pipx_bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                              = -1 ENOENT (No such file or directory)
[pid  5393] execve("/home/runner/.cargo/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */ <unfinished ...>
[pid  5387] <... clone resumed>)                                                                                                                                                                        = 5393
[pid  5393] <... execve resumed>)                                                                                                                                                                       = 0
[pid  5393] arch_prctl(0x3001 /* ARCH_??? */, 0x7ffced0f9c70)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5393] arch_prctl(ARCH_SET_FS, 0x7fcd89a6c900)                                                                                                                                                     = 0
[pid  5393] execve("/home/runner/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc", ["/home/runner/.rustup/toolchains/"..., "-vV"], 0x559d9c37fdf0 /* 133 vars */)                          = 0
[pid  5393] arch_prctl(0x3001 /* ARCH_??? */, 0x7ffe3ea45140)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5393] arch_prctl(ARCH_SET_FS, 0x7f7951e85640)                                                                                                                                                     = 0
[pid  5393] exit_group(0)                                                                                                                                                                               = ?
[pid  5393] +++ exited with 0 +++
[pid  5387] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=5393, si_uid=1001, si_status=0, si_utime=4, si_stime=3} ---
[pid  5387] wait4(5393, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL)                                                                                                                               = 5393
[pid  5387] clone(child_stack=0x7f9caadeeff0, flags=CLONE_VM|CLONE_VFORK|SIGCHLDstrace: Process 5394 attached
 <unfinished ...>
[pid  5394] execve("/usr/lib/llvm-15/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                       = -1 ENOENT (No such file or directory)
[pid  5394] execve("/opt/hostedtoolcache/sccache/0.4.0-pre.10/x64/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                              = -1 ENOENT (No such file or directory)
[pid  5394] execve("/home/runner/.local/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                    = -1 ENOENT (No such file or directory)
[pid  5394] execve("/opt/pipx_bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                              = -1 ENOENT (No such file or directory)
[pid  5394] execve("/home/runner/.cargo/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */ <unfinished ...>
[pid  5387] <... clone resumed>)                                                                                                                                                                        = 5394
[pid  5394] <... execve resumed>)                                                                                                                                                                       = 0
[pid  5394] arch_prctl(0x3001 /* ARCH_??? */, 0x7ffe1b3ad1f0)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5394] arch_prctl(ARCH_SET_FS, 0x7ff2ccb90900)                                                                                                                                                     = 0
[pid  5394] execve("/home/runner/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc", ["/home/runner/.rustup/toolchains/"..., "-vV"], 0x56280e252fd0 /* 133 vars */)                          = 0
[pid  5394] arch_prctl(0x3001 /* ARCH_??? */, 0x7ffcffda6c50)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5394] arch_prctl(ARCH_SET_FS, 0x7f8dcc94d640)                                                                                                                                                     = 0
[pid  5394] exit_group(0)                                                                                                                                                                               = ?
[pid  5394] +++ exited with 0 +++
[pid  5387] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=5394, si_uid=1001, si_status=0, si_utime=5, si_stime=2} ---
[pid  5387] wait4(5394, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL)                                                                                                                               = 5394
  Installing cargo-deny v0.13.7
[pid  5387] clone(child_stack=0x7f9caadeeff0, flags=CLONE_VM|CLONE_VFORK|SIGCHLDstrace: Process 5395 attached
 <unfinished ...>
[pid  5395] execve("/usr/lib/llvm-15/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                       = -1 ENOENT (No such file or directory)
[pid  5395] execve("/opt/hostedtoolcache/sccache/0.4.0-pre.10/x64/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                              = -1 ENOENT (No such file or directory)
[pid  5395] execve("/home/runner/.local/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                    = -1 ENOENT (No such file or directory)
[pid  5395] execve("/opt/pipx_bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                              = -1 ENOENT (No such file or directory)
[pid  5395] execve("/home/runner/.cargo/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */ <unfinished ...>
[pid  5387] <... clone resumed>)                                                                                                                                                                        = 5395
[pid  5395] <... execve resumed>)                                                                                                                                                                       = 0
[pid  5395] arch_prctl(0x3001 /* ARCH_??? */, 0x7fff3acd56c0)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5395] arch_prctl(ARCH_SET_FS, 0x7f8cf9898900)                                                                                                                                                     = 0
[pid  5395] execve("/home/runner/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc", ["/home/runner/.rustup/toolchains/"..., "-vV"], 0x55ee25122ae0 /* 133 vars */)                          = 0
[pid  5395] arch_prctl(0x3001 /* ARCH_??? */, 0x7ffd81991890)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5395] arch_prctl(ARCH_SET_FS, 0x7fdfdb563640)                                                                                                                                                     = 0
[pid  5395] exit_group(0)                                                                                                                                                                               = ?
[pid  5395] +++ exited with 0 +++
[pid  5387] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=5395, si_uid=1001, si_status=0, si_utime=4, si_stime=1} ---
[pid  5387] wait4(5395, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL)                                                                                                                               = 5395
[pid  5387] clone(child_stack=0x7f9caadeeff0, flags=CLONE_VM|CLONE_VFORK|SIGCHLDstrace: Process 5396 attached
 <unfinished ...>
[pid  5396] execve("/usr/lib/llvm-15/bin/sccache", ["sccache", "/home/runner/.cargo/bin/cargo-au"..., "rustc", "-", "--crate-name", "___", "--print=file-names", "--crate-type", "bin", "--crate-type", "rlib", "--crate-type", "dylib", "--crate-type", "cdylib", "--crate-type", "staticlib", "--crate-type", "proc-macro", "--print=sysroot", "--print=split-debuginfo", "--print=crate-name", "--print=cfg"], 0x55958851f860 /* 133 vars */) = -1 ENOENT (No such file or directory)
[pid  5396] execve("/opt/hostedtoolcache/sccache/0.4.0-pre.10/x64/sccache", ["sccache", "/home/runner/.cargo/bin/cargo-au"..., "rustc", "-", "--crate-name", "___", "--print=file-names", "--crate-type", "bin", "--crate-type", "rlib", "--crate-type", "dylib", "--crate-type", "cdylib", "--crate-type", "staticlib", "--crate-type", "proc-macro", "--print=sysroot", "--print=split-debuginfo", "--print=crate-name", "--print=cfg"], 0x55958851f860 /* 133 vars */ <unfinished ...>
[pid  5387] <... clone resumed>)                                                                                                                                                                        = 5396
[pid  5396] <... execve resumed>)                                                                                                                                                                       = 0
[pid  5396] arch_prctl(ARCH_SET_FS, 0x7f74baa77270)                                                                                                                                                     = 0
[pid  5396] clone(child_stack=0x7f74baa73888, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000strace: Process 5397 attached
, parent_tid=[5397], tls=0x7f74baa73b20, child_tidptr=0x7f74bb9e19b8) = 5397
[pid  5396] clone(child_stack=0x7f74ba86d888, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000strace: Process 5398 attached
, parent_tid=[5398], tls=0x7f74ba86db20, child_tidptr=0x7f74bb9e19b8) = 5398
[pid  5396] clone(child_stack=0x7f74ba66a888, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000strace: Process 5399 attached
, parent_tid=[5399], tls=0x7f74ba66ab20, child_tidptr=0x7f74bb9e19b8) = 5399
[pid  5398] exit(0)                                                                                                                                                                                     = ?
[pid  5398] +++ exited with 0 +++
[pid  5399] exit(0)                                                                                                                                                                                     = ?
[pid  5399] +++ exited with 0 +++
[pid  5397] exit(0)                                                                                                                                                                                     = ?
[pid  5397] +++ exited with 0 +++
[pid  5396] exit_group(2)                                                                                                                                                                               = ?
[pid  5396] +++ exited with 2 +++
[pid  5387] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=5396, si_uid=1001, si_status=2, si_utime=0, si_stime=0} ---
[pid  5387] wait4(5396, [{WIFEXITED(s) && WEXITSTATUS(s) == 2}], 0, NULL)                                                                                                                               = 5396
[pid  5387] clone(child_stack=0x7f9caadeeff0, flags=CLONE_VM|CLONE_VFORK|SIGCHLDstrace: Process 5403 attached
 <unfinished ...>
[pid  5403] execve("/usr/lib/llvm-15/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                       = -1 ENOENT (No such file or directory)
[pid  5403] execve("/opt/hostedtoolcache/sccache/0.4.0-pre.10/x64/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                              = -1 ENOENT (No such file or directory)
[pid  5403] execve("/home/runner/.local/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                    = -1 ENOENT (No such file or directory)
[pid  5403] execve("/opt/pipx_bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */)                                                                                                              = -1 ENOENT (No such file or directory)
[pid  5403] execve("/home/runner/.cargo/bin/rustc", ["rustc", "-vV"], 0x5595883a4500 /* 133 vars */ <unfinished ...>
[pid  5387] <... clone resumed>)                                                                                                                                                                        = 5403
[pid  5403] <... execve resumed>)                                                                                                                                                                       = 0
[pid  5403] arch_prctl(0x3001 /* ARCH_??? */, 0x7ffcef42a690)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5403] arch_prctl(ARCH_SET_FS, 0x7f0b225c3900)                                                                                                                                                     = 0
[pid  5403] execve("/home/runner/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc", ["/home/runner/.rustup/toolchains/"..., "-vV"], 0x56183349bbc0 /* 133 vars */)                          = 0
[pid  5403] arch_prctl(0x3001 /* ARCH_??? */, 0x7ffedea7c040)                                                                                                                                           = -1 EINVAL (Invalid argument)
[pid  5403] arch_prctl(ARCH_SET_FS, 0x7f9df5116640)                                                                                                                                                     = 0
[pid  5403] exit_group(0)                                                                                                                                                                               = ?
[pid  5403] +++ exited with 0 +++
[pid  5387] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=5403, si_uid=1001, si_status=0, si_utime=4, si_stime=3} ---
[pid  5387] wait4(5403, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL)                                                                                                                               = 5403
[pid  5387] clone(child_stack=0x7f9caadeeff0, flags=CLONE_VM|CLONE_VFORK|SIGCHLDstrace: Process 5404 attached
 <unfinished ...>
[pid  5404] execve("/usr/lib/llvm-15/bin/sccache", ["sccache", "/home/runner/.cargo/bin/cargo-au"..., "rustc", "-", "--crate-name", "___", "--print=file-names", "--crate-type", "bin", "--crate-type", "rlib", "--crate-type", "dylib", "--crate-type", "cdylib", "--crate-type", "staticlib", "--crate-type", "proc-macro", "--print=sysroot", "--print=split-debuginfo", "--print=crate-name", "--print=cfg"], 0x5595884beb30 /* 133 vars */) = -1 ENOENT (No such file or directory)
[pid  5404] execve("/opt/hostedtoolcache/sccache/0.4.0-pre.10/x64/sccache", ["sccache", "/home/runner/.cargo/bin/cargo-au"..., "rustc", "-", "--crate-name", "___", "--print=file-names", "--crate-type", "bin", "--crate-type", "rlib", "--crate-type", "dylib", "--crate-type", "cdylib", "--crate-type", "staticlib", "--crate-type", "proc-macro", "--print=sysroot", "--print=split-debuginfo", "--print=crate-name", "--print=cfg"], 0x5595884beb30 /* 133 vars */ <unfinished ...>
[pid  5387] <... clone resumed>)                                                                                                                                                                        = 5404
[pid  5404] <... execve resumed>)                                                                                                                                                                       = 0
[pid  5404] arch_prctl(ARCH_SET_FS, 0x7fa60a384270)                                                                                                                                                     = 0
[pid  5404] clone(child_stack=0x7fa60a380888, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000strace: Process 5405 attached
, parent_tid=[5405], tls=0x7fa60a380b20, child_tidptr=0x7fa60b2e89b8) = 5405
[pid  5404] clone(child_stack=0x7fa60a17a888, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000strace: Process 5406 attached
, parent_tid=[5406], tls=0x7fa60a17ab20, child_tidptr=0x7fa60b2e89b8) = 5406
[pid  5404] clone(child_stack=0x7fa609f77888, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[5407], tls=0x7fa609f77b20, child_tidptr=0x7fa60b2e89b8) = 5407
strace: Process 5407 attached
[pid  5406] exit(0)                                                                                                                                                                                     = ?
[pid  5406] +++ exited with 0 +++
[pid  5407] exit(0)                                                                                                                                                                                     = ?
[pid  5407] +++ exited with 0 +++
[pid  5405] exit(0)                                                                                                                                                                                     = ?
[pid  5405] +++ exited with 0 +++
[pid  5404] exit_group(2)                                                                                                                                                                               = ?
[pid  5404] +++ exited with 2 +++
[pid  5387] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=5404, si_uid=1001, si_status=2, si_utime=0, si_stime=0} ---
[pid  5387] wait4(5404, [{WIFEXITED(s) && WEXITSTATUS(s) == 2}], 0, NULL)                                                                                                                               = 5404
[pid  5387] exit_group(101)                                                                                                                                                                             = ?
[pid  5387] +++ exited with 101 +++
<... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 101}], 0, NULL)                                                                                                                                  = 5387
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=5387, si_uid=1001, si_status=101, si_utime=10, si_stime=5} ---
exit_group(101)                                                                                                                                                                                         = ?

@Shnatsel
Copy link
Member

It's getting late in my timezone, so I'll investigate the log and try to reproduce tomorrow. Thank you!

@NobodyXu
Copy link

You are welcome!

@NobodyXu
Copy link

I also tried upgrading sccache to v0.4.0-pre.11 which was released early today but it still failed

@Shnatsel
Copy link
Member

I can reproduce this locally when running the command from #87 (comment)

Thanks for getting me to this point. The rest should be "just" debugging.

@Shnatsel
Copy link
Member

This is a bug in sccache.

It appears that sccache calls the Rust workspace wrapper with the arguments intended for the C compiler instead of the Rust compiler. It invokes /home/runner/.cargo/bin/cargo-auditable-v0.6.1 -E /tmp/sccachemNgxBK/testfile.c, which is not a valid call to rustc. The Rust compiler does not accept the -E option (gcc does), and it's being passed a C file, not a Rust file.

There's nothing I can do to fix this in cargo auditable. You'll have to file a bug against sccache. I'll research workarounds so you could get the caching going without waiting on a fix.

@Shnatsel
Copy link
Member

Ah, the sccache-less workaround is to use a shared target directory for all your projects: https://doc.rust-lang.org/nightly/cargo/reference/config.html#buildtarget-dir

@Shnatsel
Copy link
Member

I've also opened #112 to print a more debuggable error when this happens.

@NobodyXu NobodyXu mentioned this issue Mar 21, 2023
Open
@NobodyXu
Copy link

Thank you for taking your time for this issue!
I've submit an issue to the upstream.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

cope with failure to parse rustc args tofay/rust-audit
3 participants
@Shnatsel @tofay @NobodyXu