Bug 1076729 - Continuous add/delete of an entry in MMR setup causes entryrdn-index conflict
Summary: Continuous add/delete of an entry in MMR setup causes entryrdn-index conflict
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: 389-ds-base
Version: 7.0
Hardware: Unspecified
OS: Unspecified
medium
unspecified
Target Milestone: rc
: 7.1
Assignee: Noriko Hosoi
QA Contact: Viktor Ashirov
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-03-14 22:45 UTC by Milan Kubík
Modified: 2015-03-05 09:34 UTC (History)
3 users (show)

Fixed In Version: 389-ds-base-1.3.3.1-1.el7
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-03-05 09:34:02 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2015:0416 normal SHIPPED_LIVE Important: 389-ds-base security, bug fix, and enhancement update 2015-03-05 14:26:33 UTC

Description Milan Kubík 2014-03-14 22:45:57 UTC
Description of problem:
I ran into this problem trying to verify #1074084. When I tried to run a script that adds and deletes an entry on all masters repeatedly to create a conflict and nsuniqueid entry one of the servers got into the state which can be seen in this log excerpt:

    [14/Mar/2014:05:53:54 -0400] - slapd started.  Listening on All Interfaces port 2389 for LDAP requests
    [14/Mar/2014:05:59:29 -0400] entryrdn-index - _entryrdn_insert_key: Same DN (dn: uid=range_user12,ou=People,dc=example,dc=com) is already in the entryrdn file with different ID 4383.  Expected ID is 4384.
    [14/Mar/2014:05:59:29 -0400] - database index operation failed BAD 1031, err=9999 Unknown error 9999
    [14/Mar/2014:05:59:29 -0400] - add: attempt to index 4384 failed (rc=9999)
    [14/Mar/2014:05:59:30 -0400] conn=200 op=477 csn=5322d301000700070000 - Annotated DN nsuniqueid=3fb02ccc-ab5f11e3-9f529539-057f01ef+uid=range_user12,ou=People,dc=example,dc=com has naming conflict
    [14/Mar/2014:05:59:30 -0400] conn=200 op=479 csn=5322d302000000070000 - Annotated DN nsuniqueid=3fb02ccc-ab5f11e3-9f529539-057f01ef,nsuniqueid=3fb02ccc-ab5f11e3-9f529539-057f01ef+uid=range_user12,ou=People,dc=example,dc=com has naming conflict
    [14/Mar/2014:05:59:30 -0400] ldbm_back_delete - Attempt to Tombstone again a tombstone entry uid=range_user12,ou=people,dc=example,dc=com
    [14/Mar/2014:05:59:30 -0400] NSMMReplicationPlugin - IsValidOperation: NULL operation CSN
    [14/Mar/2014:05:59:30 -0400] NSMMReplicationPlugin - write_changelog_and_ruv: can't add a change for uid=range_user12,ou=people,dc=example,dc=com (uniqid: 3fb02ccc-ab5f11e3-9f529539-057f01ef, optype: 32) to changelog csn
    [14/Mar/2014:05:59:30 -0400] - SLAPI_PLUGIN_BE_TXN_POST_DELETE_FN plugin returned error code
    [14/Mar/2014:05:59:30 -0400] - SLAPI_PLUGIN_BE_TXN_POST_DELETE_FN plugin returned error code but did not set SLAPI_RESULT_CODE
    [14/Mar/2014:05:59:31 -0400] ldbm_back_delete - Attempt to Tombstone again a tombstone entry uid=range_user12,ou=people,dc=example,dc=com
    [14/Mar/2014:05:59:31 -0400] NSMMReplicationPlugin - IsValidOperation: NULL operation CSN
    [14/Mar/2014:05:59:31 -0400] NSMMReplicationPlugin - write_changelog_and_ruv: can't add a change for uid=range_user12,ou=people,dc=example,dc=com (uniqid: 3fb02ccc-ab5f11e3-9f529539-057f01ef, optype: 32) to changelog csn
    [14/Mar/2014:05:59:31 -0400] - SLAPI_PLUGIN_BE_TXN_POST_DELETE_FN plugin returned error code
    [14/Mar/2014:05:59:31 -0400] - SLAPI_PLUGIN_BE_TXN_POST_DELETE_FN plugin returned error code but did not set SLAPI_RESULT_CODE
    ...
    [14/Mar/2014:06:00:06 -0400] conn=202 op=76 csn=5322d296000600090000 - Annotated DN nsuniqueid=3fb02ccc-ab5f11e3-9f529539-057f01ef,nsuniqueid=3fb02ccc-ab5f11e3-9f529539-057f01ef+uid=range_user12,ou=People,dc=example,dc=com has naming conflict
    [14/Mar/2014:06:00:06 -0400] conn=202 op=78 csn=5322d296000800090000 - Annotated DN nsuniqueid=3fb02ccc-ab5f11e3-9f529539-057f01ef,nsuniqueid=3fb02ccc-ab5f11e3-9f529539-057f01ef+uid=range_user12,ou=People,dc=example,dc=com has naming conflict
    ...
    [14/Mar/2014:06:00:13 -0400] conn=202 op=416 csn=5322d302000100090000 - Annotated DN nsuniqueid=3fb02ccc-ab5f11e3-9f529539-057f01ef,nsuniqueid=3fb02ccc-ab5f11e3-9f529539-057f01ef+uid=range_user12,ou=People,dc=example,dc=com has naming conflict
    [14/Mar/2014:06:00:27 -0400] ldbm_back_delete - Attempt to Tombstone again a tombstone entry uid=range_user12,ou=people,dc=example,dc=com
    [14/Mar/2014:06:00:27 -0400] NSMMReplicationPlugin - IsValidOperation: NULL operation CSN
    [14/Mar/2014:06:00:27 -0400] NSMMReplicationPlugin - write_changelog_and_ruv: can't add a change for uid=range_user12,ou=people,dc=example,dc=com (uniqid: 3fb02ccc-ab5f11e3-9f529539-057f01ef, optype: 32) to changelog csn
    [14/Mar/2014:06:00:27 -0400] - SLAPI_PLUGIN_BE_TXN_POST_DELETE_FN plugin returned error code
    [14/Mar/2014:06:00:27 -0400] - SLAPI_PLUGIN_BE_TXN_POST_DELETE_FN plugin returned error code but did not set SLAPI_RESULT_CODE


There seems to be a problem with entryrdn-index that causes (?) a cascade of other problems (deleting tombstone entry, invalid CSN operation, corrupted changelog).

Version-Release number of selected component (if applicable):
389-ds-base-1.3.1.6-24.el7

How reproducible:
always

Steps to Reproduce:
1. Set up MMR environment.
2. Continuously add and delete an entry on all masters, trying to create conflicts and nsuniqueid entries.

Actual results:
After some time the entry is no longer replicated on the affected server. Also the entry is not searchable, add operation fails and reports the entry being present, delete operation fails.


Expected results:
The conflict in entryrdn index does not occur.

Additional info:
Possible blocker for bugzilla #1074084. Probably a race condition.

Comment 2 Noriko Hosoi 2014-05-12 23:00:46 UTC
Milan Kubík wrote:
> I ran into this problem trying to verify #1074084.
How to verify: https://bugzilla.redhat.com/show_bug.cgi?id=1074084#c2
(although it is very simple...)

Comment 4 Amita Sharma 2015-01-12 08:20:55 UTC
M1 ::
[12/Jan/2015:13:46:21 +051800] conn=243 fd=66 slot=66 connection from ::1 to ::1
[12/Jan/2015:13:46:21 +051800] conn=243 op=0 BIND dn="cn=Directory Manager" method=128 version=3
[12/Jan/2015:13:46:21 +051800] conn=243 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[12/Jan/2015:13:46:21 +051800] conn=243 op=1 ADD dn="uid=amita,ou=people,dc=example,dc=com"
[12/Jan/2015:13:46:21 +051800] conn=243 op=1 RESULT err=0 tag=105 nentries=0 etime=0 csn=54b382d6000500010000
[12/Jan/2015:13:46:21 +051800] conn=243 op=2 UNBIND
[12/Jan/2015:13:46:21 +051800] conn=243 op=2 fd=66 closed - U1
[12/Jan/2015:13:46:21 +051800] conn=244 fd=66 slot=66 connection from ::1 to ::1
[12/Jan/2015:13:46:21 +051800] conn=244 op=0 BIND dn="cn=Directory Manager" method=128 version=3
[12/Jan/2015:13:46:21 +051800] conn=244 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[12/Jan/2015:13:46:21 +051800] conn=244 op=1 DEL dn="uid=amita,ou=people,dc=example,dc=com"
[12/Jan/2015:13:46:22 +051800] conn=244 op=1 RESULT err=0 tag=107 nentries=0 etime=1 csn=54b382d6000600010000
[12/Jan/2015:13:46:22 +051800] conn=244 op=2 UNBIND
[12/Jan/2015:13:46:22 +051800] conn=244 op=2 fd=66 closed - U1
[12/Jan/2015:13:46:22 +051800] conn=49 op=21 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop"
[12/Jan/2015:13:46:22 +051800] conn=49 op=21 RESULT err=0 tag=120 nentries=0 etime=0
[12/Jan/2015:13:46:23 +051800] conn=48 op=203 EXT oid="2.16.840.1.113730.3.5.5" name="Netscape Replication End Session"
[12/Jan/2015:13:46:23 +051800] conn=48 op=203 RESULT err=0 tag=120 nentries=0 etime=0
[12/Jan/2015:13:46:23 +051800] conn=48 op=204 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop"
[12/Jan/2015:13:46:23 +051800] conn=48 op=204 RESULT err=0 tag=120 nentries=0 etime=0
[12/Jan/2015:13:46:23 +051800] conn=48 op=205 DEL dn="uid=amita,ou=people,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=48 op=205 RESULT err=0 tag=107 nentries=0 etime=0 csn=54b382d5000400020000
[12/Jan/2015:13:46:23 +051800] conn=48 op=206 ADD dn="uid=amita,ou=People,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=48 op=206 RESULT err=0 tag=105 nentries=0 etime=0 csn=54b382d5000500020000
[12/Jan/2015:13:46:23 +051800] conn=48 op=207 DEL dn="uid=amita,ou=people,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=48 op=207 RESULT err=0 tag=107 nentries=0 etime=0 csn=54b382d5000700020000
[12/Jan/2015:13:46:23 +051800] conn=48 op=208 ADD dn="uid=amita,ou=People,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=48 op=208 RESULT err=0 tag=105 nentries=0 etime=0 csn=54b382d6000000020000
[12/Jan/2015:13:46:23 +051800] conn=48 op=209 DEL dn="uid=amita,ou=people,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=48 op=209 RESULT err=0 tag=107 nentries=0 etime=0 csn=54b382d6000100020000
[12/Jan/2015:13:46:23 +051800] conn=48 op=210 ADD dn="uid=amita,ou=People,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=48 op=210 RESULT err=0 tag=105 nentries=0 etime=0 csn=54b382d6000200020000
[12/Jan/2015:13:46:23 +051800] conn=48 op=211 DEL dn="uid=amita,ou=people,dc=example,dc=com"
[12/Jan/2015:13:46:24 +051800] conn=48 op=211 RESULT err=0 tag=107 nentries=0 etime=1 csn=54b382d6000300020000
[12/Jan/2015:13:46:24 +051800] conn=48 op=212 ADD dn="uid=amita,ou=People,dc=example,dc=com"
[12/Jan/2015:13:46:24 +051800] conn=48 op=212 RESULT err=0 tag=105 nentries=0 etime=0 csn=54b382d6000400020000
[12/Jan/2015:13:46:24 +051800] conn=48 op=213 DEL dn="uid=amita,ou=people,dc=example,dc=com"
[12/Jan/2015:13:46:24 +051800] conn=48 op=213 RESULT err=0 tag=107 nentries=0 etime=0 csn=54b382d6000500020000
[12/Jan/2015:13:46:24 +051800] conn=48 op=214 ADD dn="uid=amita,ou=People,dc=example,dc=com"
[12/Jan/2015:13:46:24 +051800] conn=48 op=214 RESULT err=0 tag=105 nentries=0 etime=0 csn=54b382d6000600020000
[12/Jan/2015:13:46:24 +051800] conn=48 op=215 DEL dn="uid=amita,ou=people,dc=example,dc=com"
[12/Jan/2015:13:46:24 +051800] conn=48 op=215 RESULT err=0 tag=107 nentries=0 etime=0 csn=54b382d7000000020000
[12/Jan/2015:13:46:25 +051800] conn=49 op=23 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop"
[12/Jan/2015:13:46:25 +051800] conn=49 op=23 RESULT err=0 tag=120 nentries=0 etime=0
[12/Jan/2015:13:46:26 +051800] conn=48 op=217 EXT oid="2.16.840.1.113730.3.5.5" name="Netscape Replication End Session"
[12/Jan/2015:13:46:26 +051800] conn=48 op=217 RESULT err=0 tag=120 nentries=0 etime=0
[12/Jan/2015:13:46:28 +051800] conn=49 op=24 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop"
[12/Jan/2015:13:46:28 +051800] conn=49 op=24 RESULT err=0 tag=120 nentries=0 etime=0
[12/Jan/2015:13:46:28 +051800] conn=49 op=25 EXT oid="2.16.840.1.113730.3.5.5" name="Netscape Replication End Session"
[12/Jan/2015:13:46:28 +051800] conn=49 op=25 RESULT err=0 tag=120 nentries=0 etime=0
[12/Jan/2015:13:47:27 +051800] conn=48 op=218 UNBIND
[12/Jan/2015:13:47:27 +051800] conn=48 op=218 fd=64 closed - U1
[12/Jan/2015:13:47:29 +051800] conn=49 op=27 UNBIND
[12/Jan/2015:13:47:29 +051800] conn=49 op=27 fd=65 closed - U1

M2 ::
===
[12/Jan/2015:13:46:23 +051800] conn=46 op=205 DEL dn="uid=amita,ou=people,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=46 op=205 RESULT err=0 tag=107 nentries=0 etime=0 csn=54b382d5000500010000
[12/Jan/2015:13:46:23 +051800] conn=46 op=206 ADD dn="uid=amita,ou=People,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=46 op=206 RESULT err=0 tag=105 nentries=0 etime=0 csn=54b382d5000600010000
[12/Jan/2015:13:46:23 +051800] conn=46 op=207 DEL dn="uid=amita,ou=people,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=46 op=207 RESULT err=0 tag=107 nentries=0 etime=0 csn=54b382d6000000010000
[12/Jan/2015:13:46:23 +051800] conn=46 op=208 ADD dn="uid=amita,ou=People,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=46 op=208 RESULT err=0 tag=105 nentries=0 etime=0 csn=54b382d6000100010000
[12/Jan/2015:13:46:23 +051800] conn=46 op=209 DEL dn="uid=amita,ou=people,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=46 op=209 RESULT err=0 tag=107 nentries=0 etime=0 csn=54b382d6000200010000
[12/Jan/2015:13:46:23 +051800] conn=46 op=210 ADD dn="uid=amita,ou=People,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=46 op=210 RESULT err=0 tag=105 nentries=0 etime=0 csn=54b382d6000300010000
[12/Jan/2015:13:46:23 +051800] conn=46 op=211 DEL dn="uid=amita,ou=people,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=46 op=211 RESULT err=0 tag=107 nentries=0 etime=0 csn=54b382d6000400010000
[12/Jan/2015:13:46:23 +051800] conn=46 op=212 ADD dn="uid=amita,ou=People,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=46 op=212 RESULT err=0 tag=105 nentries=0 etime=0 csn=54b382d6000500010000
[12/Jan/2015:13:46:23 +051800] conn=46 op=213 DEL dn="uid=amita,ou=people,dc=example,dc=com"
[12/Jan/2015:13:46:23 +051800] conn=46 op=213 RESULT err=0 tag=107 nentries=0 etime=0 csn=54b382d6000600010000
[12/Jan/2015:13:46:25 +051800] conn=48 op=24 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop"
[12/Jan/2015:13:46:25 +051800] conn=48 op=24 RESULT err=0 tag=120 nentries=0 etime=0
[12/Jan/2015:13:46:26 +051800] conn=46 op=215 EXT oid="2.16.840.1.113730.3.5.5" name="Netscape Replication End Session"
[12/Jan/2015:13:46:26 +051800] conn=46 op=215 RESULT err=0 tag=120 nentries=0 etime=0
[12/Jan/2015:13:46:27 +051800] conn=46 op=216 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop"
[12/Jan/2015:13:46:27 +051800] conn=46 op=216 RESULT err=0 tag=120 nentries=0 etime=0
[12/Jan/2015:13:46:27 +051800] conn=46 op=217 EXT oid="2.16.840.1.113730.3.5.5" name="Netscape Replication End Session"
[12/Jan/2015:13:46:27 +051800] conn=46 op=217 RESULT err=0 tag=120 nentries=0 etime=0
[12/Jan/2015:13:46:27 +051800] conn=48 op=26 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop"
[12/Jan/2015:13:46:27 +051800] conn=48 op=26 RESULT err=0 tag=120 nentries=0 etime=0
[12/Jan/2015:13:46:27 +051800] conn=48 op=27 EXT oid="2.16.840.1.113730.3.5.5" name="Netscape Replication End Session"
[12/Jan/2015:13:46:27 +051800] conn=48 op=27 RESULT err=0 tag=120 nentries=0 etime=0
[12/Jan/2015:13:47:27 +051800] conn=48 op=28 UNBIND
[12/Jan/2015:13:47:27 +051800] conn=48 op=28 fd=66 closed - U1
[12/Jan/2015:13:47:28 +051800] conn=46 op=218 UNBIND
[12/Jan/2015:13:47:28 +051800] conn=46 op=218 fd=64 closed - U1

No error found, hence marking as VERIFIED.

Comment 6 errata-xmlrpc 2015-03-05 09:34:02 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHSA-2015-0416.html


Note You need to log in before you can comment on or make changes to this bug.