Bug 11109 - testsuite failure on i586/gcc-4.8.3: TEST: "cache miss doesntexist
Summary: testsuite failure on i586/gcc-4.8.3: TEST: "cache miss doesntexist
Alias: None
Product: ccache
Classification: Unclassified
Component: ccache (show other bugs)
Version: 3.2.1
Hardware: x86 Linux
: P5 normal
Target Milestone: 3.2.2
Assignee: Joel Rosdahl
QA Contact: Joel Rosdahl
Depends on:
Reported: 2015-02-20 18:11 UTC by Martin Pluskal
Modified: 2015-06-20 12:57 UTC (History)
0 users

See Also:

last lines of strace -f -o strace.log ./test.sh (9.22 KB, application/x-xz)
2015-03-30 12:42 UTC, Martin Pluskal
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Pluskal 2015-02-20 18:11:58 UTC
When running testsuite on current openSUSE-Tumbleweed, with gcc-4.8.3, following failure occurs:
CC='gcc' ./test.sh
compiler: /usr/bin/gcc
version: gcc (SUSE Linux) 4.8.3 20141208 [gcc-4_8-branch revision 218481] Copyright (C) 2013 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
test dir: testdir.26863
starting testsuite base
starting testsuite link
starting testsuite hardlink
starting testsuite cpp2
starting testsuite nlevels4
starting testsuite nlevels1
starting testsuite basedir
starting testsuite direct
starting testsuite compression
starting testsuite readonly
starting testsuite readonly_direct
starting testsuite extrafiles
SUITE: "extrafiles", TEST: "cache miss doesntexist" - Expected "error hashing extra file" to be 1, got
cache directory                     /home/abuild/rpmbuild/BUILD/ccache-3.2.1/testdir.26863/.ccache
primary config                      /home/abuild/rpmbuild/BUILD/ccache-3.2.1/testdir.26863/.ccache/ccache.conf
secondary config      (readonly)    /etc/ccache.conf
cache hit (direct)                     0
cache hit (preprocessed)               3
cache miss                             3
files in cache                         3
cache size                          12.3 kB
max cache size                       5.0 GB
Test data and log file have been left in testdir.26863
Makefile:83: recipe for target 'test' failed
make: *** [test] Error 1

Issue seems to be limited to i586.
Comment 1 Joel Rosdahl 2015-03-08 16:18:11 UTC
That's strange, can't reproduce the problem. Can you attach ccache.log from testdir.* to the bug report?
Comment 2 Martin Pluskal 2015-03-10 08:52:31 UTC
File is unfortunetally too large for bugzilla attachment so its provided here (https://www.dropbox.com/s/bl02gk9dyivk9m0/ccache.log.xz?dl=0)

Suspicious part:
[2015-03-10T08:15:08.411078 16488] Running preprocessor
[2015-03-10T08:15:08.411095 16488] Executing /usr/bin/gcc -E test.c
[2015-03-10T08:15:08.417173 16488] Got object file hash from preprocessor
[2015-03-10T08:15:08.417269 16488] Copying /home/abuild/rpmbuild/BUILD/ccache-3.2.1/testdir.2712/.ccache/5/9/d77b5f47f6c07f36c35c8bd3b78653-224.o to test.o via test.o.daredevil.16488.agSdmx (uncompressed)
[2015-03-10T08:15:08.417396 16488] Created from cache: /home/abuild/rpmbuild/BUILD/ccache-3.2.1/testdir.2712/.ccache/5/9/d77b5f47f6c07f36c35c8bd3b78653-224.o -> test.o
[2015-03-10T08:15:08.417428 16488] Succeeded getting cached result
[2015-03-10T08:15:08.417444 16488] Unlink /tmp/test.stdout.daredevil.16488.oDFN34.i
[2015-03-10T08:15:08.417505 16488] Unlink /tmp/test.stdout.daredevil.16488.oDFN34
[2015-03-10T08:15:08.417529 16488] Unlink /tmp/tmp.cpp_stderr.daredevil.16488.8Gc6BC
[2015-03-10T08:15:08.417594 16488] lockfile_acquire: symlink /home/abuild/rpmbuild/BUILD/ccache-3.2.1/testdir.2712/.ccache/5/stats.lock: Permission denied
[2015-03-10T08:15:08.417620 16488] lockfile_acquire: symlink /home/abuild/rpmbuild/BUILD/ccache-3.2.1/testdir.2712/.ccache/5/stats.lock: Permission denied
[2015-03-10T08:15:08.417641 16488] lockfile_acquire: symlink /home/abuild/rpmbuild/BUILD/ccache-3.2.1/testdir.2712/.ccache/5/stats.lock: Permission denied
[2015-03-10T08:15:08.417672 16488] lockfile_acquire: symlink /home/abuild/rpmbuild/BUILD/ccache-3.2.1/testdir.2712/.ccache/5/stats.lock: Permission denied
[2015-03-10T08:15:08.417693 16488] lockfile_acquire: symlink /home/abuild/rpmbuild/BUILD/ccache-3.2.1/testdir.2712/.ccache/5/stats.lock: Permission denied
[2015-03-10T08:15:08.417713 16488] lockfile_acquire: symlink /home/abuild/rpmbuild/BUILD/ccache-3.2.1/testdir.2712/.ccache/5/stats.lock: Permission denied
[2015-03-10T08:15:08.417737 16488] lockfile_acquire: symlink /home/abuild/rpmbuild/BUILD/ccache-3.2.1/testdir.2712/.ccache/5/stats.lock: Permission denied

Build fails locally or on build service (see https://build.opensuse.org/package/show/home:pluskalm:branches:devel:tools:building/ccache) - for reasons unknown to me only i586 build fails.
Comment 3 Joel Rosdahl 2015-03-29 15:12:56 UTC

1. What file system are you using?
2. Could you try this patch and see if it makes a difference? https://git.samba.org/?p=ccache.git;a=commitdiff_plain;h=1032c0bb24c89bc7d7591fa39aafbce778c433f9
3. When ccache runs amok, could you attach to it with strace, save the log and attach/send it?[*] This could give clues to whether ccache makes any bad assumptions about the syscalls.

[*]: I.e., something like this: strace -p $(pidof ccache) 2>ccache.strace
Comment 4 Martin Pluskal 2015-03-30 12:42:54 UTC
Created attachment 10920 [details]
last lines of strace -f -o strace.log ./test.sh

(In reply to Joel Rosdahl from comment #3)
1) filesystem is btrfs
2) will try
3) see attached partial log (last 1024 lines) - can provide full if requested
Comment 5 Martin Pluskal 2015-03-30 15:33:58 UTC
Hmm seems that issue does not occur when xfs is used.
Comment 6 Joel Rosdahl 2015-03-30 19:18:18 UTC
Yeah, I'm not surprised that it's filesystem-related.

I would like to understand what happens when the repeated

    lockfile_acquire: symlink /home/abuild/rpmbuild/BUILD/ccache-3.2.1/testdir.2712/.ccache/5/stats.lock: Permission denied

logs appear. The strace log you attached unfortunately doesn't seem to include information about it. Looks like you are passing "-f" to strace so that it follows forks? System calls made by other processes than ccache are not of interest for debugging this problem, I think.

So yes, if you can share more of the strace log, or do it in a more targeted way (e.g. waiting for ccache to hang and then attaching to the running process), that would helpful.

In more detail, I'm looking for syscall traces of lock creation calls, i.e. symlink(".../stats.lock", ...), when they go bad. Something about btrfs's behavior trips ccache up.
Comment 7 Martin Pluskal 2015-04-01 07:12:59 UTC
(In reply to Joel Rosdahl from comment #6)
Sure: full log is at https://www.dropbox.com/s/sr4lfg8et3x14eu/strace.log.xz?dl=0
Comment 8 Joel Rosdahl 2015-05-01 14:42:45 UTC

Was the strace done with or without the patch I mentioned earlier (https://git.samba.org/?p=ccache.git;a=commitdiff_plain;h=1032c0bb24c89bc7d7591fa39aafbce778c433f9)?
Comment 9 Martin Pluskal 2015-06-19 12:20:30 UTC
(In reply to Joel Rosdahl from comment #8)
Sorry for late reply, strace was captured without patch, nevertheless with latest release (3.2.2) I am not able to reproduce issue.
Comment 10 Joel Rosdahl 2015-06-20 12:56:51 UTC
Great, then I think that the mentioned commit fixed the bug.
Comment 11 Joel Rosdahl 2015-06-20 12:57:10 UTC
Fix included in v3.2.2.