Bug 1222286

Another build and again it's hanging in the same place, but again
only on armv7hl:
http://koji.fedoraproject.org/koji/taskinfo?taskID=9767065
https://kojipkgs.fedoraproject.org//work/tasks/7067/9767067/build.log

This works fine on x86-64 & i686.

The configure.ac fragment is very simple so it's not likely to
be a problem with autoconf, although I guess anything is possible:

    AC_MSG_CHECKING([that $QEMU -help works])
    if $QEMU -help >&AS_MESSAGE_LOG_FD 2>&1; then
        AC_MSG_RESULT([yes])
    else
        AC_MSG_RESULT([no])
        AC_MSG_FAILURE(<error message omitted>)
    fi

strace output is here:
https://kojipkgs.fedoraproject.org//work/tasks/7470/9767470/build.log

It's frankly bizarre.  The last system calls are:

open("/dev/urandom", O_RDONLY|O_LARGEFILE) = 3
fcntl64(3, F_GETFD)                     = 0
fcntl64(3, F_SETFD, FD_CLOEXEC)         = 0
fstat64(3, {st_mode=S_IFCHR|0444, st_rdev=makedev(1, 9), ...}) = 0
clock_gettime(CLOCK_REALTIME, {1431870340, 192190777}) = 0
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 330000}, ru_stime={0, 55000}, ...}
) = 0
read(3, "*\222:\253\26\211\313\245\6KF\256Bm\242\363s\202>`u\223\6*1\351\234\324
E\362\347j", 32) = 32
read(3, "83\313y\206\10\316^\226\342&\266;R3\215\375\350\227\363+\16?\210LTy\345
v.\251\243", 32) = 32
read(3, "\231\302\270,\311\271z\324", 8) = 8
gettimeofday({1431870340, 198569}, NULL) = 0
gettimeofday({1431870340, 198647}, NULL) = 0

... and gettimeofday repeats in a loop forever.  The context looks as
if it is a bug in libselinux.

According to gdb, this is the backtrace:

warning: Probes-based dynamic linker interface failed.
Reverting to original interface.
Cannot parse expression `.L1046 4@r4'.
#0  0xb6fd10b0 in dl_main () from /lib/ld-linux-armhf.so.3
#1  0xb6fe6670 in _dl_sysdep_start () from /lib/ld-linux-armhf.so.3
#2  0xb6fd23a8 in _dl_start () from /lib/ld-linux-armhf.so.3
#3  0xb6fcdb50 in _start () from /lib/ld-linux-armhf.so.3
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

OK I believe the code is from libnettle (gnutls):

lib/nettle/rnd-common.c:_rnd_system_entropy_init contains

        _gnutls_urandom_fd = open("/dev/urandom", O_RDONLY);
        if (_gnutls_urandom_fd < 0) {
                _gnutls_debug_log("Cannot open urandom!\n");
                goto fallback;
        }

        old = fcntl(_gnutls_urandom_fd, F_GETFD);
        if (old != -1)
                fcntl(_gnutls_urandom_fd, F_SETFD, old | FD_CLOEXEC);

        if (fstat(_gnutls_urandom_fd, &st) >= 0) {
                _gnutls_urandom_fd_mode = st.st_mode;
        }

lib/nettle/rnd-common.c:_rnd_get_event contains

        gettime(&e->now);

#ifdef HAVE_GETRUSAGE
        if (getrusage(ARG_RUSAGE, &e->rusage) < 0) {
                _gnutls_debug_log("getrusage failed: %s\n",
                          strerror(errno));
        }
#endif

which looks identical to the sequence of syscalls being made.  It's
still a mystery where the infinite loop happens.

I'm still pretty sure this stack trace is wrong, but I got gdb
to print out the register contents:

warning: Probes-based dynamic linker interface failed.
Reverting to original interface.
Cannot parse expression `.L1046 4@r4'.
r0             0xb6fff8f4	3070228724
r1             0x0	0
r2             0xb6fff908	3070228744
r3             0xb6fff8f4	3070228724
r4             0xb6fff8f4	3070228724
r5             0x0	0
r6             0xfffffffc	4294967292
r7             0xa3	163
r8             0xa3	163
r9             0x0	0
r10            0xb6fff908	3070228744
r11            0xbefff95c	3204446556
r12            0xb6ffefac	3070226348
sp             0xbefff8c0	0xbefff8c0
lr             0xb6fd10b0	-1224929104
pc             0xb6fd10b0	0xb6fd10b0 <dl_main+11624>
cpsr           0x60070010	1611071504
Thread 1 (process 804):
#0  0xb6fd10b0 in dl_main () from /lib/ld-linux-armhf.so.3
#1  0xb6fe6670 in _dl_sysdep_start () from /lib/ld-linux-armhf.so.3
#2  0xb6fd23a8 in _dl_start () from /lib/ld-linux-armhf.so.3
#3  0xb6fcdb50 in _start () from /lib/ld-linux-armhf.so.3
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

*If* the stack trace is to be believed, then it points to
the following code in glibc.  PC is marked with an arrow.

    40a0:       eb00376c        bl      11e58 <_dl_debug_initialize>
    40a4:       e580500c        str     r5, [r0, #12]
    40a8:       e1a04000        mov     r4, r0
    40ac:       eb003768        bl      11e54 <_dl_debug_state>
--> 40b0:       e320f000        nop     {0}
    40b4:       eb0052c7        bl      18bd8 <_dl_unload_cache>
    40b8:       e24bd020        sub     sp, fp, #32
    40bc:       e8bd8ff0        pop     {r4, r5, r6, r7, r8, r9, sl, fp, pc}

The gnutls stacktrace being repeated is run within the library constructor. Could it be that one of these calls causes a dlopen in that platform which in turn causes the infinite loop?

Finally I am able to reproduce this locally, so I'll attach a
debugger and find out what's really going on here.

First observation is that the stack trace above *is* bogus.  qemu-system-arm
for some reason behaves differently under gdb, triggering some kind
of (gdb?) bug.  Please ignore the stack traces in comments 3, 5 & 6.
And my apologies for blaming gnutls.

The REAL stack trace points to ceph:

#0  0xb284846c in gettimeofday () from /lib/libc.so.6
#1  0xb405b868 in Cycles::init () at common/Cycles.cc:75
#2  0xb6b28500 in call_init.part () from /lib/ld-linux-armhf.so.3
#3  0xb6b28664 in _dl_init () from /lib/ld-linux-armhf.so.3
#4  0xb6b17b84 in _dl_start_user () from /lib/ld-linux-armhf.so.3

A very trivial reproducer for this is:

$ echo 'main(){}' > test.c
$ gcc test.c -lrados -o test
$ ./test

The final command will hang forever on 32 bit ARM.

Created attachment 1026798 [details]
fix-cycles-arch.patch

BLEAH UPSTREAM FIRST *!#$

Turns out that Ubuntu fixed this and are carrying a downstream patch
for it, which I have attached.

Ubuntu bug: https://bugs.launchpad.net/ubuntu/+source/ceph/+bug/1432786

Actually, that patch got half-merged upstream (the first half) and that is why you were seeing the hang-ups. I'll apply the second half of the patch and rebuild the packages.

ceph-0.94.1-1.fc22 has been submitted as an update for Fedora 22.
https://admin.fedoraproject.org/updates/FEDORA-2015-8189/ceph-0.94.1-1.fc22

btw: Note that it is not fixed in ceph-0.94.1-1.fc22, it is (should be) fixed in ceph-0.94.1-2.fc22 and ceph-0.94.1-2.fc23 that were just recently built in koji:

http://koji.fedoraproject.org/koji/taskinfo?taskID=9777655
http://koji.fedoraproject.org/koji/taskinfo?taskID=9777671

Can confirm that this is fixed in ceph-0.94.1-2.fc23 on armv7hl.

Package ceph-0.94.1-2.fc22:
* should fix your issue,
* was pushed to the Fedora 22 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing ceph-0.94.1-2.fc22'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2015-8189/ceph-0.94.1-2.fc22
then log in and leave karma (feedback).

FWIW qemu built against this package still seems to hang:

http://koji.fedoraproject.org/koji/taskinfo?taskID=9780467

But I'm trying another build now

Package ceph-0.94.1-3.fc22:
* should fix your issue,
* was pushed to the Fedora 22 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing ceph-0.94.1-3.fc22'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2015-8189/ceph-0.94.1-3.fc22
then log in and leave karma (feedback).

This has regressed somehow, so it's started to happen again.

https://kojipkgs.fedoraproject.org//work/tasks/1496/9871496/build.log

The build log shows that it is using:

DEBUG util.py:388:   librados2                   armv7hl 1:0.94.1-3.fc23                build 1.5 M

https://kojipkgs.fedoraproject.org//work/tasks/1496/9871496/root.log

I don't understand exactly why, since the patch exists and
is still being applied.  Perhaps the patch is not a complete
fix for the problem.

I can reproduce this on baremetal armv7hl with
librados2-0.94.1-3.fc23.armv7hl
qemu-system-arm-2.3.0-5.fc23.armv7hl
and (as before) simply running 'qemu-system-arm -help'.

Unfortunately gdb doesn't let me get a stack trace.  It simply
ignores ^C.

I was able to use strace, and the process is doing this over and
over again:

gettimeofday({1432934064, 725311}, NULL) = 0
nanosleep({0, 2000001}, NULL)           = 0
gettimeofday({1432934064, 728002}, NULL) = 0
nanosleep({0, 2000001}, NULL)           = 0

Created attachment 1032285 [details]
strace qemu-system-arm -help

Just few thoughts:

The ceph itself should not run the loop, now. Is there any chance that qemu is trying to do that instead?

Can you still reproduce on bare metal with the simple reproducer that you mentioned in Comment 10?

What about the older librados2-0.94.1-2.fc23.armv7hl? The only change between -2 and -3 should be that lttng was disabled but one never knows.

I'm trying to get my hands on an armhfp machine to debug further myself but that may take some time.

I'll answer the questions myself as I've finally got my hands on an armhfp machine where I could reproduce.

The steps in Comment 10 do not reproduce the issue so that bug is indeed fixed. I've tapped into the running process (gdb -p $(pidof qemu-system-arm)) and I didn't see anything ceph (rbd/rados) related in the backtrace.

The backtrace leading to nanosleep was

#0  0xffffffff in nanosleep () at /lib/libpthread.so.0
#1  0xffffffff in base::internal::SpinLockDelay(int volatile*, int, int) () at /lib/libtcmalloc.so.4
#2  0xffffffff in SpinLock::SlowLock() () at /lib/libtcmalloc.so.4
#3  0xffffffff in tcmalloc::ThreadCache::InitModule() () at /lib/libtcmalloc.so.4
#4  0xffffffff in tc_malloc () at /lib/libtcmalloc.so.4
#5  0xffffffff in __fopen_internal () at /lib/libc.so.6
#6  0xffffffff in load_debug_frame () at /lib/libunwind.so.8
#7  0xffffffff in locate_debug_info () at /lib/libunwind.so.8
#8  0xffffffff in _ULarm_dwarf_find_debug_frame () at /lib/libunwind.so.8
#9  0xffffffff in _ULarm_dwarf_callback () at /lib/libunwind.so.8
#10 0xffffffff in dl_iterate_phdr () at /lib/libc.so.6
#11 0xffffffff in _ULarm_find_proc_info () at /lib/libunwind.so.8
#12 0xffffffff in fetch_proc_info () at /lib/libunwind.so.8
#13 0xffffffff in _ULarm_dwarf_find_save_locs () at /lib/libunwind.so.8
#14 0xffffffff in _ULarm_dwarf_step () at /lib/libunwind.so.8
#15 0xffffffff in _ULarm_step () at /lib/libunwind.so.8
#16 0xffffffff in GetStackTrace_libunwind(void**, int, int) () at /lib/libtcmalloc.so.4
#17 0xffffffff in GetStackTrace(void**, int, int) () at /lib/libtcmalloc.so.4
#18 0xffffffff in tcmalloc::PageHeap::GrowHeap(unsigned int) () at /lib/libtcmalloc.so.4
#19 0xffffffff in tcmalloc::PageHeap::New(unsigned int) () at /lib/libtcmalloc.so.4
#20 0xffffffff in tcmalloc::CentralFreeList::Populate() () at /lib/libtcmalloc.so.4
#21 0xffffffff in tcmalloc::CentralFreeList::FetchFromOneSpansSafe(int, void**, void**) () at /lib/libtcmalloc.so.4
#22 0xffffffff in tcmalloc::CentralFreeList::RemoveRange(void**, void**, int) () at /lib/libtcmalloc.so.4
#23 0xffffffff in tcmalloc::ThreadCache::FetchFromCentralCache(unsigned int, unsigned int) () at /lib/libtcmalloc.so.4
#24 0xffffffff in tc_malloc () at /lib/libtcmalloc.so.4
#25 0xffffffff in strdup () at /lib/libc.so.6
#26 0xffffffff in verify_selinuxmnt () at /lib/libselinux.so.1
#27 0xffffffff in init_lib () at /lib/libselinux.so.1
#28 0xffffffff in call_init.part () at /lib/ld-linux-armhf.so.3
#29 0xffffffff in _dl_init_internal () at /lib/ld-linux-armhf.so.3
#30 0xffffffff in _dl_start_user () at /lib/ld-linux-armhf.so.3

The suspects seemed to be tcmalloc (gperftools) or libunwind. While both of these are used by ceph, neither of them is used by the client libraries (rbd/rados) that qemu links to.

I've done some more tests and it seems that tcmalloc (gperftools) is actually the one causing the hang-ups, i.e. similar to comment 10, I did

$ echo 'main(){}' > test.c
$ gcc test.c -ltcmalloc -o test
$ ./test

and the program hanged indefinitely.

I'm moving this bz back to ON_QA (as there actually was a bug in ceph code that was fixed in the -2 release) and I'll clone this bz for the tcmalloc issue.

Thanks - yes I believe you are correct.  Quite annoying that two
difficult bugs look coincidentally so similar :-(

The patch was merged to Ceph master upstream in 35c5fd0091fc4d63b21207fb94e46b343519fd56 (https://github.com/ceph/ceph/pull/4839)

ceph-0.94.1-3.fc22 has been pushed to the Fedora 22 stable repository.  If problems still persist, please make note of it in this bug report.