389-ds-base

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

Closed: wontfix
Reopen Issue 
389-ds-base-1.3.4.6-1.fc23
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,' 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,'

{{{
(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-/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);
1141
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: 1.3.5.0

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)
Metadata
None
None
None
Normal
ack
IPA
None
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.