The problem is not systematic, it can be reproduced on a VM running freeipa unit tests. I reproduced it one time out of 4.
The problem is reproduced while testing fix https://fedorahosted.org/389/ticket/47787 on 1.3.2 with those backports:
85106f0 Ticket 47721 - Schema Replication Issue (follow up) 96ab39f Ticket 47721 - Schema Replication Issue (follow up + cleanup) 6ebea73 Ticket 47721 - Schema Replication Issue 30f47c5 Ticket 47676 : (cont.) Replication of the schema fails 'master branch' -> 1.2.11 or 1.3.1 9558f55 Ticket 47676 : Replication of the schema fails 'master branch' -> 1.2.11 or 1.3.1 0ba131b Ticket 47541 - Fix Jenkins errors adce8c6 Ticket 47541 - Replication of the schema may overwrite consumer 'attributetypes' even if consumer definition 0d344e3 Bump version 1.3.2.17 4799be9 Ticket 47787: A replicated MOD fails (Unwilling to perform) if it targets a tombstone
Now looking at the deadlock reason, the problem looks not related to any of those fixes.
The scenario of the hang is related to Thread 4 and Thread 5. Thread 4 applies a DEL on 'userRoot' backend and update userRoot/objectclass index. To do this it acquires in WRITE the page '4' of this db. Then it tries to record the DEL in the retro changelog and wait for Thread 5 that owns the RETROCL lock.
Thread 5 applies a MOD on 'ipa' backend. It adds the MOD in the retroCL and acquired the lock. While adding the entry in the changelog, it does an internal search on 'userRoot' using 'objectclass' in filter component. It needs to read the page 4 of the userRoot/objectclass index and hang waiting for Thread 4
Thread 5 is MOD ("ou=ca,ou=requests,o=ipaca") In be_txn_post op write_replog_db -> Acquire retrocl_internal_lock add: "changenumber=886,cn=changelog" search("cn=groups,cn=accounts,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com", one_level, "(member=changenumber=886,cn=changelog)") key: 'objectclass=referral' 8000595d dd= 0 locks held 18 write locks 14 pid/thread 10992/139941434517248 flags 0 priority 100 8000595d READ 1 WAIT userRoot/objectclass.db page 4 ... Thread 4 is DEL ("fqdn=ipatestcert.idm.lab.bos.redhat.com,cn=computers,cn=accounts,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com") 8000595b dd= 1 locks held 62 write locks 31 pid/thread 10992/139941426124544 flags 0 priority 100 ... 8000595b WRITE 17 HELD userRoot/objectclass.db page 4 8000595b READ 8 HELD userRoot/objectclass.db page 4 ... In be_txn_post of write_replog_db -> Wait for retrocl_internal_lock
The test case is described in https://fedorahosted.org/freeipa/ticket/4279#comment:7 The hanging instance is F20 replica
attachment 47797.tar.gz
Ah, so retrocl can be called recursively. You can't use a simple PRLock because it is not re-entrant. You will need to use a PRMonitor, or use a PRRWLock. I suggest PRMonitor unless you require separate read/write locking.
Hello Rich,
I am not sure it is called recursively. Here Thread 5 called retrocl_postob in MOD (ipaca backend) post op, then while adding the entry in the changelog this is the schemacompat-plugin that does an internal search on 'userRoot'.
Forgot to mention: it the DB transaction are done with DB_TXN_NOWAIT (default behavior), the Thread 5 is looping on a cursor->c_get with DB_DEADLOCK and the CPU is high. If the transaction is begin with flags=0 (wait), then the Thread 5 hanging on the lock and CPU is low.
In thread 4 - who is holding this lock? {{{ #4 0x00007f46d3691734 in write_replog_db (newsuperior=0x0, modrdn_mods=0x0, newrdn=0x0, log_e=0x0, curtime=1399376225, flag=0, log_m=0x0, dn=0x7f46c42da470 "fqdn=ipatestcert.idm.lab.bos.redhat.com,cn=computers,cn=accounts,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com", optype=3, pb=0x7f46a6fe4ae0) at ldap/servers/plugins/retrocl/retrocl_po.c:187 }}}
THis is the thread 5 that is already adding an entry in the changelog. Thread 5 hold retrocl_internal_lock :
{{{ Thread 5 ... #36 0x00007f46e04e757a in op_shared_add (pb=pb@entry=0x7f46e326c960) at ldap/servers/slapd/add.c:735 #37 0x00007f46e04e7dd3 in add_internal_pb (pb=pb@entry=0x7f46e326c960) at ldap/servers/slapd/add.c:434 #38 0x00007f46e04e8aa3 in slapi_add_internal_pb (pb=pb@entry=0x7f46e326c960) at ldap/servers/slapd/add.c:356 #39 0x00007f46d3691c81 in write_replog_db (newsuperior=0x0, modrdn_mods=0x0, newrdn=0x0, log_e=0x0, curtime=1399376225, flag=0, log_m=0x7f46e30364c0, dn=0x7f46e32227c0 "ou=ca,ou=requests,o=ipaca", optype=<optimized out>, pb=<optimized out>) at ldap/servers/plugins/retrocl/retrocl_po.c:371 #40 retrocl_postob (pb=<optimized out>, optype=<optimized out>) at ldap/servers/plugins/retrocl/retrocl_po.c:668 ...
}}}
Testing a fix suggested by Rich. (catch DB_DEADLOCK, release cursor, abort txn, then returns a failure and let caller to retry).
The fix looks successful to prevent the hang. The hang use to occur one time out 3-4 run of freeipa unit tests. With the fix I was unable to reproduce the hang in 10 run.
Note, that this fix triggers the failure of the add_internal_pb in case of DB_DEADLOCK. This reveal a problem (https://fedorahosted.org/389/ticket/47802) if the caller of add_internal_pb does not test the failure.
attachment 0001-Ticket-deadlock-txn-failure.patch
The fix looks good to me. As you see in this declaration, entryrdn_get_elem has a sibling _entryrdn_get_tombstone_elem. Do we want to apply the similar change to the function, too? {{{ 116 static int _entryrdn_get_elem(DBC cursor, DBT key, DBT data, const char comp_key, rdn_elem elem); 116 static int _entryrdn_get_elem(DBC cursor, DBT key, DBT data, const char comp_key, rdn_elem elem, DB_TXN db_txn); 117 117 static int _entryrdn_get_tombstone_elem(DBC cursor, Slapi_RDN srdn, DBT key, const char comp_key, rdn_elem *elem); }}} And does which 389-ds-base version need this fix? Probably, 1.3.2?
Hi Noriko, thanks for looking at the fix. Yes you are correct, fixing _entryrdn_get_tombstone_elem as well is a good idea and looks not complex. Note that there is no test case for _entryrdn_get_tombstone_elem, freeipa unit test only reproduce hang with normal nodes (not tombstone).
I will rework the fix
Oppss missed the second part of your update.
It looks like the bug exists at least in master, 1.3.2, 1.3.1 and 1.2.11
I reproduced and tested the fix in 1.3.2, so yes the bug exists in 1.3.2 and I believe it worth backporting it into that version. For previous versions, we may backport on demand. The signature of the hang being very clear, it will be easy to determine that we hit that bug.
attachment 0001-Ticket-47797-DB-deadlock-when-two-threads-on-separat.patch
Minor nitpick: there are indentation issues in your patch. Tabs were used in places where the surrounding code was using 4 space indentations.
'''Fix in master'''
git merge ticket_47797 Updating 708a56b..0dd8b68 Fast-forward ldap/servers/slapd/back-ldbm/ldbm_entryrdn.c | 263 +++++++++++++++++++++++++++++++++++++++++++++++++------------------------------ 1 file changed, 163 insertions(+), 100 deletions(-)
git push origin master Counting objects: 13, done. Delta compression using up to 4 threads. Compressing objects: 100% (7/7), done. Writing objects: 100% (7/7), 2.42 KiB, done. Total 7 (delta 5), reused 0 (delta 0) To ssh://git.fedorahosted.org/git/389/ds.git 708a56b..85016a8 master -> master
commit 85016a8 Author: Thierry bordaz (tbordaz) tbordaz@redhat.com Date: Thu Jul 10 14:05:16 2014 +0200
'''Fix in 389-ds-base-1.3.2'''
git push origin 389-ds-base-1.3.2 Counting objects: 13, done. Delta compression using up to 4 threads. Compressing objects: 100% (7/7), done. Writing objects: 100% (7/7), 2.31 KiB, done. Total 7 (delta 5), reused 0 (delta 0) To ssh://git.fedorahosted.org/git/389/ds.git 513788c..a722b2e 389-ds-base-1.3.2 -> 389-ds-base-1.3.2
commit a722b2e Author: Thierry bordaz (tbordaz) tbordaz@redhat.com Date: Thu Jul 10 14:05:16 2014 +0200
'''Fix in master (indentation of the fix)'''
git merge ticket_47797 Updating 85016a8..0bfe1ee Fast-forward ldap/servers/slapd/back-ldbm/ldbm_entryrdn.c | 38 +++++++++++++++++++------------------- 1 file changed, 19 insertions(+), 19 deletions(-)
git push origin master Counting objects: 13, done. Delta compression using up to 4 threads. Compressing objects: 100% (7/7), done. Writing objects: 100% (7/7), 929 bytes, done. Total 7 (delta 5), reused 0 (delta 0) To ssh://git.fedorahosted.org/git/389/ds.git 85016a8..0bfe1ee master -> master
commit 0bfe1ee Author: Thierry bordaz (tbordaz) tbordaz@redhat.com Date: Fri Jul 11 15:24:53 2014 +0200
'''Fix in 389-ds-base-1.3.2 (indentation of the fix)'''
git push origin 389-ds-base-1.3.2 Counting objects: 13, done. Delta compression using up to 4 threads. Compressing objects: 100% (7/7), done. Writing objects: 100% (7/7), 911 bytes, done. Total 7 (delta 5), reused 0 (delta 0) To ssh://git.fedorahosted.org/git/389/ds.git a722b2e..107722f 389-ds-base-1.3.2 -> 389-ds-base-1.3.2
commit 107722f Author: Thierry bordaz (tbordaz) tbordaz@redhat.com Date: Fri Jul 11 15:24:53 2014 +0200
Metadata Update from @tbordaz: - Issue assigned to tbordaz - Issue set to the milestone: 1.3.2.20
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/1128
If you want to receive further updates on the issue, please navigate to the github issue and click on subscribe button.
subscribe
Thank you for understanding. We apologize for all inconvenience.
Metadata Update from @spichugi: - Issue close_status updated to: wontfix (was: Fixed)
Login to comment on this ticket.