389 replication issue

[Frank Munsche]

Hi Guys,

I got a replication issue with the 389 ds running at centos 6.7 and the 
following 389 pkgs installed:

389-admin.x86_64                    1.1.35-1.el6                     @epel    
389-admin-console.noarch       1.1.8-1.el6                       @epel    
389-adminutil.x86_64               1.1.19-1.el6                     @epel    
389-console.noarch                  1.1.7-1.el6                       @epel    
389-ds-base.x86_64                 1.2.11.15-65.el6_7           @updates 
389-ds-base-libs.x86_64          1.2.11.15-65.el6_7           @updates 
389-ds-console.noarch             1.2.6-1.el6                        @epel    
389-dsgw.x86_64                     1.1.11-1.el6                       @epel

I'm running a multimaster configuration based on two directory servers (ds1, 
ds2)

When the replication is initiated at ds1 (replication from ds1 to ds2, 
nsds5BeginReplicaRefresh set to 'start') , I find these entries in the error 
log of ds1:

[15/Dec/2015:19:10:11 +0000] NSMMReplicationPlugin - Beginning total update of 
replica "agmt="cn=ds1TOds2" (ds2:389)".
[15/Dec/2015:19:10:11 +0000] NSMMReplicationPlugin - Need to create 
replication keep alive entry <cn=repl keep alive 1,dc=example,dc=org>
[15/Dec/2015:19:10:11 +0000] NSMMReplicationPlugin - add dn: cn=repl keep 
alive 1,dc=example,dc=org
objectclass: top
objectclass: ldapsubentry
objectclass: extensibleObject
cn: repl keep alive 1
[15/Dec/2015:19:10:14 +0000] NSMMReplicationPlugin - Finished total update of 
replica "agmt="cn=ds1TOds2" (ds2:389)". Sent 341 entries.
[15/Dec/2015:19:10:14 +0000] NSMMReplicationPlugin - agmt="cn=ds1TOds2" 
(ds2:389): Consumer failed to replay change (uniqueid 72eca481-a35f11e5-
a546a0ed-cca505a5, CSN 56706593000100010000): Server is unwilling to perform 
(53). Will retry later.
[15/Dec/2015:19:15:16 +0000] NSMMReplicationPlugin - agmt="cn=ds1TOds2" 
(ds2:389): Consumer failed to replay change (uniqueid 72eca481-a35f11e5-
a546a0ed-cca505a5, CSN 56706593000100010000): Server is unwilling to perform 
(53). Will retry later.

I was wondering about :

NSMMReplicationPlugin - agmt="cn=ds1TOds2" (ds2:389): Consumer failed to 
replay change (uniqueid 72eca481-a35f11e5-a546a0ed-cca505a5, CSN 
56706593000100010000): Server is unwilling to perform (53). Will retry later.

Checked the access log at ds2:

[15/Dec/2015:19:10:14 +0000] conn=28 fd=64 slot=64 connection from 
192.168.22.11 to 172.17.0.12
[15/Dec/2015:19:10:14 +0000] conn=28 op=0 EXT oid="1.3.6.1.4.1.1466.20037" 
name="startTLS"
[15/Dec/2015:19:10:14 +0000] conn=28 op=0 RESULT err=0 tag=120 nentries=0 
etime=0
[15/Dec/2015:19:10:14 +0000] conn=28 TLS1.2 256-bit AES
[15/Dec/2015:19:10:14 +0000] conn=28 op=1 BIND dn="cn=replication 
manager,cn=config" method=128 version=3
[15/Dec/2015:19:10:14 +0000] conn=28 op=1 RESULT err=0 tag=97 nentries=0 
etime=0 dn="cn=replication manager,cn=config"
[15/Dec/2015:19:10:14 +0000] conn=28 op=2 SRCH base="" scope=0 
filter="(objectClass=*)" attrs="supportedControl supportedExtension"
[15/Dec/2015:19:10:14 +0000] conn=28 op=2 RESULT err=0 tag=101 nentries=1 
etime=0
[15/Dec/2015:19:10:14 +0000] conn=28 op=3 SRCH base="" scope=0 
filter="(objectClass=*)" attrs="supportedControl supportedExtension"
[15/Dec/2015:19:10:14 +0000] conn=28 op=3 RESULT err=0 tag=101 nentries=1 
etime=0
[15/Dec/2015:19:10:14 +0000] conn=28 op=4 EXT oid="2.16.840.1.113730.3.5.12" 
name="replication-multimaster-extop"
[15/Dec/2015:19:10:14 +0000] conn=28 op=4 RESULT err=0 tag=120 nentries=0 
etime=0
[15/Dec/2015:19:10:14 +0000] conn=28 op=5 SRCH 
base="cn=replica,cn=dc\3Dexample\2Cdc\3Dorg,cn=mapping tree,cn=config" scope=0 
filter="(objectClass=*)" attrs="nsDS5ReplicaId"
[15/Dec/2015:19:10:14 +0000] conn=28 op=5 RESULT err=0 tag=101 nentries=1 
etime=0
[15/Dec/2015:19:10:14 +0000] conn=28 op=6 ADD dn="cn=repl keep alive 
1,dc=example,dc=org"
[15/Dec/2015:19:10:14 +0000] conn=28 op=6 RESULT err=53 tag=105 nentries=0 
etime=0 csn=56706593000100010000
[15/Dec/2015:19:10:16 +0000] conn=28 op=7 EXT oid="2.16.840.1.113730.3.5.5" 
name="Netscape Replication End Session"
[15/Dec/2015:19:10:16 +0000] conn=28 op=7 RESULT err=0 tag=120 nentries=0 
etime=0

And crosschecked the csn 56706593000100010000 at ds1 with the changelog dump:

changetype: add
replgen: 566feaa1000000010000
csn: 56706593000100010000
nsuniqueid: 72eca481-a35f11e5-a546a0ed-cca505a5
parentuniqueid: 2cbf2300-a31611e5-8f779323-18f831a8
dn: cn=repl keep alive 1,dc=example,dc=org
change::
add: objectClass
objectClass: top
objectClass: ldapsubentry
objectClass: extensibleObject
-
add: cn
cn: repl keep alive 1
-
add: internalCreatorsName
internalCreatorsName: cn=Multimaster Replication Plugin,cn=plugins,cn=config
-
add: internalModifiersName
internalModifiersName: cn=Multimaster Replication Plugin,cn=plugins,cn=config
-
add: creatorsName
creatorsName:
-
add: modifiersName
modifiersName:
-
add: createTimestamp
createTimestamp: 20151215191011Z
-
add: modifyTimestamp
modifyTimestamp: 20151215191011Z
-
add: nsUniqueId
nsUniqueId: 72eca481-a35f11e5-a546a0ed-cca505a5
-
add: parentid
parentid: 1
-
add: entryid
entryid: 342
-
add: entrydn
entrydn: cn=repl keep alive 1,dc=example,dc=org

Does someone have a glue what the  cn=repl keep alive 1,dc=example,dc=org is 
for and what causes the problem here?

thank you very much,

cheers, Frank

[thierry bordaz]

Hi Frank,

keep alive entry was introduced https://fedorahosted.org/389/ticket/48266
the ADD failed but does the entry exists on the re-initialized replica ?
It is looking like it was created during total init, so its replicaition 
(ADD) may fail because the entry already exists.

thanks
thierry

On 12/15/2015 08:31 PM, Frank Munsche wrote:
> Hi Guys,
>
> I got a replication issue with the 389 ds running at centos 6.7 and the
> following 389 pkgs installed:
>
> 389-admin.x86_64                    1.1.35-1.el6                     @epel
> 389-admin-console.noarch       1.1.8-1.el6                       @epel
> 389-adminutil.x86_64               1.1.19-1.el6                     @epel
> 389-console.noarch                  1.1.7-1.el6                       @epel
> 389-ds-base.x86_64                 1.2.11.15-65.el6_7           @updates
> 389-ds-base-libs.x86_64          1.2.11.15-65.el6_7           @updates
> 389-ds-console.noarch             1.2.6-1.el6                        @epel
> 389-dsgw.x86_64                     1.1.11-1.el6                       @epel
>
> I'm running a multimaster configuration based on two directory servers (ds1,
> ds2)
>
> When the replication is initiated at ds1 (replication from ds1 to ds2,
> nsds5BeginReplicaRefresh set to 'start') , I find these entries in the error
> log of ds1:
>
> [15/Dec/2015:19:10:11 +0000] NSMMReplicationPlugin - Beginning total update of
> replica "agmt="cn=ds1TOds2" (ds2:389)".
> [15/Dec/2015:19:10:11 +0000] NSMMReplicationPlugin - Need to create
> replication keep alive entry <cn=repl keep alive 1,dc=example,dc=org>
> [15/Dec/2015:19:10:11 +0000] NSMMReplicationPlugin - add dn: cn=repl keep
> alive 1,dc=example,dc=org
> objectclass: top
> objectclass: ldapsubentry
> objectclass: extensibleObject
> cn: repl keep alive 1
> [15/Dec/2015:19:10:14 +0000] NSMMReplicationPlugin - Finished total update of
> replica "agmt="cn=ds1TOds2" (ds2:389)". Sent 341 entries.
> [15/Dec/2015:19:10:14 +0000] NSMMReplicationPlugin - agmt="cn=ds1TOds2"
> (ds2:389): Consumer failed to replay change (uniqueid 72eca481-a35f11e5-
> a546a0ed-cca505a5, CSN 56706593000100010000): Server is unwilling to perform
> (53). Will retry later.
> [15/Dec/2015:19:15:16 +0000] NSMMReplicationPlugin - agmt="cn=ds1TOds2"
> (ds2:389): Consumer failed to replay change (uniqueid 72eca481-a35f11e5-
> a546a0ed-cca505a5, CSN 56706593000100010000): Server is unwilling to perform
> (53). Will retry later.
>
> I was wondering about :
>
> NSMMReplicationPlugin - agmt="cn=ds1TOds2" (ds2:389): Consumer failed to
> replay change (uniqueid 72eca481-a35f11e5-a546a0ed-cca505a5, CSN
> 56706593000100010000): Server is unwilling to perform (53). Will retry later.
>
> Checked the access log at ds2:
>
> [15/Dec/2015:19:10:14 +0000] conn=28 fd=64 slot=64 connection from
> 192.168.22.11 to 172.17.0.12
> [15/Dec/2015:19:10:14 +0000] conn=28 op=0 EXT oid="1.3.6.1.4.1.1466.20037"
> name="startTLS"
> [15/Dec/2015:19:10:14 +0000] conn=28 op=0 RESULT err=0 tag=120 nentries=0
> etime=0
> [15/Dec/2015:19:10:14 +0000] conn=28 TLS1.2 256-bit AES
> [15/Dec/2015:19:10:14 +0000] conn=28 op=1 BIND dn="cn=replication
> manager,cn=config" method=128 version=3
> [15/Dec/2015:19:10:14 +0000] conn=28 op=1 RESULT err=0 tag=97 nentries=0
> etime=0 dn="cn=replication manager,cn=config"
> [15/Dec/2015:19:10:14 +0000] conn=28 op=2 SRCH base="" scope=0
> filter="(objectClass=*)" attrs="supportedControl supportedExtension"
> [15/Dec/2015:19:10:14 +0000] conn=28 op=2 RESULT err=0 tag=101 nentries=1
> etime=0
> [15/Dec/2015:19:10:14 +0000] conn=28 op=3 SRCH base="" scope=0
> filter="(objectClass=*)" attrs="supportedControl supportedExtension"
> [15/Dec/2015:19:10:14 +0000] conn=28 op=3 RESULT err=0 tag=101 nentries=1
> etime=0
> [15/Dec/2015:19:10:14 +0000] conn=28 op=4 EXT oid="2.16.840.1.113730.3.5.12"
> name="replication-multimaster-extop"
> [15/Dec/2015:19:10:14 +0000] conn=28 op=4 RESULT err=0 tag=120 nentries=0
> etime=0
> [15/Dec/2015:19:10:14 +0000] conn=28 op=5 SRCH
> base="cn=replica,cn=dc\3Dexample\2Cdc\3Dorg,cn=mapping tree,cn=config" scope=0
> filter="(objectClass=*)" attrs="nsDS5ReplicaId"
> [15/Dec/2015:19:10:14 +0000] conn=28 op=5 RESULT err=0 tag=101 nentries=1
> etime=0
> [15/Dec/2015:19:10:14 +0000] conn=28 op=6 ADD dn="cn=repl keep alive
> 1,dc=example,dc=org"
> [15/Dec/2015:19:10:14 +0000] conn=28 op=6 RESULT err=53 tag=105 nentries=0
> etime=0 csn=56706593000100010000
> [15/Dec/2015:19:10:16 +0000] conn=28 op=7 EXT oid="2.16.840.1.113730.3.5.5"
> name="Netscape Replication End Session"
> [15/Dec/2015:19:10:16 +0000] conn=28 op=7 RESULT err=0 tag=120 nentries=0
> etime=0
>
> And crosschecked the csn 56706593000100010000 at ds1 with the changelog dump:
>
> changetype: add
> replgen: 566feaa1000000010000
> csn: 56706593000100010000
> nsuniqueid: 72eca481-a35f11e5-a546a0ed-cca505a5
> parentuniqueid: 2cbf2300-a31611e5-8f779323-18f831a8
> dn: cn=repl keep alive 1,dc=example,dc=org
> change::
> add: objectClass
> objectClass: top
> objectClass: ldapsubentry
> objectClass: extensibleObject
>
> add: cn
> cn: repl keep alive 1
>
> add: internalCreatorsName
> internalCreatorsName: cn=Multimaster Replication Plugin,cn=plugins,cn=config
>
> add: internalModifiersName
> internalModifiersName: cn=Multimaster Replication Plugin,cn=plugins,cn=config
>
> add: creatorsName
> creatorsName:
>
> add: modifiersName
> modifiersName:
>
> add: createTimestamp
> createTimestamp: 20151215191011Z
>
> add: modifyTimestamp
> modifyTimestamp: 20151215191011Z
>
> add: nsUniqueId
> nsUniqueId: 72eca481-a35f11e5-a546a0ed-cca505a5
>
> add: parentid
> parentid: 1
>
> add: entryid
> entryid: 342
>
> add: entrydn
> entrydn: cn=repl keep alive 1,dc=example,dc=org
>
> Does someone have a glue what the  cn=repl keep alive 1,dc=example,dc=org is
> for and what causes the problem here?
>
> thank you very much,
>
> cheers, Frank
>
> --
> 389 users mailing list
> 389-users@%(host_name)s
> http://lists.fedoraproject.org/admin/lists/[e-mail]