Hang during ld_preload

[BenWiederhake]

When running faketime on CentOS 7, libfaketime hangs during initialization. This seems related to #520, but I'm not entirely sure.

I used the example from the readme: LD_PRELOAD=/censored/path/to/my/usr/local/lib/faketime/libfaketime.so.1 FAKETIME="@2000-01-01 11:12:13" date , no output is produced.

Running with strace, the last few syscalls are:

set_tid_address(0x7f30f2621a10)         = 22529
set_robust_list(0x7f30f2621a20, 24)     = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7f30f1747860, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f30f1750630}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x7f30f17478f0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f30f1750630}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
futex(0x7f30f206a0d0, FUTEX_WAKE_PRIVATE, 2147483647) = 0
brk(NULL)                               = 0x1c47000
brk(0x1c68000)                          = 0x1c68000
statfs("/dev/shm", {f_type=TMPFS_MAGIC, f_bsize=4096, f_blocks=2794636, f_bfree=2794353, f_bavail=2794353, f_files=2794636, f_ffree=2794609, f_fsid={val=[0, 0]}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_NOSUID|ST_NODEV}) = 0
futex(0x7f30f195c350, FUTEX_WAKE_PRIVATE, 2147483647) = 0
lstat("/dev/shm/sem.7mKj5w", 0x7ffcf34121b0) = -1 ENOENT (Datei oder Verzeichnis nicht gefunden)
open("/dev/shm/sem.7mKj5w", O_RDWR|O_CREAT|O_EXCL, 0600) = 3
write(3, "\1\0\0\0\0\0\0\0\200\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 32) = 32
mmap(NULL, 32, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0) = 0x7f30f263e000
link("/dev/shm/sem.7mKj5w", "/dev/shm/sem.faketime_sem_22529") = 0
futex(0x7f30f26525f0, FUTEX_WAIT_PRIVATE, 1, NULL

(The rest of the last line is missing because that's how strace displays a syscall that hasn't returned yet.)

So it seems to wait on some kind of mutex, but I'm not sure why it would hang when there's nothing else running yet. After all, who could possibly be holding a lock already?

Running and attaching with gdb shows:

(gdb) bt
#0  0x00007fa58f3951f5 in __pthread_once_slow () from /lib64/libpthread.so.0
#1  0x00007fa590297e50 in ftpl_init () from /censored/path/to/my/usr/local/lib/faketime/libfaketime.so.1
#2  0x00007fa590292282 in __fxstat64 () from /censored/path/to/my/usr/local/lib/faketime/libfaketime.so.1
#3  0x00007fa58f39c244 in check_add_mapping () from /lib64/libpthread.so.0
#4  0x00007fa58f39c844 in sem_open () from /lib64/libpthread.so.0
#5  0x00007fa59029064e in ft_sem_create () from /censored/path/to/my/usr/local/lib/faketime/libfaketime.so.1
#6  0x00007fa590290807 in ft_shm_create () from /censored/path/to/my/usr/local/lib/faketime/libfaketime.so.1
#7  0x00007fa590290bfd in ft_shm_really_init () from /censored/path/to/my/usr/local/lib/faketime/libfaketime.so.1
#8  0x00007fa58f39520b in __pthread_once_slow () from /lib64/libpthread.so.0
#9  0x00007fa590290bd3 in ft_shm_init () from /censored/path/to/my/usr/local/lib/faketime/libfaketime.so.1
#10 0x00007fa59029765e in ftpl_really_init () from /censored/path/to/my/usr/local/lib/faketime/libfaketime.so.1
#11 0x00007fa58f39520b in __pthread_once_slow () from /lib64/libpthread.so.0
#12 0x00007fa590297e50 in ftpl_init () from /censored/path/to/my/usr/local/lib/faketime/libfaketime.so.1
#13 0x00007fa5900969c3 in _dl_init_internal () from /lib64/ld-linux-x86-64.so.2
#14 0x00007fa59008817a in _dl_start_user () from /lib64/ld-linux-x86-64.so.2

Running with FAKETIME_DEBUG_DLSYM=1 reveals that some symbols cannot be found, which is weird because I compiled faketime on the same system just a few minutes prior, so it should see the same symbols as during compile time:

[FAKETIME_DEBUG_DLSYM] Cannot find symbol: stat
[FAKETIME_DEBUG_DLSYM] Cannot find symbol: lstat
[FAKETIME_DEBUG_DLSYM] Cannot find symbol: fstat
[FAKETIME_DEBUG_DLSYM] Cannot find symbol: stat64
[FAKETIME_DEBUG_DLSYM] Cannot find symbol: sem_clockwait
[FAKETIME_DEBUG_DLSYM] Cannot find symbol: __ftime
[FAKETIME_DEBUG_DLSYM] Cannot find symbol: clock_gettime64
[FAKETIME_DEBUG_DLSYM] Cannot find symbol: __clock_gettime64
[FAKETIME_DEBUG_DLSYM] Cannot find symbol: timer_settime@GLIBC_2.2
[FAKETIME_DEBUG_DLSYM] Cannot find symbol: timer_gettime@GLIBC_2.2

(no further output)

Compiling with -DDEBUG and using … FAKETIME_DEBUG=1 date doesn't reveal any more information.

Can you help me get faketime to run on CentOS 7?

[BenWiederhake]

Oh! This seems to be a regression in v0.9.11. It works in v0.9.10, breaks in v0.9.11, and remains broken in v0.9.12 and current master (949b36e at the time of writing.)

A quick git bisect points to 2503b0f:

2503b0fffc19268396dbf4fa60071e1e04ef9908 is the first bad commit
commit 2503b0fffc19268396dbf4fa60071e1e04ef9908
Author: Ian Jackson <ijackson@chiark.greenend.org.uk>
Date:   Tue Jan 21 18:44:42 2025 +0000

    Replace data race with use of pthread_once (ftpl_init)
    
    At the cost of no longer nicely detecting recursive initialisation
    problems.
    
    Fixes Debian bug #1093599

 src/libfaketime.c | 50 +++++++-------------------------------------------
 1 file changed, 7 insertions(+), 43 deletions(-)

That seems plausible, as this commit changes the implementation of ftpl_init, which is near the top of the stack.

[wolfcw]

CC'in @ijackson on this who maybe has some ideas. We were never really able to fix the underlying problem, which continues to occur with other preloaded libraries such jemalloc and libasan.

[ijackson]

There are two copies of ftpl_init in the stack trace you show.

You'll note that my commit message says "At the cost of no longer nicely detecting recursive initialisation problems." This would be one of those.

The root causse seems to be that sem_open calls check_add_mapping which then calls __fxstat64. Presumably , the sem_open on Debian doesn't call stat, or this would have failed for me when I was developing 2503b0f (or, subsequently, in our CI).

I think to fix this in faketime, pthread_once will have to be replaced with an errorcheck mutex. When the lock attempt fails with EDEADLK, this indicates that some call we are making during ftpl_init is somehow calling back into a syscall we want to fake. Then we should fall back to non-faked time behaviour for whatever that internal thing is (and hope that it won't matter that the time behaves oddly as seen by whatever that libc-internal thing is).

Replacing pthread_once with an ERRORCHECK mutex will be annoying because AFAICT there's no const initialiser for ERRORCHECK mutexes. So actuallly, we'll still have to use pthread_once - but only to initialise the mutex.

Another possibility is to investigate why CentOS's sem_open is calling stat.

Good luck!

[KnBrckr]

Also looks related to #494