Hello,
This logs are coming from the supplier. It confirms what you said.
The supplier retrieves a starting point for sending updates
(53f5e4b5000000050000) then sends the next update
53f5e647000000050000 (uid=shilen3,ou=people,ou=test,dc=duke,dc=edu).
For some reason the consumerhost:636 is unwilling to apply the
update (is the backend readonly ?).
Have you got the error logs from consumerhost (with replication
logging enabled) ?.
thanks
theirry
On 08/21/2014 02:45 PM, Shilen Patel wrote:
Here's the additional logging for the init issue:
[21/Aug/2014:13:31:55 +0100] NSMMReplicationPlugin - Finished total
update of replica "agmt="cn=test5toSing1" (consumerhost:636)". Sent
278 entries.
[21/Aug/2014:13:31:55 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): Cancelling linger on the
connection
[21/Aug/2014:13:31:55 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): Disconnected from the consumer
[21/Aug/2014:13:31:55 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): State: start ->
ready_to_acquire_replica
[21/Aug/2014:13:31:55 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): Trying secure
slapi_ldap_init_ext
[21/Aug/2014:13:31:55 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): binddn = cn=xxx passwd = xxx
[21/Aug/2014:13:31:56 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): No linger to cancel on the
connection
[21/Aug/2014:13:31:57 +0100] - _csngen_adjust_local_time: gen state
before 53f5e64c0000:1408624203:0:1
[21/Aug/2014:13:31:57 +0100] - _csngen_adjust_local_time: gen state
after 53f5e6be0000:1408624317:0:1
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): Replica was successfully
acquired.
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): State:
ready_to_acquire_replica -> sending_updates
[21/Aug/2014:13:31:58 +0100] - csngen_adjust_time: gen state before
53f5e6be0001:1408624317:0:1
[21/Aug/2014:13:31:58 +0100] - _csngen_adjust_local_time: gen state
before 53f5e6be0001:1408624317:0:1
[21/Aug/2014:13:31:58 +0100] - _csngen_adjust_local_time: gen state
after 53f5e6bf0000:1408624318:0:1
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin - changelog program
- _cl5GetDBFile: found DB object 2b9c0c0 for database
/var/lib/dirsrv/slapd-idms-authdir/changelogdb/e9c04c06-1c0711e4-a066d327-58be45f0_53e0f14e000000050000.db4
[21/Aug/2014:13:31:58 +0100] - _cl5PositionCursorForReplay
(agmt="cn=test5toSing1" (consumerhost:636)): Consumer RUV:
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): {replicageneration}
53e0f14e000000050000
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): {replica 5 ldap://xxx:389}
53e0f3cc000000050000 53f5e4b5000000050000 00000000
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): {replica 8 ldap://xxx:389}
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): {replica 7 ldap://xxx:389}
53f3a401000000070000 53f3a401000000070000 00000000
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): {replica 6 ldap://xxx:389}
53e3b64f000000060000 53f3a68e000000060000 00000000
[21/Aug/2014:13:31:58 +0100] - _cl5PositionCursorForReplay
(agmt="cn=test5toSing1" (consumerhost:636)): Supplier RUV:
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): {replicageneration}
53e0f14e000000050000
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): {replica 5 ldap://xxx:389}
53e0f3cc000000050000 53f5e647000000050000 53f5e646
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): {replica 8 ldap://xxx:389}
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): {replica 7 ldap://xxx:389}
53f3a401000000070000 53f3a401000000070000 00000000
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): {replica 6 ldap://xxx:389}
53e3b64f000000060000 53f3a68e000000060000 00000000
[21/Aug/2014:13:31:58 +0100] agmt="cn=test5toSing1" (consumerhost:636)
- clcache_get_buffer: found thread private buffer cache 7fac100773d0
[21/Aug/2014:13:31:58 +0100] agmt="cn=test5toSing1" (consumerhost:636)
- clcache_get_buffer: _pool is 2b8b6f0 _pool->pl_busy_lists is
7fac140012e0 _pool->pl_busy_lists->bl_buffers is 7fac04126e60
[21/Aug/2014:13:31:58 +0100] agmt="cn=test5toSing1" (consumerhost:636)
- session start: anchorcsn=53f5e4b5000000050000
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin - changelog program
- agmt="cn=test5toSing1" (consumerhost:636): CSN 53f5e4b5000000050000
found, position set for replay
[21/Aug/2014:13:31:58 +0100] agmt="cn=test5toSing1" (consumerhost:636)
- load=1 rec=1 csn=53f5e647000000050000
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): replay_update: Sending add
operation (dn="uid=shilen3,ou=people,ou=test,dc=duke,dc=edu"
csn=53f5e647000000050000)
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): replay_update: Consumer
successfully sent operation with csn 53f5e647000000050000
[21/Aug/2014:13:31:58 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): Consumer failed to replay
change (uniqueid b92e2101-292e11e4-a066d327-58be45f0, CSN
53f5e647000000050000): Server is unwilling to perform (53). Will retry
later.
[21/Aug/2014:13:31:58 +0100] agmt="cn=test5toSing1" (consumerhost:636)
- session end: state=0 load=1 sent=1 skipped=0 skipped_new_rid=0
skipped_csn_gt_cons_maxcsn=0 skipped_up_to_date=0 skipped_csn_gt_ruv=0
skipped_csn_covered=0
[21/Aug/2014:13:31:59 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): Successfully released consumer
[21/Aug/2014:13:31:59 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): Beginning linger on the
connection
[21/Aug/2014:13:31:59 +0100] NSMMReplicationPlugin -
agmt="cn=test5toSing1" (consumerhost:636): State: sending_updates ->
start_backoff
Thanks!
-- Shilen
From: Mark Reynolds <mareynol(a)redhat.com <mailto:mareynol@redhat.com>>
Reply-To: "mreynolds(a)redhat.com <mailto:mreynolds@redhat.com>"
<mreynolds(a)redhat.com <mailto:mreynolds@redhat.com>>
Date: Tuesday, August 19, 2014 3:32 PM
To: "General discussion list for the 389 Directory server project."
<389-users(a)lists.fedoraproject.org
<mailto:389-users@lists.fedoraproject.org>>, Shilen Patel
<shilen(a)duke.edu <mailto:shilen@duke.edu>>
Subject: Re: [389-users] Replication error after initializing consumer
On 08/19/2014 03:05 PM, Shilen Patel wrote:
> Hi Mark,
>
> So with this issue, I'm not adding a password at all to the
> entry. See the LDIF in (2) below.
No, I was referring to your first email, not this issue. Sorry I
should of responded separately.
> I'll open a ticket.
For what issue? For the initialization issue I want you to grab
the logging first. For the first issue(userpassword not being
replicated), if you can reproduce it when only adding already
hashed passwords, then please file a ticket with a reproducible
testcase.
I hope that clears things up.
Regards,
Mark
>
> Thanks!
>
> -- Shilen
>
> From: Mark Reynolds <mareynol(a)redhat.com
> <mailto:mareynol@redhat.com>>
> Reply-To: "mreynolds(a)redhat.com <mailto:mreynolds@redhat.com>"
> <mreynolds(a)redhat.com <mailto:mreynolds@redhat.com>>
> Date: Tuesday, August 19, 2014 2:58 PM
> To: "General discussion list for the 389 Directory server
> project." <389-users(a)lists.fedoraproject.org
> <mailto:389-users@lists.fedoraproject.org>>, Shilen Patel
> <shilen(a)duke.edu <mailto:shilen@duke.edu>>
> Subject: Re: [389-users] Replication error after initializing
> consumer
>
> Shilen,
>
> A few things, you should not be adding a prehashed password
> (e.g. {SSHA}DMK4S6PK6+rKSLNOL1Hl01mVJmgGi5jH) - but that
> should not break replication. Can you confirm that only
> prehashed passwords are causing the issue? If so, please
> files a ticket with a reproducible testcase:
>
https://fedorahosted.org/389/newticket
>
> As for this replication issue, enabling replication logging
> might provide more information:
>
>
https://access.redhat.com/documentation/en-US/Red_Hat_Directory_Server/9....
>
> Then post the logging output back on this list. You should
> also undo this logging level once you're done - as this
> logging level can impact performance.
>
> Thanks,
> Mark
>
>
> On 08/19/2014 01:08 PM, Shilen Patel wrote:
>> Hi,
>>
>> I'm not sure if this is related to my previous email, but
>> I'm also seeing issues when adding an entry while a suffix
>> on a consumer is being initialized. Again, I'm
>> running 1.2.11.30. Here are the details:
>>
>> 1. Using the console, I started to initialize a suffix.
>>
>> [19/Aug/2014:17:46:35 +0100] NSMMReplicationPlugin -
>> Beginning total update of replica "agmt="cn=test5toSing1"
>> (consumerhost:636)".
>>
>> 2. While that was happening, I added an entry to the suffix
>> on the master.
>>
>> dn: uid=shilen3,ou=people,ou=test,dc=duke,dc=edu
>> changetype: add
>> objectclass: top
>> objectclass: person
>> objectclass: inetorgperson
>> objectclass: organizationalperson
>> cn: test
>> sn: test
>> uid: shilen3
>>
>>
>> [19/Aug/2014:17:47:04 +0100] conn=155 op=1 ADD
>> dn="uid=shilen3,ou=people,ou=test,dc=duke,dc=edu"
>> [19/Aug/2014:17:47:04 +0100] conn=155 op=1 RESULT err=0
>> tag=105 nentries=0 etime=0 csn=53f37f89000000050000
>>
>> 3. The init later finished.
>>
>> [19/Aug/2014:17:48:55 +0100] NSMMReplicationPlugin -
>> Finished total update of replica "agmt="cn=test5toSing1"
>> (consumerhost:636)". Sent 270 entries.
>>
>> At this point, the entry does exist on the consumer.
>> Presumably it was added as part of the init.
>>
>>
>> 4. However, the master still wants to send the ADD to the
>> consumer. On the consumer, I have the following repeated
>> every few seconds:
>>
>> [19/Aug/2014:17:48:54 +0100] conn=2002 op=56 ADD
>> dn="uid=shilen3,ou=people,ou=test,dc=duke,dc=edu"
>> [19/Aug/2014:17:48:54 +0100] conn=2002 op=56 RESULT err=53
>> tag=105 nentries=0 etime=0 csn=53f37f89000000050000
>>
>> And on the master, I have this:
>>
>> [19/Aug/2014:17:48:58 +0100] NSMMReplicationPlugin -
>> agmt="cn=test5toSing1" (consumerhost:636): Consumer failed
>> to replay change (uniqueid
>> 5d458a02-27c011e4-a066d327-58be45f0, CSN
>> 53f37f89000000050000): Server is unwilling to perform (53).
>> Will retry later.
>>
>> A cl-dump shows the following:
>>
>> changetype: add
>> replgen: 53e0f14e000000050000
>> csn: 53f37f89000000050000
>> nsuniqueid: 5d458a02-27c011e4-a066d327-58be45f0
>> parentuniqueid: bcd34401-21ba11df-80799838-3cd697e9
>> dn: uid=shilen3,ou=people,ou=test,dc=duke,dc=edu
>> change::
>> add: objectClass
>> objectClass: top
>> objectClass: person
>> objectClass: inetorgperson
>> objectClass: organizationalperson
>> -
>> add: cn
>> cn: test
>> -
>> add: sn
>> sn: test
>> -
>> add: uid
>> uid: shilen3
>> -
>> add: creatorsName
>> creatorsName: cn=directory manager
>> -
>> add: modifiersName
>> modifiersName: cn=directory manager
>> -
>> add: createTimestamp
>> createTimestamp: 20140819164704Z
>> -
>> add: modifyTimestamp
>> modifyTimestamp: 20140819164704Z
>> -
>> add: nsUniqueId
>> nsUniqueId: 5d458a02-27c011e4-a066d327-58be45f0
>> -
>> add: parentid
>> parentid: 2
>> -
>> add: entryid
>> entryid: 277
>> -
>> add: entrydn
>> entrydn: uid=shilen3,ou=people,ou=test,dc=duke,dc=edu
>> -
>>
>>
>> If anyone has any thoughts on this one, that would be
>> appreciated.
>>
>> Thanks!
>>
>> -- Shilen
>>
>>
>> --
>> 389 users mailing list
>>
389-users@lists.fedoraproject.orghttps://admin.fedoraproject.org/mailman/listinfo/389-users
>
>
>
> --
> 389 users mailing list
>
389-users@lists.fedoraproject.orghttps://admin.fedoraproject.org/mailman/listinfo/389-users
--
389 users mailing list
389-users(a)lists.fedoraproject.org
https://admin.fedoraproject.org/mailman/listinfo/389-users