#48597 Deadlock when rebuilding the group of authorized replication managers
Closed: wontfix None Opened 5 years ago by tbordaz.

freeipa-server-4.3 (jenkins build)

The deadlock occurs because two locks (replica and dbpage) are taken in the opposite order.
One thread is processing the incoming starting replication session. The thread checks (while holding the replica lock) that the bind dn is part of the group of authorized replication managers. But because of period resync of that group it triggers a lookup of 'cn=replication managers,cn=sysaccounts,cn=etc,<domain>' that access some DB page in read (entryrdn index).

The other thread is processing a write operation that acquired the DB page (write), then a txn_be plugin triggers an internal op that needs a 'csn' (from replica csn generator). This generation of the CSN require the replica lock.

The deadlock is not systematic (because the resync of the replication managers group wait for a new replication session and has a minimum delay (60s))

Detailed analyze The deadlock occurred between threads 27 and 34. Many others threads are victims of the deadlock {{{ Thread 34 (ADD -> MEP update -> allocate csn) holds entryrdn page 23 wait for r->repl_lock Thread 27 (incoming replication session) holds r->repl_lock wait for entryrdn page 23 8000619a WRITE 2 HELD userRoot/entryrdn.db page 23 (thread 34) 3fb READ 1 WAIT userRoot/entryrdn.db page 23 (thread 27) 46b READ 1 WAIT /var/lib/dirsrv/slapd-DOM-131-IDM-LAB-ENG-BRQ-REDHAT-COM/cldb/3e456119-d0f411e5-b0d3fd70-1222e87f_56bcdeb3000000040000.db page 35 471 READ 1 WAIT userRoot/objectclass.db page 5 402 READ 1 WAIT userRoot/objectclass.db page 5 48e READ 1 WAIT userRoot/objectclass.db page 5 48f READ 1 WAIT userRoot/objectclass.db page 5 3fd READ 1 WAIT userRoot/objectclass.db page 2 490 READ 1 WAIT userRoot/objectclass.db page 2 445 READ 1 WAIT userRoot/krbPrincipalName.db page 5 }}} Thread 27 is refreshing (replica_updatedn_list_group_replace) the replica groupdn_list (authorized replication managers) from 'cn=replication managers,cn=sysaccounts,cn=etc,<domain>' {{{ (gdb) thread [Current thread is 27 (Thread 0x7f66877f6700 (LWP 28964))] (gdb) where #0 pthread_cond_wait@@GLIBC_2.3.2( ) at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185 #1 0x00007f66aa28c0fb in __db_pthread_mutex_condwait( ) at ../../src/mutex/mut_pthread.c:321 #2 __db_hybrid_mutex_suspend( ) at ../../src/mutex/mut_pthread.c:577 #3 0x00007f66aa28b52f in __db_tas_mutex_lock_int( ) at ../../src/mutex/mut_tas.c:255 #4 __db_tas_mutex_lock( ) at ../../src/mutex/mut_tas.c:286 #5 0x00007f66aa335c97 in __lock_get_internal( ) at ../../src/lock/lock.c:989 #6 0x00007f66aa336727 in __lock_get( ) at ../../src/lock/lock.c:469 #7 0x00007f66aa3624c7 in __db_lget( ) at ../../src/db/db_meta.c:1257 #8 0x00007f66aa2a9222 in __bam_search( ) at ../../src/btree/bt_search.c:723 #9 0x00007f66aa293f0c in __bamc_search( ) at ../../src/btree/bt_cursor.c:2804 #10 0x00007f66aa296517 in __bamc_get( ) at ../../src/btree/bt_cursor.c:999 #11 0x00007f66aa34ed14 in __dbc_iget( ) at ../../src/db/db_cam.c:952 #12 0x00007f66aa34f54d in __dbc_get( ) at ../../src/db/db_cam.c:770 #13 0x00007f66aa35def2 in __dbc_get_pp( ) at ../../src/db/db_iface.c:2361 #14 0x00007f66a55cb434 in _entryrdn_get_elem( ) at ldap/servers/slapd/back-ldbm/ldbm_entryrdn.c:1778 #15 0x00007f66a55ce928 in _entryrdn_index_read( ) at ldap/servers/slapd/back-ldbm/ldbm_entryrdn.c:3217 #16 0x00007f66a55cfdbb in entryrdn_index_read_ext( ) at ldap/servers/slapd/back-ldbm/ldbm_entryrdn.c:419 #17 0x00007f66a55a0049 in dn2entry_ext( ) at ldap/servers/slapd/back-ldbm/dn2entry.c:63 #18 0x00007f66a55a2e81 in find_entry_internal_dn( ) at ldap/servers/slapd/back-ldbm/findentry.c:101 #19 find_entry_internal( ) at ldap/servers/slapd/back-ldbm/findentry.c:264 #20 0x00007f66a55a3169 in find_entry( ) at ldap/servers/slapd/back-ldbm/findentry.c:284 #21 0x00007f66a55dd44b in ldbm_back_search( ) at ldap/servers/slapd/back-ldbm/ldbm_search.c:587 #22 0x00007f66b254a270 in op_shared_search( ) at ldap/servers/slapd/opshared.c:802 #23 0x00007f66b255ab4e in search_internal_callback_pb( ) at ldap/servers/slapd/plugin_internal_op.c:783 #24 0x00007f66b255add8 in search_internal_pb( ) at ldap/servers/slapd/plugin_internal_op.c:636 #25 0x00007f66b255b033 in slapi_search_internal_pb( ) at ldap/servers/slapd/plugin_internal_op.c:545 #26 0x00007f66a53255f3 in replica_updatedn_list_get_members( ) at ldap/servers/plugins/replication/repl5_updatedn_list.c:190 #27 0x00007f66a5325830 in replica_updatedn_list_add_ext( ) at ldap/servers/plugins/replication/repl5_updatedn_list.c:259 #28 0x00007f66a532584a in replica_updatedn_list_add_ext( ) at ldap/servers/plugins/replication/repl5_updatedn_list.c:261 #29 0x00007f66a5325a69 in replica_updatedn_list_group_replace( ) at ldap/servers/plugins/replication/repl5_updatedn_list.c:132 #30 0x00007f66a5312f62 in replica_is_updatedn( ) at ldap/servers/plugins/replication/repl5_replica.c:1120 #31 0x00007f66a52fa565 in multimaster_extop_StartNSDS50ReplicationRequest( ) at ldap/servers/plugins/replication/repl_extop.c:786 #32 0x00007f66b2553b88 in plugin_call_exop_plugins( ) at ldap/servers/slapd/plugin.c:510 #33 0x00005565dcc14da6 in do_extended( ) at ldap/servers/slapd/extendop.c:337 #34 0x00005565dcc0e194 in connection_dispatch_operation( ) at ldap/servers/slapd/connection.c:672 #35 connection_threadmain( ) at ldap/servers/slapd/connection.c:1735 #36 0x00007f66b07265cb in _pt_root( ) at ../../../nspr/pr/src/pthreads/ptthread.c:212 #37 0x00007f66b00c560a in start_thread( ) at pthread_create.c:334 #38 0x00007f66afdffa4d in clone( ) at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109 }}} Thread 34 is ADD that triggers an internal MOD (MEP plugin) that need to generate a csn. {{{ Thread 34 (Thread 0x7f668affd700 (LWP 28957)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185 #1 0x00007f66b0720f63 in PR_EnterMonitor (mon=0x5565dd8800b0) at ../../../nspr/pr/src/pthreads/ptsynch.c:603 #2 0x00007f66a5312685 in replica_get_ruv () from /usr/lib64/dirsrv/plugins/libreplication-plugin.so #3 0x00007f66a531277a in assign_csn_callback () from /usr/lib64/dirsrv/plugins/libreplication-plugin.so #4 0x00007f66a531659d in replica_generate_next_csn () from /usr/lib64/dirsrv/plugins/libreplication-plugin.so #5 0x00007f66b251c1d1 in entry_assign_operation_csn () from /usr/lib64/dirsrv/libslapd.so.0 #6 0x00007f66a55d75a3 in ldbm_back_modify () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #7 0x00007f66b2543595 in op_shared_modify () from /usr/lib64/dirsrv/libslapd.so.0 #8 0x00007f66b2544045 in modify_internal_pb () from /usr/lib64/dirsrv/libslapd.so.0 #9 0x00007f66a4eb6565 in mep_add_managed_entry () from /usr/lib64/dirsrv/plugins/libmanagedentries-plugin.so #10 0x00007f66a4eb8aa3 in mep_add_post_op () from /usr/lib64/dirsrv/plugins/libmanagedentries-plugin.so #11 0x00007f66b2555969 in plugin_call_func () from /usr/lib64/dirsrv/libslapd.so.0 #12 0x00007f66b2555bf5 in plugin_call_plugins () from /usr/lib64/dirsrv/libslapd.so.0 #13 0x00007f66a55bc8b0 in ldbm_back_add () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #14 0x00007f66b24fbdfa in op_shared_add () from /usr/lib64/dirsrv/libslapd.so.0 #15 0x00007f66b24fd178 in do_add () from /usr/lib64/dirsrv/libslapd.so.0 #16 0x00005565dcc0e28f in connection_threadmain () #17 0x00007f66b07265cb in _pt_root (arg=0x5565dd8f23f0) at ../../../nspr/pr/src/pthreads/ptthread.c:212 #18 0x00007f66b00c560a in start_thread (arg=0x7f668affd700) at pthread_create.c:334 #19 0x00007f66afdffa4d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109 }}}

In replica_updatedn_list_group_replace() we could separate the build of the new memberlist (without lock) and then do the replace with the lock

An other occurrence of this bug but this time when a ADD (updating the RUV) need to access the replica lock owned by the thread updating the authorized replication manager list {{{ 3eb dd=149 locks held 0 write locks 0 pid/thread 24150/ 140228735989504 flags 0 priority 100 7f898bfef700 3eb READ 1 WAIT userRoot/entryrdn.db page 23 800064ac dd=6 locks held 41 write locks 32 pid/thread 24150/ 140228794738432 flags 0 priority 100 7f898f7f6700 800064ac WRITE 1 HELD /var/lib/dirsrv/slapd-<domain>/cldb/e1e9a005-ea1711e5-b358ed8b-eca27b34_56e70bd8000000040000.db page 15 800064ac READ 4 HELD userRoot/objectclass.db page 5 800064ac WRITE 2 HELD userRoot/objectclass.db page 5 800064ac WRITE 1 HELD userRoot/entryrdn.db page 23 800064ac WRITE 1 HELD userRoot/objectclass.db page 2 800064ac WRITE 1 HELD changelog/changenumber.db page 1 ... Thread 31 (Thread 0x7f898f7f6700 (LWP 24174)):: #0 0x00007f89b64a8b10 in pthread_cond_wait@@GLIBC_2.3.2 from /lib64/libpthread.so.0 #1 0x00007f89b6afefa3 in PR_EnterMonitor from /lib64/libnspr4.so #2 0x00007f89ab6ea865 in replica_lock at ldap/servers/plugins/replication/repl5_replica.c:110 #3 replica_get_rid at ldap/servers/plugins/replication/repl5_replica.c:722 #4 0x00007f89ab6d9c77 in agmt_update_maxcsn at ldap/servers/plugins/replication/repl5_agmt.c:3014 #5 0x00007f89ab6e5f54 in write_changelog_and_ruv at ldap/servers/plugins/replication/repl5_plugins.c:1203 #6 0x00007f89b893c9a9 in plugin_call_func at ldap/servers/slapd/plugin.c:1987 #7 0x00007f89b893cc35 in plugin_call_list at ldap/servers/slapd/plugin.c:1931 #8 plugin_call_plugins at ldap/servers/slapd/plugin.c:438 #9 0x00007f89ab9948b0 in ldbm_back_add at ldap/servers/slapd/back-ldbm/ldbm_add.c:1141 #10 0x00007f89b88e2dfa in op_shared_add at ldap/servers/slapd/add.c:714 #11 0x00007f89b88e4178 in do_add at ldap/servers/slapd/add.c:226 #12 0x0000561ac08cf458 in connection_dispatch_operation at ldap/servers/slapd/connection.c:604 #13 connection_threadmain at ldap/servers/slapd/connection.c:1751 #14 0x00007f89b6b0465b in _pt_root from /lib64/libnspr4.so #15 0x00007f89b64a360a in start_thread from /lib64/libpthread.so.0 #16 0x00007f89b61dda4d in clone from /lib64/libc.so.6 Thread 24 (Thread 0x7f898bfef700 (LWP 24181)): #0 0x00007f89b64a8b10 in pthread_cond_wait@@GLIBC_2.3.2 from /lib64/libpthread.so.0 #1 0x00007f89b06670fb in __db_hybrid_mutex_suspend from /lib64/libdb-5.3.so #2 0x00007f89b066652f in __db_tas_mutex_lock from /lib64/libdb-5.3.so #3 0x00007f89b0710c97 in __lock_get_internal from /lib64/libdb-5.3.so #4 0x00007f89b0711727 in __lock_get from /lib64/libdb-5.3.so #5 0x00007f89b073d4c7 in __db_lget from /lib64/libdb-5.3.so #6 0x00007f89b0684222 in __bam_search from /lib64/libdb-5.3.so #7 0x00007f89b066ef0c in __bamc_search from /lib64/libdb-5.3.so #8 0x00007f89b0671517 in __bamc_get from /lib64/libdb-5.3.so #9 0x00007f89b0729d14 in __dbc_iget from /lib64/libdb-5.3.so #10 0x00007f89b0738ef2 in __dbc_get_pp from /lib64/libdb-5.3.so #11 0x00007f89ab9a3434 in _entryrdn_get_elem at ldap/servers/slapd/back-ldbm/ldbm_entryrdn.c:1778 #12 0x00007f89ab9a6928 in _entryrdn_index_read at ldap/servers/slapd/back-ldbm/ldbm_entryrdn.c:3217 #13 0x00007f89ab9a7dbb in entryrdn_index_read_ext at ldap/servers/slapd/back-ldbm/ldbm_entryrdn.c:419 #14 0x00007f89ab978049 in dn2entry_ext at ldap/servers/slapd/back-ldbm/dn2entry.c:63 #15 0x00007f89ab97ae81 in find_entry_internal_dn at ldap/servers/slapd/back-ldbm/findentry.c:101 #16 find_entry_internal at ldap/servers/slapd/back-ldbm/findentry.c:264 #17 0x00007f89ab97b169 in find_entry at ldap/servers/slapd/back-ldbm/findentry.c:284 #18 0x00007f89ab9b544b in ldbm_back_search at ldap/servers/slapd/back-ldbm/ldbm_search.c:587 #19 0x00007f89b8931280 in op_shared_search at ldap/servers/slapd/opshared.c:802 #20 0x00007f89b8941b8e in search_internal_callback_pb at ldap/servers/slapd/plugin_internal_op.c:783 #21 0x00007f89b8941e18 in search_internal_pb at ldap/servers/slapd/plugin_internal_op.c:636 #22 0x00007f89b8942073 in slapi_search_internal_pb at ldap/servers/slapd/plugin_internal_op.c:545 #23 0x00007f89ab6fd833 in replica_updatedn_list_get_members at ldap/servers/plugins/replication/repl5_updatedn_list.c:190 #24 0x00007f89ab6fda70 in replica_updatedn_list_add_ext at ldap/servers/plugins/replication/repl5_updatedn_list.c:259 #25 0x00007f89ab6fda8a in replica_updatedn_list_add_ext at ldap/servers/plugins/replication/repl5_updatedn_list.c:261 #26 0x00007f89ab6fdca9 in replica_updatedn_list_group_replace at ldap/servers/plugins/replication/repl5_updatedn_list.c:132 #27 0x00007f89ab6eb1b2 in replica_is_updatedn at ldap/servers/plugins/replication/repl5_replica.c:1120 #28 0x00007f89ab6d25a5 in multimaster_extop_StartNSDS50ReplicationRequest at ldap/servers/plugins/replication/repl_extop.c:786 #29 0x00007f89b893abc8 in plugin_call_exop_plugins at ldap/servers/slapd/plugin.c:510 #30 0x0000561ac08d5f76 in do_extended at ldap/servers/slapd/extendop.c:337 #31 0x0000561ac08cf34a in connection_dispatch_operation at ldap/servers/slapd/connection.c:672 #32 connection_threadmain at ldap/servers/slapd/connection.c:1751 #33 0x00007f89b6b0465b in _pt_root from /lib64/libnspr4.so #34 0x00007f89b64a360a in start_thread from /lib64/libpthread.so.0 #35 0x00007f89b61dda4d in clone from /lib64/libc.so.6 }}}

Hi Thierry, I have a question. It might be a stupid one, though... :)

This means at the line 1139, other threads could have a chance to set new r->groupdn_list and the line 1142-1144 could replace with this groupdn_list? It is guaranteed it does not occur or it is ok even if it occurs? If the answer is yes, I will ack.
1138 replica_unlock(r->repl_lock);
1139 replica_updatedn_list_group_replace(groupdn_list, updatedn_groupds_copy);
1140 replica_lock(r->repl_lock);
1142 replica_updatedn_list_delete(r->groupdn_list, NULL);
1143 replica_updatedn_list_free(r->groupdn_list);
1144 r->groupdn_list = groupdn_list;
1145 slapi_valueset_free(updatedn_groupds_copy);

Hi Noriko,

Good catch !!

The key element is r->updatedn_groups (nsDS5ReplicaBindDnGroup) that is updated while holding the lock.
r->groupdn_list contains the list of members of those groups.

If during the refresh, 'nsDS5ReplicaBindDnGroup' is updated then there is a risk the updated groupdn_list is overwritten by the refresh.
It should be a transient issue as the next refresh will evaluate the correct updatedn_groups.
But if nsDS5ReplicaBindDnGroupCheckInterval is very long (or infinite), replication can break.

I think a possible fix is (after reacquiring replica lock), to check that updatedn_groupds_copy and r->updatedn_groups are identical.

Thank you, Thierry! Your take 2 patch looks nice!

Thanks Noriko for the review

git push origin '''master'''
Counting objects: 7, done.
Delta compression using up to 8 threads.
Compressing objects: 100% (7/7), done.
Writing objects: 100% (7/7), 2.30 KiB | 0 bytes/s, done.
Total 7 (delta 5), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/ds.git
6858dfd..5cfd3de master -> master

Metadata Update from @tbordaz:
- Issue assigned to tbordaz
- Issue set to the milestone:

4 years ago

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/389ds/389-ds-base/issues/1784

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Metadata Update from @spichugi:
- Issue close_status updated to: wontfix (was: Fixed)

a year ago

Login to comment on this ticket.