`sccache-dist`: cache can end up somehow corrupted

[lissyx]

I have no STR unfortunately, but I was using sccache-dist circa ~0.7.1pre and it was running fine. Recently updated to 0.7.4 and intermittently I end up with mozilla-central failing to perform some link step, at various places.

After long and extensible debugging, one should note the following:

• need to remove the offending .o from objdir (pppolicy.o for the example)
• sccache (built only with dist-client feature set) log shows cache it on the same .o

Looking at it closely:

$ ll obj-browser-dbg/security/nss/cmd/lib/lib_sectool/pppolicy.o
-rw-rw-r-- 1 alex alex 704 mars   4 12:52 obj-browser-dbg/security/nss/cmd/lib/lib_sectool/pppolicy.o

On a successfull builds, it's bigger:

$ ll obj-browser-dbg/security/nss/cmd/lib/lib_sectool/pppolicy.o
-rw-r--r-- 1 alexandre alexandre 47K  4 mars  10:02 obj-browser-dbg/security/nss/cmd/lib/lib_sectool/pppolicy.o

The bogus one content's through objdump -tTC shows no symbol

Checking the local sccache content,

$ zipinfo -l ~/.cache/sccache/a/6/a60422ee74380eb71dd55572d4a4fd2c43ad2b611ddbb322c105462e9ec4115e
Archive:  /home/alex/.cache/sccache/a/6/a60422ee74380eb71dd55572d4a4fd2c43ad2b611ddbb322c105462e9ec4115e
Zip file size: 589 bytes, number of entries: 2
-rw-rw-r--  4.6 unx      277 b-      277 stor 80-Jan-01 00:00 obj
-rw-r--r--  4.6 unx      120 b-      120 stor 80-Jan-01 00:00 stderr

277 bytes is obviously weird. Getting rid of this cache key and the matching objdir file, issuing a rebuild:

$ zipinfo -l ~/.cache/sccache/a/6/a60422ee74380eb71dd55572d4a4fd2c43ad2b611ddbb322c105462e9ec4115e
Archive:  /home/alex/.cache/sccache/a/6/a60422ee74380eb71dd55572d4a4fd2c43ad2b611ddbb322c105462e9ec4115e
Zip file size: 14154 bytes, number of entries: 2
-rw-rw-r--  4.6 unx    13842 b-    13842 stor 80-Jan-01 00:00 obj
-rw-r--r--  4.6 unx      120 b-      120 stor 80-Jan-01 00:00 stderr

And no more linkage failure (on this file at least). I have no idea how it got corrupted at first.

[sylvestre]

It can generate errors like:

 0:04.95 ld.lld: error: undefined symbol: SECU_PrintPrivKeyUsagePeriodExtension
 0:04.95 >>> referenced by secutil.c:2124 (/home/alex/codaz/Mozilla/gecko-cinnabar/security/nss/cmd/lib/secutil.c:2124)
 0:04.95 >>>               /home/alex/codaz/Mozilla/gecko-cinnabar/obj-browser-dbg/security/nss/cmd/pk12util/pk12util_pk12util/../../lib/lib_sectool/secutil.o:(SECU_PrintExtensions)
 

[zig-for]

I hit this same exact issue. Tiny object file, no symbols.

[zig-for]

This was running CMake + ninja + clang-12 though I could have accidentally poisoned the cache with a bad compiler (initially - c++ instead of clang-12, then clang-12 instead of clang++-12 for cpp).

[lissyx]

I ran 0.7.1 for a few weeks without a problem, I've switched to 0.7.2 last monday and so far so good. I'll keep slowly bisecting ...

[StephanDollberg]

Facing the same issue on a C++ build. Getting random linker errors.

0.7.1 working fine so far.

[johnLate]

I think I've narrowed it down a bit:

In this example the first invocation with sccache results in sccache: Compiler killed by signal 1, the second invocation with the same file results in an object file despite compile errors.

$ cat foobar.cpp 
foobar;

$ g++ -c foobar.cpp -o foobar.o ; echo exitcode: $? ; ls -l foobar.o
foobar.cpp:1:1: error: ‘foobar’ does not name a type
    1 | foobar;
      | ^~~~~~
exitcode: 1
ls: cannot access 'foobar.o': No such file or directory

$ g++ -c foobar.cpp -o foobar.o ; echo exitcode: $? ; ls -l foobar.o
foobar.cpp:1:1: error: ‘foobar’ does not name a type
    1 | foobar;
      | ^~~~~~
exitcode: 1
ls: cannot access 'foobar.o': No such file or directory

$ sccache g++ -c foobar.cpp -o foobar.o ; echo exitcode: $? ; ls -l foobar.o
foobar.cpp:1:1: error: 'foobar' does not name a type
    1 | # 1 "foobar.cpp"
      | ^~~~~~
sccache: Compiler killed by signal 1
exitcode: 254
ls: cannot access 'foobar.o': No such file or directory

$ sccache g++ -c foobar.cpp -o foobar.o ; echo exitcode: $? ; ls -l foobar.o
exitcode: 0
-rw-r----- 1 user user 1080 Mai  4 19:25 foobar.o

$ 

(This is with 0.7.2, can someone test 0.8.0?)

[johnLate]

I've tested 0.7.1, 0.7.2 and 0.8.0 now.

0.7.1 is not affected.

0.7.2 and 0.8.0 are affected (only when distributed compilation is configured).

Steps to reproduce: https://gist.github.com/johnLate/9ea390dfa59a4641cfc8ff20263ce14b

[sylvestre]

@johnLate I know it can be painful but having an exact changeset would help a lot :)

[johnLate]

@sylvestre You weren't kidding. This was my first time using the rust compiler and each "cargo build" took more than 6 minutes.

/tmp/scc/gh/sccache$ git bisect log
# bad: [2a6ca4d79c7acfb6c58220c1db5a448784acd662] Fix some typos
# good: [1d71d5d810c161ff85217c71608d1d2262c35afb] prepare version 0.7.1
git bisect start 'v0.7.2' 'v0.7.1'
# good: [9d9ea15f90e250a79b64be394a1486e6c8806208] Appease the TOML formatter
git bisect good 9d9ea15f90e250a79b64be394a1486e6c8806208
# bad: [033ea2a5f913f5c3341b5b93cf29eaa86fc6d361] build(deps): bump jobserver from 0.1.26 to 0.1.27
git bisect bad 033ea2a5f913f5c3341b5b93cf29eaa86fc6d361
# bad: [e63185b6d434aac581d5da1037f51786e60df2bd] Activate preprocessor cache mode by default
git bisect bad e63185b6d434aac581d5da1037f51786e60df2bd
# good: [b3e75d0861a73b71a1d9452a78328c53dc8fb3e9] Fix input file times in end-to-end tests
git bisect good b3e75d0861a73b71a1d9452a78328c53dc8fb3e9
# first bad commit: [e63185b6d434aac581d5da1037f51786e60df2bd] Activate preprocessor cache mode by default

/tmp/scc/gh/sccache$

[lissyx]

FTR I am running on 0.8.0 for a few days and I have that in my config:

[cache.disk.preprocessor_cache_mode]
# Whether to use the preprocessor cache mode
use_preprocessor_cache_mode = false
# Whether to use file times to check for changes
file_stat_matches = true
# Whether to also use ctime (file status change) time to check for changes
use_ctime_for_stat = true
# Whether to ignore `__TIME__` when caching
ignore_time_macros = false
# Whether to skip (meaning not cache, only hash) system headers
skip_system_headers = false
# Whether hash the current working directory
hash_working_directory = true

So far I think I have not yet hit the issue.

[sylvestre]

@lissyx because you disabled use_preprocessor_cache_mode = false
Performances will regress.

@johnLate many thanks for your abnegation!

@Alphare does it ring a bell? (corrupted cache with str) thanks

[lissyx]

@lissyx because you disabled use_preprocessor_cache_mode = false Performances will regress.

That was the point: verifying this was the problem. Between reduced performance and broken builds, I've made my choice :)

[Alphare]

@johnLate thanks for all the effort, this is quite helpful. I have limited time to look into this now, but I wanted to at least get an idea.

I see that when implemented the PCM I even left a TODO wondering about the effects of masking the preprocessor output in dist mode.
However, in the limited time I have today to look at this, it's not obvious to me why a compiler error would result in writing to the PCM cache causing the subsequent miscompilation, and only in dist-client mode. The TODO above is the most suspect thing IMO.

FYI the slowness in compilation is mainly due to linker + linker settings, removing

[profile.release]
codegen-units = 1
lto = true
strip = true

from the Cargo.toml makes it much faster. Also, switching to a faster linker like mold if available. :)