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 <[email protected] <mailto:[email protected]>>
Reply-To: "[email protected] <mailto:[email protected]>"
<[email protected] <mailto:[email protected]>>
Date: Tuesday, August 19, 2014 3:32 PM
To: "General discussion list for the 389 Directory server project."
<[email protected]
<mailto:[email protected]>>, Shilen Patel
<[email protected] <mailto:[email protected]>>
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 <[email protected]
<mailto:[email protected]>>
Reply-To: "[email protected] <mailto:[email protected]>"
<[email protected] <mailto:[email protected]>>
Date: Tuesday, August 19, 2014 2:58 PM
To: "General discussion list for the 389 Directory server
project." <[email protected]
<mailto:[email protected]>>, Shilen Patel
<[email protected] <mailto:[email protected]>>
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.0/html/Configuration_Command_and_File_Reference/error-logs.html#error-logs-levels
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
[email protected]https://admin.fedoraproject.org/mailman/listinfo/389-users
--
389 users mailing list
[email protected]https://admin.fedoraproject.org/mailman/listinfo/389-users
--
389 users mailing list
[email protected]
https://admin.fedoraproject.org/mailman/listinfo/389-users
--
389 users mailing list
[email protected]
https://admin.fedoraproject.org/mailman/listinfo/389-users
