Bug 1235847

Summary:	handling of "No original_tombstone for changenumber" errors
Product:	Red Hat Enterprise Linux 7	Reporter:	Marc Sauton <msauton>
Component:	389-ds-base	Assignee:	Noriko Hosoi <nhosoi>
Status:	CLOSED ERRATA	QA Contact:	Viktor Ashirov <vashirov>
Severity:	urgent	Docs Contact:
Priority:	urgent
Version:	7.1	CC:	ekeck, gparente, nhosoi, nkinder, rmeggins, sramling, tbordaz
Target Milestone:	rc	Keywords:	ZStream
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	389-ds-base-1.3.4.0-1.el7	Doc Type:	Bug Fix
Doc Text:	The "No original_tombstone for changenumber" error message was logged unnecessarily when no original_tombstone value was defined. The message is now logged only when necessary.	Story Points:	---
Clone Of:
Clones:	1260000 (view as bug list)		Environment:
Last Closed:	2015-11-19 11:42:47 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	1260000

Description Marc Sauton 2015-06-25 22:07:22 UTC

Description of problem:
dirsrv's ns-slapd errors log from salesforce case number 01460148 

are showing the same apparently harmless pattern as described in upstream ticket
https://fedorahosted.org/389/ticket/47912

[11/Jun/2015:12:45:26 -0600] ldbm_back_delete - conn=0 op=0 [retry: 1] No original_tombstone for changenumber=130490,cn=changelog!!

the sf 01460148 is about a different problem, but has some traces, so creating this RHEL 7.1 bz to track the proposed log improvement in ticket 47912


Version-Release number of selected component (if applicable):
RHEL 7.1
389-ds-base-1.3.3.1-16.el7_1.x86_64


How reproducible:
N/A

Steps to Reproduce:
1. N/A
2.
3.

Actual results:


Expected results:


Additional info:

Comment 1 Marc Sauton 2015-06-25 22:07:47 UTC

adding link to 47912

Comment 4 Viktor Ashirov 2015-07-09 20:32:29 UTC

Hi Noriko, 
could you please provide steps to reproduce?

Thanks!

Comment 5 Noriko Hosoi 2015-07-09 21:58:41 UTC

(In reply to Viktor Ashirov from comment #4)
> Hi Noriko, 
> could you please provide steps to reproduce?

Hi Viktor,

The problem was this false error message was logged even in the tombstone deletion... :(
> dbm_back_delete - conn=0 op=0 [retry: 1] No original_tombstone for changenumber=##,cn=changelog!!

Please create tombstone entries and configure reaping tombstone with short delay and interval to make the reap occur quite often.
  nsds5ReplicaPurgeDelay
  nsds5ReplicaTombstonePurgeInterval

You may want to stress the server by repeating the add and delete since the message is logged in the deadlock retry.  If the tombstone entries are deleted without a log message "No original_tombstone for changenumber=##,cn=changelog!!"
we could set VERIFIED.

Thanks!
--noriko

Comment 9 Sankar Ramalingam 2015-09-22 12:27:41 UTC

Hi Noriko,

I am seeing errors relevant to killing deadlocks. Can you please check if this is expected?

Modified nsds5ReplicaPurgeDelay and nsds5ReplicaTombstonePurgeInterval attributes to hold small values and deleted about 9999 entries from one of the master. 

[root@dhcp35-196 ~]# PORT="1189"; ldapsearch -LLL -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b  "cn=replica,cn=\"dc=grpmembers,dc=com\",cn=mapping tree,cn=config"  nsds5ReplicaPurgeDelay nsds5ReplicaTombstonePurgeInterval
dn: cn=replica,cn=dc\3Dgrpmembers\2Cdc\3Dcom,cn=mapping tree,cn=config
nsds5ReplicaPurgeDelay: 120
nsds5ReplicaTombstonePurgeInterval: 90

[root@dhcp35-196 ~]# PORT="1289"; ldapsearch -LLL -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b  "cn=replica,cn=\"dc=grpmembers,dc=com\",cn=mapping tree,cn=config"  nsds5ReplicaPurgeDelay nsds5ReplicaTombstonePurgeInterval
dn: cn=replica,cn=dc\3Dgrpmembers\2Cdc\3Dcom,cn=mapping tree,cn=config
nsds5ReplicaPurgeDelay: 120
nsds5ReplicaTombstonePurgeInterval: 90


==> /var/log/dirsrv/slapd-M1/errors <==
[22/Sep/2015:08:00:22 -0400] NSMMReplicationPlugin - changelog program - _cl5WriteOperationTxn: retry (49) the transaction (csn=5601428f0000078c0000) failed (rc=-30993 (BDB0068 DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock))
[22/Sep/2015:08:00:22 -0400] NSMMReplicationPlugin - changelog program - _cl5WriteOperationTxn: failed to write entry with csn (5601428f0000078c0000); db error - -30993 BDB0068 DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock
[22/Sep/2015:08:00:22 -0400] NSMMReplicationPlugin - write_changelog_and_ruv: can't add a change for uid=usrA75,ou=people,dc=grpmembers,dc=com (uniqid: 6e9e4052-603711e5-8264b3c0-1fc4650c, optype: 32) to changelog csn 5601428f0000078c0000
[22/Sep/2015:08:00:22 -0400] - SLAPI_PLUGIN_BE_TXN_POST_DELETE_FN plugin returned error code but did not set SLAPI_RESULT_CODE

==> /var/log/dirsrv/slapd-M2/errors <==
[22/Sep/2015:08:00:54 -0400] NSMMReplicationPlugin - agmt="cn=1289_NEW_to_1616_on_dhcp35-196.lab.eng.blr.redhat.com" (dhcp35-196:1616): Consumer failed to replay change (uniqueid 84136700-603711e5-8264b3c0-1fc4650c, CSN 560142a70000078c0000): Operations error (1). Will retry later.

==> /var/log/dirsrv/slapd-M1/errors <==
[22/Sep/2015:08:01:07 -0400] NSMMReplicationPlugin - changelog program - _cl5WriteOperationTxn: retry (49) the transaction (csn=560142a10000078c0000) failed (rc=-30993 (BDB0068 DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock))
[22/Sep/2015:08:01:07 -0400] NSMMReplicationPlugin - changelog program - _cl5WriteOperationTxn: failed to write entry with csn (560142a10000078c0000); db error - -30993 BDB0068 DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock
[22/Sep/2015:08:01:07 -0400] NSMMReplicationPlugin - write_changelog_and_ruv: can't add a change for uid=usrA84,ou=people,dc=grpmembers,dc=com (uniqid: 6e9e405b-603711e5-8264b3c0-1fc4650c, optype: 32) to changelog csn 560142a10000078c0000
[22/Sep/2015:08:01:07 -0400] - SLAPI_PLUGIN_BE_TXN_POST_DELETE_FN plugin returned error code but did not set SLAPI_RESULT_CODE

Comment 12 Sankar Ramalingam 2015-09-23 10:30:21 UTC

I ran the tests again with the latest builds of 389-ds-base-1.3.4.0-18 and found error messages related DEADLOCK as well as "No original_tombstone for changenumber" error. Hence, marking the bug as Verified.

==> /var/log/dirsrv/slapd-M1/errors <==
[23/Sep/2015:05:06:02 -0400] - repl5_inc_waitfor_async_results timed out waiting for responses: 527 529
[23/Sep/2015:05:07:06 -0400] - repl5_inc_waitfor_async_results timed out waiting for responses: 0 583
[23/Sep/2015:05:07:14 -0400] - repl5_inc_waitfor_async_results timed out waiting for responses: 528 540

==> /var/log/dirsrv/slapd-M2/errors <==
[23/Sep/2015:05:08:20 -0400] - repl5_inc_waitfor_async_results timed out waiting for responses: 0 350
[23/Sep/2015:05:09:31 -0400] - repl5_inc_waitfor_async_results timed out waiting for responses: 353 358


Build tested:
[root@dhcp35-196 export]# rpm -qa |grep -i 389-ds
389-ds-base-1.3.4.0-18.el7.x86_64
389-ds-base-libs-1.3.4.0-18.el7.x86_64

Comment 13 Sankar Ramalingam 2015-09-23 10:41:47 UTC

(In reply to Sankar Ramalingam from comment #12)
> I ran the tests again with the latest builds of 389-ds-base-1.3.4.0-18 and
> found 
NO
error messages related DEADLOCK as well as "No original_tombstone for
> changenumber" error. Hence, marking the bug as Verified.
> 
> ==> /var/log/dirsrv/slapd-M1/errors <==
> [23/Sep/2015:05:06:02 -0400] - repl5_inc_waitfor_async_results timed out
> waiting for responses: 527 529
> [23/Sep/2015:05:07:06 -0400] - repl5_inc_waitfor_async_results timed out
> waiting for responses: 0 583
> [23/Sep/2015:05:07:14 -0400] - repl5_inc_waitfor_async_results timed out
> waiting for responses: 528 540
> 
> ==> /var/log/dirsrv/slapd-M2/errors <==
> [23/Sep/2015:05:08:20 -0400] - repl5_inc_waitfor_async_results timed out
> waiting for responses: 0 350
> [23/Sep/2015:05:09:31 -0400] - repl5_inc_waitfor_async_results timed out
> waiting for responses: 353 358
> 
> 
> Build tested:
> [root@dhcp35-196 export]# rpm -qa |grep -i 389-ds
> 389-ds-base-1.3.4.0-18.el7.x86_64
> 389-ds-base-libs-1.3.4.0-18.el7.x86_64

Comment 14 errata-xmlrpc 2015-11-19 11:42:47 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/RHBA-2015-2351.html