On 10/19/2016 03:48 PM, Andrew E. Bruno wrote:
On Wed, Oct 19, 2016 at 10:13:26AM +0200, Ludwig Krispenz wrote:
On 10/18/2016 08:52 PM, Andrew E. Bruno wrote:
We had one of our replicas fail today with the following errors:


[18/Oct/2016:13:40:47 -0400] agmt="cn=meTosrv-m14-32.cbls.ccr.buffalo.edu" 
(srv-m14-32:389) - Can't locate CSN 58065ef3000100030000 in the changelog (DB rc=-30988). 
If replication stops, the consumer may need to be reinitialized.
[18/Oct/2016:13:43:07 -0400] NSMMReplicationPlugin - changelog program - 
_cl5WriteOperationTxn: retry (49) the transaction (csn=58065f74000500040000) 
failed (rc=-30993 (BDB0068 DB_LOCK_DEADLOCK: Locker killed to resolve a 
deadlock))
[18/Oct/2016:13:43:07 -0400] NSMMReplicationPlugin - changelog program - 
_cl5WriteOperationTxn: failed to write entry with csn (58065f74000500040000); 
db error - -30993 BDB0068 DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock
[18/Oct/2016:13:43:07 -0400] NSMMReplicationPlugin - write_changelog_and_ruv: 
can't add a change for 
uid=janedoe,cn=users,cn=accounts,dc=cbls,dc=ccr,dc=buffalo,dc=edu (uniqid: 
939bca48-2ced11e5-ac0b8f7e-e0b1a377, optype: 64) to changelog csn 
58065f74000500040000
[18/Oct/2016:13:43:07 -0400] - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin 
returned error but did not set SLAPI_RESULT_CODE
[18/Oct/2016:13:43:07 -0400] NSMMReplicationPlugin - process_postop: Failed to 
apply update (58065f74000500040000) error (1).  Aborting replication 
session(conn=1314106 op=1688559)
[18/Oct/2016:13:43:12 -0400] - cos_cache_change_notify: modified entry is 
NULL--updating cache just in case
[18/Oct/2016:13:43:12 -0400] - Skipping CoS Definition cn=Password 
Policy,cn=accounts,dc=cbls,dc=ccr,dc=buffalo,dc=edu--no CoS Templates found, 
which should be added before the CoS Definition.
[18/Oct/2016:13:43:20 -0400] - Operation error fetching Null DN 
(4a729f9a-955a11e6-aaffa516-e778e883), error -30993.
[18/Oct/2016:13:43:20 -0400] - dn2entry_ext: Failed to get id for 
changenumber=30856302,cn=changelog from entryrdn index (-30993)
[18/Oct/2016:13:43:20 -0400] - Operation error fetching 
changenumber=30856302,cn=changelog (null), error -30993.
[18/Oct/2016:13:43:20 -0400] DSRetroclPlugin - replog: an error occured while 
adding change number 30856302, dn = changenumber=30856302,cn=changelog: 
Operations error.
[18/Oct/2016:13:43:20 -0400] retrocl-plugin - retrocl_postob: operation failure 
[1]
[18/Oct/2016:13:43:20 -0400] NSMMReplicationPlugin - process_postop: Failed to 
apply update (58065f9f000000600000) error (1).  Aborting replication 
session(conn=1901274 op=5)
[18/Oct/2016:13:43:24 -0400] - ldbm_back_seq deadlock retry BAD 1601, err=0 
BDB0062 Successful return: 0
[18/Oct/2016:13:43:25 -0400] NSMMReplicationPlugin - changelog program - 
_cl5WriteOperationTxn: retry (49) the transaction (csn=58065f7c000a00040000) 
failed (rc=-30993 (BDB0068 DB_LOCK_DEADLOCK: Locker killed to resolve a 
deadlock))
[18/Oct/2016:13:43:25 -0400] NSMMReplicationPlugin - changelog program - 
_cl5WriteOperationTxn: failed to write entry with csn (58065f7c000a00040000); 
db error - -30993 BDB0068 DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock
[18/Oct/2016:13:43:25 -0400] NSMMReplicationPlugin - write_changelog_and_ruv: 
can't add a change for 
uid=janedoe,cn=users,cn=accounts,dc=cbls,dc=ccr,dc=buffalo,dc=edu (uniqid: 
4080421a-2d0211e5-ac0b8f7e-e0b1a377, optype: 64) to changelog csn 
58065f7c000a00040000


ns-slapd was hung so we restarted and now it's stuck and won't come back up. It
hangs up here:

[18/Oct/2016:14:12:31 -0400] - Skipping CoS Definition cn=Password 
Policy,cn=accounts,dc=cbls,dc=ccr,dc=buffalo,dc=edu--no CoS Templates found, 
which should be added before the CoS Definition.
[18/Oct/2016:14:12:31 -0400] NSMMReplicationPlugin - changelog program - 
_cl5NewDBFile: PR_DeleteSemaphore: 
/var/lib/dirsrv/slapd-CBLS-CCR-BUFFALO-EDU/cldb/a32992ce-71b811e5-9d33a516-e778e883.sema;
 NSPR error - -5943
[18/Oct/2016:14:12:32 -0400] NSMMReplicationPlugin - changelog program - 
_cl5NewDBFile: PR_DeleteSemaphore: 
/var/lib/dirsrv/slapd-CBLS-CCR-BUFFALO-EDU/cldb/986efe12-71b811e5-9d33a516-e778e883.sema;
 NSPR error - -5943


Tried deleting the semaphore files and restarting but no luck. Attached
is a stacktrace of the stuck ns-slapd process.

Here's the versions were running:

ipa-server-4.2.0-15.0.1.el7.centos.19.x86_64
389-ds-base-1.3.4.0-33.el7_2.x86_64

FWIW, we were experimenting with the new life-cycle management features,
specifically "preserved" users and deleted the user "janedoe" when this
happened.  From the errors above looks like this host failed to
replicate the change?  Not sure if this is related or not.

Is it possible to recover the database? Thanks in advance for any pointers.
from the stack trace the process is not hanging, it is trying to recover.
After a crash/kill  the changelog does not contai a RUV and it is
reconstructed by reading all records in the changelog, if this is large it
can take some time.
If you look at that part of the stack repeatedly,

#4  0x00007f4e88daeba5 in cl5DBData2Entry (data=<optimized out>, len=<optimized 
out>, entry=entry@entry=0x7ffff6598910) at 
ldap/servers/plugins/replication/cl5_api.c:2342
         rc = <optimized out>
         version = <optimized out>
         pos = 0x7f4e9839d091 ""
         strCSN = 0x0
         op = 0x7ffff6598980
         add_mods = 0x7f4e983a5e80
         rawDN = 0x7f4e98396e20 
"fqdn=cpn-k08-29-02.cbls.ccr.buffalo.edu,cn=computers,cn=accounts,dc=cbls,dc=ccr,dc=buffalo,dc=edu"
         s = 
"\300\037>\230N\177\000\000@\210Y\366\377\177\000\000@\210Y\366\377"
#5  0x00007f4e88daf5d6 in _cl5GetNextEntry (entry=entry@entry=0x7ffff6598910, 
iterator=0x7f4e983a5e80) at ldap/servers/plugins/replication/cl5_api.c:5291
         rc = 0
         it = 0x7f4e983a5e80
         key = {data = 0x0, size = 21, ulen = 0, dlen = 0, doff = 0, app_data = 
0x0, flags = 16}
         data = {data = 0x7f4e9839cff0, size = 335, ulen = 0, dlen = 0, doff = 
0, app_data = 0x0, flags = 16}
#6  0x00007f4e88dafb34 in _cl5ConstructRUV (purge=1, obj=0x7f4e983e1fc0, 
replGen=0x7ffff6598910 "\200\211Y\366\377\177") at 
ldap/servers/plugins/replication/cl5_api.c:4306


you should see some progress in which entry is handled

Ludwig, thanks very much for the help. As you pointed out just needed to let it
finish.  ns-slapd eventually came back up once it finished reading the
changelog. Still seeing some errors related to the NSMMReplicationPlugin failed
to apply update and from the managed-entries-plugin. Can these safely be
ignored or are they indicative of a more serious problem?

This is difficult to say the reason of managed entries messages.
It says that the origin entry "uid=janedoe,cn=deleted users,cn=accounts,cn=provisioning,dc=cbls,dc=ccr,dc=buffalo,dc=edu" is still having a managed entry ('|mepManagedEntry') that is possibly something like '|cn=janedoe,cn=groups,cn=accounts,dc=cbls,dc=ccr,dc=buffalo,dc=edu".

This is looking like a bug because user 'janedoe' being a preserved user, it should not have any reference to existing groups.

Could you dump uid=janedoe entry:
ldapsearch -D "cn=directory manager" -w xxxx -b ""uid=janedoe,cn=deleted users,cn=accounts,cn=provisioning,dc=cbls,dc=ccr,dc=buffalo,dc=edu" nscpentrywsi

If the link still exists, it is looking like a bug but IMHO it should not create security issue.

regards
thierry

[19/Oct/2016:09:28:46 -0400] - Operation error fetching Null DN 
(e73b48a4-95ff11e6-8bc7a516-e778e883), error -30993.
[19/Oct/2016:09:28:46 -0400] - dn2entry_ext: Failed to get id for 
changenumber=30856335,cn=changelog from entryrdn index (-30993)
[19/Oct/2016:09:28:46 -0400] - Operation error fetching 
changenumber=30856335,cn=changelog (null), error -30993.
[19/Oct/2016:09:28:46 -0400] DSRetroclPlugin - replog: an error occured while 
adding change number 30856335, dn = changenumber=30856335,cn=changelog: 
Operations error.
[19/Oct/2016:09:28:46 -0400] retrocl-plugin - retrocl_postob: operation failure 
[1]
[19/Oct/2016:09:28:46 -0400] NSMMReplicationPlugin - process_postop: Failed to 
apply update (5806acf7000000600000) error (1).  Aborting replication 
session(conn=9 op=28)
[19/Oct/2016:09:28:54 -0400] - Operation error fetching Null DN 
(e73b48a7-95ff11e6-8bc7a516-e778e883), error -30993.
[19/Oct/2016:09:28:59 -0400] - dn2entry_ext: Failed to get id for 
changenumber=30856337,cn=changelog from entryrdn index (-30993)
[19/Oct/2016:09:29:17 -0400] - Operation error fetching 
changenumber=30856337,cn=changelog (null), error -30993.
[19/Oct/2016:09:29:17 -0400] DSRetroclPlugin - replog: an error occured while 
adding change number 30856337, dn = changenumber=30856337,cn=changelog: 
Operations error.
[19/Oct/2016:09:29:17 -0400] retrocl-plugin - retrocl_postob: operation failure 
[1]
[19/Oct/2016:09:29:17 -0400] NSMMReplicationPlugin - process_postop: Failed to 
apply update (5806acf7000000600000) error (1).  Aborting replication 
session(conn=15 op=5)
[19/Oct/2016:09:29:20 -0400] - Retry count exceeded in delete
[19/Oct/2016:09:29:20 -0400] DSRetroclPlugin - delete_changerecord: could not 
delete change record 30712389 (rc: 51)
[19/Oct/2016:09:29:28 -0400] - Operation error fetching Null DN 
(0afe8e82-960011e6-8bc7a516-e778e883), error -30993.
[19/Oct/2016:09:29:28 -0400] - dn2entry_ext: Failed to get id for 
changenumber=30856351,cn=changelog from entryrdn index (-30993)
[19/Oct/2016:09:29:28 -0400] - Operation error fetching 
changenumber=30856351,cn=changelog (null), error -30993.
[19/Oct/2016:09:29:28 -0400] DSRetroclPlugin - replog: an error occured while 
adding change number 30856351, dn = changenumber=30856351,cn=changelog: 
Operations error.
[19/Oct/2016:09:29:28 -0400] retrocl-plugin - retrocl_postob: operation failure 
[1]
[19/Oct/2016:09:29:28 -0400] NSMMReplicationPlugin - process_postop: Failed to 
apply update (5806acf7000000600000) error (1).  Aborting replication 
session(conn=25 op=5)
[19/Oct/2016:09:29:31 -0400] - Retry count exceeded in delete
[19/Oct/2016:09:29:31 -0400] DSRetroclPlugin - delete_changerecord: could not 
delete change record 30712865 (rc: 51)
[19/Oct/2016:09:29:39 -0400] - Operation error fetching Null DN 
(0afe8e90-960011e6-8bc7a516-e778e883), error -30993.
[19/Oct/2016:09:29:39 -0400] - dn2entry_ext: Failed to get id for 
changenumber=30856364,cn=changelog from entryrdn index (-30993)
[19/Oct/2016:09:29:39 -0400] - Operation error fetching 
changenumber=30856364,cn=changelog (null), error -30993.
[19/Oct/2016:09:29:39 -0400] DSRetroclPlugin - replog: an error occured while 
adding change number 30856364, dn = changenumber=30856364,cn=changelog: 
Operations error.
[19/Oct/2016:09:29:39 -0400] retrocl-plugin - retrocl_postob: operation failure 
[1]
[19/Oct/2016:09:29:39 -0400] NSMMReplicationPlugin - process_postop: Failed to 
apply update (5806acf7000000600000) error (1).  Aborting replication 
session(conn=35 op=5)
[19/Oct/2016:09:29:42 -0400] - Retry count exceeded in delete
[19/Oct/2016:09:29:42 -0400] DSRetroclPlugin - delete_changerecord: could not 
delete change record 30713364 (rc: 51)
[19/Oct/2016:09:29:42 -0400] - Operation error fetching Null DN 
(0afe8ea0-960011e6-8bc7a516-e778e883), error -30993.
[19/Oct/2016:09:29:42 -0400] - dn2entry_ext: Failed to get id for 
changenumber=30856379,cn=changelog from entryrdn index (-30993)
[19/Oct/2016:09:29:42 -0400] - Operation error fetching 
changenumber=30856379,cn=changelog (null), error -30993.
[19/Oct/2016:09:29:42 -0400] DSRetroclPlugin - replog: an error occured while 
adding change number 30856379, dn = changenumber=30856379,cn=changelog: 
Operations error.
[19/Oct/2016:09:29:42 -0400] retrocl-plugin - retrocl_postob: operation failure 
[1]
[19/Oct/2016:09:29:42 -0400] NSMMReplicationPlugin - process_postop: Failed to 
apply update (5806acf7000000600000) error (1).  Aborting replication 
session(conn=36 op=5)
[19/Oct/2016:09:29:50 -0400] - Operation error fetching Null DN 
(0afe8ea2-960011e6-8bc7a516-e778e883), error -30993.
[19/Oct/2016:09:29:50 -0400] - dn2entry_ext: Failed to get id for 
changenumber=30856380,cn=changelog from entryrdn index (-30993)
[19/Oct/2016:09:29:50 -0400] - Operation error fetching 
changenumber=30856380,cn=changelog (null), error -30993.
[19/Oct/2016:09:29:50 -0400] DSRetroclPlugin - replog: an error occured while 
adding change number 30856380, dn = changenumber=30856380,cn=changelog: 
Operations error.
[19/Oct/2016:09:29:50 -0400] retrocl-plugin - retrocl_postob: operation failure 
[1]
...
[19/Oct/2016:09:30:06 -0400] managed-entries-plugin - mep_mod_post_op: Unable to find 
config for origin entry "uid=janedoe,cn=deleted 
users,cn=accounts,cn=provisioning,dc=cbls,dc=ccr,dc=buffalo,dc=edu".
[19/Oct/2016:09:30:06 -0400] managed-entries-plugin - mep_mod_post_op: Unable to find 
config for origin entry "uid=janedoe,cn=deleted 
users,cn=accounts,cn=provisioning,dc=cbls,dc=ccr,dc=buffalo,dc=edu".






-- 
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project

Reply via email to