bug#48941: [powerpc64le-linux] libfaketime CLOCK_MONOTONIC test hangs

[Chris Marusich]

Thiago Jung Bauermann <bauermann@kolabnow.com> writes:

> GDB uses the shell to launch the debugged program. That is probably where
> ‘/bin/sh’ is entering the picture here. I don’t know whether that has any 
> relation to your foreign distro’s libc being used.
>
> The output of `help run` in GDB mentions that the shell is specified by the 
> ‘$SHELL’ environment variable. Perhaps you have that set?
>
> One way to see if this is the problem is to use the GDB command
> `set startup-with-shell off` to make it launch the debugged program without 
> the shell.

Thank you for this suggestion.  When I ran "set startup-with-shell off",
gdb successfully launched the program.

It seems something in the Guix-built software is trying to run /bin/sh.
Perhaps there is stray hard-coded path in GDB or something that needs to
be fixed...  In any case, I'm glad I can continue debugging!

>> The x86-64 systems I have that run pure Guix don't have any
>> /lib*/ directories. You might try running gdb with
>> LD_LIBRARY_PATH=/gnu/store/kmblbljiygayhlc5gb02an9imhy90ws9-glibc-2.33/l
>> ib to have the Guix libc.so picked up before the other one. HTH
>
> Another alternative worth trying is the ‘--container’ option to ‘guix 
> environment’, to completely isolate GDB from the foreign distro. You might 
> want to add the coreutils package to the ‘--ad-hoc’ list so that you can 
> get amenities such as an ls command. :-)

When I tried "--container", gdb successfully launched the program.  So
it's another viable work-around for the gdb issue.

As for the actual libfaketime bug, when it hung I pressed Control+C, and
here's the backtrace at that point:

--8<---------------cut here---------------start------------->8---
(gdb) backtrace
#0  0x00007ffff7eccba0 in __futex_abstimed_wait_common64 
(futex_word=0x7ffff7aaf1c0, expected=<optimized out>, clockid=<optimized out>, 
abstime=0x0, private=<optimized out>, cancel=<optimized out>) at 
../sysdeps/nptl/futex-internal.c:74
#1  0x00007ffff7eb9934 in __pthread_clockjoin_ex (threadid=140737348563184, 
thread_return=0x7fffffffe2d0, clockid=<optimized out>, abstime=<optimized out>, 
block=<optimized out>) at pthread_join_common.c:102
#2  0x00007ffff7eb9684 in __pthread_join (threadid=<optimized out>, 
thread_return=<optimized out>) at pthread_join.c:24
#3  0x0000000010001784 in main (argc=1, argv=0x7fffffffe718) at timetest.c:146
--8<---------------cut here---------------end--------------->8---

Here's the entire session in which I built the problematic test and
debugged it, including a full back trace with local variables:

--8<---------------cut here---------------start------------->8---
[0] [env] marusich@suzaku:/tmp/guix-build-libfaketime-0.9.9.drv-0
$ ~/guix-core-updates/pre-inst-env guix environment libfaketime --ad-hoc 
gcc-toolchain@10.3.0:debug gdb
[0] [env] marusich@suzaku:/tmp/guix-build-libfaketime-0.9.9.drv-0
$ cd source/
[0] [env] marusich@suzaku:/tmp/guix-build-libfaketime-0.9.9.drv-0/source
$ make FAKETIME_COMPILE_CFLAGS='-DFORCE_MONOTONIC_FIX -g' CC=gcc 
PREFIX=/tmp/guix-build-libfaketime-0.9.9.drv-0/myprefix clean
make  -C src clean
make[1]: Entering directory '/tmp/guix-build-libfaketime-0.9.9.drv-0/source/src'
make[1]: Leaving directory '/tmp/guix-build-libfaketime-0.9.9.drv-0/source/src'
make  -C test clean
make[1]: Entering directory 
'/tmp/guix-build-libfaketime-0.9.9.drv-0/source/test'
make[1]: Leaving directory '/tmp/guix-build-libfaketime-0.9.9.drv-0/source/test'
[0] [env] marusich@suzaku:/tmp/guix-build-libfaketime-0.9.9.drv-0/source
$ make FAKETIME_COMPILE_CFLAGS='-DFORCE_MONOTONIC_FIX -g' CC=gcc 
PREFIX=/tmp/guix-build-libfaketime-0.9.9.drv-0/myprefix
make  -C src all
make[1]: Entering directory '/tmp/guix-build-libfaketime-0.9.9.drv-0/source/src'
gcc -o libfaketime.o -c -std=gnu99 -Wall -Wextra -Werror -Wno-nonnull-compare 
-DFAKE_PTHREAD -DFAKE_STAT -DFAKE_UTIME -DFAKE_SLEEP -DFAKE_TIMERS 
-DFAKE_INTERNAL_CALLS -fPIC 
-DPREFIX='"'/tmp/guix-build-libfaketime-0.9.9.drv-0/myprefix'"' 
-DLIBDIRNAME='"'/lib/faketime'"' -DFORCE_MONOTONIC_FIX -g   libfaketime.c
gcc -o libfaketime.so.1 -Wl,-soname,libfaketime.so.1  -lpthread 
-Wl,--version-script=libfaketime.map -shared libfaketime.o -ldl -lm -lrt
gcc -o libfaketimeMT.o -c -std=gnu99 -Wall -Wextra -Werror -Wno-nonnull-compare 
-DFAKE_PTHREAD -DFAKE_STAT -DFAKE_UTIME -DFAKE_SLEEP -DFAKE_TIMERS 
-DFAKE_INTERNAL_CALLS -fPIC 
-DPREFIX='"'/tmp/guix-build-libfaketime-0.9.9.drv-0/myprefix'"' 
-DLIBDIRNAME='"'/lib/faketime'"' -DFORCE_MONOTONIC_FIX -g  
-DPTHREAD_SINGLETHREADED_TIME libfaketime.c
gcc -o libfaketimeMT.so.1 -Wl,-soname,libfaketimeMT.so.1  -lpthread 
-Wl,--version-script=libfaketime.map -shared libfaketimeMT.o -ldl -lm -lrt
gcc -o faketime -std=gnu99 -Wall -Wextra -Werror -Wno-nonnull-compare 
-DFAKE_PTHREAD -DFAKE_STAT -DFAKE_UTIME -DFAKE_SLEEP -DFAKE_TIMERS 
-DFAKE_INTERNAL_CALLS -fPIC 
-DPREFIX='"'/tmp/guix-build-libfaketime-0.9.9.drv-0/myprefix'"' 
-DLIBDIRNAME='"'/lib/faketime'"' -DFORCE_MONOTONIC_FIX -g   faketime.c  
-lpthread -Wl,--version-script=libfaketime.map -lrt
make[1]: Leaving directory '/tmp/guix-build-libfaketime-0.9.9.drv-0/source/src'
[0] [env] marusich@suzaku:/tmp/guix-build-libfaketime-0.9.9.drv-0/source
$ make FAKETIME_COMPILE_CFLAGS='-DFORCE_MONOTONIC_FIX -g' CC=gcc 
PREFIX=/tmp/guix-build-libfaketime-0.9.9.drv-0/myprefix test
make  -C src all
make[1]: Entering directory '/tmp/guix-build-libfaketime-0.9.9.drv-0/source/src'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory '/tmp/guix-build-libfaketime-0.9.9.drv-0/source/src'
make  -C test all
make[1]: Entering directory 
'/tmp/guix-build-libfaketime-0.9.9.drv-0/source/test'
gcc -c -std=gnu99 -Wall -DFAKE_STAT -Werror -Wextra -DFORCE_MONOTONIC_FIX -g 
timetest.c
gcc -o timetest timetest.o -lrt -lpthread
./testframe.sh functests
# Begin Test Suites in functests

# Begin functests/test_exclude_mono.sh
# PLATFORM=linuxlike
out=1763825.60556745 When not faking monotonic time, timestamps should be 
different ref=1763826.62729077 - ok
# functests/test_exclude_mono.sh summary: 1 succeeded, 0 failed
# End functests/test_exclude_mono.sh - OK

# Begin functests/test_null.sh
out=0 () ref=1627019232 - ok
# functests/test_null.sh summary: 1 succeeded, 0 failed
# End functests/test_null.sh - OK

# Begin functests/test_true.sh
# functests/test_true.sh summary: 1 succeeded, 0 failed
# End functests/test_true.sh - OK

# Begin functests/test_walkone.sh
# PLATFORM=linuxlike
out=1 (secs since Epoch) - ok
out=2 (secs since Epoch) - ok
out=4 (secs since Epoch) - ok
out=8 (secs since Epoch) - ok
out=16 (secs since Epoch) - ok
out=32 (secs since Epoch) - ok
out=64 (secs since Epoch) - ok
out=128 (secs since Epoch) - ok
out=256 (secs since Epoch) - ok
out=512 (secs since Epoch) - ok
out=1024 (secs since Epoch) - ok
out=2048 (secs since Epoch) - ok
out=4096 (secs since Epoch) - ok
out=8192 (secs since Epoch) - ok
out=16384 (secs since Epoch) - ok
out=32768 (secs since Epoch) - ok
out=65536 (secs since Epoch) - ok
out=131072 (secs since Epoch) - ok
out=262144 (secs since Epoch) - ok
out=524288 (secs since Epoch) - ok
out=1048576 (secs since Epoch) - ok
out=2097152 (secs since Epoch) - ok
out=4194304 (secs since Epoch) - ok
out=8388608 (secs since Epoch) - ok
out=16777216 (secs since Epoch) - ok
out=33554432 (secs since Epoch) - ok
out=67108864 (secs since Epoch) - ok
out=134217728 (secs since Epoch) - ok
out=268435456 (secs since Epoch) - ok
out=536870912 (secs since Epoch) - ok
out=1073741824 (secs since Epoch) - ok
# functests/test_walkone.sh summary: 31 succeeded, 0 failed
# End functests/test_walkone.sh - OK

# Test Suites summary: 4 succeeded, 0 failed
# End Test Suites - OK

Running the test program with no faked time specified
$ LD_PRELOAD=../src/libfaketime.so.1 ./timetest
pthread_cond_timedwait: CLOCK_REALTIME test
(Intentionally sleeping 1 second...)
pthread_cond_timedwait: CLOCK_MONOTONIC test
(Intentionally sleeping 1 second..., see docs about CLOCK_MONOTONIC test)
^Cmake[1]: *** [Makefile:19: test] Interrupt
make: *** [Makefile:11: test] Interrupt

[130] [env] marusich@suzaku:/tmp/guix-build-libfaketime-0.9.9.drv-0/source
$ cd test/
[0] [env] marusich@suzaku:/tmp/guix-build-libfaketime-0.9.9.drv-0/source/test
$ gdb ./timetest
GNU gdb (GDB) 10.2
Copyright (C) 2021 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "powerpc64le-unknown-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./timetest...
(gdb) set debug-file-directory 
/gnu/store/32fjhp30k34fh0g9f1gmgcj8pc5wldq6-profile/lib/debug
(gdb) add-auto-load-safe-path 
/gnu/store/kmblbljiygayhlc5gb02an9imhy90ws9-glibc-2.33/lib/libthread_db-1.0.so
(gdb) set environment LD_PRELOAD=../src/libfaketime.so.1
(gdb) set environment FAKETIME=-10d
(gdb) set environment NO_FAKE_STAT=1
(gdb) set startup-with-shell off
(gdb) run
Starting program: /tmp/guix-build-libfaketime-0.9.9.drv-0/source/test/timetest
[Thread debugging using libthread_db enabled]
Using host libthread_db library 
"/gnu/store/kmblbljiygayhlc5gb02an9imhy90ws9-glibc-2.33/lib/libthread_db.so.1".
[New Thread 0x7ffff7aaf0f0 (LWP 2140545)]
pthread_cond_timedwait: CLOCK_REALTIME test
(Intentionally sleeping 1 second...)
pthread_cond_timedwait: CLOCK_MONOTONIC test
(Intentionally sleeping 1 second..., see docs about CLOCK_MONOTONIC test)
^C
Thread 1 "timetest" received signal SIGINT, Interrupt.
0x00007ffff7eccba0 in __futex_abstimed_wait_common64 
(futex_word=0x7ffff7aaf1c0, expected=<optimized out>, clockid=<optimized out>, 
abstime=0x0, private=<optimized out>, cancel=<optimized out>) at 
../sysdeps/nptl/futex-internal.c:74
74      ../sysdeps/nptl/futex-internal.c: No such file or directory.
(gdb) backtrace
#0  0x00007ffff7eccba0 in __futex_abstimed_wait_common64 
(futex_word=0x7ffff7aaf1c0, expected=<optimized out>, clockid=<optimized out>, 
abstime=0x0, private=<optimized out>, cancel=<optimized out>) at 
../sysdeps/nptl/futex-internal.c:74
#1  0x00007ffff7eb9934 in __pthread_clockjoin_ex (threadid=140737348563184, 
thread_return=0x7fffffffe2d0, clockid=<optimized out>, abstime=<optimized out>, 
block=<optimized out>) at pthread_join_common.c:102
#2  0x00007ffff7eb9684 in __pthread_join (threadid=<optimized out>, 
thread_return=<optimized out>) at pthread_join.c:24
#3  0x0000000010001784 in main (argc=1, argv=0x7fffffffe718) at timetest.c:146
(gdb) backtrace -full
#0  0x00007ffff7eccba0 in __futex_abstimed_wait_common64 
(futex_word=0x7ffff7aaf1c0, expected=<optimized out>, clockid=<optimized out>, 
abstime=0x0, private=<optimized out>, cancel=<optimized out>) at 
../sysdeps/nptl/futex-internal.c:74
        r4 = 265
        r7 = 0
        _arg5 = 0
        _arg2 = <optimized out>
        r5 = 2140545
        r8 = 4294967295
        _arg6 = 4294967295
        _arg3 = <optimized out>
        r0 = 221
        r3 = -512
        r6 = 0
        _arg4 = <optimized out>
        _arg1 = <optimized out>
        sc_cancel_oldtype = 0
        sc_ret = <optimized out>
        clockbit = <optimized out>
        err = <optimized out>
        op = <optimized out>
#1  0x00007ffff7eb9934 in __pthread_clockjoin_ex (threadid=140737348563184, 
thread_return=0x7fffffffe2d0, clockid=<optimized out>, abstime=<optimized out>, 
block=<optimized out>) at pthread_join_common.c:102
        ret = <optimized out>
        _buffer = {__routine = 0x7ffff7eb97d0 <cleanup>, __arg = 
0x7ffff7aaf518, __canceltype = -6000, __prev = 0x0}
        tid = <optimized out>
        pd = 0x7ffff7aaf0f0
        self = <optimized out>
        result = 0
        pd_result = <optimized out>
#2  0x00007ffff7eb9684 in __pthread_join (threadid=<optimized out>, 
thread_return=<optimized out>) at pthread_join.c:24
No locals.
#3  0x0000000010001784 in main (argc=1, argv=0x7fffffffe718) at timetest.c:146
        now = 140737488347536
        tb = {time = 140737354082104, millitm = 1, timezone = 0, dstflag = 0}
        tv = {tv_sec = 140737354081200, tv_usec = 1}
        ts = {tv_sec = 140737354092312, tv_nsec = 0}
        timerid1 = 0x0
        timerid2 = 0x7ffff7f313ca
        sev = {sigev_value = {sival_int = -134273224, sival_ptr = 
0x7ffff7ff2738}, sigev_signo = -1358151624, sigev_notify = 0, _sigev_un = {_pad 
= {-7632, 32767, 1140867716, 32767, -134571396, 32767, -134251008, 32767, 
-7888, 32767,
              -135299328, 32767}, _tid = -7632, _sigev_thread = {_function = 
0x7fffffffe230, _attribute = 0x7fff44004284}}}
        its = {it_interval = {tv_sec = 140737488347536, tv_nsec = 
140737353288760}, it_value = {tv_sec = 140737488347512, tv_nsec = 
7737577984389116719}}
        mask = {__val = {4294967297, 140737488347472, 1, 0, 1, 140737354081200, 
140737488347648, 0, 384, 140737353252608, 140737350926336, 140737350298984, 
140737354086848, 0, 4294967295, 7883960601630828079}}
        sa = {__sigaction_handler = {sa_handler = 0x31325f6d68735f65, 
sa_sigaction = 0x31325f6d68735f65}, sa_mask = {__val = {215624265780, 9, 0, 
140737354076688, 0, 0, 0, 0, 0, 0, 1392, 140737353287368, 140737353293872,
              140737353482696, 140737353288760, 140737353481312}}, sa_flags = 
-134274128, sa_restorer = 0x7fffffffe2b0}
        buf = {st_dev = 140733797368452, st_ino = 140737353809984, st_nlink = 
140737354104320, st_mode = 4294959792, st_uid = 32767, st_gid = 4294959992, 
__pad2 = 32767, st_rdev = 268633376, st_size = 0, st_blksize = 0,
          st_blocks = 140737354076688, st_atim = {tv_sec = 140737488347824, 
tv_nsec = 140737488348952}, st_mtim = {tv_sec = 1, tv_nsec = 8}, st_ctim = 
{tv_sec = 0, tv_nsec = 140737352442432}, __glibc_reserved4 = 140737488347904,
          __glibc_reserved5 = 8, __glibc_reserved6 = 268442956}
        thread = 140737348563184
        ret = 0x7fffffffe300
        timer_getoverrun_timerid1 = -7816
        timer_getoverrun_timerid2 = 32767
(gdb)
--8<---------------cut here---------------end--------------->8---

I'll forward this information to upstream and ask if they need more.
I'll also let them know which version of the libraries (e.g., glibc) are
being used, since they said it might help to know.

-- 
Chris

signature.asc
Description: PGP signature