On 4/20/20 3:02 PM, Kees Bakker wrote:
> On 20-04-2020 14:51, Rob Crittenden wrote:
>> Kees Bakker via FreeIPA-users wrote:
>>> On 20-04-2020 09:58, Kees Bakker via FreeIPA-users wrote:
>>>> On 20-04-2020 09:09, Florence Blanc-Renaud wrote:
>>>>> On 4/20/20 8:28 AM, Kees Bakker via FreeIPA-users wrote:
>>>>>> Hey,
>>>>>>
>>>>>> I'm looking for advice how to analyse/debug this.
>>>>>>
>>>>>> On one of the masters the dirsrv is unresponsive. It runs, but
every
>>>>>> attempt to connect it hangs.
>>>>>>
>>>>>> The command "systemctl status" does not show anything
alarming
>>>>>>
>>>>>> ● dirsrv(a)EXAMPLE-COM.service - 389 Directory Server EXAMPLE-COM.
>>>>>> Loaded: loaded (/usr/lib/systemd/system/dirsrv@.service;
enabled; vendor preset: disabled)
>>>>>> Active: active (running) since vr 2020-04-17 13:46:25 CEST;
1h 33min ago
>>>>>> Process: 3123
ExecStartPre=/usr/sbin/ds_systemd_ask_password_acl /etc/dirsrv/slapd-%i/dse.ldif
(code=exited, status=0/SUCCESS)
>>>>>> Main PID: 3134 (ns-slapd)
>>>>>> Status: "slapd started: Ready to process
requests"
>>>>>> CGroup:
/system.slice/system-dirsrv.slice/dirsrv(a)EXAMPLE-COM.service
>>>>>> └─3134 /usr/sbin/ns-slapd -D
/etc/dirsrv/slapd-EXAMPLE-COM -i /var/run/dirsrv/slapd-EXAMPLE-COM.pid
>>>>>>
>>>>>> apr 17 15:13:54
linge.example.com ns-slapd[3134]: GSSAPI client
step 1
>>>>>> apr 17 15:13:54
linge.example.com ns-slapd[3134]: GSSAPI client
step 1
>>>>>> apr 17 15:13:54
linge.example.com ns-slapd[3134]: GSSAPI client
step 1
>>>>>> apr 17 15:13:54
linge.example.com ns-slapd[3134]: GSSAPI client
step 1
>>>>>> apr 17 15:13:54
linge.example.com ns-slapd[3134]: GSSAPI client
step 2
>>>>>> apr 17 15:18:54
linge.example.com ns-slapd[3134]: GSSAPI client
step 1
>>>>>> apr 17 15:18:54
linge.example.com ns-slapd[3134]: GSSAPI client
step 1
>>>>>> apr 17 15:18:55
linge.example.com ns-slapd[3134]: GSSAPI client
step 1
>>>>>> apr 17 15:18:55
linge.example.com ns-slapd[3134]: GSSAPI client
step 1
>>>>>> apr 17 15:18:55
linge.example.com ns-slapd[3134]: GSSAPI client
step 2
>>>>>>
>>>>>> However, an ldapsearch command hangs forever
>>>>>>
>>>>>> [root@rotte ~]# ldapsearch -H
ldaps://linge.example.com -D
uid=keesbtest,cn=users,cn=accounts,dc=example,dc=com -W -LLL -o ldif-wrap=no -b
cn=users,cn=accounts,dc=example,dc=com
'(&(objectClass=person)(memberOf=cn=admins,cn=groups,cn=accounts,dc=example,dc=com))'
uid
>>>>>> Enter LDAP Password:
>>>>>>
>>>>>> Even if I use the socket
(ldapi://%2fvar%2frun%2fslapd-EXAMPLE-COM.socket) the ldapsearch
>>>>>> command hangs.
>>>>>>
>>>>>> "ipactl status" hangs
>>>>>>
>>>>>> "kinit" hangs
>>>>>>
>>>>>>
>>>>> Hi,
>>>>> you can start by having a look at dirsrv error log in
>>>>> /var/log/dirsrv-slapd-YOUR_DOMAIN/errors, and the journal.
>>>>>
>>>>> The FAQ page of 389 also explains a few troubleshooting steps:
>>>>>
http://www.port389.org/docs/389ds/FAQ/faq.html#Troubleshooting
>>>> I did exactly that, look at the "errors" log, but there was no
clue, at least
>>>> not for me. Strange enough it kept running for a few hours and then it
>>>> was hanging again.
>>>>
>>>> I tried the command "ipctl restart", but that was hanging
forever.
>>>> However "systemctl restart dirsrv@MY-DOMAIN" was able to
restart
>>>> it after several minutes. Meanwhile the sn-slapd process was using 100%
>>>> CPU.
>>>>
>>>> Another remark I want to make. Every ldap connection (ldapsearch,
whatever)
>>>> hangs for ever. No timeout, nothing.
>>>>
>>>> When it rains, it pours, they say. There is another master with the same
symptom.
>>>> I'm getting nervous now.
>>>>
>>>> Thanks for the Troubleshooting link. I'll have to dive into the deep,
I guess.
>>> Could it be a deadlock?
>>>
>>> [root@linge ~]# grep -a1 '^#0.*lock' slapd-stacktrace.1587374239.txt
>>> Thread 23 (Thread 0x7ff8ff265700 (LWP 14474)):
>>> #0 0x00007ff929430144 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0
>>> #1 0x00007ff9190cc49c in map_rdlock () at
/usr/lib64/dirsrv/plugins/schemacompat-plugin.so
>>> --
>>> Thread 7 (Thread 0x7ff8f7255700 (LWP 14490)):
>>> #0 0x00007ff929430144 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0
>>> #1 0x00007ff9190cc49c in map_rdlock () at
/usr/lib64/dirsrv/plugins/schemacompat-plugin.so
>>> --
>>> Thread 4 (Thread 0x7ff8f5a52700 (LWP 14493)):
>>> #0 0x00007ff929430144 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0
>>> #1 0x00007ff9190cc49c in map_rdlock () at
/usr/lib64/dirsrv/plugins/schemacompat-plugin.so
>>> --
>>> Thread 2 (Thread 0x7ff92c355700 (LWP 15679)):
>>> #0 0x00007ff92943035e in pthread_rwlock_wrlock () at /lib64/libpthread.so.0
>>> #1 0x00007ff9190b6639 in backend_be_pre_write_cb () at
/usr/lib64/dirsrv/plugins/schemacompat-plugin.so
>>>
>>> Without debuginfo the trace of these threads look like this:
>>>
>>> Thread 23 (Thread 0x7ff8ff265700 (LWP 14474)):
>>> #0 0x00007ff929430144 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0
>>> #1 0x00007ff9190cc49c in map_rdlock () at
/usr/lib64/dirsrv/plugins/schemacompat-plugin.so
>>> #2 0x00007ff9190b8745 in backend_search_cb () at
/usr/lib64/dirsrv/plugins/schemacompat-plugin.so
>>> #3 0x00007ff92bcd9028 in plugin_call_func () at
/usr/lib64/dirsrv/libslapd.so.0
>>> #4 0x00007ff92bcd92e3 in plugin_call_plugins () at
/usr/lib64/dirsrv/libslapd.so.0
>>> #5 0x00007ff92bccc0d7 in op_shared_search () at
/usr/lib64/dirsrv/libslapd.so.0
>>> #6 0x0000562454427bbe in do_search ()
>>> #7 0x000056245441595a in connection_threadmain ()
>>> #8 0x00007ff929a8cc5b in _pt_root () at /lib64/libnspr4.so
>>> #9 0x00007ff92942ce65 in start_thread () at /lib64/libpthread.so.0
>>> #10 0x00007ff928ad888d in clone () at /lib64/libc.so.6
>>>
>>> Thread 7 (Thread 0x7ff8f7255700 (LWP 14490)):
>>> #0 0x00007ff929430144 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0
>>> #1 0x00007ff9190cc49c in map_rdlock () at
/usr/lib64/dirsrv/plugins/schemacompat-plugin.so
>>> #2 0x00007ff9190b8745 in backend_search_cb () at
/usr/lib64/dirsrv/plugins/schemacompat-plugin.so
>>> #3 0x00007ff92bcd9028 in plugin_call_func () at
/usr/lib64/dirsrv/libslapd.so.0
>>> #4 0x00007ff92bcd92e3 in plugin_call_plugins () at
/usr/lib64/dirsrv/libslapd.so.0
>>> #5 0x00007ff92bccc0d7 in op_shared_search () at
/usr/lib64/dirsrv/libslapd.so.0
>>> #6 0x0000562454427bbe in do_search ()
>>> #7 0x000056245441595a in connection_threadmain ()
>>> #8 0x00007ff929a8cc5b in _pt_root () at /lib64/libnspr4.so
>>> #9 0x00007ff92942ce65 in start_thread () at /lib64/libpthread.so.0
>>> #10 0x00007ff928ad888d in clone () at /lib64/libc.so.6
>>>
>>> Thread 4 (Thread 0x7ff8f5a52700 (LWP 14493)):
>>> #0 0x00007ff929430144 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0
>>> #1 0x00007ff9190cc49c in map_rdlock () at
/usr/lib64/dirsrv/plugins/schemacompat-plugin.so
>>> #2 0x00007ff9190b8745 in backend_search_cb () at
/usr/lib64/dirsrv/plugins/schemacompat-plugin.so
>>> #3 0x00007ff92bcd9028 in plugin_call_func () at
/usr/lib64/dirsrv/libslapd.so.0
>>> #4 0x00007ff92bcd92e3 in plugin_call_plugins () at
/usr/lib64/dirsrv/libslapd.so.0
>>> #5 0x00007ff92bccc0d7 in op_shared_search () at
/usr/lib64/dirsrv/libslapd.so.0
>>> #6 0x0000562454427bbe in do_search ()
>>> #7 0x000056245441595a in connection_threadmain ()
>>> #8 0x00007ff929a8cc5b in _pt_root () at /lib64/libnspr4.so
>>> #9 0x00007ff92942ce65 in start_thread () at /lib64/libpthread.so.0
>>> #10 0x00007ff928ad888d in clone () at /lib64/libc.so.6
>>>
>>> Thread 2 (Thread 0x7ff92c355700 (LWP 15679)):
>>> #0 0x00007ff92943035e in pthread_rwlock_wrlock () at /lib64/libpthread.so.0
>>> #1 0x00007ff9190b6639 in backend_be_pre_write_cb () at
/usr/lib64/dirsrv/plugins/schemacompat-plugin.so
>>> #2 0x00007ff92bcd9028 in plugin_call_func () at
/usr/lib64/dirsrv/libslapd.so.0
>>> #3 0x00007ff92bcd92e3 in plugin_call_plugins () at
/usr/lib64/dirsrv/libslapd.so.0
>>> #4 0x00007ff91b08ac88 in ldbm_back_delete () at
/usr/lib64/dirsrv/plugins/libback-ldbm.so
>>> #5 0x00007ff92bc89feb in op_shared_delete () at
/usr/lib64/dirsrv/libslapd.so.0
>>> #6 0x00007ff92bc8a1c8 in delete_internal_pb () at
/usr/lib64/dirsrv/libslapd.so.0
>>> #7 0x00007ff9196f131e in delete_changerecord () at
/usr/lib64/dirsrv/plugins/libretrocl-plugin.so
>>> #8 0x00007ff9196f1605 in changelog_trim_thread_fn () at
/usr/lib64/dirsrv/plugins/libretrocl-plugin.so
>>> #9 0x00007ff929a8cc5b in _pt_root () at /lib64/libnspr4.so
>>> #10 0x00007ff92942ce65 in start_thread () at /lib64/libpthread.so.0
>>> #11 0x00007ff928ad888d in clone () at /lib64/libc.so.6
>>>
>>> With the following (stripped) debuginfo you can see that it is hanging while
deleting
>>> a changerecord.
>>>
>>> Thread 2 (Thread 0x7ff92c355700 (LWP 15679)):
>>> #0 0x00007ff92943035e in pthread_rwlock_wrlock () at /lib64/libpthread.so.0
>>> #1 0x00007ff9190b6639 in backend_be_pre_write_cb () at
/usr/lib64/dirsrv/plugins/schemacompat-plugin.so
>>> #2 0x00007ff92bcd9028 in plugin_call_func (list=0x5624565a3340,
operation=operation@entry=453, pb=pb@entry=0x5624629c28
>>> 40, call_one=call_one@entry=0) at ldap/servers/slapd/plugin.c:2028
>>> n = <optimized out>
>>> func = 0x7ff9190b65a0 <backend_be_pre_write_cb>
>>> rc = <optimized out>
>>> return_value = 0
>>> count = 0
>>> #3 0x00007ff92bcd92e3 in plugin_call_list (pb=0x5624629c2840, operation=453,
list=<optimized out>) at ldap/servers/slap
>>> d/plugin.c:1972
>>> p = 0x5624564ea2c0
>>> locked = <optimized out>
>>> plugin_list_number = 3
>>> rc = 0
>>> do_op = <optimized out>
>>> #4 0x00007ff92bcd92e3 in plugin_call_plugins (pb=pb@entry=0x5624629c2840,
whichfunction=whichfunction@entry=453) at lda
>>> p/servers/slapd/plugin.c:442
>>> p = 0x5624564ea2c0
>>> locked = <optimized out>
>>> plugin_list_number = 3
>>> rc = 0
>>> do_op = <optimized out>
>>> #5 0x00007ff91b08ac88 in ldbm_back_delete (pb=0x5624629c2840) at
ldap/servers/slapd/back-ldbm/ldbm_delete.c:373
>>> be = 0x5624564fc000
>>> inst = 0x56245635c680
>>> li = 0x5624562d3a40
>>> e = 0x562462377810
>>> tombstone = 0x0
>>> original_tombstone = 0x0
>>> tmptombstone = 0x0
>>> dn = 0x56245d90fa70 "changenumber=879530,cn=changelog"
>>> txn = {back_txn_txn = 0x562459c2cc60}
>>> parent_txn = 0x0
>>> retval = 0
>>> msg = <optimized out>
>>> errbuf = 0x0
>>> retry_count = <optimized out>
>>> disk_full = 0
>>> parent_found = <optimized out>
>>> ruv_c_init = 0
>>> parent_modify_c = {old_entry = 0x0, new_entry = 0x0, smods = 0x0,
attr_encrypt = 0}
>>> ruv_c = {old_entry = 0x0, new_entry = 0x0, smods = 0x0, attr_encrypt
= 0}
>>> ...
>>>
>> What distribution are you using and what version of 389-ds?
>>
> Centos7
>
> [root@linge ~]# rpm -qa 389\*
> 389-ds-base-debuginfo-1.3.9.1-13.el7_7.x86_64
> 389-ds-base-libs-1.3.9.1-13.el7_7.x86_64
> 389-ds-base-1.3.9.1-13.el7_7.x86_64
>
> [root@linge ~]# rpm -qa centos-release
> centos-release-7-7.1908.0.el7.centos.x86_64
>
>
This is a known bug [1].
With the same bug there are two deadlock scenario but only one is fixed (for example in
slapi-nis-0.56.4-1 [2]).
A fix for the second one is under tests.
At the moment I would recommend the workaround [3]. The drawback is a growth of the
retroCL database but unless you have a very high rate of update it should not be a
concern.
[1]
https://bugzilla.redhat.com/show_bug.cgi?id=1751295
[2]
https://koji.fedoraproject.org/koji/buildinfo?buildID=1457771
[3]
https://bugzilla.redhat.com/show_bug.cgi?id=1751295#c5
OK, thanks for the help. I will try that.
Two remarks.
1) I did an update a few days ago. (1.3.8.4-18.el7_6 => 1.3.9.1-13.el7_7). Then two
days after the update this hang started to happen.
2) the nasty thing about this is, that 398-ds was still alive, but all connections to it
hang forever (even "ipactl restart")
--
Kees