Hello Shilen,
I am able to reproduce on 1.2.11.30 with the following testcase.
#!/bin/sh
VAL=${1:-10000}
ldapmodify -h localhost -p 44389 -D "cn=directory manager" -w
password -a -f /tmp/my.ldif &
ldapmodify -h localhost -p 44389 -D "cn=directory manager" -w
password <<!EOF
dn:
cn=meTo_localhost.localdomain:45389,cn=replica,cn=dc\=example\,dc\=com,cn=mapping
tree,cn=config
changetype: modify
replace: nsds5BeginReplicaRefresh
nsds5BeginReplicaRefresh: start
dn: cn=added${VAL}_1,dc=example,dc=com
changetype: add
objectClass: top
objectClass: person
sn: added${VAL}
cn: added${VAL}
dn: cn=added${VAL}_2,dc=example,dc=com
changetype: add
objectClass: top
objectClass: person
sn: added${VAL}
cn: added${VAL}
dn: cn=added${VAL}_3,dc=example,dc=com
changetype: add
objectClass: top
objectClass: person
sn: added${VAL}
cn: added${VAL}
!EOF
I can reproduce it since 1.2.11.12 and after. So I doubt it is a
regression.
I fail to reproduce it on master, so it seems it has been fixed
somewhere but I failed to identify the bug number.
The problem is trigger because the consumer receives an entry it
already has. It should skip the update (because it already knows it)
AND update its RUV. Here it does not update the ruv so replication
start and start again at the same point.
Here we have a log (replication log on consumer) like:
[25/Aug/2014:09:25:33 +0200] NSMMReplicationPlugin -
ruv_add_csn_inprogress: successfully inserted csn
53fae4e2000000010000 into pending list
[25/Aug/2014:09:25:33 +0200] e4-a0dabef1-abe99f7b - urp_add
(cn=addedthierry1_1,dc=example,dc=com): an entry with this
uniqueid already exists.
[25/Aug/2014:09:25:33 +0200] NSMMReplicationPlugin - conn=14
op=5 csn=53fae4e2000000010000 process postop: canceling
operation csn
[25/Aug/2014:09:25:33 +0200] NSMMReplicationPlugin -
csnplInsert: CSN Pending list content:
[25/Aug/2014:09:25:34 +0200] NSMMReplicationPlugin -
53fae4e4000000010000, not committed
Where the postop is canceling the operation. That is fine but IMHO
it should also update the RUV.
thanks
thierry
On 08/22/2014 09:22 PM, Shilen Patel wrote:
I first noticed it in a suffix that had about 90K entries. After
that, I was reproducing it in a suffix with about 280 entries.
Thanks!
-- Shilen
From: thierry bordaz <tbordaz(a)redhat.com <mailto:tbordaz@redhat.com>>
Date: Friday, August 22, 2014 3:18 PM
To: Shilen Patel <shilen(a)duke.edu <mailto:shilen@duke.edu>>
Cc: "mreynolds(a)redhat.com <mailto:mreynolds@redhat.com>"
<mreynolds(a)redhat.com <mailto:mreynolds@redhat.com>>, "General
discussion list for the 389 Directory server project."
<389-users(a)lists.fedoraproject.org
<mailto:389-users@lists.fedoraproject.org>>
Subject: Re: [389-users] Replication error after initializing consumer
How many entries are in the initialized suffix ?
thierry
On 08/22/2014 07:18 PM, Shilen Patel wrote:
> I can reproduce it easily and consistently in my environment.
> First off, I'm running 1.2.11.30. I didn't have this issue
> until I upgraded to this version (or at least it never came up).
> And I have a couple of masters and a couple of consumers. When
> everything is in sync, I do the following:
>
> 1. Init via the console from a master to a consumer on one of
> the suffixes.
> 2. While the init is still happening (i.e. it is somewhere in
> the middle of it), I add an entry to the master.
> 3. When the init is done, the newly added entry does exist on
> the consumer, but the errors show up indicating that the master
> is trying to send that ADD to the consumer.
>
> Not sure if that helps?
>
> Thanks!
>
> -- Shilen
>
>
> From: thierry bordaz <tbordaz(a)redhat.com
<mailto:tbordaz@redhat.com>>
> Date: Friday, August 22, 2014 1:10 PM
> To: Shilen Patel <shilen(a)duke.edu <mailto:shilen@duke.edu>>
> Cc: "mreynolds(a)redhat.com <mailto:mreynolds@redhat.com>"
> <mreynolds(a)redhat.com <mailto:mreynolds@redhat.com>>, "General
> discussion list for the 389 Directory server project."
> <389-users(a)lists.fedoraproject.org
> <mailto:389-users@lists.fedoraproject.org>>
> Subject: Re: [389-users] Replication error after initializing
> consumer
>
> Hello,
>
> I am still fighting to reproduce this issue.
> Have you a reproducible test case, so that I could
> investigate locally ?
>
> thanks
> thierry
>
> On 08/22/2014 06:47 PM, Shilen Patel wrote:
>> While the issue is happening, if I add another entry to the
>> same suffix, it does not replicate over it seems. The same
>> error continues.
>>
>> Thanks!
>>
>> -- Shilen
>>
>> From: thierry bordaz <tbordaz(a)redhat.com
>> <mailto:tbordaz@redhat.com>>
>> Date: Friday, August 22, 2014 12:02 PM
>> To: Shilen Patel <shilen(a)duke.edu <mailto:shilen@duke.edu>>
>> Cc: "mreynolds(a)redhat.com <mailto:mreynolds@redhat.com>"
>> <mreynolds(a)redhat.com <mailto:mreynolds@redhat.com>>,
>> "General discussion list for the 389 Directory server
>> project." <389-users(a)lists.fedoraproject.org
>> <mailto:389-users@lists.fedoraproject.org>>
>> Subject: Re: [389-users] Replication error after
>> initializing consumer
>>
>> Hello Shilen,
>>
>> I wonder if it is not a transient issue.
>> If you add an other entry on the supplier, is it
>> replicated and the warning messages do no long occur ?
>>
>> thanks
>> theirry
>>
>> On 08/22/2014 03:59 PM, Shilen Patel wrote:
>>> Once the init is done, the following is repeated on the
>>> consumer (when logging is turned up). Note that the
>>> ADD was done while the init was happening and after the
>>> init is done, the entry does exist on the consumer but,
>>> from what I can tell, the supplier wants to still send
>>> it to the consumer and the consumer is rejecting it.
>>>
>>> Also, the other issue that I'm noticing is that a
>>> couple of my consumers seem to be crashing (about once
>>> a day). Right now, they are not getting any traffic at
>>> all other than updates from replication. I'm debugging
>>> that at the moment and will report what I find.
>>>
>>> [22/Aug/2014:14:48:34 +0100] - import test: Import
>>> complete. Processed 282 entries in 145 seconds. (1.94
>>> entries/sec)
>>> [22/Aug/2014:14:48:34 +0100] NSMMReplicationPlugin -
>>> multimaster_be_state_change: replica
>>> ou=test,dc=duke,dc=edu is coming online; enabling
>>> replication
>>> [22/Aug/2014:14:48:34 +0100] NSMMReplicationPlugin -
>>> _replica_configure_ruv: No ruv tombstone found for
>>> replica ou=test,dc=duke,dc=edu. Created a new one
>>> [22/Aug/2014:14:48:34 +0100] NSMMReplicationPlugin -
>>> conn=0 op=0 repl="ou=test,dc=duke,dc=edu": Released
>>> replica held by locking_purl=conn=15 id=4
>>> [22/Aug/2014:14:48:34 +0100] NSMMReplicationPlugin -
>>> replica_enable_replication: replica
>>> ou=test,dc=duke,dc=edu is relinquished
>>> [22/Aug/2014:14:48:34 +0100] NSMMReplicationPlugin -
>>> conn=15 op=287 repl="ou=test,dc=duke,dc=edu": Replica
>>> not in use
>>> [22/Aug/2014:14:48:34 +0100] NSMMReplicationPlugin -
>>> conn=15 op=287 Relinquishing consumer connection extension
>>> [22/Aug/2014:14:48:36 +0100] NSMMReplicationPlugin -
>>> conn=13 op=69 Acquired consumer connection extension
>>> [22/Aug/2014:14:48:36 +0100] NSMMReplicationPlugin -
>>> conn=13 op=69 repl="ou=test,dc=duke,dc=edu": Begin
>>> incremental protocol
>>> [22/Aug/2014:14:48:36 +0100] - csngen_adjust_time: gen
>>> state before 53f74a330001:1408715314:0:1
>>> [22/Aug/2014:14:48:36 +0100] -
>>> _csngen_adjust_local_time: gen state before
>>> 53f74a330001:1408715314:0:1
>>> [22/Aug/2014:14:48:36 +0100] -
>>> _csngen_adjust_local_time: gen state after
>>> 53f74a350000:1408715316:0:1
>>> [22/Aug/2014:14:48:36 +0100] NSMMReplicationPlugin -
>>> conn=13 op=69 repl="ou=test,dc=duke,dc=edu": Acquired
>>> replica
>>> [22/Aug/2014:14:48:36 +0100] NSMMReplicationPlugin -
>>> conn=13 op=69 repl="ou=test,dc=duke,dc=edu":
>>> StartNSDS50ReplicationRequest: response=0 rc=0
>>> [22/Aug/2014:14:48:36 +0100] NSMMReplicationPlugin -
>>> conn=13 op=69 Relinquishing consumer connection extension
>>> [22/Aug/2014:14:48:36 +0100] NSMMReplicationPlugin -
>>> ruv_add_csn_inprogress: successfully inserted csn
>>> 53f749bb000000050000 into pending list
>>> [22/Aug/2014:14:48:36 +0100] £ - urp_add
>>> (uid=shilen3,ou=people,ou=test,dc=duke,dc=edu): an
>>> entry with this uniqueid already exists.
>>> [22/Aug/2014:14:48:36 +0100] NSMMReplicationPlugin -
>>> conn=13 op=70 csn=53f749bb000000050000 process postop:
>>> canceling operation csn
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=16 op=63 Acquired consumer connection extension
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=16 op=63 repl="ou=test,dc=duke,dc=edu": Begin
>>> incremental protocol
>>> [22/Aug/2014:14:48:37 +0100] - csngen_adjust_time: gen
>>> state before 53f74a350000:1408715316:0:1
>>> [22/Aug/2014:14:48:37 +0100] -
>>> _csngen_adjust_local_time: gen state before
>>> 53f74a350000:1408715316:0:1
>>> [22/Aug/2014:14:48:37 +0100] -
>>> _csngen_adjust_local_time: gen state after
>>> 53f74a360000:1408715317:0:1
>>> [22/Aug/2014:14:48:37 +0100] - csngen_adjust_time: gen
>>> state after 53f74a360000:1408715317:0:1
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=16 op=63 repl="ou=test,dc=duke,dc=edu": Replica
in
>>> use locking_purl=conn=13 id=69
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=16 op=63 replica="ou=test,dc=duke,dc=edu": Unable
>>> to acquire replica: error: replica busy locked by
>>> conn=13 id=69 for incremental update
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=16 op=63 repl="ou=test,dc=duke,dc=edu":
>>> StartNSDS50ReplicationRequest: response=1 rc=0
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=16 op=63 Relinquishing consumer connection extension
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=18 op=4 Acquired consumer connection extension
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=18 op=4 repl="ou=test,dc=duke,dc=edu": Begin
>>> incremental protocol
>>> [22/Aug/2014:14:48:37 +0100] - csngen_adjust_time: gen
>>> state before 53f74a360000:1408715317:0:1
>>> [22/Aug/2014:14:48:37 +0100] - csngen_adjust_time: gen
>>> state after 53f74a360000:1408715317:0:1
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=18 op=4 repl="ou=test,dc=duke,dc=edu": Replica in
>>> use locking_purl=conn=13 id=69
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=18 op=4 replica="ou=test,dc=duke,dc=edu": Unable
>>> to acquire replica: error: replica busy locked by
>>> conn=13 id=69 for incremental update
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=18 op=4 repl="ou=test,dc=duke,dc=edu":
>>> StartNSDS50ReplicationRequest: response=1 rc=0
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=18 op=4 Relinquishing consumer connection extension
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=13 op=71 Acquired consumer connection extension
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=13 op=71 repl="ou=test,dc=duke,dc=edu": Released
>>> replica held by locking_purl=conn=13 id=69
>>> [22/Aug/2014:14:48:37 +0100] NSMMReplicationPlugin -
>>> conn=13 op=71 Relinquishing consumer connection extension
>>> [22/Aug/2014:14:48:38 +0100] NSMMReplicationPlugin -
>>> conn=17 op=63 Acquired consumer connection extension
>>> [22/Aug/2014:14:48:38 +0100] NSMMReplicationPlugin -
>>> conn=17 op=63 repl="ou=test,dc=duke,dc=edu": Begin
>>> incremental protocol
>>> [22/Aug/2014:14:48:38 +0100] - csngen_adjust_time: gen
>>> state before 53f74a360000:1408715317:0:1
>>> [22/Aug/2014:14:48:38 +0100] -
>>> _csngen_adjust_local_time: gen state before
>>> 53f74a360000:1408715317:0:1
>>> [22/Aug/2014:14:48:38 +0100] -
>>> _csngen_adjust_local_time: gen state after
>>> 53f74a370000:1408715318:0:1
>>> [22/Aug/2014:14:48:38 +0100] NSMMReplicationPlugin -
>>> conn=17 op=63 repl="ou=test,dc=duke,dc=edu": Acquired
>>> replica
>>> [22/Aug/2014:14:48:38 +0100] NSMMReplicationPlugin -
>>> conn=17 op=63 repl="ou=test,dc=duke,dc=edu":
>>> StartNSDS50ReplicationRequest: response=0 rc=0
>>> [22/Aug/2014:14:48:38 +0100] NSMMReplicationPlugin -
>>> conn=17 op=63 Relinquishing consumer connection extension
>>> [22/Aug/2014:14:48:38 +0100] NSMMReplicationPlugin -
>>> ruv_add_csn_inprogress: successfully inserted csn
>>> 53f749bb000000050000 into pending list
>>> [22/Aug/2014:14:48:38 +0100] £ - urp_add
>>> (uid=shilen3,ou=people,ou=test,dc=duke,dc=edu): an
>>> entry with this uniqueid already exists.
>>>
>>> Thanks!
>>>
>>> -- Shilen
>>>
>>>
>>> From: thierry bordaz <tbordaz(a)redhat.com
>>> <mailto:tbordaz@redhat.com>>
>>> Date: Thursday, August 21, 2014 10:20 AM
>>> To: "mreynolds(a)redhat.com
>>> <mailto:mreynolds@redhat.com>"
<mreynolds(a)redhat.com
>>> <mailto:mreynolds@redhat.com>>
>>> Cc: "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
>>>
>>> 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@lists.fedoraproject.orghttps://admin.fedoraproject.org/mailman/listinfo/389-users
>>>
>>
>