1307152 – keep alive entries can break replication

Bug 1307152 - keep alive entries can break replication

Summary: keep alive entries can break replication

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 6
Classification:	Red Hat
Component:	389-ds-base
Sub Component:
Version:	6.0
Hardware:	All
OS:	Linux
Priority:	urgent
Severity:	urgent
Target Milestone:	rc
Target Release:	---
Assignee:	Noriko Hosoi
QA Contact:	Viktor Ashirov
Docs Contact:	Petr Bokoc
URL:
Whiteboard:
Depends On:
Blocks:	1309962
TreeView+	depends on / blocked

Reported:	2016-02-12 20:56 UTC by Noriko Hosoi
Modified:	2020-09-13 21:38 UTC (History)
CC List:	8 users (show)
Fixed In Version:	389-ds-base-1.2.11.15-73.el6
Doc Type:	Bug Fix
Doc Text:	Unnecessary `keep alive` entries no longer cause missing replication Previously, a `keep alive` entry was being created at too many opportunities during replication, potentially causing a race condition when adding the entry to the replica changelog and resulting in operations being dropped from the replication. With this update, unnecessary `keep alive` entry creation has been eliminated, and missing replication no longer occurs.
Clone Of:
Clones:	1309962 (view as bug list)
Environment:
Last Closed:	2016-05-10 19:22:58 UTC
Target Upstream Version:

Attachments	(Terms of Use)
Add an attachment (proposed patch, testcase, etc.)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Github	389ds 389-ds-base issues 1767	0	None	None	None	2020-09-13 21:38:52 UTC
Red Hat Product Errata	RHBA-2016:0737	0	normal	SHIPPED_LIVE	389-ds-base bug fix and enhancement update	2016-05-10 22:29:13 UTC

Description Noriko Hosoi 2016-02-12 20:56:01 UTC

This bug is created as a clone of upstream ticket:
https://fedorahosted.org/389/ticket/48445

There is a scenario where the added keep alive entry is in the database but is missing from the changelog. When this entry is updated the replication of the MOD fails because the ADD of the entry is not replicated.

It looks like the changelog is recreated just after adding the keep alive entry

[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - Need to create replication keep alive entry <cn=repl keep alive 3,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com>
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - add dn: cn=repl keep alive 3,dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com
objectclass: top
objectclass: ldapsubentry
objectclass: extensibleObject
cn: repl keep alive 3
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - ruv_add_csn_inprogress: successfully inserted csn 56ab4413000100030000 into pending list
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: no DB object found for database /var/lib/dirsrv/slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM/cldb/2abae513-c67611e5-b4f3d71a-a8c5143d_56ab4413000000030000.db
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5NewDBFile: semaphore /var/lib/dirsrv/slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM/cldb/2abae513-c67611e5-b4f3d71a-a8c5143d.sema
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5NewDBFile: maxConcurrentWrites=2
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5GetEntryCount: 0 changes for replica 2abae513-c67611e5-b4f3d71a-a8c5143d
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5AddDBFile: Added new DB object 55a280d8fb30
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5DBOpenFileByReplicaName: created new DB object 55a280d8fb30
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: found DB object 55a280d8fb30 for database /var/lib/dirsrv/slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM/cldb/2abae513-c67611e5-b4f3d71a-a8c5143d_56ab4413000000030000.db
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - ruv_update_ruv: successfully committed csn 56ab4413000100030000
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - conn=0 op=0 repl="dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com": Released replica held by locking_purl=conn=5 id=5
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - replica_enable_replication: replica dc=abc,dc=idm,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com is relinquished
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - agmt="cn=meTovm-058-073.abc.idm.lab.eng.brq.redhat.com" (vm-058-073:389): No linger to cancel on the connection
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - agmt="cn=meTovm-058-073.abc.idm.lab.eng.brq.redhat.com" (vm-058-073:389): Disconnected from the consumer
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - agmt="cn=meTovm-058-073.abc.idm.lab.eng.brq.redhat.com" (vm-058-073:389): State: start -> ready_to_acquire_replica
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - agmt="cn=meTovm-058-073.abc.idm.lab.eng.brq.redhat.com" (vm-058-073:389): Trying non-secure slapi_ldap_init_ext
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - agmt="cn=meTovm-058-073.abc.idm.lab.eng.brq.redhat.com" (vm-058-073:389): binddn = ,  passwd =
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - agmt="cn=meTovm-058-073.abc.idm.lab.eng.brq.redhat.com" (vm-058-073:389): Unable to acquire replica: permission denied. The bind dn "" does not have permission to supply replication updates to the replica. Will retry later.
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - agmt="cn=meTovm-058-073.abc.idm.lab.eng.brq.redhat.com" (vm-058-073:389): Beginning linger on the connection
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - agmt="cn=meTovm-058-073.abc.idm.lab.eng.brq.redhat.com" (vm-058-073:389): State: ready_to_acquire_replica -> start_backoff
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5GetDBFile: found DB object 55a280d8fb30 for database /var/lib/dirsrv/slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM/cldb/2abae513-c67611e5-b4f3d71a-a8c5143d_56ab4413000000030000.db
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5DBDeleteFile: removed DB object 55a280d8fb30
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5DBCloseFile: Closing database /var/lib/dirsrv/slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM/cldb/2abae513-c67611e5-b4f3d71a-a8c5143d_56ab4413000000030000.db
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5DBCloseFile: Closed the changelog database handle for /var/lib/dirsrv/slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM/cldb/2abae513-c67611e5-b4f3d71a-a8c5143d_56ab4413000000030000.db (rc: 0)
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5DBCloseFile: removing the changelog /var/lib/dirsrv/slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM/cldb/2abae513-c67611e5-b4f3d71a-a8c5143d_56ab4413000000030000.db (flag 256)
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5DBCloseFile: Deleted the changelog database file /var/lib/dirsrv/slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM/cldb/2abae513-c67611e5-b4f3d71a-a8c5143d_56ab4413000000030000.db
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: no DB object found for database /var/lib/dirsrv/slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM/cldb/2abae513-c67611e5-b4f3d71a-a8c5143d_56ab4397000000040000.db
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5NewDBFile: semaphore /var/lib/dirsrv/slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM/cldb/2abae513-c67611e5-b4f3d71a-a8c5143d.sema
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5NewDBFile: maxConcurrentWrites=2
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5GetEntryCount: 0 changes for replica 2abae513-c67611e5-b4f3d71a-a8c5143d
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5AddDBFile: Added new DB object 7f02342026d0
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5DBOpenFileByReplicaName: created new DB object 7f02342026d0
[29/Jan/2016:11:50:59 +0100] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: found DB object 7f02342026d0 for database /var/lib/dirsrv/slapd-ABC-IDM-LAB-ENG-BRQ-REDHAT-COM/cldb/2abae513-c67611e5-b4f3d71a-

Comment 1 Marc Sauton 2016-02-12 22:35:36 UTC

GSS Approved Z-Stream

Comment 7 Amita Sharma 2016-03-29 11:51:57 UTC

[root@ipaqa64vmd export]# rpm -qa | grep 389
389-ds-base-1.2.11.15-74.el6.x86_64
389-ds-base-libs-1.2.11.15-74.el6.x86_64
[root@ipaqa64vmd export]# cat /etc/redhat-release 
Red Hat Enterprise Linux Server release 6.8 Beta (Santiago)

Executed steps :: https://bugzilla.redhat.com/show_bug.cgi?id=1309962#c12

Keep alive entry is added on M1 by M2 after 100+ updates ::
[29/Mar/2016:07:42:20 -0400] NSMMReplicationPlugin - agmt="cn=M1_to_M2" (localhost:1389): replay_update: Sending add operation (dn="cn=repl keep alive 7,dc=example,dc=com" csn=56fa6829000100070000)
[29/Mar/2016:07:42:20 -0400] NSMMReplicationPlugin - agmt="cn=M1_to_M2" (localhost:1389): replay_update: Consumer successfully sent operation with csn 56fa6829000100070000
[29/Mar/2016:07:42:20 -0400] agmt="cn=M1_to_M2" (localhost:1389) - load=1 rec=2 csn=56fa6a1a000000070000
[29/Mar/2016:07:42:20 -0400] - repl5_inc_result_threadmain: read result for message_id 0
[29/Mar/2016:07:42:20 -0400] NSMMReplicationPlugin - agmt="cn=M1_to_M2" (localhost:1389): replay_update: Sending add operation (dn="uid=ami,dc=example,dc=com" csn=56fa6a1a000000070000)
[29/Mar/2016:07:42:20 -0400] - repl5_inc_result_threadmain: read result for message_id 5
[29/Mar/2016:07:42:20 -0400] - repl5_inc_result_threadmain: result 1, 68, 1, 5, (null)
[29/Mar

Hence VERIFIED

Comment 9 errata-xmlrpc 2016-05-10 19:22:58 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-2016-0737.html

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