Discussion:
How to debug occasional hashmap corruption?
(too old to reply)
juice
2018-11-06 09:57:00 UTC
Permalink
Hi,

During the past half year I have seen systemd dump core three times due
to what I suspect a hashmap corruption or race.
Each time it looks a bit different and is triggered by different things
but it somehow centers on hashmap operations.

What would be the prefered way to debug this? I cannot add huge logging
as this is something that happens once in a blue moon and always in
different compute nodes.
Is there some way I could easily test it by increasing the chance of
such
corruption/race happening?

The systemd version we currently have is 238 and the linux kernel is
4.14.69

Here is the latest coredump trace of the problem.

[***@mn-0 robot]#
[***@mn-0 robot]# gdb /lib/systemd/systemd
./core.systemd.0.6db5fc1f8d114369ae625ab03660c46e.1437.1539266612000000
GNU gdb (GDB) Fedora 8.1-14.wf29
Copyright (C) 2018 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-redhat-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://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 /lib/systemd/systemd...Reading symbols from
/usr/lib/debug/usr/lib/systemd/systemd-238-10.wf29.x86_64.debug...done.
done.
[New LWP 1437]
[New LWP 1]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `/usr/lib/systemd/systemd --switched-root --system
--deserialize 16'.
Program terminated with signal SIGABRT, Aborted.
#0 0x00007f13d7e2e1c7 in kill () from /lib64/libc.so.6
[Current thread is 1 (LWP 1437)]
Missing separate debuginfos, use: dnf debuginfo-install
audit-libs-2.8.3-4.wf29.x86_64 glibc-2.27-15.wf29.x86_64
kmod-libs-25-2.wf29.x86_64 libacl-2.2.52-20.wf29.x86_64 libattr-2.4.47-2
3.wf29.x86_64 libblkid-2.32-5.wf29.x86_64 libcap-2.25-10.wf29.x86_64
libcap-ng-0.7.8-9.wf29.x86_64 libgcc-7.3.1-5.wf29.x86_64
libmount-2.32-5.wf29.x86_64 libuuid-2.32-5.wf29.x86_64 lz4-
libs-1.8.1.2-4.wf29.x86_64 pam-1.3.0-13.wf29.x86_64
xz-libs-5.2.3-6.wf29.x86_64 zlib-1.2.11-5.wf29.x86_64
(gdb)
(gdb) bt
#0 0x00007f13d7e2e1c7 in kill () from /lib64/libc.so.6
#1 0x00005607e9a93887 in crash (sig=6) at ../src/core/main.c:196
#2 <signal handler called>
#3 0x00007f13d7e2dedb in raise () from /lib64/libc.so.6
#4 0x00007f13d7e2f291 in abort () from /lib64/libc.so.6
#5 0x00007f13d937739a in log_assert_failed_realm
(realm=***@entry=LOG_REALM_SYSTEMD, text=***@entry=0x7f13d9423042
"x",
file=***@entry=0x7f13d9435e08
"../src/libsystemd/sd-bus/bus-objects.c", line=***@entry=1618,
func=***@entry=0x7f13d94366d0 <__PRETTY_FUNCTION__.13175>
"vtable_member_compare_func") at ../src/basic/log.c:826
#6 0x00007f13d93bdca1 in vtable_member_compare_func (a=<optimized out>,
b=<optimized out>) at ../src/libsystemd/sd-bus/bus-objects.c:1618
#7 0x00007f13d936d4bb in base_bucket_scan (h=***@entry=0x7f13d98f9740,
idx=412, ***@entry=411, key=***@entry=0x5607eb85b700) at
../src/basic/hashmap.c:1251
#8 0x00007f13d936ea11 in hashmap_put (h=0x7f13d98f9740,
key=***@entry=0x5607eb85b700, value=***@entry=0x5607eb85b700) at
../src/basic/hashmap.c:1268
#9 0x00007f13d93c0066 in add_object_vtable_internal
(bus=***@entry=0x5607eb7b2e00, slot=***@entry=0x0,
path=***@entry=0x5607e9b51fc8 "/org/freedesktop/systemd1/unit",
interface=<optimized out>, ***@entry=0x7f13d9418b30
"org.freedesktop.systemd1.Service", vtable=<optimized out>,
fallback=***@entry=true,
find=0x5607e9aa1080 <bus_unit_interface_find>,
userdata=0x5607eb7273c0) at ../src/libsystemd/sd-bus/bus-objects.c:1739
#10 0x00007f13d93c0515 in sd_bus_add_fallback_vtable
(bus=***@entry=0x5607eb7b2e00, slot=***@entry=0x0,
prefix=***@entry=0x5607e9b51fc8 "/org/freedesktop/systemd1/unit",
interface=***@entry=0x7f13d9418b30
"org.freedesktop.systemd1.Service", vtable=<optimized out>,
find=***@entry=0x5607e9aa1080 <bus_unit_interface_find>,
userdata=0x5607eb7273c0) at
../src/libsystemd/sd-bus/bus-objects.c:1849
#11 0x00005607e9aa08be in bus_setup_api_vtables
(m=***@entry=0x5607eb7273c0, bus=0x5607eb7b2e00) at ../src/core/dbus.c:573
#12 0x00005607e9aa1fc2 in bus_on_connection (s=<optimized out>,
fd=<optimized out>, revents=<optimized out>, userdata=0x5607eb7273c0) at
../src/core/dbus.c:711
#13 0x00007f13d93f35f8 in source_dispatch (s=***@entry=0x5607eb8162c0) at
../src/libsystemd/sd-event/sd-event.c:2307
#14 0x00007f13d93f4dfa in sd_event_dispatch (e=***@entry=0x5607eb727910)
at ../src/libsystemd/sd-event/sd-event.c:2667
#15 0x00007f13d93f4f89 in sd_event_run (e=0x5607eb727910,
timeout=15000000) at ../src/libsystemd/sd-event/sd-event.c:2727
#16 0x00005607e9ad0df4 in manager_loop (m=0x5607eb7273c0) at
../src/core/manager.c:2615
#17 0x00005607e9a8f5a5 in invoke_main_loop
(ret_error_message=0x7ffe0ed707a8, ret_switch_root_init=<synthetic
pointer>, ret_switch_root_dir=<synthetic pointer>,
ret_fds=0x7ffe0ed707b8, ret_shutdown_verb=<synthetic pointer>,
ret_retval=<synthetic pointer>, ret_reexecute=<synthetic pointer>,
m=0x5607eb7273c0) at ../src/core/main.c:1651
#18 main (argc=5, argv=0x7ffe0ed70a98) at ../src/core/main.c:2430
(gdb)
--
- Juice -
Lennart Poettering
2018-11-06 10:27:49 UTC
Permalink
Post by juice
Hi,
During the past half year I have seen systemd dump core three times due
to what I suspect a hashmap corruption or race.
Each time it looks a bit different and is triggered by different things
but it somehow centers on hashmap operations.
What would be the prefered way to debug this? I cannot add huge logging
as this is something that happens once in a blue moon and always in
different compute nodes.
Is there some way I could easily test it by increasing the chance of such
corruption/race happening?
This looks very much like a memory corruption of some sorts and
valgrind should be the tool of choice to track that down.

Lennart
--
Lennart Poettering, Red Hat
juice
2018-11-06 12:30:19 UTC
Permalink
Post by Lennart Poettering
Post by juice
Hi,
During the past half year I have seen systemd dump core three times due
to what I suspect a hashmap corruption or race.
Each time it looks a bit different and is triggered by different things
but it somehow centers on hashmap operations.
What would be the prefered way to debug this? I cannot add huge logging
as this is something that happens once in a blue moon and always in
different compute nodes.
Is there some way I could easily test it by increasing the chance of such
corruption/race happening?
This looks very much like a memory corruption of some sorts and
valgrind should be the tool of choice to track that down.
Lennart
Thanks tor the prompt reply, Lennart.

I agree; using valgrind indeed was something already considered, however
I
suspect it might add some overhead in systemd operation?

The question here was more on the lines how to trigger the problem?
It is quite rare as it seems the occurrance is about once per two months
on
our QL3 test pool which contains hunderds of VM guests...
It would be impractical to build and deploy a release which contains
systemd
running under valgrind on every node! :)
--
- Juice -
Vito Caputo
2018-11-06 18:11:32 UTC
Permalink
Post by juice
Post by Lennart Poettering
Post by juice
Hi,
During the past half year I have seen systemd dump core three times due
to what I suspect a hashmap corruption or race.
Each time it looks a bit different and is triggered by different things
but it somehow centers on hashmap operations.
What would be the prefered way to debug this? I cannot add huge logging
as this is something that happens once in a blue moon and always in
different compute nodes.
Is there some way I could easily test it by increasing the chance of such
corruption/race happening?
This looks very much like a memory corruption of some sorts and
valgrind should be the tool of choice to track that down.
Lennart
Thanks tor the prompt reply, Lennart.
I agree; using valgrind indeed was something already considered, however I
suspect it might add some overhead in systemd operation?
The question here was more on the lines how to trigger the problem?
It is quite rare as it seems the occurrance is about once per two months on
our QL3 test pool which contains hunderds of VM guests...
It would be impractical to build and deploy a release which contains systemd
running under valgrind on every node! :)
In such scenarios where valgrind's overhead is impractical, I'd give
address sanitizer a try.

https://clang.llvm.org/docs/AddressSanitizer.html

Regards,
Vito Caputo
juice
2018-11-14 10:43:28 UTC
Permalink
Post by juice
Post by Lennart Poettering
Post by juice
Hi,
During the past half year I have seen systemd dump core three times due
to what I suspect a hashmap corruption or race.
Each time it looks a bit different and is triggered by different things
but it somehow centers on hashmap operations.
What would be the prefered way to debug this? I cannot add huge logging
as this is something that happens once in a blue moon and always in
different compute nodes.
Is there some way I could easily test it by increasing the chance of such
corruption/race happening?
This looks very much like a memory corruption of some sorts and
valgrind should be the tool of choice to track that down.
Lennart
Thanks tor the prompt reply, Lennart.
I agree; using valgrind indeed was something already considered,
however I
suspect it might add some overhead in systemd operation?
I have been trying to start systemd under valgrind but seems it is not a
trivial
task to do. Moreover, no searching has revealed a general receipe for
doing that
other than the advice in systemd README's to compile with
-Dvalgrind=true option.

So, where could I find information on how to set up memory corruption
debug on
a live system for testing?

- juice -

Dorian ROSSE
2018-11-06 14:29:16 UTC
Permalink
For repair a hash corruption which a signature for each file are the BASS framework from Thalos cybersecurity worker that add this program on Clam AV for check all files signatures ;)

Regards.


Dorian Rosse.

________________________________
De : systemd-devel <systemd-devel-***@lists.freedesktop.org> de la part de juice <***@swagman.org>
Envoyé : mardi, novembre 6, 2018 11:03
À : systemd-***@lists.freedesktop.org
Objet : [systemd-devel] How to debug occasional hashmap corruption?


Hi,

During the past half year I have seen systemd dump core three times due
to what I suspect a hashmap corruption or race.
Each time it looks a bit different and is triggered by different things
but it somehow centers on hashmap operations.

What would be the prefered way to debug this? I cannot add huge logging
as this is something that happens once in a blue moon and always in
different compute nodes.
Is there some way I could easily test it by increasing the chance of
such
corruption/race happening?

The systemd version we currently have is 238 and the linux kernel is
4.14.69

Here is the latest coredump trace of the problem.

[***@mn-0 robot]#
[***@mn-0 robot]# gdb /lib/systemd/systemd
./core.systemd.0.6db5fc1f8d114369ae625ab03660c46e.1437.1539266612000000
GNU gdb (GDB) Fedora 8.1-14.wf29
Copyright (C) 2018 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-redhat-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://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 /lib/systemd/systemd...Reading symbols from
/usr/lib/debug/usr/lib/systemd/systemd-238-10.wf29.x86_64.debug...done.
done.
[New LWP 1437]
[New LWP 1]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `/usr/lib/systemd/systemd --switched-root --system
--deserialize 16'.
Program terminated with signal SIGABRT, Aborted.
#0 0x00007f13d7e2e1c7 in kill () from /lib64/libc.so.6
[Current thread is 1 (LWP 1437)]
Missing separate debuginfos, use: dnf debuginfo-install
audit-libs-2.8.3-4.wf29.x86_64 glibc-2.27-15.wf29.x86_64
kmod-libs-25-2.wf29.x86_64 libacl-2.2.52-20.wf29.x86_64 libattr-2.4.47-2
3.wf29.x86_64 libblkid-2.32-5.wf29.x86_64 libcap-2.25-10.wf29.x86_64
libcap-ng-0.7.8-9.wf29.x86_64 libgcc-7.3.1-5.wf29.x86_64
libmount-2.32-5.wf29.x86_64 libuuid-2.32-5.wf29.x86_64 lz4-
libs-1.8.1.2-4.wf29.x86_64 pam-1.3.0-13.wf29.x86_64
xz-libs-5.2.3-6.wf29.x86_64 zlib-1.2.11-5.wf29.x86_64
(gdb)
(gdb) bt
#0 0x00007f13d7e2e1c7 in kill () from /lib64/libc.so.6
#1 0x00005607e9a93887 in crash (sig=6) at ../src/core/main.c:196
#2 <signal handler called>
#3 0x00007f13d7e2dedb in raise () from /lib64/libc.so.6
#4 0x00007f13d7e2f291 in abort () from /lib64/libc.so.6
#5 0x00007f13d937739a in log_assert_failed_realm
(realm=***@entry=LOG_REALM_SYSTEMD, text=***@entry=0x7f13d9423042
"x",
file=***@entry=0x7f13d9435e08
"../src/libsystemd/sd-bus/bus-objects.c", line=***@entry=1618,
func=***@entry=0x7f13d94366d0 <__PRETTY_FUNCTION__.13175>
"vtable_member_compare_func") at ../src/basic/log.c:826
#6 0x00007f13d93bdca1 in vtable_member_compare_func (a=<optimized out>,
b=<optimized out>) at ../src/libsystemd/sd-bus/bus-objects.c:1618
#7 0x00007f13d936d4bb in base_bucket_scan (h=***@entry=0x7f13d98f9740,
idx=412, ***@entry=411, key=***@entry=0x5607eb85b700) at
../src/basic/hashmap.c:1251
#8 0x00007f13d936ea11 in hashmap_put (h=0x7f13d98f9740,
key=***@entry=0x5607eb85b700, value=***@entry=0x5607eb85b700) at
../src/basic/hashmap.c:1268
#9 0x00007f13d93c0066 in add_object_vtable_internal
(bus=***@entry=0x5607eb7b2e00, slot=***@entry=0x0,
path=***@entry=0x5607e9b51fc8 "/org/freedesktop/systemd1/unit",
interface=<optimized out>, ***@entry=0x7f13d9418b30
"org.freedesktop.systemd1.Service", vtable=<optimized out>,
fallback=***@entry=true,
find=0x5607e9aa1080 <bus_unit_interface_find>,
userdata=0x5607eb7273c0) at ../src/libsystemd/sd-bus/bus-objects.c:1739
#10 0x00007f13d93c0515 in sd_bus_add_fallback_vtable
(bus=***@entry=0x5607eb7b2e00, slot=***@entry=0x0,
prefix=***@entry=0x5607e9b51fc8 "/org/freedesktop/systemd1/unit",
interface=***@entry=0x7f13d9418b30
"org.freedesktop.systemd1.Service", vtable=<optimized out>,
find=***@entry=0x5607e9aa1080 <bus_unit_interface_find>,
userdata=0x5607eb7273c0) at
../src/libsystemd/sd-bus/bus-objects.c:1849
#11 0x00005607e9aa08be in bus_setup_api_vtables
(m=***@entry=0x5607eb7273c0, bus=0x5607eb7b2e00) at ../src/core/dbus.c:573
#12 0x00005607e9aa1fc2 in bus_on_connection (s=<optimized out>,
fd=<optimized out>, revents=<optimized out>, userdata=0x5607eb7273c0) at
../src/core/dbus.c:711
#13 0x00007f13d93f35f8 in source_dispatch (s=***@entry=0x5607eb8162c0) at
../src/libsystemd/sd-event/sd-event.c:2307
#14 0x00007f13d93f4dfa in sd_event_dispatch (e=***@entry=0x5607eb727910)
at ../src/libsystemd/sd-event/sd-event.c:2667
#15 0x00007f13d93f4f89 in sd_event_run (e=0x5607eb727910,
timeout=15000000) at ../src/libsystemd/sd-event/sd-event.c:2727
#16 0x00005607e9ad0df4 in manager_loop (m=0x5607eb7273c0) at
../src/core/manager.c:2615
#17 0x00005607e9a8f5a5 in invoke_main_loop
(ret_error_message=0x7ffe0ed707a8, ret_switch_root_init=<synthetic
pointer>, ret_switch_root_dir=<synthetic pointer>,
ret_fds=0x7ffe0ed707b8, ret_shutdown_verb=<synthetic pointer>,
ret_retval=<synthetic pointer>, ret_reexecute=<synthetic pointer>,
m=0x5607eb7273c0) at ../src/core/main.c:1651
#18 main (argc=5, argv=0x7ffe0ed70a98) at ../src/core/main.c:2430
(gdb)


--
- Juice -
John Reiser
2018-11-06 16:42:23 UTC
Permalink
Post by juice
During the past half year I have seen systemd dump core three times due
to what I suspect a hashmap corruption or race.
Each time it looks a bit different and is triggered by different things
but it somehow centers on hashmap operations.
Three intermittent hardware failures in one year on 10,000 boxes is normal.
Keep good records. If the same box appears twice, then physically destroy it.

Meanwhile, log all events to a circular buffer that just keeps rotating:
date+time (32 bits, 1 microsecond precision), caller (return address),
argument summary (fixed format: string prefixes or hash). Analyze the dump.

Lock each hashmap operation to insure single-threaded operation,t;
prevent even multiple [supposedly] read-only access.
Lock each signal handler: only one instance of a given signal at a time.
Loading...