Using freeipa 4.4 git build and 389-ds-base-libs-1.3.5.14-1.fc24.x86_64
The deadlock occurs because of two locks (DB pages and Schema Compat map) taken in the opposite order. DB pages were acquired by an update of custodia config. A first deadlocking thread was doing an internal search triggered by topology plugin. A second deadlocking thread was doing an internal search triggered by a config update (register DS plugin).
Owner of DB pages ADD "cn=sig/<vm_fqdn>,cn=custodia,cn=ipa,cn=etc,<suffix>" Thread 29 (Thread 0x7f5269ff3700 (LWP 48552)): Owners of slapi-nis map lock Acquired slapi-nis map lock (read) then waiting for DB pages (owned by Thread 29) ipa_topo_apply_shared_config internal search slapi-nis -b "cn=topology,cn=ipa,cn=etc,<suffix>" -s one "(ipaReplTopoConfRoot=<suffix>)" Thread 11 (Thread 0x7f5277fff700 (LWP 48533)): Acquire slapi-nis map lock (read) then waiting for DB page (owned by Thread 29) ADD: "cn=ipa_pwd_extop,cn=plugins,cn=config" -> slapi-nis does int_search -b "cn=groups,cn=accounts,<suffix>" -s one "(member=cn=ipa_pwd_extop,cn=plugins,cn=config)" Thread 26 (Thread 0x7f526b7f6700 (LWP 48549)):
This bug is somehow related to https://fedorahosted.org/freeipa/ticket/6280 triggered by an other use case. So far it is not 100% sure this ticket is a duplicate of https://fedorahosted.org/freeipa/ticket/6280.
Some details about that deadlock:
DB locks are
a dd=31 locks held 0 write locks 0 pid/thread 48522/139991967557376 (7F526B7F6700) flags 0 priority 100 a READ 1 WAIT userRoot/objectclass.db page 7 8 dd=33 locks held 0 write locks 0 pid/thread 48522/139992177309440 (7F5277FFF700)flags 0 priority 100 8 READ 1 WAIT userRoot/entryrdn.db page 25 8000003b dd= 1 locks held 46 write locks 41 pid/thread 48522/139991942379264 (7F5269FF3700) flags 0 priority 100 8000003b WRITE 1 HELD userRoot/entryrdn.db page 25 8000003b WRITE 3 HELD userRoot/objectclass.db page 7
Thread owning the DB pages (in write under 8000003b txn)
ADD "cn=sig/<vm_fqdn>,cn=custodia,cn=ipa,cn=etc,<suffix>" Thread 29 (Thread 0x7f5269ff3700 (LWP 48552)): #0 0x00007f529b325f68 in __pthread_rwlock_wrlock_slow () from /lib64/libpthread.so.0 #1 0x00007f528e3d8f8e in backend_shr_post_add_cb.part () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so #2 0x00007f528e3d9167 in backend_shr_betxn_post_add_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so #3 0x00007f529d7bfd39 in plugin_call_func () from /usr/lib64/dirsrv/libslapd.so.0 #4 0x00007f529d7bffa4 in plugin_call_plugins () from /usr/lib64/dirsrv/libslapd.so.0 #5 0x00007f529038e6e7 in ldbm_back_add () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #6 0x00007f529d762eb9 in op_shared_add () from /usr/lib64/dirsrv/libslapd.so.0 #7 0x00007f529d764198 in do_add () from /usr/lib64/dirsrv/libslapd.so.0 #8 0x0000555ef4f51320 in connection_threadmain () #9 0x00007f529b9825cc in _pt_root (arg=0x555ef7469440) at ../../../nspr/pr/src/pthreads/ptthread.c:216 #10 0x00007f529b3215ca in start_thread () from /lib64/libpthread.so.0 #11 0x00007f529b05af6d in clone () from /lib64/libc.so.6
A first deadlocking thread is related with topology plugin looking for its shared config
Acquired slapi-nis map lock (read) then waiting for DB pages (owned by Thread 29) ipa_topo_apply_shared_config internal search slapi-nis -b "cn=topology,cn=ipa,cn=etc,<suffix>" -s one "(ipaReplTopoConfRoot=<suffix>)" Thread 11 (Thread 0x7f5277fff700 (LWP 48533)): #0 0x00007f529b326bd0 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x00007f5294825643 in __db_pthread_mutex_condwait (env=0x555ef70b9ee0, mutex=139992767818630, timespec=0x0, mutexp=<optimized out>) at ../../src/mutex/mut_pthread.c:321 #2 __db_hybrid_mutex_suspend (env=env@entry=0x555ef70b9ee0, mutex=mutex@entry=2196, timespec=timespec@entry=0x0, exclusive=exclusive@entry=1) at ../../src/mutex/mut_pthread.c:577 #3 0x00007f5294824a27 in __db_tas_mutex_lock_int (nowait=0, timeout=0, mutex=2196, env=0x555ef70b9ee0) at ../../src/mutex/mut_tas.c:255 #4 __db_tas_mutex_lock (env=env@entry=0x555ef70b9ee0, mutex=2196, timeout=timeout@entry=0) at ../../src/mutex/mut_tas.c:286 #5 0x00007f52948d2070 in __lock_get_internal (lt=lt@entry=0x555ef725b240, sh_locker=sh_locker@entry=0x7f528a5362d0, flags=flags@entry=0, obj=<optimized out>, lock_mode=<optimized out>, timeout=timeout@entry=0, lock=<optimized out>) at ../../src/lock/lock.c:989 #6 0x00007f52948d2ba7 in __lock_get (env=env@entry=0x555ef70b9ee0, locker=0x7f528a5362d0, flags=0, obj=obj@entry=0x7f522c012b60, lock_mode=lock_mode@entry=DB_LOCK_READ, lock=lock@entry=0x7f5277ff7c90) at ../../src/lock/lock.c:469 #7 0x00007f52948ff43f in __db_lget (dbc=dbc@entry=0x7f522c012a70, action=action@entry=0, pgno=25, mode=mode@entry=DB_LOCK_READ, lkflags=lkflags@entry=0, lockp=lockp@entry=0x7f5277ff7c90) at ../../src/db/db_meta.c:1257 #8 0x00007f529484385a in __bam_search (dbc=dbc@entry=0x7f522c012a70, root_pgno=1, root_pgno@entry=0, key=key@entry=0x7f5277ff8010, flags=<optimized out>, slevel=slevel@entry=1, recnop=recnop@entry=0x0, exactp=0x7f5277ff7dc4) at ../../src/btree/bt_search.c:723 #9 0x00007f529482d79b in __bamc_search (dbc=0x7f522c012a70, root_pgno=root_pgno@entry=0, key=0x7f5277ff8010, flags=flags@entry=10, exactp=exactp@entry=0x7f5277ff7dc4) at ../../src/btree/bt_cursor.c:2804 #10 0x00007f529482fdff in __bamc_get (dbc=0x7f522c012a70, key=<optimized out>, data=0x7f5277ff8040, flags=10, pgnop=0x7f5277ff7e54) at ../../src/btree/bt_cursor.c:999 #11 0x00007f52948eb8a3 in __dbc_iget (dbc=0x555ef7264840, key=0x7f5277ff8010, data=0x7f5277ff8040, flags=10) at ../../src/db/db_cam.c:952 #12 0x00007f52948ec14d in __dbc_get (dbc=dbc@entry=0x555ef7264840, key=key@entry=0x7f5277ff8010, data=data@entry=0x7f5277ff8040, flags=flags@entry=10) at ../../src/db/db_cam.c:770 #13 0x00007f52948fb1d6 in __dbc_get_pp (dbc=0x555ef7264840, key=0x7f5277ff8010, data=0x7f5277ff8040, flags=10) at ../../src/db/db_iface.c:2361 #14 0x00007f529039d724 in _entryrdn_get_elem () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #15 0x00007f52903a0c58 in _entryrdn_index_read () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #16 0x00007f52903a2179 in entryrdn_index_read_ext () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #17 0x00007f5290371729 in dn2entry_ext () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #18 0x00007f52903745b8 in find_entry_internal.isra () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #19 0x00007f5290374a6b in find_entry () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #20 0x00007f52903afd36 in ldbm_back_search () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #21 0x00007f529d7b43b0 in op_shared_search () from /usr/lib64/dirsrv/libslapd.so.0 #22 0x00007f529d7c4f9e in search_internal_callback_pb () from /usr/lib64/dirsrv/libslapd.so.0 #23 0x00007f529d7c522d in search_internal_pb () from /usr/lib64/dirsrv/libslapd.so.0 #24 0x00007f52914227b0 in ipa_topo_util_get_replica_conf () from /usr/lib64/dirsrv/plugins/libtopology.so #25 0x00007f529141f16d in ipa_topo_apply_shared_config () from /usr/lib64/dirsrv/plugins/libtopology.so #26 0x00007f529d785a9c in eq_loop () from /usr/lib64/dirsrv/libslapd.so.0 #27 0x00007f529b9825cc in _pt_root (arg=0x555ef74886f0) at ../../../nspr/pr/src/pthreads/ptthread.c:216 #28 0x00007f529b3215ca in start_thread () from /lib64/libpthread.so.0 #29 0x00007f529b05af6d in clone () from /lib64/libc.so.6
A second deadlocking thread is creating adding ipa_pwd_extop plugin (early phase of the replica install)
Acquire slapi-nis map lock (read) then waiting for DB page (owned by Thread 29) ADD: "cn=ipa_pwd_extop,cn=plugins,cn=config" -> slapi-nis does int_search -b "cn=groups,cn=accounts,<suffix>" -s one "(member=cn=ipa_pwd_extop,cn=plugins,cn=config)" Thread 26 (Thread 0x7f526b7f6700 (LWP 48549)): #0 0x00007f529b326bd0 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x00007f5294825643 in __db_pthread_mutex_condwait (env=0x555ef70b9ee0, mutex=139992767818630, timespec=0x0, mutexp=<optimized out>) at ../../src/mutex/mut_pthread.c:321 #2 __db_hybrid_mutex_suspend (env=env@entry=0x555ef70b9ee0, mutex=mutex@entry=2197, timespec=timespec@entry=0x0, exclusive=exclusive@entry=1) at ../../src/mutex/mut_pthread.c:577 #3 0x00007f5294824a27 in __db_tas_mutex_lock_int (nowait=0, timeout=0, mutex=2197, env=0x555ef70b9ee0) at ../../src/mutex/mut_tas.c:255 #4 __db_tas_mutex_lock (env=env@entry=0x555ef70b9ee0, mutex=2197, timeout=timeout@entry=0) at ../../src/mutex/mut_tas.c:286 #5 0x00007f52948d2070 in __lock_get_internal (lt=lt@entry=0x555ef725b240, sh_locker=sh_locker@entry=0x7f528a5365d0, flags=flags@entry=0, obj=<optimized out>, lock_mode=<optimized out>, timeout=timeout@entry=0, lock=<optimized out>) at ../../src/lock/lock.c:989 #6 0x00007f52948d2ba7 in __lock_get (env=env@entry=0x555ef70b9ee0, locker=0x7f528a5365d0, flags=0, obj=obj@entry=0x555ef725c680, lock_mode=lock_mode@entry=DB_LOCK_READ, lock=lock@entry=0x7f526b7e72e0) at ../../src/lock/lock.c:469 #7 0x00007f52948ff43f in __db_lget (dbc=dbc@entry=0x555ef725c590, action=action@entry=0, pgno=7, mode=mode@entry=DB_LOCK_READ, lkflags=lkflags@entry=0, lockp=lockp@entry=0x7f526b7e72e0) at ../../src/db/db_meta.c:1257 #8 0x00007f529484385a in __bam_search (dbc=dbc@entry=0x555ef725c590, root_pgno=1, root_pgno@entry=0, key=key@entry=0x7f526b7e75b0, flags=<optimized out>, slevel=slevel@entry=1, recnop=recnop@entry=0x0, exactp=0x7f526b7e7414) at ../../src/btree/bt_search.c:723 #9 0x00007f529482d79b in __bamc_search (dbc=dbc@entry=0x555ef725c590, root_pgno=root_pgno@entry=0, key=0x7f526b7e75b0, flags=<optimized out>, exactp=<optimized out>) at ../../src/btree/bt_cursor.c:2804 #10 0x00007f529482f90f in __bamc_get (dbc=0x555ef725c590, key=<optimized out>, data=<optimized out>, flags=<optimized out>, pgnop=0x7f526b7e74a4) at ../../src/btree/bt_cursor.c:1099 #11 0x00007f52948eb8a3 in __dbc_iget (dbc=0x555ef70b7b50, key=0x7f526b7e75b0, data=0x7f526b7e75e0, flags=26) at ../../src/db/db_cam.c:952 #12 0x00007f52948ec14d in __dbc_get (dbc=dbc@entry=0x555ef70b7b50, key=key@entry=0x7f526b7e75b0, data=data@entry=0x7f526b7e75e0, flags=flags@entry=2074) at ../../src/db/db_cam.c:770 #13 0x00007f52948fb1d6 in __dbc_get_pp (dbc=0x555ef70b7b50, key=0x7f526b7e75b0, data=0x7f526b7e75e0, flags=2074) at ../../src/db/db_iface.c:2361 #14 0x00007f5290379282 in idl_new_fetch () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #15 0x00007f5290387d80 in index_read_ext_allids () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #16 0x00007f5290371ccd in keys2idl () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #17 0x00007f529037256a in ava_candidates.isra () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #18 0x00007f5290372b29 in filter_candidates_ext () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #19 0x00007f5290373adf in list_candidates () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #20 0x00007f5290372a9a in filter_candidates_ext () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #21 0x00007f5290373adf in list_candidates () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #22 0x00007f5290372a9a in filter_candidates_ext () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #23 0x00007f52903740af in filter_candidates () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #24 0x00007f52903b0b3b in ldbm_back_search () from /usr/lib64/dirsrv/plugins/libback-ldbm.so #25 0x00007f529d7b43b0 in op_shared_search () from /usr/lib64/dirsrv/libslapd.so.0 #26 0x00007f529d7c4f9e in search_internal_callback_pb () from /usr/lib64/dirsrv/libslapd.so.0 #27 0x00007f528e3d9e79 in backend_shr_update_references_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so #28 0x00007f528e3e64ff in map_data_foreach_map () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so #29 0x00007f528e3d7e3b in backend_shr_update_references () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so #30 0x00007f528e3d900b in backend_shr_post_add_cb.part () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so #31 0x00007f528e3d9167 in backend_shr_betxn_post_add_cb () from /usr/lib64/dirsrv/plugins/schemacompat-plugin.so #32 0x00007f529d7bfd39 in plugin_call_func () from /usr/lib64/dirsrv/libslapd.so.0 #33 0x00007f529d7bffa4 in plugin_call_plugins () from /usr/lib64/dirsrv/libslapd.so.0 #34 0x00007f529d77a79a in dse_add () from /usr/lib64/dirsrv/libslapd.so.0 #35 0x00007f529d762eb9 in op_shared_add () from /usr/lib64/dirsrv/libslapd.so.0 #36 0x00007f529d764198 in do_add () from /usr/lib64/dirsrv/libslapd.so.0 #37 0x0000555ef4f51320 in connection_threadmain () #38 0x00007f529b9825cc in _pt_root (arg=0x555ef7468b10) at ../../../nspr/pr/src/pthreads/ptthread.c:216 #39 0x00007f529b3215ca in start_thread () from /lib64/libpthread.so.0 #40 0x00007f529b05af6d in clone () from /lib64/libc.so.6
I don't see how thread 11 is involved except that it also waits for the db pages.
thread 26 holds the db lock and waits for the slapi-nis lock and thread 29 holds the slapi nis lock and waits for the db lock.
Replying to [comment:3 lkrispen]:
I don't see how thread 11 is involved except that it also waits for the db pages. thread 26 holds the db lock and waits for the slapi-nis lock and thread 29 holds the slapi nis lock and waits for the db lock.
Yes you are right. This thread is victim of the deadlock of the two others.
Metadata Update from @tbordaz: - Issue assigned to someone - Issue set to the milestone: FreeIPA 4.5 backlog