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@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@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.

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@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@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?

rob

On 4/20/20 3:02 PM, Kees Bakker wrote:

On 20-04-2020 14:51, Rob Crittenden wrote:

...

*** EXTERNAL E-MAIL ***

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@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@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

best regards thierry

On 20-04-2020 15:35, Kees Bakker via FreeIPA-users wrote:

On 20-04-2020 15:16, thierry bordaz wrote:

...

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@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@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")

Current setting... 2d, what a coincidence, ha ha

dn: cn=Retro Changelog Plugin,cn=plugins,cn=config cn: Retro Changelog Plugin nsslapd-changelogmaxage: 2d

Sorry to revive an old thread. I'm getting deadlocks again. See below

On 20-04-2020 15:16, thierry bordaz wrote:

[...]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

best regards thierry

I followed the recommendation to set nsslapd-changelogmaxage to -1. The system has been running successfully for a year.

Recently I upgraded all packages in this CentOS7 system. Ever since that moment the server is quite unusable.

[root@linge ~]# gdb -ex 'set confirm off' -ex 'set pagination off' -ex 'thread apply all bt full' -ex 'quit' /usr/sbin/ns-slapd `pidof ns-slapd` |& grep '^#0.*lock' #0  0x00007f96eaf3939e in pthread_rwlock_wrlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf3939e in pthread_rwlock_wrlock () at /lib64/libpthread.so.0

[root@linge ~]# rpm -qa 389* 389-ds-base-libs-1.3.10.2-10.el7_9.x86_64 389-ds-base-1.3.10.2-10.el7_9.x86_64 389-ds-base-debuginfo-1.3.10.2-10.el7_9.x86_64

[root@linge ~]# rpm -qa slapi* slapi-nis-0.56.5-3.el7_9.x86_64

[root@linge ~]# rpm -qa centos-release centos-release-7-9.2009.1.el7.centos.x86_64

Are there any new hints to avoid the deadlock?

Hi Thierry,

Just to be clear, changelogmaxage was changed to -1 by me after the upgrade and I've confirmed it is now set to -1.

The reason for me to change the value was because of the deadlock. Apparently, it did not make much of a difference. It still gets into a deadlock with the value -1.

BTW. I've sent the whole stacktrace directly to you to avoid the 4000+ lines to this mailing list.

Here is the stack trace of one of the threads. The one that hangs in trim_changelog

Thread 2 (Thread 0x7f96ede68700 (LWP 2151)): #0  0x00007f96eaf3939e in pthread_rwlock_wrlock () at /lib64/libpthread.so.0 #1  0x00007f96da9d281f in map_wrlock () at /usr/lib64/dirsrv/plugins/schemacompat-plugin.so #2  0x00007f96da9c1e58 in backend_shr_delete_cb.part.5 () at /usr/lib64/dirsrv/plugins/schemacompat-plugin.so #3  0x00007f96da9c1fd1 in backend_shr_betxn_post_delete_cb () at /usr/lib64/dirsrv/plugins/schemacompat-plugin.so #4  0x00007f96ed7ec688 in plugin_call_func (list=0x55cb03cdd8c0, operation=operation@entry=563, pb=pb@entry=0x55cb4c670fc0, call_one=call_one@entry=0) at ldap/servers/slapd/plugin.c:2028         n = <optimized out>         func = 0x7f96da9c1f70 <backend_shr_betxn_post_delete_cb>         rc = <optimized out>         return_value = 0         count = 2 #5  0x00007f96ed7ec943 in plugin_call_list (pb=0x55cb4c670fc0, operation=563, list=<optimized out>) at ldap/servers/slapd/plugin.c:1972         p = 0x55cb03cb0000         locked = <optimized out>         plugin_list_number = 21         rc = 0         do_op = <optimized out> #6  0x00007f96ed7ec943 in plugin_call_plugins (pb=pb@entry=0x55cb4c670fc0, whichfunction=whichfunction@entry=563) at ldap/servers/slapd/plugin.c:442         p = 0x55cb03cb0000         locked = <optimized out>         plugin_list_number = 21         rc = 0         do_op = <optimized out> #7  0x00007f96dc990def in ldbm_back_delete (pb=0x55cb4c670fc0) at ldap/servers/slapd/back-ldbm/ldbm_delete.c:1267         be = 0x55cb03c31040         inst = 0x55cb03a8c680         li = 0x55cb03a017c0         e = 0x55cb15499a40         tombstone = 0x0         original_tombstone = 0x0         tmptombstone = 0x0         dn = 0x55cb1742a600 "changenumber=891343,cn=changelog"         txn = {back_txn_txn = 0x55cb2b7b6dc0}         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 = 0x55cb159982a0, new_entry = 0x55cb19e03030, smods = 0x55cb47da1ae0, attr_encrypt = 1}         ruv_c = {old_entry = 0x0, new_entry = 0x0, smods = 0x0, attr_encrypt = 0}         rc = 0         ldap_result_code = 0         ldap_result_message = 0x0         sdnp = 0x55cb5fd93bc0         e_uniqueid = 0x0         nscpEntrySDN = {flag = 0 '\000', udn = 0x0, dn = 0x0, ndn = 0x0, ndn_len = 0}         operation = 0x55cb5ef86000         opcsn = 0x0         is_fixup_operation = 0         is_ruv = 0         is_replicated_operation = 0         is_tombstone_entry = <optimized out>         delete_tombstone_entry = 0         create_tombstone_entry = 0         addr = 0x55cb5ef86100         addordel_flags = 38         entryusn_str = 0x0         orig_entry = 0x0         parentsdn = {flag = 2 '\002', udn = 0x0, dn = 0x55cb516c3580 "cn=changelog", ndn = 0x0, ndn_len = 12}         opreturn = 0         free_delete_existing_entry = 1         not_an_error = 0         parent_switched = 0         myrc = 0         conn_id = 0         tombstone_csn = <optimized out>         deletion_csn_str = "\247\001\000\000\000\000\000\000\000T\334YHi\365\357\300\017g", <incomplete sequence \313>         op_id = 0         ep_id = <optimized out>         tomb_ep_id = 0         result_sent = 0         pb_conn = 0x0         parent_op = 1         parent_time = {tv_sec = 183860, tv_nsec = 41743941} #8  0x00007f96ed79d3bb in op_shared_delete (pb=pb@entry=0x55cb4c670fc0) at ldap/servers/slapd/delete.c:324         rc = 0         rawdn = 0x55cb5b28de00 "changenumber=891343, cn=changelog"         dn = <optimized out>         be = 0x55cb03c31040         internal_op = 32         sdn = 0x55cb5fd93bc0         operation = 0x55cb5ef86000         referral = 0x0         ecopy = 0x0         errorbuf = "\000\066\062\062Z\nmodifyTime", '\000' <repeats 16 times>, "\071\063\066\062\062Z\nnsUniqueI", '\000' <repeats 16 times>, "\327\320~\003ڇ\316c!\f=\037$z\215\301;\215\006\065\341\n\310V\300\006\365I\344|x\210\216\f\215\060e\243S\350\000T\334YHi\365\357\016\237V\202\332PG\347\300\070\314\003\313U\000\000\300\070\314\003\313U\000\000\000T\334YHi\365\357\000\000\000\000\000\000\000\000\300\070\314\003\313U\000\000\300\070\314\003\313U\000\000\240<\250\355\226\177\000\000\000\243\002\000\000\000\000\000p|\346\355\226\177\000\000ϙ\r\000\000\000\000\000\312\360"...         err = <optimized out>         proxydn = 0x0         proxystr = 0x0         proxy_err = <optimized out>         errtext = 0x0 #9  0x00007f96ed79d598 in delete_internal_pb (pb=pb@entry=0x55cb4c670fc0) at ldap/servers/slapd/delete.c:208         controls = 0x0         op = 0x55cb5ef86000         opresult = 0 #10 0x00007f96ed79d813 in slapi_delete_internal_pb (pb=pb@entry=0x55cb4c670fc0) at ldap/servers/slapd/delete.c:151 #11 0x00007f96daff731e in delete_changerecord (cnum=cnum@entry=891343) at ldap/servers/plugins/retrocl/retrocl_trim.c:89         pb = 0x55cb4c670fc0         dnbuf = 0x55cb5b28de00 "changenumber=891343, cn=changelog"         delrc = 32662 #12 0x00007f96daff7605 in trim_changelog () at ldap/servers/plugins/retrocl/retrocl_trim.c:290         did_delete = 0         done = 0         last_in_log = <optimized out>         me = 172800         lt = <optimized out>         ldrc = <optimized out>         now = 1620819600         first_in_log = 891343         num_deleted = 3655 #13 0x00007f96daff7605 in changelog_trim_thread_fn (arg=<optimized out>) at ldap/servers/plugins/retrocl/retrocl_trim.c:333 #14 0x00007f96eb595c5b in _pt_root () at /lib64/libnspr4.so #15 0x00007f96eaf35ea5 in start_thread () at /lib64/libpthread.so.0 #16 0x00007f96ea5e19fd in clone () at /lib64/libc.so.6

-- Kees

On 12-05-2021 15:49, Thierry Bordaz wrote:

Hi Kees,

Is changelogmaxage=-1 after the upgrade ?

would you send a full pstack when it hangs ? If pthread_rwlock_wrlock is trim_changelog then you may hit another flavor of [1] (without known reason).

regards thierry

On 5/12/21 2:40 PM, Kees Bakker wrote:

...

Sorry to revive an old thread. I'm getting deadlocks again. See below

On 20-04-2020 15:16, thierry bordaz wrote:

...

[...]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

best regards thierry

I followed the recommendation to set nsslapd-changelogmaxage to -1. The system has been running successfully for a year.

Recently I upgraded all packages in this CentOS7 system. Ever since that moment the server is quite unusable.

[root@linge ~]# gdb -ex 'set confirm off' -ex 'set pagination off' -ex 'thread apply all bt full' -ex 'quit' /usr/sbin/ns-slapd `pidof ns-slapd` |& grep '^#0.*lock' #0  0x00007f96eaf3939e in pthread_rwlock_wrlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf3939e in pthread_rwlock_wrlock () at /lib64/libpthread.so.0

[root@linge ~]# rpm -qa 389* 389-ds-base-libs-1.3.10.2-10.el7_9.x86_64 389-ds-base-1.3.10.2-10.el7_9.x86_64 389-ds-base-debuginfo-1.3.10.2-10.el7_9.x86_64

[root@linge ~]# rpm -qa slapi* slapi-nis-0.56.5-3.el7_9.x86_64

[root@linge ~]# rpm -qa centos-release centos-release-7-9.2009.1.el7.centos.x86_64

Are there any new hints to avoid the deadlock?

On 12-05-2021 19:44, Thierry Bordaz wrote:

On 5/12/21 4:55 PM, Kees Bakker wrote:

...

Hi Thierry,

Just to be clear, changelogmaxage was changed to -1 by me after the upgrade and I've confirmed it is now set to -1.

The reason for me to change the value was because of the deadlock. Apparently, it did not make much of a difference. It still gets into a deadlock with the value -1.

Did you set nsslapd-changelogmaxage=-1 in the retroCL config entry ?

I've used this input file for ldapmodify

[root@linge ~]# cat change-nsslapd-changelogmaxage.txt dn: cn=Retro Changelog Plugin,cn=plugins,cn=config changetype: modify replace: nsslapd-changelogmaxage nsslapd-changelogmaxage: -1

After that

[root@linge ~]# ldapsearch -H ldapi://%2fvar%2frun%2fslapd-GHS-NL.socket -LLL -o ldif-wrap=no -b 'cn=Retro Changelog Plugin,cn=plugins,cn=config' SASL/EXTERNAL authentication started SASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth SASL SSF: 0 dn: cn=Retro Changelog Plugin,cn=plugins,cn=config cn: Retro Changelog Plugin nsslapd-attribute: nsuniqueid:targetUniqueId nsslapd-changelogmaxage: -1 nsslapd-include-suffix: cn=dns,dc=ghs,dc=nl nsslapd-plugin-depends-on-named: Class of Service nsslapd-plugin-depends-on-type: database nsslapd-pluginDescription: Retrocl Plugin nsslapd-pluginEnabled: on nsslapd-pluginId: retrocl nsslapd-pluginInitfunc: retrocl_plugin_init nsslapd-pluginPath: libretrocl-plugin nsslapd-pluginType: object nsslapd-pluginVendor: 389 Project nsslapd-pluginVersion: 1.3.10.2 nsslapd-pluginbetxn: on nsslapd-pluginprecedence: 25 objectClass: top objectClass: nsSlapdPlugin objectClass: extensibleObject

...

BTW. I've sent the whole stacktrace directly to you to avoid the 4000+ lines to this mailing list.

Here is the stack trace of one of the threads. The one that hangs in trim_changelog

Something weird is that the same hang occurs https://bugzilla.redhat.com/show_bug.cgi?id=1751295. If I am correct it is between thread 14th and 2nd.

As you are running with a fixed version (> slapi-nis-0.56.5), that means the fix is incomplete. It would require to debug a dump core to know why the fix fails.

[root@linge ~]# rpm -qa slapi* slapi-nis-0.56.5-3.el7_9.x86_64

So, that is not > 0.56.5, but it is the newest available for CentOS7. No?

At the moment I killed it and restarted. No deadlock yet, but the system is extreemly slow. And there is just ns-slapd using CPU cycles.

regards thierry

...

Thread 2 (Thread 0x7f96ede68700 (LWP 2151)): #0  0x00007f96eaf3939e in pthread_rwlock_wrlock () at /lib64/libpthread.so.0 #1  0x00007f96da9d281f in map_wrlock () at /usr/lib64/dirsrv/plugins/schemacompat-plugin.so #2  0x00007f96da9c1e58 in backend_shr_delete_cb.part.5 () at /usr/lib64/dirsrv/plugins/schemacompat-plugin.so #3  0x00007f96da9c1fd1 in backend_shr_betxn_post_delete_cb () at /usr/lib64/dirsrv/plugins/schemacompat-plugin.so #4  0x00007f96ed7ec688 in plugin_call_func (list=0x55cb03cdd8c0, operation=operation@entry=563, pb=pb@entry=0x55cb4c670fc0, call_one=call_one@entry=0) at ldap/servers/slapd/plugin.c:2028         n = <optimized out>         func = 0x7f96da9c1f70 <backend_shr_betxn_post_delete_cb>         rc = <optimized out>         return_value = 0         count = 2 #5  0x00007f96ed7ec943 in plugin_call_list (pb=0x55cb4c670fc0, operation=563, list=<optimized out>) at ldap/servers/slapd/plugin.c:1972         p = 0x55cb03cb0000         locked = <optimized out>         plugin_list_number = 21         rc = 0         do_op = <optimized out> #6  0x00007f96ed7ec943 in plugin_call_plugins (pb=pb@entry=0x55cb4c670fc0, whichfunction=whichfunction@entry=563) at ldap/servers/slapd/plugin.c:442         p = 0x55cb03cb0000         locked = <optimized out>         plugin_list_number = 21         rc = 0         do_op = <optimized out> #7  0x00007f96dc990def in ldbm_back_delete (pb=0x55cb4c670fc0) at ldap/servers/slapd/back-ldbm/ldbm_delete.c:1267         be = 0x55cb03c31040         inst = 0x55cb03a8c680         li = 0x55cb03a017c0         e = 0x55cb15499a40         tombstone = 0x0         original_tombstone = 0x0         tmptombstone = 0x0         dn = 0x55cb1742a600 "changenumber=891343,cn=changelog"         txn = {back_txn_txn = 0x55cb2b7b6dc0}         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 = 0x55cb159982a0, new_entry = 0x55cb19e03030, smods = 0x55cb47da1ae0, attr_encrypt = 1}         ruv_c = {old_entry = 0x0, new_entry = 0x0, smods = 0x0, attr_encrypt = 0}         rc = 0         ldap_result_code = 0         ldap_result_message = 0x0         sdnp = 0x55cb5fd93bc0         e_uniqueid = 0x0         nscpEntrySDN = {flag = 0 '\000', udn = 0x0, dn = 0x0, ndn = 0x0, ndn_len = 0}         operation = 0x55cb5ef86000         opcsn = 0x0         is_fixup_operation = 0         is_ruv = 0         is_replicated_operation = 0         is_tombstone_entry = <optimized out>         delete_tombstone_entry = 0         create_tombstone_entry = 0         addr = 0x55cb5ef86100         addordel_flags = 38         entryusn_str = 0x0         orig_entry = 0x0         parentsdn = {flag = 2 '\002', udn = 0x0, dn = 0x55cb516c3580 "cn=changelog", ndn = 0x0, ndn_len = 12}         opreturn = 0         free_delete_existing_entry = 1         not_an_error = 0         parent_switched = 0         myrc = 0         conn_id = 0         tombstone_csn = <optimized out>         deletion_csn_str = "\247\001\000\000\000\000\000\000\000T\334YHi\365\357\300\017g", <incomplete sequence \313>         op_id = 0         ep_id = <optimized out>         tomb_ep_id = 0         result_sent = 0         pb_conn = 0x0         parent_op = 1         parent_time = {tv_sec = 183860, tv_nsec = 41743941} #8  0x00007f96ed79d3bb in op_shared_delete (pb=pb@entry=0x55cb4c670fc0) at ldap/servers/slapd/delete.c:324         rc = 0         rawdn = 0x55cb5b28de00 "changenumber=891343, cn=changelog"         dn = <optimized out>         be = 0x55cb03c31040         internal_op = 32         sdn = 0x55cb5fd93bc0         operation = 0x55cb5ef86000         referral = 0x0         ecopy = 0x0         errorbuf = "\000\066\062\062Z\nmodifyTime", '\000' <repeats 16 times>, "\071\063\066\062\062Z\nnsUniqueI", '\000' <repeats 16 times>, "\327\320~\003ڇ\316c!\f=\037$z\215\301;\215\006\065\341\n\310V\300\006\365I\344|x\210\216\f\215\060e\243S\350\000T\334YHi\365\357\016\237V\202\332PG\347\300\070\314\003\313U\000\000\300\070\314\003\313U\000\000\000T\334YHi\365\357\000\000\000\000\000\000\000\000\300\070\314\003\313U\000\000\300\070\314\003\313U\000\000\240<\250\355\226\177\000\000\000\243\002\000\000\000\000\000p|\346\355\226\177\000\000ϙ\r\000\000\000\000\000\312\360"...         err = <optimized out>         proxydn = 0x0         proxystr = 0x0         proxy_err = <optimized out>         errtext = 0x0 #9  0x00007f96ed79d598 in delete_internal_pb (pb=pb@entry=0x55cb4c670fc0) at ldap/servers/slapd/delete.c:208         controls = 0x0         op = 0x55cb5ef86000         opresult = 0 #10 0x00007f96ed79d813 in slapi_delete_internal_pb (pb=pb@entry=0x55cb4c670fc0) at ldap/servers/slapd/delete.c:151 #11 0x00007f96daff731e in delete_changerecord (cnum=cnum@entry=891343) at ldap/servers/plugins/retrocl/retrocl_trim.c:89         pb = 0x55cb4c670fc0         dnbuf = 0x55cb5b28de00 "changenumber=891343, cn=changelog"         delrc = 32662 #12 0x00007f96daff7605 in trim_changelog () at ldap/servers/plugins/retrocl/retrocl_trim.c:290         did_delete = 0         done = 0         last_in_log = <optimized out>         me = 172800         lt = <optimized out>         ldrc = <optimized out>         now = 1620819600         first_in_log = 891343         num_deleted = 3655 #13 0x00007f96daff7605 in changelog_trim_thread_fn (arg=<optimized out>) at ldap/servers/plugins/retrocl/retrocl_trim.c:333 #14 0x00007f96eb595c5b in _pt_root () at /lib64/libnspr4.so #15 0x00007f96eaf35ea5 in start_thread () at /lib64/libpthread.so.0 #16 0x00007f96ea5e19fd in clone () at /lib64/libc.so.6

-- Kees

On 12-05-2021 15:49, Thierry Bordaz wrote:

...

Hi Kees,

Is changelogmaxage=-1 after the upgrade ?

would you send a full pstack when it hangs ? If pthread_rwlock_wrlock is trim_changelog then you may hit another flavor of [1] (without known reason).

regards thierry

On 5/12/21 2:40 PM, Kees Bakker wrote:

...

Sorry to revive an old thread. I'm getting deadlocks again. See below

On 20-04-2020 15:16, thierry bordaz wrote:

...

[...]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

best regards thierry

I followed the recommendation to set nsslapd-changelogmaxage to -1. The system has been running successfully for a year.

Recently I upgraded all packages in this CentOS7 system. Ever since that moment the server is quite unusable.

[root@linge ~]# gdb -ex 'set confirm off' -ex 'set pagination off' -ex 'thread apply all bt full' -ex 'quit' /usr/sbin/ns-slapd `pidof ns-slapd` |& grep '^#0.*lock' #0  0x00007f96eaf3939e in pthread_rwlock_wrlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf39184 in pthread_rwlock_rdlock () at /lib64/libpthread.so.0 #0  0x00007f96eaf3939e in pthread_rwlock_wrlock () at /lib64/libpthread.so.0

[root@linge ~]# rpm -qa 389* 389-ds-base-libs-1.3.10.2-10.el7_9.x86_64 389-ds-base-1.3.10.2-10.el7_9.x86_64 389-ds-base-debuginfo-1.3.10.2-10.el7_9.x86_64

[root@linge ~]# rpm -qa slapi* slapi-nis-0.56.5-3.el7_9.x86_64

[root@linge ~]# rpm -qa centos-release centos-release-7-9.2009.1.el7.centos.x86_64

Are there any new hints to avoid the deadlock?

On 13-05-2021 08:32, Thierry Bordaz wrote:

On 5/12/21 8:41 PM, Kees Bakker wrote:

...

On 12-05-2021 19:44, Thierry Bordaz wrote:

...

On 5/12/21 4:55 PM, Kees Bakker wrote:

...

Hi Thierry,

Just to be clear, changelogmaxage was changed to -1 by me after the upgrade and I've confirmed it is now set to -1.

The reason for me to change the value was because of the deadlock. Apparently, it did not make much of a difference. It still gets into a deadlock with the value -1.

Did you set nsslapd-changelogmaxage=-1 in the retroCL config entry ?

I've used this input file for ldapmodify

[root@linge ~]# cat change-nsslapd-changelogmaxage.txt dn: cn=Retro Changelog Plugin,cn=plugins,cn=config changetype: modify replace: nsslapd-changelogmaxage nsslapd-changelogmaxage: -1

After that

[root@linge ~]# ldapsearch -H ldapi://%2fvar%2frun%2fslapd-GHS-NL.socket -LLL -o ldif-wrap=no -b 'cn=Retro Changelog Plugin,cn=plugins,cn=config' SASL/EXTERNAL authentication started SASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth SASL SSF: 0 dn: cn=Retro Changelog Plugin,cn=plugins,cn=config cn: Retro Changelog Plugin nsslapd-attribute: nsuniqueid:targetUniqueId nsslapd-changelogmaxage: -1 nsslapd-include-suffix: cn=dns,dc=ghs,dc=nl nsslapd-plugin-depends-on-named: Class of Service nsslapd-plugin-depends-on-type: database nsslapd-pluginDescription: Retrocl Plugin nsslapd-pluginEnabled: on nsslapd-pluginId: retrocl nsslapd-pluginInitfunc: retrocl_plugin_init nsslapd-pluginPath: libretrocl-plugin nsslapd-pluginType: object nsslapd-pluginVendor: 389 Project nsslapd-pluginVersion: 1.3.10.2 nsslapd-pluginbetxn: on nsslapd-pluginprecedence: 25 objectClass: top objectClass: nsSlapdPlugin objectClass: extensibleObject

You did the right setting. I do not understand why thread 2 is trimming records with that setting.

...

...

...

BTW. I've sent the whole stacktrace directly to you to avoid the 4000+ lines to this mailing list.

Here is the stack trace of one of the threads. The one that hangs in trim_changelog

Something weird is that the same hang occurs https://bugzilla.redhat.com/show_bug.cgi?id=1751295. If I am correct it is between thread 14th and 2nd.

As you are running with a fixed version (> slapi-nis-0.56.5), that means the fix is incomplete. It would require to debug a dump core to know why the fix fails.

[root@linge ~]# rpm -qa slapi* slapi-nis-0.56.5-3.el7_9.x86_64

So, that is not > 0.56.5, but it is the newest available for CentOS7. No?

reading the 'fixed version' in the bug says it if fixed starting 0.56.5

I do not know if it match centOS7 versions

...

At the moment I killed it and restarted. No deadlock yet, but the system is extreemly slow. And there is just ns-slapd using CPU cycles.

Would you give some precision what is slow ? (response time, replication time,..)

If it is eating CPU, I would recommend 'top -H -p <pid> -b'. If it is always the same thread(s) eating the CPU, a pstack will tell you what it/they is/are doing. If this is various different threads likely it is due to processed requests.

I don't know what numbers to give to show the slowness. The load of the system is almost 4, while the other master (identical system) has a load of almost zero. (And the latter is used as the main LDAP server)

Right now thread 2 and thread 43 are the most active ones. Here are their stacktraces.

Thread 43 (Thread 0x7f4baa1d0700 (LWP 3583)): #0  0x00007f4bcc200a33 in select () at /lib64/libc.so.6 #1  0x00007f4bcf44ab09 in DS_Sleep (ticks=ticks@entry=250) at ldap/servers/slapd/util.c:1086         mSecs = <optimized out>         tm = {tv_sec = 0, tv_usec = 26398} #2  0x00007f4bbe587f77 in trickle_threadmain (param=<optimized out>) at ldap/servers/slapd/back-ldbm/dblayer.c:4551         interval = 250         rval = <optimized out>         priv = 0x55f87ff28b00         li = <optimized out>         debug_checkpointing = 0 #3  0x00007f4bcd1bdc5b in _pt_root () at /lib64/libnspr4.so #4  0x00007f4bccb5dea5 in start_thread () at /lib64/libpthread.so.0 #5  0x00007f4bcc2099fd in clone () at /lib64/libc.so.6

Thread 2 (Thread 0x7f4b93d39700 (LWP 15086)): #0  0x00007f4bce211ef5 in tc_malloc () at /lib64/libtcmalloc.so.4 #1  0x00007f4bcf3c15a3 in slapi_ch_malloc (size=35) at ldap/servers/slapd/ch_malloc.c:95         newmem = <optimized out> #2  0x00007f4bc57809d8 in __os_umalloc () at /lib64/libdb-5.3.so #3  0x00007f4bc5742136 in __db_retcopy () at /lib64/libdb-5.3.so #4  0x00007f4bc571a2b3 in __dbc_iget () at /lib64/libdb-5.3.so #5  0x00007f4bc5728cb2 in __dbc_get_pp () at /lib64/libdb-5.3.so #6  0x00007f4bbe5c1953 in entryrdn_lookup_dn (be=be@entry=0x55f8801ef040, rdn=<optimized out>, id=id@entry=2092284, dn=dn@entry=0x7f4b93d34188, psrdn=psrdn@entry=0x7f4b93d34190, txn=txn@entry=0x7f4b93d342d0) at ldap/servers/slapd/back-ldbm/ldbm_entryrdn.c:1188         rc = <optimized out>         ai = 0x55f880232540         db = 0x55f881edaa00         cursor = 0x55f881efe240         db_txn = 0x0         key = {data = 0x55f9026082a0, size = 9, ulen = 9, dlen = 0, doff = 0, app_data = 0x0, flags = 2056}         data = {data = 0x0, size = 0, ulen = 0, dlen = 0, doff = 0, app_data = 0x0, flags = 16}         keybuf = 0x55f9026082a0 "P2092284"         srdn = 0x55f8b9b11500         orignrdn = 0x0         nrdn = 0x55f93b909f80 "changenumber=2092283"         nrdn_len = 20         workid = 2092284         elem = <optimized out>         maybesuffix = 0         db_retry = <optimized out> #7  0x00007f4bbe5929e7 in id2entry (be=<optimized out>, id=id@entry=2092284, txn=txn@entry=0x7f4b93d342d0, err=err@entry=0x7f4b93d342c4) at ldap/servers/slapd/back-ldbm/id2entry.c:346         sdn = 0x0         normdn = 0x0         srdn = 0x0         bdn = 0x0         rdn = 0x55f93efd4f40 "changenumber=2092283"         rc = <optimized out>         inst = 0x55f88004a680         db = 0x55f881ed8600         db_txn = <optimized out>         key = {data = 0x7f4b93d34200, size = 4, ulen = 0, dlen = 0, doff = 0, app_data = 0x0, flags = 0}         data = {data = 0x55f92c680000, size = 985, ulen = 0, dlen = 0, doff = 0, app_data = 0x0, flags = 16}         e = 0x0         ee = <optimized out>         temp_id = "\000\037\354", <incomplete sequence \374> #8  0x00007f4bbe5ceb72 in ldbm_back_next_search_entry_ext (pb=0x55f95513cd80, use_extension=0) at ldap/servers/slapd/back-ldbm/ldbm_search.c:1627         be = 0x55f8801ef040         inst = 0x55f88004a680         li = 0x55f87ffbf7c0         scope = 2         managedsait = 0         attr = 0x0         filter = 0x55f8a42e8300         sr = 0x55f9557687c0         id = 2092284         e = 0x55f88b819960         nentries = 399583         expire_time = {tv_sec = 0, tv_nsec = 0}         tlimit = -1         llimit = -1         slimit = -1         isroot = 1         urls = 0x0         err = 0         basesdn = 0x55f8e973bbc0         target_uniqueid = 0x0         rc = 0         estimate = 0         txn = {back_txn_txn = 0x0}         pr_idx = -1         conn = 0x0         op = 0x55f8a2ce14a0         reverse_list = 0 #9  0x00007f4bcf405ff6 in iterate (send_result=1, be=0x55f8801ef040, pr_statp=0x7f4b93d344f4, pagesize=<optimized out>, pnentries=0x7f4b93d34588, pb=0x55f95513cd80) at ldap/servers/slapd/opshared.c:1292         ger_template_entry = 0x0         operation = 0x55f8a2ce14a0         done = 0         e = 0x55f8a82c0180         pr_stat = 0         pr_idx = -1         rc = <optimized out>         rval = 1         attrsonly = 0         attrs = 0x0         be = 0x55f8801ef040         rc = <optimized out> #10 0x00007f4bcf405ff6 in send_results_ext (pb=pb@entry=0x55f95513cd80, nentries=nentries@entry=0x7f4b93d34588, pagesize=-1, pr_stat=pr_stat@entry=0x7f4b93d344f4, send_result=1) at ldap/servers/slapd/opshared.c:1645         be = 0x55f8801ef040         rc = <optimized out> #11 0x00007f4bcf408159 in op_shared_search (pb=pb@entry=0x55f95513cd80, send_result=send_result@entry=1) at ldap/servers/slapd/opshared.c:847         be_suffix = <optimized out>         err = 0         next_be = 0x0         base = 0x7f4bc394e4e2 "cn=changelog"         normbase = <optimized out>         fstr = 0x55f8904cc540 "(&(changenumber>=-1)(targetuniqueid=1e89eb86-e20111e8-8820f96e-fc0c60a4))"         scope = 2         be = 0x55f8801ef040         be_single = 0x0         be_list = {0x55f8801ef040, 0x0, 0x0, 0x0, 0x55f8801da740, 0x55f800000001, 0x55f900000000, 0x0 <repeats 994 times>}         referral_list = {0x0 <repeats 611 times>, 0x7f4bcdd788e3 <ber_sockbuf_ctrl+387>, 0x0, 0x0, 0x0, 0x0, 0x0, 0x7f4bcdd788e3 <ber_sockbuf_ctrl+387>, 0x0 <repeats 186 times>, 0x61e7bfe702042a36, 0x40658d47b4a41ce1, 0xad61e3a2024df476, 0xde7dadc70e0b5fd8, 0xf73159a52a48ea2c, 0x4f70cb70764a2fab, 0x674523017f57e936, 0x98badcfeefcdab89, 0xc3d2e1f010325476, 0x7f4b93d37f50, 0x683f974357510ca2, 0x559e6a9b5a8a133, 0xce1fa8c242f162a9, 0xa6643132814dc94e, 0xadde7596feaa7041, 0xca0e6a6d6158d8b, 0xeb6b73d137578f64, 0x5a6da1000aeb278e, 0x24faa792f298903b, 0xf1b60146abc162e4, 0xf55006a5ea03353b, 0x7f4b93d37f50, 0x6e2c2f26e077f9de, 0x71a715d3942421dd, 0x8000000058200514, 0x0, 0x0, 0x0, 0x0, 0x2a000000000, 0x0, 0xa12a74c04e49e800, 0x0, 0x7f4b93d37f50, 0x2, 0x7f4b93d38020, 0x7f4b93d380e0, 0x2, 0x55f9217d5e00, 0x7f4bcee55d9d <k5_sha1_hash+125>, 0xfea223f37bbd812, 0xf8ec1ab4f83d9a2b, 0x2a0e21f8c65, 0xe077f9de00000000, 0x942421dd6e2c2f26, 0x5820051471a715d3, 0x80000000, 0x0, 0x0, 0x0, 0x0, 0x2a0, 0xfffffffffffffffe, 0xa12a74c04e49e800, 0x7f4bcf07fd60, 0x55f9038e6620, 0x55f8a467c400, 0x55f8cb6cc1e0, 0x0, 0x7f4bcee713e2 <krb5int_hmac_keyblock+418>, 0x40, 0x7f4b93d38170, 0x7f4b93d380e0, 0x5, 0x14970ea702, 0x55f9038e6620, 0x2, 0x40970ea702, 0x55f9217d5e00, 0x1d99616e00000002, 0x14970ea702, 0x55f9038e6620, 0x14, 0xa12a74c04e49e800, 0x20, 0x4, 0x7f4b93d38170, 0xa12a74c04e49e800, 0x4, 0x7f4b93d38170, 0x7f4bcf07ff00 <krb5int_enc_aes256>, 0x7f4bcee6a8f6 <krb5int_dk_decrypt+406>, 0x20, 0xc00000003, 0x55f90dde5e30, 0x7f4b93d380e0, 0x55f9038e6ca0, 0x0, 0x55f8cb6cd3e0, 0x55f8cb6cc1e0, 0x1400000000, 0x55f9038e6ca0, 0x5516000000, 0xa12a74c04e49e800, 0x20, 0x7f4bcf080b00, 0x1e, 0x7f4b93d38290, 0x41ed982026117e4f, 0xb3c887fe91a43017, 0x720d385d3bc2cd56, 0x50a61fb007a7a9ca, 0xa5d3e14dc70e09bd, 0xb6ead04df0228653, 0x674523017e49db9f, 0x98badcfeefcdab89, 0xc3d2e1f010325476, 0x7f4b93d38260, 0x7234e4c832eb2e6b, 0xbab56daaa29a3c86, 0xfda5dc82799faefa, 0x7b24e8909274e0fa, 0xe1bbebd5d6ad6668, 0x6e8fa927ce38a9b, 0x816585922b509df, 0xd2e805e35f84d38d, 0xdf7f8b184e7dfaca, 0x59585d6f1926cba8, 0x59d1d26715819ef8, 0x7f4b93d38260, 0x80a891fe5f5cfd30, 0x705ca35758499ae9, 0x80000000c5f084c6, 0x0, 0x0, 0x0, 0x0, 0x2a000000000, 0x7f4b93d38320, 0xa12a74c04e49e800, 0x55f977b74fc0, 0x7f4b93d38260, 0x2, 0x7f4b93d38330, 0x7f4b93d38400, 0x2, 0x55f94e35f680, 0xa12a74c04e49e800, 0xd7c43895b01e211d, 0x7f4bcee65b20 <k5_iov_cursor_put+176>, 0x2a0f3cb812d, 0xa12a74c04e49e800, 0x58499ae980a891fe, 0x7f4b93d38340, 0x55f89b92fad0, 0x7f4b93d38350, 0x7f4b93d38330, 0x7f4b93d382e0, 0x55f901527130, 0x7f4bcee547cd <krb5int_aes_encrypt+813>, 0x20, 0xa7ff7ad44e49e800, 0x0, 0x7f4b93d382e0, 0x7f4b93d38470, 0x4, 0x10, 0x7f4b00000000, 0x4, 0x0, 0x4, 0x0, 0x21cafd39017982c4, 0x6e273f72669afee0, 0x530d2dd27b61963b, 0xff29c39b99a71313, 0x9ecaf11f4ef579a1, 0x8cb433b09c5edc92, 0x21cafd39017982c4, 0x6e273f72669afee0, 0x0, 0xa12a74c04e49e800, 0x7f4b93d38470...}         attrlistbuf = "\300\207ӓK\177\000\000\301\207ӓK\177\000\000\000\000\000\000K\177\000\000\034_\032\315K\177\000\000;\232F\317K\177\000\000\020\211ӓK\177\000\000\000\000\000\000\000\000\000\000P\232F\317K\177\000\000Q\232F\317K\177\000\000\356a\032\315K\177\000\000\020\210ӓK\177", '\000' <repeats 18 times>, "\357\206ӓK\177\000\000\360\206ӓK\177\000\000\006\000\000\000K\177\000\000@\210ӓK\177\000\000A\210ӓK\177\000\000\000\000\000\000K\177\000\000\005\214D\317\000\000\000\000\000\207ӓK\177\000\000P\204x\006\371U\000 _\232F\317K\177", '\000' <repeats 19 times>, "\350IN\300t*\241\000"...         attrliststr = <optimized out>         attrs = 0x0         rc = 0         internal_op = <optimized out>         basesdn = 0x55f8d6a316b0         sdn = 0x55f8e973bbc0         operation = 0x55f8a2ce14a0         referral = 0x0         proxydn = 0x0         proxystr = 0x0         proxy_err = <optimized out>         errtext = 0x0         nentries = 0         pnentries = 399583         flag_search_base_found = 1         flag_no_such_object = 0         flag_referral = 0         flag_psearch = <optimized out>         err_code = 0         ctrlp = 0x0         ctl_value = 0x0         iscritical = 0         be_name = <optimized out>         index = -1         sent_result = 0         pr_stat = 0         pb_conn = 0x0         pagesize = -1         estimate = 0         curr_search_count = <optimized out>         pr_be = <optimized out>         pr_search_result = <optimized out>         pr_idx = -1         orig_sdn = 0x0         free_sdn = 1         vattr_lock_acquired = 1 #12 0x00007f4bcf419697 in search_internal_callback_pb (pb=pb@entry=0x55f95513cd80, callback_data=callback_data@entry=0x7f4b93d38b60, prc=prc@entry=0x7f4bcf418770 <internal_plugin_result_callback>, psec=psec@entry=0x7f4bcf4187c0 <internal_plugin_search_entry_callback>, prec=prec@entry=0x7f4bcf418780 <internal_plugin_search_referral_callback>) at ldap/servers/slapd/plugin_internal_op.c:727         controls = 0x0         op = 0x55f8a2ce14a0         filter = 0x55f8aad34480         fstr = 0x55f8a3cd7180 "(&(changenumber>=-1)(targetuniqueid=1e89eb86-e20111e8-8820f96e-fc0c60a4))"         callback_handler_data = {p_res_callback = 0x7f4bcf418770 <internal_plugin_result_callback>, p_srch_entry_callback = 0x7f4bcf4187c0 <internal_plugin_search_entry_callback>, p_ref_entry_callback = 0x7f4bcf418780 <internal_plugin_search_referral_callback>, callback_data = 0x7f4b93d38b60}         scope = 2         ifstr = 0x55f8904cc540 "(&(changenumber>=-1)(targetuniqueid=1e89eb86-e20111e8-8820f96e-fc0c60a4))"         opresult = -817789072         rc = 0         tmp_attrs = 0x0 #13 0x00007f4bcf4198e8 in search_internal_pb (pb=pb@entry=0x55f95513cd80) at ldap/servers/slapd/plugin_internal_op.c:592         psid = {rc = -1, num_entries = 399583, num_referrals = 0, entry_list_head = 0x55f8e74c92d0, referral_list_head = 0x0}         iterator = <optimized out>         tmp = 0x7f4b93d38b60         ref_iterator = <optimized out>         ref_tmp = 0x7f4bcf6af240 <global_server_id_plg>         i = <optimized out>         opresult = 0         pb_search_entries = 0x0         pb_search_referrals = 0x0 #14 0x00007f4bcf419b33 in slapi_search_internal_pb (pb=pb@entry=0x55f95513cd80) at ldap/servers/slapd/plugin_internal_op.c:502 #15 0x00007f4bc394bd13 in sync_cookie_get_change_number (uniqueid=<optimized out>, lastnr=<optimized out>) at ldap/servers/plugins/sync/sync_util.c:429         srch_pb = 0x55f95513cd80         cl_entry = <optimized out>         rv = 0         filter = 0x55f8904cc540 "(&(changenumber>=-1)(targetuniqueid=1e89eb86-e20111e8-8820f96e-fc0c60a4))"         entries = 0x7f4b93d38c6c         newnr = 18446744073709551615         uniqueid = <optimized out>         attr = 0x55f96ad77e60         val = 0x55f964c56860 #16 0x00007f4bc394bd13 in sync_cookie_update (sc=0x55f8c1753040, ec=ec@entry=0x55f9565852c0) at ldap/servers/plugins/sync/sync_util.c:514         uniqueid = <optimized out>         attr = 0x55f96ad77e60         val = 0x55f964c56860 #17 0x00007f4bc394d66d in sync_send_results (arg=<optimized out>) at ldap/servers/plugins/sync/sync_persist.c:643         noattrs = 0x0         ec = 0x55f9565852c0         attrsonly = 0         attrs = 0x0         ectrls = 0x55f906788450         chg_type = 2         req = 0x55f9704795c0         qnode = 0x55f97ea3d320         qnodenext = <optimized out>         conn_acq_flag = <optimized out>         conn = 0x55f882282ba8         op = 0x55f880953680         rc = <optimized out>         connid = 5052         opid = 0 #18 0x00007f4bcd1bdc5b in _pt_root () at /lib64/libnspr4.so #19 0x00007f4bccb5dea5 in start_thread () at /lib64/libpthread.so.0 #20 0x00007f4bcc2099fd in clone () at /lib64/libc.so.

...

...

regards thierry [...]