libfaketime
libfaketime copied to clipboard
wolfcw
libfaketime 0.9.7 and up clashes with jemalloc
Hi,
sorry, I don't know a good summary at the moment.
rsyslog is using libfaketime via LD_PRELOAD [1,2] in its test suite.
It was working fine until libfaketime-0.9.7 release, see https://github.com/rsyslog/rsyslog/issues/2099
I bisected libfaketime and found the commit which broke libfaketime for rsyslog:
$ git bisect log
git bisect start
# bad: [3ed13f498c4f2fda6f429a493c7877380aac6e46] Fix libfaketimeMT build to define PTHREAD
git bisect bad 3ed13f498c4f2fda6f429a493c7877380aac6e46
# good: [3bed636a412585cf542305cd6283c9cf9a66b9cf] Debian Bug#753460: Updated fix for 699599
git bisect good 3bed636a412585cf542305cd6283c9cf9a66b9cf
# good: [6c207c9c6886033980e78d48493bbf522da4b964] Custom timestamp filename added: ~/.faketimerc alternative
git bisect good 6c207c9c6886033980e78d48493bbf522da4b964
# bad: [0bde083556e243e87bddaaf94e68f2ef85dad769] Make sure that the constructor has been called when the loader chose to load another constructor first.
git bisect bad 0bde083556e243e87bddaaf94e68f2ef85dad769
# good: [10b479cf29d59092b20aaccf4fe8cb1aab4d9482] Merge pull request #59 from mac-joker/master
git bisect good 10b479cf29d59092b20aaccf4fe8cb1aab4d9482
# first bad commit: [0bde083556e243e87bddaaf94e68f2ef85dad769] Make sure that the constructor has been called when the loader chose to load another constructor first.
0bde083556e243e87bddaaf94e68f2ef85dad769 is the first bad commit
commit 0bde083556e243e87bddaaf94e68f2ef85dad769
Author: Erich E. Hoover
Date: Wed Dec 10 14:55:01 2014 -0700
Make sure that the constructor has been called when the loader chose to load another constructor first.
:040000 040000 060a1da4a6378d732d111a1cc5a9c937b4b467b4 6e455c8cb8a9db3fb98de92e46cf804a49fba959 M
Bad commit: 0bde083556e243e87bddaaf94e68f2ef85dad769
[1] https://github.com/rsyslog/rsyslog/blob/master/tests/faketime_common.sh [2] https://github.com/rsyslog/rsyslog/blob/master/tests/now_family_utc.sh
OK, this is related to jemalloc usage:
$ gdb --args env LD_PRELOAD=/usr/lib64/libfaketime.so.1 env FAKETIME='2016-01-01 01:00:00' ../tools/rsyslogd -C -n -irsyslog$3.pid -M../runtime/.libs:../.libs
-ftestsuites/now_family_utc.conf
GNU gdb (Gentoo 8.0.1 vanilla) 8.0.1
Copyright (C) 2017 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 "x86_64-pc-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://bugs.gentoo.org/>.
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 env...Reading symbols from /usr/lib64/debug//bin/env.debug...done.
done.
(gdb) set follow-fork-mode child
(gdb) run
Starting program: /bin/env LD_PRELOAD=/usr/lib64/libfaketime.so.1 env FAKETIME=2016-01-01\ 01:00:00 ../tools/rsyslogd -C -n -irsyslog.pid -M../runtime/.libs:../.libs
-ftestsuites/now_family_utc.conf
process 89895 is executing new program: /bin/env
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
process 89895 is executing new program: /var/tmp/portage/app-admin/rsyslog-8.30.0/work/rsyslog-8.30.0/tools/rsyslogd
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
^C
Program received signal SIGINT, Interrupt.
__lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
135 ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S: No such file or directory.
(gdb) list
130 in ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S
(gdb) bt
#0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1 0x00007ffff77a17bd in __GI___pthread_mutex_lock (mutex=mutex@entry=0x7ffff717b480 <init_lock+64>) at ../nptl/pthread_mutex_lock.c:80
#2 0x00007ffff6f6439c in malloc_mutex_lock_final (mutex=0x7ffff717b440 <init_lock>) at
/var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/include/jemalloc/internal/mutex.h:141
#3 je_malloc_mutex_lock_slow (mutex=mutex@entry=0x7ffff717b440 <init_lock>) at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/mutex.c:65
#4 0x00007ffff6f4384a in malloc_mutex_lock (tsdn=0x0, mutex=0x7ffff717b440 <init_lock>)
at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/include/jemalloc/internal/mutex.h:205
#5 malloc_init_hard () at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/jemalloc.c:1452
#6 0x00007ffff6f46b5d in malloc_init () at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/jemalloc.c:216
#7 imalloc (dopts=<synthetic pointer>, sopts=<synthetic pointer>) at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/jemalloc.c:1927
#8 calloc (num=1, size=32) at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/jemalloc.c:2060
#9 0x00007ffff75948ff in _dlerror_run (operate=operate@entry=0x7ffff75941b0 <dlsym_doit>, args=args@entry=0x7fffffffd8a0) at dlerror.c:141
#10 0x00007ffff7594258 in __dlsym (handle=<optimized out>, name=<optimized out>) at dlsym.c:70
#11 0x00007ffff7bcf8ff in ftpl_init () from /usr/lib64/libfaketime.so.1
#12 0x00007ffff7bd35fd in clock_gettime () from /usr/lib64/libfaketime.so.1
#13 0x00007ffff6f64639 in nstime_get (time=0x7ffff57f7b08) at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/nstime.c:119
#14 nstime_update_impl (time=0x7ffff57f7b08) at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/nstime.c:160
#15 0x00007ffff6f4b42f in arena_decay_reinit (decay=decay@entry=0x7ffff57f7a88, decay_ms=decay_ms@entry=10000, extents=0x7ffff57f65e8)
at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/arena.c:750
#16 0x00007ffff6f4b576 in arena_decay_init (decay=decay@entry=0x7ffff57f7a88, decay_ms=10000, stats=0x7ffff57f49a0, extents=0x7ffff57f65e8)
at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/arena.c:771
#17 0x00007ffff6f4f96c in je_arena_new (tsdn=0x0, ind=0, extent_hooks=<optimized out>) at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/arena.c:2004
#18 0x00007ffff6f44235 in arena_init_locked (tsdn=tsdn@entry=0x0, ind=ind@entry=0, extent_hooks=extent_hooks@entry=0x7ffff717aca0 <je_extent_hooks_default>)
at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/jemalloc.c:333
#19 0x00007ffff6f436e5 in je_arena_init (tsdn=tsdn@entry=0x0, ind=ind@entry=0, extent_hooks=0x7ffff717aca0 <je_extent_hooks_default>)
at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/jemalloc.c:361
#20 0x00007ffff6f437ca in malloc_init_hard_a0_locked () at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/jemalloc.c:1270
#21 0x00007ffff6f43943 in malloc_init_hard () at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/jemalloc.c:1463
#22 0x00007ffff6f44e65 in malloc_init () at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/jemalloc.c:216
#23 imalloc (dopts=<synthetic pointer>, sopts=<synthetic pointer>) at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/jemalloc.c:1927
#24 malloc (size=72704) at /var/tmp/portage/dev-libs/jemalloc-5.0.1/work/jemalloc-5.0.1/src/jemalloc.c:1977
#25 0x00007ffff5c9f028 in (anonymous namespace)::pool::pool (this=0x7ffff600b820 <(anonymous namespace)::emergency_pool>)
at /var/tmp/portage/sys-devel/gcc-7.2.0/work/gcc-7.2.0/libstdc++-v3/libsupc++/eh_alloc.cc:123
#26 __static_initialization_and_destruction_0 (__priority=65535, __initialize_p=1) at /var/tmp/portage/sys-devel/gcc-7.2.0/work/gcc-7.2.0/libstdc++-v3/libsupc++/eh_alloc.cc:262
#27 _GLOBAL__sub_I_eh_alloc.cc(void) () at /var/tmp/portage/sys-devel/gcc-7.2.0/work/gcc-7.2.0/libstdc++-v3/libsupc++/eh_alloc.cc:338
#28 0x00007ffff7de765a in call_init (l=<optimized out>, argc=argc@entry=6, argv=argv@entry=0x7fffffffdea8, env=env@entry=0x7fffffffdee0) at dl-init.c:72
#29 0x00007ffff7de776b in call_init (env=0x7fffffffdee0, argv=0x7fffffffdea8, argc=6, l=<optimized out>) at dl-init.c:30
#30 _dl_init (main_map=0x7ffff7ffe110, argc=6, argv=0x7fffffffdea8, env=0x7fffffffdee0) at dl-init.c:120
#31 0x00007ffff7dd8e2a in _dl_start_user () from /lib64/ld-linux-x86-64.so.2
#32 0x0000000000000006 in ?? ()
#33 0x00007fffffffe1d8 in ?? ()
#34 0x00007fffffffe1ea in ?? ()
#35 0x00007fffffffe1ed in ?? ()
#36 0x00007fffffffe1f0 in ?? ()
#37 0x00007fffffffe1fe in ?? ()
#38 0x00007fffffffe21a in ?? ()
#39 0x0000000000000000 in ?? ()
When I build rsyslog without jemalloc (--disable-jemalloc) libfaketime-0.9.7 works.
I spent a little time investigating this (in the process I found this issue).
The root cause here is that jemalloc does neat stuff with time and threads, it is using timers to do things like arena-decay etc.
So the problem here is that during libfaketime's initialization, it is calling dlsym(), which needs malloc, which initializes jemalloc, which creates a bunch of threads, which captures a bunch of timestamps.
In the test case I had in front of me, I was able to get things working by avoiding faking during ftpl_init:
DONT_FAKE_TIME(ftpl_init());
with that change, the only other issue is jemalloc also needs to initialize its condition-variable, so I removed stubbing on cond_init from libfaketime; and this was sufficient to get everything working.
If a PR would be more helpful, I could clean up what I have working. I was doing all of this to help out a friend, so it is conceivable that it only helps for this particular case.
Thanks, that sounds very interesting. A PR would be awesome; we could then check whether it breaks anything and use it as a base.
@timkordas A PR would still be useful w.r.t. https://github.com/rust-lang/rust/issues/60461
I'm getting your point with DONT_FAKE_TIME on ftpl_init, but could you please elaborate on "removed stubbing on cond_init"?
This is supposed to be fixed with the commit referenced above and in v0.9.8 / current HEAD, but lacks confirmation. Also, more information is still needed on the "cond_init" part. Please re-open if you have any news.
Rust still doesn't work with version 0.9.8 with default config:
Details
(gdb) bt
#0 0x00007ffff7fbf499 in ?? () from /usr/lib64/faketime/libfaketime.so.1
#1 0x00007ffff7fc43f5 in clock_gettime () from /usr/lib64/faketime/libfaketime.so.1
#2 0x00005555555851cc in nstime_get (time=0x7fffff7ff1a0) at ../jemalloc/src/nstime.c:128
#3 nstime_update_impl (time=0x7fffff7ff1a0) at ../jemalloc/src/nstime.c:160
#4 0x0000555555584db0 in _rjem_je_malloc_mutex_lock_slow (mutex=0x5555557a51d8 <init_lock>) at ../jemalloc/src/mutex.c:70
#5 0x000055555555be5f in malloc_mutex_lock (tsdn=0x0, mutex=<optimized out>) at ../jemalloc/include/jemalloc/internal/mutex.h:205
#6 malloc_init_hard () at ../jemalloc/src/jemalloc.c:1506
#7 malloc_init () at ../jemalloc/src/jemalloc.c:217
#8 imalloc (sopts=<optimized out>, dopts=<optimized out>) at ../jemalloc/src/jemalloc.c:1986
#9 calloc (num=1, size=32) at ../jemalloc/src/jemalloc.c:2138
#10 0x00007ffff5121b65 in ?? () from /usr/lib/libdl.so.2
#11 0x00007ffff5121518 in dlsym () from /usr/lib/libdl.so.2
#12 0x00007ffff7fbf4c4 in ?? () from /usr/lib64/faketime/libfaketime.so.1
#13 0x00007ffff7fc43f5 in clock_gettime () from /usr/lib64/faketime/libfaketime.so.1
#14 0x00005555555851cc in nstime_get (time=0x7fffff7ff5f0) at ../jemalloc/src/nstime.c:128
#15 nstime_update_impl (time=0x7fffff7ff5f0) at ../jemalloc/src/nstime.c:160
#16 0x0000555555584db0 in _rjem_je_malloc_mutex_lock_slow (mutex=0x5555557a51d8 <init_lock>) at ../jemalloc/src/mutex.c:70
#17 0x000055555555be5f in malloc_mutex_lock (tsdn=0x0, mutex=<optimized out>) at ../jemalloc/include/jemalloc/internal/mutex.h:205
#18 malloc_init_hard () at ../jemalloc/src/jemalloc.c:1506
#19 malloc_init () at ../jemalloc/src/jemalloc.c:217
#20 imalloc (sopts=<optimized out>, dopts=<optimized out>) at ../jemalloc/src/jemalloc.c:1986
#21 calloc (num=1, size=32) at ../jemalloc/src/jemalloc.c:2138
#22 0x00007ffff5121b65 in ?? () from /usr/lib/libdl.so.2
#23 0x00007ffff5121518 in dlsym () from /usr/lib/libdl.so.2
#24 0x00007ffff7fbf4c4 in ?? () from /usr/lib64/faketime/libfaketime.so.1
#25 0x00007ffff7fc43f5 in clock_gettime () from /usr/lib64/faketime/libfaketime.so.1
Well, I can confirm such an endless recursion with a more minimum example of jemalloc than Rust. Apparently not fixed. :-(
However, even with FAKE_PTHREAD not enabled and wrapping all of ftpl_init() in DONT_FAKE_TIME, it does not work for me, so I cannot reproduce the fix sketched by @timkordas yet. Please provide more details.
I'm currently uncertain whether this can be fixed at all in libfaketime. As @timkordas already pointed out, libfaketime needs dlsym() in order to pass intercepted function calls through to their original version; in this case it is clock_gettime(). dlsym() apparently allocates some memory, which is handled by jemalloc, and jemalloc needs to fetch a timestamp, which libfaketime cannot provide unless the dlsym() call succeeded. Hence the endless recursion.
Trying to break the recursion by returning an error just leads to another endless hang. Eventually jemalloc expects clock_gettime to always succeed (jemalloc's src/nstime.c does not have any apparent error handling for its calls to clock_gettime, but I didn't really dig into its source yet).
I'm open for suggestions...
Sorry, I haven't had a chance to clean up and submit a PR.
the old branch I have lying around has this for every instance of the !initialized check:
if (!initialized) { #ifndef SUPPORT_JEMALLOC ftpl_init(); #else DONT_FAKE_TIME(ftpl_init()); #endif }
that is, until we're initialized, we can't support any faking.
-Tim
On Tue, Sep 3, 2019 at 6:20 AM Wolfgang Hommel [email protected] wrote:
Well, I can confirm such an endless recursion with a more minimum example of jemalloc than Rust. Apparently not fixed. :-(
However, even with FAKE_PTHREAD not enabled and wrapping all of ftpl_init() in DONT_FAKE_TIME, it does not work for me, so I cannot reproduce the fix sketched by @timkordas https://github.com/timkordas yet. Please provide more details.
I'm currently uncertain whether this can be fixed at all in libfaketime. As @timkordas https://github.com/timkordas already pointed out, libfaketime needs dlsym() in order to pass intercepted function calls through to their original version; in this case it is clock_gettime(). dlsym() apparently allocates some memory, which is handled by jemalloc, and jemalloc needs to fetch a timestamp, which libfaketime cannot provide unless the dlsym() call succeeded. Hence the endless recursion.
Trying to break the recursion by returning an error just leads to another endless hang. Eventually jemalloc expects clock_gettime to always succeed (jemalloc's src/nstime.c does not have any apparent error handling for its calls to clock_gettime, but I didn't really dig into its source yet).
I'm open for suggestions...
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/wolfcw/libfaketime/issues/130?email_source=notifications&email_token=AHGXTGNWQNDJJARFMTQ6RXDQHZQANA5CNFSM4EFI55W2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5YFG7I#issuecomment-527455101, or mute the thread https://github.com/notifications/unsubscribe-auth/AHGXTGMWTBH2BIH5MTYMXRDQHZQANANCNFSM4EFI55WQ .
Thanks for sharing! Interestingly enough, this doesn't change anything for me, and I'm a bit puzzled why that works for you.
My jemalloc test program simply malloc()s a couple of bytes and uses jemalloc, just like libfaketime, as LD_PRELOAD library. Are you linking it with your application?
One aspect here is that each of the intercepted time-related system calls checks whether libfaketime is initialized as its first step and calls ftpl_init() if required. ftpl_init() then pretty quickly dives into dlsym() of all the original functions, where the recursion with jemalloc happens. I don't see how DONT_FAKE_TIME(), which simply sets the global variable dont_fake to false as a wrapper around arbitrary calls, would even influence that.
826f8b779242cf66b3f6537c1549c2a6b9cd40e4 will now detect and warn about recursive calls to clock_gettime() as they happen when used together with current jemalloc.
First, it will try to go the DONT_FAKE_TIME(ftpl_init()) way suggested by @timkordas, even if that never worked for me.
On the next recursion, it will return -1 to the call to clock_gettime(), which signals an error that should help the caller (jemalloc's nstime_get() in this particular case) to detect that something is wrong.
This does not fix compatibility with current jemalloc for me. I assume that jemalloc currently does not expect and handle such an error on calls to clock_gettime(). I'd appreciate any suggestions on how we can fix this purely on the libfaketime side, but at the moment I assume that it can't work without changes made to jemalloc as well.
Therefore, I don't know what to do about https://github.com/rust-lang/rust/issues/60461 right now, sorry.
I think this cannot be easily solved, as the initial stacktrace shows that the malloc called by dlsym causes the recursion. Since I think libfaketime cannot know whether jemalloc is done initialising (or if it is used at all), I think it cannot know when it is allowed to start using dlsym.
What do you think?
Also the stacktrace does not show an endless recursion, but I think a deadlock. jemalloc locks its semaphore, then calls a clock function ending in faketime, faketime calls dlsym to load original clock function, dlsym calls malloc and ends up in jemalloc again. jemalloc locks its ... Wait, its already locked, so it waits. Forever. jemalloc init is not reentrant. I see not much what faketime could do about jemallocs deadlock.
Do you think I misread the initial stracktrace and understood well?
In case I didn't missunderstand, I think it would only help to link either jemalloc or libfaketime statically (against libc and libdl, and whatever is needed). At least on Linux with its extremely stable kernel ABI I think this should be even quite portable across systems without recompiling (on other systems, statically linked binaries might be very system specific).
For me malloc is really basic, so I think it should avoid any dependencies (I don't know what it needs clock for, maybe it writes a log file or so?).
mmm I just wonder if normal clock_gettime() in glibc could in a future version also do some lazy initialization and need malloc. If there is nothing that forbids that (some standard or so), then I think this is more likely a jemalloc issue than a libfaketime one - because in that case it would fail without libfaketime as well :)
I just tested this again with latest libfaketime (0.9.9) and every application linked against jemalloc is still failing. So we will stick to 0.9.6...
I'm reopening this issue as it does not seem to be resolved. Even if there's no idea how to get to a resolution, it's useful to be able to find known outstanding issues in the list of open issues.
I'm reopening this issue as it does not seem to be resolved. Even if there's no idea how to get to a resolution, it's useful to be able to find known outstanding issues in the list of open issues.
So you think my analysis (that it is a dead lock because of non-reentrant init in remalloc) is incorrect? Could you please provide a correct analysis?
@sdettmer i'm not claiming that your analysis is incorrect -- it looks reasonable to me.
i'm trying to understand whether a fix has been applied that would let this work with jemalloc, and i don't think it's resolved.
I tried building this simple test binary with -ljemalloc :
#include <jemalloc/jemalloc.h>
int main() {
unsigned char *foo = malloc(100);
foo = realloc(foo, 1000);
free(foo);
return 0;
}
And it does hang when run under faketime.
That makes me think we don't have a solution to this problem. is there a fix i'm missing, beyond "don't do that, then"?
No, we don't have a fix for that.
Last time we traced this, we figured out that https://github.com/jemalloc/jemalloc/blob/dev/src/nstime.c has calls to clock_gettime() but does not check the return value for errors. So while libfaketime can detect the problem (it leads to indirect recursive calls, see https://github.com/wolfcw/libfaketime/blob/0ca35dd8c4532075d6805133a8f2f319f54c26ff/src/libfaketime.c#L2261-L2291), jemalloc (and probably similar libraries showing the same problem with libfaketime, e.g., libasan) does not expect clock_gettime() to fail and does not adjust to this situation.
As a consequence, libfaketime cannot initialize properly (because its use of dlsym() apparently needs to malloc() memory somewhere), and things hang. Given that we can neither return the real time from libfaketime nor a properly faked time without initialisation, and the caller ignores the error-indicating return value, there is likely little to nothing that can be done on libfaketime's side.
We could try with returning a constant (non-zero) fake timestamp and postpone initialisation to a later point, but similar to unrelated "hang" issues with other libraries (e.g., glibc and FORCE_MONOTONIC_FIX), this eventually means we'd have to return constant timestamps more than once before it is "safe" to use dlsym(), and thus might need a detection of which other libraries (and in which version) are in use. However, the use of constant timestamps may still break the calling application (once we can then switch to properly faked timestamps), so I don't think a clean solution is possible without the calling function honouring clock_gettime()'s return value.
But is the change from 0bde083556e243e87bddaaf94e68f2ef85dad769 correct? I.e. previous versions without this change are working, so you could argue this change is causing the problem. But maybe it is required/fixing another issue or just uncovered this long standing bug?
Should we try to connect with people from jemalloc to get their input? Maybe they have an idea or could implement clock_gettime() error handling if this is really missing.
The recursion seems to be like this:
- An application, compiled with jemalloc support, uses malloc(), as provided by jemalloc
- jemalloc internally uses clock_gettime()
- libfaketime provides clock_gettime(), but requires dlsym() to get to the original clock_gettime()
- dlsym() uses malloc(). There we go again.
libfaketime cannot work properly unless initialised, and the change you pointed to just makes sure that libfaketime initialisation is done no matter which of its functions is called first.
To make things work for every component involved, including libfaketime, the recursion must be broken. Once libfaketime is initalised, this should no longer be a problem. Alternatively, we'd need a dlsym() implementation that does not rely on malloc() (and thus calls jemalloc recursively).
Currently, libfaketime detects the recursion and tries to break it (by returning an error value). But given that, so far, jemalloc apparently ignores this error value, recursion detection alone does not solve the problem yet.
My current guess is that this either would have to be addressed in jemalloc (i.e., handle clock_gettime() return values appropriately), or we'd need a dlsym() without dynamic memory allocation for libfaketime initialisation (i.e., don't call jemalloc's malloc() recursively during dlsym()).
Thanks you all for your valuable input. Let me try to summarize what I think is the current state of analysis.
To @wolfcw summary
The recursion seems to be like this:
I would like to add that strictly speaking it is not just a recursion but a cyclic dependency. Dependencies need to form a DAG (https://en.wikipedia.org/wiki/Directed_acyclic_graph) to be resolvable, but we we have the cycle. The special form of recursion we find here I think is called "reentrance".
I don't think libfaketime can detect a recursive call, because as pointed by @wolfcw summary, there is only one instance of clock_gettime(). In contrast, jemalloc() calls itself indirectly and jemalloc() possibly could detect and work around this (I did not though through, possibly it is not safely feasible when for example including signal handlers calling malloc when a signal arrives while in jemalloc code - signal safe reentrace usually is hard).
Because I don't see faketime called twice in the analysis (only jemalloc is), I think the initialization patches will do no good (and don't work) and should not be merged into.
I don't see where this error value introduced by the patch could be returned - the problem is, that dlopen blocks and thus never returns.
faketime also cannot load libc to get the "real" malloc, because it would also need to call dlopen.
I think malloc() is a very essential function and to make it dependent on clock_gettime(), which might be implemented as system call with context switch, for example, is possibly not the best idea. Code simply relies on malloc. jemalloc could initialize all its dependency (by calling all needed functions) before hijacking malloc, but still it's not safe. jemalloc could try to implement a "reentrance" detection and simply call original malloc in that case, however this possibly breaks things (for example, the allocated block then would not be traced, but the free of it could be, so it would look like a memory corruption, because a block is freed without mallocing according to jemalloc log file!). jemalloc could also try to link its dependencies statically.
Let's collect our options.
Link statically
As pointed before, like jemalloc, I think also libfaketime could link dl* and malloc (libc.a, libdl.a) statically to solve this particular issue, but I don't know whether every user wants to pay its price.
Initialization Function
The initialization order of technically independent libraries is, as far I know, undefined. However, libdl will use a fixed one (either in order of appearance or in reverse order I think). So we possibly could practically enforce to init libfaketime first (although not guaranteed because officially undefined). If so, I think we could use an initialization function in libfaketime to dlload first (https://stackoverflow.com/a/9759936 shows ways to accomplish this).
This approach would be Linux (or GCC) specific. I think other systems may use other ways to archive that; every system supporting C++ should have a way to do so, but I'm not sure if C standard guarantees that such exists everywhere).
Implement real clock_gettime
When being Linux specific, we could also consider implementing the syscall our selves. Possibly its something like
/* Get current value of CLOCK and store it in TP. */
int
__clock_gettime (clockid_t clock_id, struct timespec *tp)
{
return INLINE_VSYSCALL (clock_gettime, 2, clock_id, tp);
}
(see https://code.woboq.org/userspace/glibc/sysdeps/unix/sysv/linux/clock_gettime.c.html#__clock_gettime) Maybe we can even call this function.
but this would be very slow
without vDSO. vDSO could be complicated If we cannot call __vdso_clock_gettime I think code would be too complicated. I think it's Linux specific and quite ugly.
In summary I think we could investigate the initialization function option.
What do you think?
Thanks for your precise summary and listing the options!!
I need to dig deeper into them, just wanted to point out that we are already using
static void ftpl_init (void) __attribute__ ((constructor));
and I'm not sure whether using -Wl,-init,<function name> when using gcc significantly changes something based on your StackOverflow link.
Also, a solution that only works for Linux would be fine as a first step, we just have to make sure not to break things for other OS.
link statically
So, does someone have a makefile building a correct static faketime executable? It doesn't seem trivial to me. (I'd probably use musl for that purpose, but that's hopefully not a complication, even if used against a glibc-linked binary later.)
Just pinging if there was an update for this issue. I had been using a patched version of libfaketime to get around the jemalloc issue for builds I am doing. The patch was not accepted, so I am not sure if there is any update for this going forward.
I did not submit a patch I was build from 0.9.9 based on a patch .. details here in this issue https://github.com/wolfcw/libfaketime/issues/355
I believe there was a concern in the patch, so it was not merged.
Thanks for pointing those out. Yes, PR #333 was withdrawn by its author, @ronrother, as it could not cover all cases reliably. Your issue with stale shared memory files might be a consequence of failed initialisations, but working around those will not fix the jemalloc compatibility issue.
As I posted above on Sep 3, 2019, I think one key aspect here is that jemalloc does not consider that calls to clock_gettime() may ever fail. I've just checked their current src/nstime.c again and nothing seems to have changed there in this regard. I still think that we cannot fix this compatibility issue purely on libfaketime's end, altough I'd be happy to be proven wrong.
I didn't find an issue related to libfaketime in jemalloc's repository, so opening one might be a logical step to help with progress. There are other tools like libasan, which apparently have similar incompatibilities. It'd really help if those affected could assist with digging into both ends. :-)
I hit this issue with libfaketime 0.9.10, with glibc 2.39, Firefox 123.0, on ArchLinux. I explored ways to avoid the issue by avoiding malloc calls triggered from libfaketime, and managed to break the cyclic dependency between malloc and libfaketime (details below).
One of the issues is that dlsym tries to allocate memory when a symbol is not found. From libfaketime's perspective, the absence of some symbols is expected. Here is an example of the symbols that could not resolve when run on my system:
- dlsym(__ftime) not found at line 2696
- dlvsym(timer_settime@GLIBC_2.2) not found at line 2761
- dlvsym(timer_gettime@GLIBC_2.2) not found at line 2769
I created a patch (#463) to allow users to avoid calling dlsym on non-existent symbols, and compiled it, along with the existing compile-time option FAKE_STATELESS=1 (to avoid malloc in sem_open). After this, I successfully managed to use faketime with Firefox 123.0 (with libfaketime branched off v0.9.10, because master seems to trigger a failure in Firefox for reasons that are likely unrelated to this issue - filed #464). EDIT: I submitted a PR for a runtime alternative to FAKE_STATELESS=1 compile-time flag, at #465.
How to avoid (indirect) malloc calls from libfaketime
When I tried to launch Firefox through faketime, it crashed due to infinite recursion in malloc. The part of the stack that highlights the relevant calls is as follows. malloc (in Firefox) indirectly calls time (from libfaketime), which calls dlsym that in turn triggers malloc and then infinite recursion. dlsym calls malloc because it tries to allocate memory for exception reporting when the symbol is not found.
Stack trace: malloc -> time -> dlsym -> malloc -> exception/malloc recursion
#95207 0x000056111b95921a in malloc () #95208 0x00007f9982983af2 in malloc (size=87) at ../include/rtld-malloc.h:56 #95209 __GI__dl_exception_create_format (exception=exception@entry=0x7ffc36a0e8e0, objname=0x7f99829b6f80 "/tmp/libfaketime/src/libfaketime.so.1", fmt=fmt@entry=0x7f99829a9e2b "undefined symbol: %s%s%s") at dl-exception.c:157 #95210 0x00007f998298a72d in _dl_lookup_symbol_x (undef_name=0x7f9982974b90 "__ftime", undef_map=<optimized out>, ref=0x7ffc36a0e958, symbol_scope=<optimized out>, version=<optimized out>, type_class=0, flags=2, skip_map=0x7f998297e000) at dl-lookup.c:809 #95211 0x00007f99824860ce in do_sym (handle=<optimized out>, name=0x7f9982974b90 "__ftime", who=0x7f998296f323 <ftpl_really_init+1049>, vers=vers@entry=0x0, flags=flags@entry=2) at dl-sym.c:146 #95212 0x00007f99824863f1 in _dl_sym (handle=<optimized out>, name=<optimized out>, who=<optimized out>) at dl-sym.c:195 #95213 0x00007f99823b94f8 in dlsym_doit (a=a@entry=0x7ffc36a0ebc0) at dlsym.c:40 #95214 0x00007f99829814e1 in __GI__dl_catch_exception (exception=exception@entry=0x7ffc36a0eb20, operate=0x7f99823b94e0 <dlsym_doit>, args=0x7ffc36a0ebc0) at dl-catch.c:237 #95215 0x00007f9982981603 in _dl_catch_error (objname=0x7ffc36a0eb78, errstring=0x7ffc36a0eb80, mallocedp=0x7ffc36a0eb77, operate=<optimized out>, args=<optimized out>) at dl-catch.c:256 #95216 0x00007f99823b8f07 in _dlerror_run (operate=operate@entry=0x7f99823b94e0 <dlsym_doit>, args=args@entry=0x7ffc36a0ebc0) at dlerror.c:138 #95217 0x00007f99823b9585 in dlsym_implementation (dl_caller=<optimized out>, name=<optimized out>, handle=<optimized out>) at dlsym.c:54 #95218 ___dlsym (handle=<optimized out>, name=<optimized out>) at dlsym.c:68 #95219 0x00007f998296f323 in ftpl_really_init () from /tmp/libfaketime/src/libfaketime.so.1 #95220 0x00007f998296ffb4 in ftpl_init () from /tmp/libfaketime/src/libfaketime.so.1 #95221 0x00007f998296e025 in time () from /tmp/libfaketime/src/libfaketime.so.1 #95222 0x000056111b9a0af3 in ?? () #95223 0x000056111b95935f in malloc () #95224 0x00007f99826ac4fb in (anonymous namespace)::pool::pool (this=0x7f9982876280 <(anonymous namespace)::emergency_pool>) at /usr/src/debug/gcc/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:235 #95225 __static_initialization_and_destruction_0 () at /usr/src/debug/gcc/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:373 #95226 _GLOBAL__sub_I_eh_alloc.cc(void) () at /usr/src/debug/gcc/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:456 #95227 0x00007f99829851be in call_init (env=0x7ffc36a0f010, argv=0x7ffc36a0efe8, argc=4, l=<optimized out>) at dl-init.c:74 #95228 call_init (l=<optimized out>, argc=4, argv=0x7ffc36a0efe8, env=0x7ffc36a0f010) at dl-init.c:26 #95229 0x00007f99829852ac in _dl_init (main_map=0x7f99829b62e0, argc=4, argv=0x7ffc36a0efe8, env=0x7ffc36a0f010) at dl-init.c:121 #95230 0x00007f998299bbc0 in _dl_start_user () from /lib64/ld-linux-x86-64.so.2
I digged in the source code of glibc and found that it tries to allocate memory for an error message when a symbol is not found: https://github.com/bminor/glibc/blob/b6e3898194bbae78910bbe9cd086937014961e45/elf/dl-lookup.c#L800-L812
The logic there seems enabled by default, and can be opted out of by setting the environment variable LD_DEBUG=unused (parsed by glibc in rtld.c).
But after starting with LD_DEBUG=unused faketime 2024-03-11 (command here), I still get a crash, now through sem_open:
Stack trace: malloc -> time -> ftpl_init -> ftpl_really_init -> ft_shm_init -> sem_open -> malloc -> exception/malloc recursion
#91000 0x00005585f3e09d49 in malloc () #91001 0x00007fb718cb0fab in __sem_check_add_mapping (name=name@entry=0x7ffc4cc95410 "/faketime_sem_1112645", fd=fd@entry=3, existing=existing@entry=0x0) at ../sysdeps/pthread/sem_routines.c:104 #91002 0x00007fb718cb0b68 in __sem_open (name=0x7ffc4cc95410 "/faketime_sem_1112645", oflag=0) at ../sysdeps/pthread/sem_open.c:83 #91003 0x00007fb7192b6b07 in ft_shm_init () from /tmp/libfaketime/src/libfaketime.so.1 #91004 0x00007fb7192bd6a2 in ftpl_init () from /tmp/libfaketime/src/libfaketime.so.1 #91005 0x00007fb7192bb997 in time () from /tmp/libfaketime/src/libfaketime.so.1 #91006 0x00005585f3e18846 in GMut* InfallibleAllocPolicy::new_<GMut>() () #91007 0x00005585f3e09dde in malloc () #91008 0x00007fb718eac4fb in (anonymous namespace)::pool::pool (this=0x7fb719076280 <(anonymous namespace)::emergency_pool>) at /usr/src/debug/gcc/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:235 #91009 __static_initialization_and_destruction_0 () at /usr/src/debug/gcc/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:373 #91010 _GLOBAL__sub_I_eh_alloc.cc(void) () at /usr/src/debug/gcc/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:456 #91011 0x00007fb7192d31be in call_init (env=0x7ffc4cc95a40, argv=0x7ffc4cc95a18, argc=4, l=<optimized out>) at dl-init.c:74 #91012 call_init (l=<optimized out>, argc=4, argv=0x7ffc4cc95a18, env=0x7ffc4cc95a40) at dl-init.c:26 #91013 0x00007fb7192d32ac in _dl_init (main_map=0x7fb7193042e0, argc=4, argv=0x7ffc4cc95a18, env=0x7ffc4cc95a40) at dl-init.c:121 #91014 0x00007fb7192e9bc0 in _dl_start_user () from /lib64/ld-linux-x86-64.so.2
I don't see a reasonable way to avoid the malloc call from sem_open's internals (glibc source of sem_routines.c).
But libfaketime's source shows that the FAKE_STATELESS compile-time flag skips the relevant function, so I compiled with the flag, and tried again:
$ cd /tmp/libfaketime # this repository
$ make PREFIX= LIBDIRNAME=$PWD FAKETIME_COMPILE_CFLAGS=-DFAKE_STATELESS=1
$ LD_DEBUG=unused LD_PRELOAD=/tmp/libfaketime/src/libfaketime.so.1 FAKETIME='2024-06-07 12:34:56' firefox --no-remote -profile /tmp/profiledir
And then it crashes again, but this time in mktime...
Stack trace: malloc -> time -> ftpl_init -> ftpl_really_init -> parse_ft_string -> mktime -> free -> malloc/exception recursion
#95212 0x000055606fbe121a in malloc () #95213 0x00007ff08a4aef35 in __cxxabiv1::__cxa_allocate_exception (thrown_size=136) at /usr/src/debug/gcc/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:398 #95214 0x00007ff08a49c4a0 in __cxxabiv1::throw_recursive_init_exception () at /usr/src/debug/gcc/gcc/libstdc++-v3/libsupc++/guard.cc:248 #95215 __cxxabiv1::__cxa_guard_acquire (g=0x55606fca2628) at /usr/src/debug/gcc/gcc/libstdc++-v3/libsupc++/guard.cc:299 #95216 0x000055606fc22673 in free () #95217 0x00007ff08a1fc1da in tzset_internal (always=always@entry=1) at tzset.c:401 #95218 0x00007ff08a1fc343 in __tzset () at tzset.c:551 #95219 0x00007ff08a1fb01d in __GI_mktime (tp=0x7ffc0f69dc20) at mktime.c:541 #95220 0x00007ff08a757803 in parse_ft_string () from /tmp/libfaketime/src/libfaketime.so.1 #95221 0x00007ff08a758f61 in ftpl_really_init () from /tmp/libfaketime/src/libfaketime.so.1 #95222 0x00007ff08a758fb4 in ftpl_init () from /tmp/libfaketime/src/libfaketime.so.1 #95223 0x00007ff08a757025 in time () from /tmp/libfaketime/src/libfaketime.so.1 #95224 0x000055606fc28af3 in ?? () #95225 0x000055606fbe135f in malloc () #95226 0x00007ff08a4ac4fb in (anonymous namespace)::pool::pool (this=0x7ff08a676280 <(anonymous namespace)::emergency_pool>) at /usr/src/debug/gcc/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:235 #95227 __static_initialization_and_destruction_0 () at /usr/src/debug/gcc/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:373 #95228 _GLOBAL__sub_I_eh_alloc.cc(void) () at /usr/src/debug/gcc/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:456 #95229 0x00007ff08a76e1be in call_init (env=0x7ffc0f69e110, argv=0x7ffc0f69e0e8, argc=4, l=<optimized out>) at dl-init.c:74 #95230 call_init (l=<optimized out>, argc=4, argv=0x7ffc0f69e0e8, env=0x7ffc0f69e110) at dl-init.c:26 #95231 0x00007ff08a76e2ac in _dl_init (main_map=0x7ff08a79f2e0, argc=4, argv=0x7ffc0f69e0e8, env=0x7ffc0f69e110) at dl-init.c:121 #95232 0x00007ff08a784bc0 in _dl_start_user () from /lib64/ld-linux-x86-64.so.2
Okay, next try: now avoiding mktime... When relative fake time is specified, libfaketime takes a code path that doesn't call mktime. So I tried that (+/- followed by a number, followed by m/h/d/y):
LD_DEBUG=unused LD_PRELOAD=/tmp/libfaketime/src/libfaketime.so.1 FAKETIME='+123.45d' firefox --no-remote -profile /tmp/profiledir
Now from libfaketime's perspective, everything works, but Firefox unfortunately crashes, due to the side effects of the LD_DEBUG=unused flag (the same issue occurs when I launch Firefox with LD_DEBUG=unused without libfaketime),
[1056855, Main Thread] ###!!! ASSERTION: GTK+ 2.x symbols detected. Using GTK+ 2.x and GTK+ 3 in the same process is not supported: 'glib assertion', file /usr/src/debug/firefox/firefox-123.0/toolkit/xre/nsSigHandlers.cpp:184
After patching libfaketime once more (#463), to enable skipping of dlsym/dlvsym calls without the use of LD_DEBUG=unused (and with FAKE_STATELESS=1), I can run without issues in libfaketime, but I am hitting an assertion failure in Firefox, ETIMEDOUT after a pthread_cond_timedwait call (EDIT: this is #464).
Because v0.9.10 works I wondered whether the issue was with the master branch, and indeed, when I checked out https://github.com/wolfcw/libfaketime/commits/v0.9.10/ , applied #463 and #465 on top, then I finally managed to launch Firefox 123.0 with faketime:
FAKETIME_IGNORE_SYMBOLS=__ftime,timer_settime@GLIBC_2.2,timer_gettime@GLIBC_2.2 /tmp/libfaketime/src/faketime --disable-shm 2024-05-08 firefox --no-remote -profile /tmp/profiledir
EDIT: libfaketime has only started to be an issue in Firefox since version 120, here is the bug I filed: https://bugzilla.mozilla.org/show_bug.cgi?id=1884996 (and fixed in Firefox 125!)
