Replication failing on some records

List overview All Threads
Download

newer

older

Ansible and ipa-client-install

FreeIPA 4.4 with Yubikey and...

Nick Campion

7 Jun 2017 7 Jun '17

3:58 p.m.

Hi all,

We have a 3 master setup that is failing to replicate changes from a particular node to the other IPA instances. The replication status says it's all fine, however the record hasn't been changed on the other servers. We've seen this on user password changes, adding hosts and services. The only thing we've found that seems to fix this temporarily is to re-initialize from the master with the changed record. A force-sync doesn't pick up the changed record.

Not sure what logs would be helpful to diagnose what is happening in this setup.

# ipa-replica-manage -v list `hostname` freeipa03.mgmt.example.com: replica last init status: None last init ended: 1970-01-01 00:00:00+00:00 last update status: Error (0) Replica acquired successfully: Incremental update succeeded last update ended: 2017-06-07 14:43:53+00:00 freeipa02.mgmt.example.com: replica last init status: None last init ended: 1970-01-01 00:00:00+00:00 last update status: Error (0) Replica acquired successfully: Incremental update succeeded last update ended: 2017-06-07 14:43:53+00:00

# ldapsearch -W -x -D "cn=directory manager" -b "cn=users,cn=accounts,dc=ipa,dc=example,dc=com" "nsds5ReplConflict=*" * nsds5ReplConflict Enter LDAP Password: # extended LDIF # # LDAPv3 # base <cn=users,cn=accounts,dc=ipa,dc=example,dc=com> with scope subtree # filter: nsds5ReplConflict=* # requesting: * nsds5ReplConflict #

# search result search: 2 result: 0 Success

# numResponses: 1

Any help in what else can be checked or what logs would be helpful would be appreciated.

Thanks

Nick

Attachments:

attachment.html (text/html — 3.2 KB)

Show replies by thread

Mark Reynolds

8 Jun 8 Jun

3:45 p.m.

On 06/07/2017 10:58 AM, Nick Campion via FreeIPA-users wrote:

...

Hi all,

We have a 3 master setup that is failing to replicate changes from a particular node to the other IPA instances. The replication status says it's all fine, however the record hasn't been changed on the other servers. We've seen this on user password changes, adding hosts and services. The only thing we've found that seems to fix this temporarily is to re-initialize from the master with the changed record. A force-sync doesn't pick up the changed record.

What is the change you making, what attribute are you updating? Could it be possible that its being excluded by fractional replication? Or is it all changes?

Any errors in the logs on the nodes(good and bad): /var/log/dirsrv/slapd-INSTANCE/errors

Do you see replication sessions starting between the bad node and good ones? Are they talking? Check the access log ( /var/log/dirsrv/slapd-INSTANCE/access) on a good node and look for "connection from <BAD NODE IP address>"

Next would be to enable replication logging on the bad node and reproduce the problem (then disable repl logging right away), then send us the logs to look at. See https://access.redhat.com/documentation/en-us/red_hat_directory_server/10/ht...

Regards, Mark

...

Not sure what logs would be helpful to diagnose what is happening in this setup.

# ipa-replica-manage -v list `hostname` freeipa03.mgmt.example.com: replica last init status: None last init ended: 1970-01-01 00:00:00+00:00 last update status: Error (0) Replica acquired successfully: Incremental update succeeded last update ended: 2017-06-07 14:43:53+00:00 freeipa02.mgmt.example.com: replica last init status: None last init ended: 1970-01-01 00:00:00+00:00 last update status: Error (0) Replica acquired successfully: Incremental update succeeded last update ended: 2017-06-07 14:43:53+00:00

# ldapsearch -W -x -D "cn=directory manager" -b "cn=users,cn=accounts,dc=ipa,dc=example,dc=com" "nsds5ReplConflict=*" * nsds5ReplConflict Enter LDAP Password: # extended LDIF # # LDAPv3 # base <cn=users,cn=accounts,dc=ipa,dc=example,dc=com> with scope subtree # filter: nsds5ReplConflict=* # requesting: * nsds5ReplConflict #

# search result search: 2 result: 0 Success

# numResponses: 1

Any help in what else can be checked or what logs would be helpful would be appreciated.

Thanks

Nick

FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org

Nick Campion

9 Jun 9 Jun

12:54 p.m.

Thanks Mark,

So this example is a user password change using kinit, the password has been changed on freeipa02 but not then replicated to the others. This happens for other records, but I don't have examples of these at the moment.

As far as I'm aware, there is no fractal replication set up.

Freeipa01:

# dynamic-kepler, users, accounts, ipa.example.com dn: uid=dynamic-kepler,cn=users,cn=accounts,dc=ipa,dc=example,dc=com uid: dynamic-kepler krbLastPwdChange: 20170608170011Z krbPasswordExpiration: 20170608170011Z

Freeipa02:

Freeipa03:

Errors on Freeipa02:

[08/Jun/2017:01:46:50.635529447 +0000] replica_generate_next_csn: opcsn=5938ac8b000500030000 <= basecsn=5938ac8b000500040000, adjusted opcsn=5938ac8b000600030000 [08/Jun/2017:12:16:46.497249649 +0000] replica_generate_next_csn: opcsn=5939402f000500030000 <= basecsn=5939402f000800040000, adjusted opcsn=5939402f000900030000 [08/Jun/2017:23:38:48.197750001 +0000] replica_generate_next_csn: opcsn=5939e009000100030000 <= basecsn=5939e009000f00040000, adjusted opcsn=5939e009001000030000

The other nodes have no errors from this data.

Access logs:

Freeipa01:

Freeipa02:

Shows no logs "to" the other 2 nodes.

Freeipa03:

[08/Jun/2017:17:10:06.343697044 +0000] conn=9237 fd=70 slot=70 connection from 192.168.0.12 to 192.168.0.13 [08/Jun/2017:19:54:05.025713675 +0000] conn=9665 fd=70 slot=70 connection from 192.168.0.12 to 192.168.0.13

Freeipa02 replication logging:

[09/Jun/2017:11:24:58.827281135 +0000] NSMMReplicationPlugin - csnplCommitALL: processing data csn 593964af000900030000

Repeats 800 - 900 time per second with a different csn.

[09/Jun/2017:11:23:35.369961485 +0000] NSMMReplicationPlugin - conn=25423 op=264360 Acquired consumer connection extension [09/Jun/2017:11:23:35.372119530 +0000] NSMMReplicationPlugin - conn=25423 op=264360 repl="dc=ipa,dc=example,dc=com": Begin incremental protocol [09/Jun/2017:11:23:35.373351582 +0000] csngen_adjust_time: gen state before 593a85370005:1497007413:0:2 [09/Jun/2017:11:23:35.375049196 +0000] _csngen_adjust_local_time: gen state before 593a85370005:1497007413:0:2 [09/Jun/2017:11:23:35.378561540 +0000] _csngen_adjust_local_time: gen state after 593a85380000:1497007414:0:2 [09/Jun/2017:11:23:35.379799723 +0000] csngen_adjust_time: gen state after 593a85380002:1497007414:0:2 [09/Jun/2017:11:23:35.381061072 +0000] NSMMReplicationPlugin - conn=25423 op=264360 repl="dc=ipa,dc=example,dc=com": Acquired replica [09/Jun/2017:11:23:35.383050359 +0000] NSMMReplicationPlugin - conn=25423 op=264360 repl="dc=ipa,dc=example,dc=com": StartNSDS90ReplicationRequest: response=0 rc=0 [09/Jun/2017:11:23:35.384410556 +0000] NSMMReplicationPlugin - conn=25423 op=264360 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.401662597 +0000] NSMMReplicationPlugin - conn=25423 op=264361 Acquired consumer connection extension [09/Jun/2017:11:23:35.405738547 +0000] NSMMReplicationPlugin - conn=25423 op=264361 repl="dc=ipa,dc=example,dc=com": Released replica held by locking_purl=conn=25423 id=264360 [09/Jun/2017:11:23:35.407391362 +0000] NSMMReplicationPlugin - conn=25423 op=264361 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.409022374 +0000] NSMMReplicationPlugin - conn=25423 op=264362 Acquired consumer connection extension [09/Jun/2017:11:23:35.410925163 +0000] NSMMReplicationPlugin - conn=25423 op=264362 repl="dc=ipa,dc=example,dc=com": Begin incremental protocol [09/Jun/2017:11:23:35.413478042 +0000] csngen_adjust_time: gen state before 593a85380002:1497007414:0:2 [09/Jun/2017:11:23:35.414970366 +0000] csngen_adjust_time: gen state after 593a85380008:1497007414:0:2 [09/Jun/2017:11:23:35.416204493 +0000] NSMMReplicationPlugin - conn=25423 op=264362 repl="dc=ipa,dc=example,dc=com": Acquired replica [09/Jun/2017:11:23:35.417872073 +0000] NSMMReplicationPlugin - conn=25423 op=264362 repl="dc=ipa,dc=example,dc=com": StartNSDS90ReplicationRequest: response=0 rc=0 [09/Jun/2017:11:23:35.419084756 +0000] NSMMReplicationPlugin - conn=25423 op=264362 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.425564689 +0000] NSMMReplicationPlugin - conn=25423 op=264363 Acquired consumer connection extension [09/Jun/2017:11:23:35.428869588 +0000] NSMMReplicationPlugin - conn=25423 op=264363 repl="dc=ipa,dc=example,dc=com": Released replica held by locking_purl=conn=25423 id=264362 [09/Jun/2017:11:23:35.430048781 +0000] NSMMReplicationPlugin - conn=25423 op=264363 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.446697335 +0000] NSMMReplicationPlugin - conn=25423 op=264364 Acquired consumer connection extension [09/Jun/2017:11:23:35.449104495 +0000] NSMMReplicationPlugin - conn=25423 op=264364 repl="dc=ipa,dc=example,dc=com": Begin incremental protocol [09/Jun/2017:11:23:35.450352007 +0000] csngen_adjust_time: gen state before 593a85380008:1497007414:0:2 [09/Jun/2017:11:23:35.451676656 +0000] csngen_adjust_time: gen state after 593a8538000a:1497007414:0:2 [09/Jun/2017:11:23:35.455589607 +0000] NSMMReplicationPlugin - conn=25423 op=264364 repl="dc=ipa,dc=example,dc=com": Acquired replica [09/Jun/2017:11:23:35.457436037 +0000] NSMMReplicationPlugin - conn=25423 op=264364 repl="dc=ipa,dc=example,dc=com": StartNSDS90ReplicationRequest: response=0 rc=0 [09/Jun/2017:11:23:35.458682967 +0000] NSMMReplicationPlugin - conn=25423 op=264364 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.463307540 +0000] NSMMReplicationPlugin - conn=25423 op=264365 Acquired consumer connection extension [09/Jun/2017:11:23:35.466539770 +0000] NSMMReplicationPlugin - conn=25423 op=264365 repl="dc=ipa,dc=example,dc=com": Released replica held by locking_purl=conn=25423 id=264364 [09/Jun/2017:11:23:35.467923321 +0000] NSMMReplicationPlugin - conn=25423 op=264365 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.616313341 +0000] NSMMReplicationPlugin - conn=25423 op=264366 Acquired consumer connection extension [09/Jun/2017:11:23:35.618268832 +0000] NSMMReplicationPlugin - conn=25423 op=264366 repl="dc=ipa,dc=example,dc=com": Begin incremental protocol [09/Jun/2017:11:23:35.619545238 +0000] csngen_adjust_time: gen state before 593a8538000a:1497007414:0:2 [09/Jun/2017:11:23:35.620724991 +0000] csngen_adjust_time: gen state after 593a8538000f:1497007414:0:2 [09/Jun/2017:11:23:35.622223896 +0000] NSMMReplicationPlugin - conn=25423 op=264366 repl="dc=ipa,dc=example,dc=com": Acquired replica [09/Jun/2017:11:23:35.624000688 +0000] NSMMReplicationPlugin - conn=25423 op=264366 repl="dc=ipa,dc=example,dc=com": StartNSDS90ReplicationRequest: response=0 rc=0 [09/Jun/2017:11:23:35.625239857 +0000] NSMMReplicationPlugin - conn=25423 op=264366 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.632952778 +0000] NSMMReplicationPlugin - conn=25423 op=264367 Acquired consumer connection extension [09/Jun/2017:11:23:35.636376469 +0000] NSMMReplicationPlugin - conn=25423 op=264367 repl="dc=ipa,dc=example,dc=com": Released replica held by locking_purl=conn=25423 id=264366 [09/Jun/2017:11:23:35.638246352 +0000] NSMMReplicationPlugin - conn=25423 op=264367 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.640313811 +0000] NSMMReplicationPlugin - conn=25423 op=264368 Acquired consumer connection extension [09/Jun/2017:11:23:35.641698620 +0000] NSMMReplicationPlugin - conn=25423 op=264368 repl="dc=ipa,dc=example,dc=com": Begin incremental protocol [09/Jun/2017:11:23:35.642781684 +0000] csngen_adjust_time: gen state before 593a8538000f:1497007414:0:2 [09/Jun/2017:11:23:35.643891535 +0000] csngen_adjust_time: gen state after 593a85380012:1497007414:0:2 [09/Jun/2017:11:23:35.645168025 +0000] NSMMReplicationPlugin - conn=25423 op=264368 repl="dc=ipa,dc=example,dc=com": Acquired replica [09/Jun/2017:11:23:35.646733260 +0000] NSMMReplicationPlugin - conn=25423 op=264368 repl="dc=ipa,dc=example,dc=com": StartNSDS90ReplicationRequest: response=0 rc=0 [09/Jun/2017:11:23:35.647809079 +0000] NSMMReplicationPlugin - conn=25423 op=264368 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.657157358 +0000] NSMMReplicationPlugin - conn=25423 op=264369 Acquired consumer connection extension [09/Jun/2017:11:23:35.660230137 +0000] NSMMReplicationPlugin - conn=25423 op=264369 repl="dc=ipa,dc=example,dc=com": Released replica held by locking_purl=conn=25423 id=264368 [09/Jun/2017:11:23:35.661335755 +0000] NSMMReplicationPlugin - conn=25423 op=264369 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.664472242 +0000] NSMMReplicationPlugin - conn=25423 op=264370 Acquired consumer connection extension [09/Jun/2017:11:23:35.665951740 +0000] NSMMReplicationPlugin - conn=25423 op=264370 repl="dc=ipa,dc=example,dc=com": Begin incremental protocol [09/Jun/2017:11:23:35.666980091 +0000] csngen_adjust_time: gen state before 593a85380012:1497007414:0:2 [09/Jun/2017:11:23:35.668332835 +0000] csngen_adjust_time: gen state after 593a85380015:1497007414:0:2 [09/Jun/2017:11:23:35.669862710 +0000] NSMMReplicationPlugin - conn=25423 op=264370 repl="dc=ipa,dc=example,dc=com": Acquired replica [09/Jun/2017:11:23:35.671275797 +0000] NSMMReplicationPlugin - conn=25423 op=264370 repl="dc=ipa,dc=example,dc=com": StartNSDS90ReplicationRequest: response=0 rc=0 [09/Jun/2017:11:23:35.672308999 +0000] NSMMReplicationPlugin - conn=25423 op=264370 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.681152759 +0000] NSMMReplicationPlugin - conn=25423 op=264371 Acquired consumer connection extension [09/Jun/2017:11:23:35.684694343 +0000] NSMMReplicationPlugin - conn=25423 op=264371 repl="dc=ipa,dc=example,dc=com": Released replica held by locking_purl=conn=25423 id=264370 [09/Jun/2017:11:23:35.685964169 +0000] NSMMReplicationPlugin - conn=25423 op=264371 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.688474490 +0000] NSMMReplicationPlugin - conn=25423 op=264372 Acquired consumer connection extension [09/Jun/2017:11:23:35.689898052 +0000] NSMMReplicationPlugin - conn=25423 op=264372 repl="dc=ipa,dc=example,dc=com": Begin incremental protocol [09/Jun/2017:11:23:35.691210304 +0000] csngen_adjust_time: gen state before 593a85380015:1497007414:0:2 [09/Jun/2017:11:23:35.693114309 +0000] csngen_adjust_time: gen state after 593a8538001b:1497007414:0:2 [09/Jun/2017:11:23:35.694414531 +0000] NSMMReplicationPlugin - conn=25423 op=264372 repl="dc=ipa,dc=example,dc=com": Acquired replica [09/Jun/2017:11:23:35.695705088 +0000] NSMMReplicationPlugin - conn=25423 op=264372 repl="dc=ipa,dc=example,dc=com": StartNSDS90ReplicationRequest: response=0 rc=0 [09/Jun/2017:11:23:35.696904120 +0000] NSMMReplicationPlugin - conn=25423 op=264372 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.705321103 +0000] NSMMReplicationPlugin - conn=25423 op=264373 Acquired consumer connection extension [09/Jun/2017:11:23:35.708729601 +0000] NSMMReplicationPlugin - conn=25423 op=264373 repl="dc=ipa,dc=example,dc=com": Released replica held by locking_purl=conn=25423 id=264372 [09/Jun/2017:11:23:35.710117231 +0000] NSMMReplicationPlugin - conn=25423 op=264373 Relinquishing consumer connection extension [09/Jun/2017:11:23:35.804518175 +0000] _csngen_adjust_local_time: gen state before 593a8538001b:1497007414:0:2 [09/Jun/2017:11:23:35.806089913 +0000] _csngen_adjust_local_time: gen state after 593a85390000:1497007415:0:2 [09/Jun/2017:11:23:35.807226603 +0000] NSMMReplicationPlugin - ruv_add_csn_inprogress: successfully inserted csn 593a8539000000030000 into pending list [09/Jun/2017:11:23:35.808490329 +0000] NSMMReplicationPlugin - Purged state information from entry uid=admin,cn=users,cn=accounts,dc=ipa,dc=example,dc=com up to CSN 59314aac001300040000 [09/Jun/2017:11:23:35.813252764 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:23:35.815030341 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:23:36.966971030 +0000] NSMMReplicationPlugin - conn=25423 op=264374 Acquired consumer connection extension [09/Jun/2017:11:23:37.152983273 +0000] NSMMReplicationPlugin - conn=25423 op=264374 repl="dc=ipa,dc=example,dc=com": Begin incremental protocol [09/Jun/2017:11:23:40.513966641 +0000] NSMMReplicationPlugin - conn=31891 op=108 Acquired consumer connection extension [09/Jun/2017:11:23:40.516032713 +0000] NSMMReplicationPlugin - conn=31891 op=108 repl="dc=ipa,dc=example,dc=com": Begin incremental protocol [09/Jun/2017:11:23:59.148426236 +0000] NSMMReplicationPlugin - ruv_update_ruv: successfully committed csn 593a8539000000030000 [09/Jun/2017:11:23:59.150000307 +0000] csngen_adjust_time: gen state before 593a85390001:1497007415:0:2 [09/Jun/2017:11:23:59.151524926 +0000] _csngen_adjust_local_time: gen state before 593a85390001:1497007415:0:2 [09/Jun/2017:11:23:59.152735294 +0000] _csngen_adjust_local_time: gen state after 593a85500000:1497007438:0:2 [09/Jun/2017:11:23:59.153668431 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): State: wait_for_changes -> wait_for_changes [09/Jun/2017:11:23:59.154793650 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): State: wait_for_changes -> ready_to_acquire_replica [09/Jun/2017:11:23:59.155870517 +0000] NSMMReplicationPlugin - conn=25423 op=264374 repl="dc=ipa,dc=example,dc=com": Acquired replica [09/Jun/2017:11:23:59.157054222 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): State: wait_for_changes -> wait_for_changes [09/Jun/2017:11:23:59.158237336 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): State: wait_for_changes -> ready_to_acquire_replica [09/Jun/2017:11:23:59.159455126 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Cancelling linger on the connection [09/Jun/2017:11:23:59.161084796 +0000] csngen_adjust_time: gen state before 593a85500000:1497007438:0:2 [09/Jun/2017:11:23:59.163055051 +0000] NSMMReplicationPlugin - conn=31891 op=108 repl="dc=ipa,dc=example,dc=com": Replica in use locking_purl=conn=25423 id=264374 [09/Jun/2017:11:23:59.164692726 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFile: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:23:59.165998389 +0000] NSMMReplicationPlugin - changelog program - cl5GetOperationCount: found DB object 7fc617e39fb0 [09/Jun/2017:11:23:59.167383700 +0000] NSMMReplicationPlugin - conn=31891 op=108 replica="dc=ipa,dc=example,dc=com": Unable to acquire replica: error: replica busy locked by conn=25423 id=264374 for incremental update [09/Jun/2017:11:23:59.168588051 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Cancelling linger on the connection [09/Jun/2017:11:23:59.169680583 +0000] NSMMReplicationPlugin - conn=25423 op=264374 repl="dc=ipa,dc=example,dc=com": StartNSDS90ReplicationRequest: response=0 rc=0 [09/Jun/2017:11:23:59.170777957 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFile: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:23:59.171838122 +0000] NSMMReplicationPlugin - changelog program - cl5GetOperationCount: found DB object 7fc617e39fb0 [09/Jun/2017:11:23:59.173023432 +0000] NSMMReplicationPlugin - conn=31891 op=108 repl="dc=ipa,dc=example,dc=com": StartNSDS90ReplicationRequest: response=1 rc=0 [09/Jun/2017:11:23:59.174115819 +0000] NSMMReplicationPlugin - ruv_add_csn_inprogress: successfully inserted csn 593a8550000200030000 into pending list [09/Jun/2017:11:23:59.175212206 +0000] NSMMReplicationPlugin - conn=25423 op=264374 Relinquishing consumer connection extension [09/Jun/2017:11:23:59.176245867 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Replica was successfully acquired. [09/Jun/2017:11:23:59.177346814 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Replica was successfully acquired. [09/Jun/2017:11:23:59.178446626 +0000] NSMMReplicationPlugin - conn=31891 op=108 Relinquishing consumer connection extension [09/Jun/2017:11:23:59.179481731 +0000] NSMMReplicationPlugin - Purged state information from entry uid=dynamic-kepler,cn=users,cn=accounts,dc=ipa,dc=example,dc=com up to CSN 59314aac001300040000 [09/Jun/2017:11:23:59.180647455 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): State: ready_to_acquire_replica -> sending_updates [09/Jun/2017:11:23:59.181915531 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): State: ready_to_acquire_replica -> sending_updates [09/Jun/2017:11:23:59.183084279 +0000] csngen_adjust_time: gen state before 593a85500003:1497007438:0:2 [09/Jun/2017:11:23:59.184247501 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFile: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:23:59.185241528 +0000] csngen_adjust_time: gen state before 593a85500003:1497007438:0:2 [09/Jun/2017:11:23:59.186423239 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFile: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:23:59.187605163 +0000] _cl5PositionCursorForReplay (agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389)): Consumer RUV: [09/Jun/2017:11:23:59.188816969 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): {replicageneration} 57867ff5000000040000 [09/Jun/2017:11:23:59.189875597 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): {replica 4 ldap://freeipa01.mgmt.example.com:389} 57867ffe000000040000 593a854f000800040000 00000000 [09/Jun/2017:11:23:59.191148141 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): {replica 3 ldap://freeipa02.mgmt.example.com:389} 57867ffa000000030000 5937cccd000300030000 00000000 [09/Jun/2017:11:23:59.192435806 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): {replica 5 ldap://freeipa03.mgmt.example.com:389} 59355988000000050000 593a8512000400050000 00000000 [09/Jun/2017:11:23:59.193752191 +0000] _cl5PositionCursorForReplay (agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389)): Supplier RUV: [09/Jun/2017:11:23:59.194855092 +0000] NSMMReplicationPlugin - ruv_add_csn_inprogress: successfully inserted csn 593a8550000300030000 into pending list [09/Jun/2017:11:23:59.196013013 +0000] _cl5PositionCursorForReplay (agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389)): Consumer RUV: [09/Jun/2017:11:23:59.197018847 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): {replicageneration} 57867ff5000000040000 [09/Jun/2017:11:23:59.198149650 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): {replica 5 ldap://freeipa03.mgmt.example.com:389} 59355988000000050000 593a854f000200050000 00000000 [09/Jun/2017:11:23:59.199164207 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): {replica 3 ldap://freeipa02.mgmt.example.com:389} 57867ffa000000030000 5937cccd000300030000 00000000 [09/Jun/2017:11:23:59.200160501 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): {replica 4 ldap://freeipa01.mgmt.example.com:389} 57867ffe000000040000 593a8549000200040000 00000000 [09/Jun/2017:11:23:59.201223801 +0000] _cl5PositionCursorForReplay (agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389)): Supplier RUV: [09/Jun/2017:11:23:59.202406176 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): {replicageneration} 57867ff5000000040000 [09/Jun/2017:11:23:59.203534024 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): {replica 3 ldap://freeipa02.mgmt.example.com:389} 57867ffa000000030000 5937ccd3000a00030000 5937ccd0 [09/Jun/2017:11:23:59.204516976 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): {replica 4 ldap://freeipa01.mgmt.example.com:389} 57867ffe000000040000 593a852c001300040000 593a852c [09/Jun/2017:11:23:59.205570891 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): {replica 5 ldap://freeipa03.mgmt.example.com:389} 59355988000000050000 593a8512000400050000 593a8511 [09/Jun/2017:11:23:59.206847122 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - clcache_get_buffer: found thread private buffer cache 7fc5ec02a250 [09/Jun/2017:11:23:59.207950863 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - clcache_get_buffer: _pool is 7fc617e6c070 _pool->pl_busy_lists is 7fc5e8052d30 _pool->pl_busy_lists->bl_buffers is 7fc5e8052c30 [09/Jun/2017:11:23:59.209067644 +0000] clcache_initial_anchorcsn - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - (cscb 0 - state 0) - csnPrevMax () csnMax (5937ccd3000a00030000) csnBuf (5937ccd3001a00040000) csnConsumerMax (5937cccd000300030000) [09/Jun/2017:11:23:59.210151400 +0000] clcache_initial_anchorcsn - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - (cscb 1 - state 1) - csnPrevMax () csnMax (593a852c001300040000) csnBuf (5937ccd3001a00040000) csnConsumerMax (593a8549000200040000) [09/Jun/2017:11:23:59.211264387 +0000] clcache_initial_anchorcsn - anchor is now: 5937cccd000300030000 [09/Jun/2017:11:23:59.212241989 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): {replicageneration} 57867ff5000000040000 [09/Jun/2017:11:23:59.213476236 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): {replica 3 ldap://freeipa02.mgmt.example.com:389} 57867ffa000000030000 5937ccd3000a00030000 5937ccd0 [09/Jun/2017:11:23:59.214735708 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): {replica 4 ldap://freeipa01.mgmt.example.com:389} 57867ffe000000040000 593a852c001300040000 593a852c [09/Jun/2017:11:23:59.215853690 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): {replica 5 ldap://freeipa03.mgmt.example.com:389} 59355988000000050000 593a8512000400050000 593a8511 [09/Jun/2017:11:23:59.217009469 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - clcache_get_buffer: found thread private buffer cache 7fc5f800cee0 [09/Jun/2017:11:23:59.218074716 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - clcache_get_buffer: _pool is 7fc617e6c070 _pool->pl_busy_lists is 7fc5e8052d30 _pool->pl_busy_lists->bl_buffers is 7fc5e8052c30 [09/Jun/2017:11:23:59.219157320 +0000] clcache_initial_anchorcsn - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - (cscb 0 - state 0) - csnPrevMax () csnMax (5937ccd3000a00030000) csnBuf (5937ccd3001a00040000) csnConsumerMax (5937cccd000300030000) [09/Jun/2017:11:23:59.220647475 +0000] clcache_initial_anchorcsn - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - (cscb 1 - state 1) - csnPrevMax () csnMax (593a8512000400050000) csnBuf (5937ccd3001a00040000) csnConsumerMax (593a8512000400050000) [09/Jun/2017:11:23:59.221818485 +0000] clcache_initial_anchorcsn - anchor is now: 5937cccd000300030000 [09/Jun/2017:11:23:59.222874292 +0000] NSMMReplicationPlugin - Purged state information from entry uid=dynamic-kepler,cn=users,cn=accounts,dc=ipa,dc=example,dc=com up to CSN 59314aac001300040000 [09/Jun/2017:11:23:59.223866110 +0000] NSMMReplicationPlugin - changelog program - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): CSN 5937cccd000300030000 found, position set for replay [09/Jun/2017:11:23:59.224974543 +0000] NSMMReplicationPlugin - changelog program - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): CSN 5937cccd000300030000 found, position set for replay [09/Jun/2017:11:23:59.226535009 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=1 rec=1 csn=5937cccd000500030000 [09/Jun/2017:11:23:59.227905158 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=claim-winter,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000500030000) [09/Jun/2017:11:23:59.228971714 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=1 rec=1 csn=5937cccd000500030000 [09/Jun/2017:11:23:59.230147572 +0000] repl5_inc_result_threadmain starting [09/Jun/2017:11:23:59.231294475 +0000] repl5_inc_result_threadmain starting [09/Jun/2017:11:23:59.232517579 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:23:59.233688545 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=claim-winter,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000500030000) not sent - empty [09/Jun/2017:11:23:59.234698603 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937cccd000500030000 [09/Jun/2017:11:23:59.235705585 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid 6cce4f02-6fe611e6-96f2be56-1da7a3c1, CSN 5937cccd000500030000): [09/Jun/2017:11:23:59.236758912 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=1 rec=2 csn=5937cccd000600030000 [09/Jun/2017:11:23:59.237960234 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=rust-leeloo,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000600030000) [09/Jun/2017:11:23:59.239122213 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=rust-leeloo,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000600030000) not sent - empty [09/Jun/2017:11:23:59.240561993 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937cccd000600030000 [09/Jun/2017:11:23:59.241609779 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid 56a8a935-704f11e6-96f2be56-1da7a3c1, CSN 5937cccd000600030000): [09/Jun/2017:11:23:59.242656367 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:23:59.243731678 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=claim-winter,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000500030000) [09/Jun/2017:11:23:59.244786013 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.246022182 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.247079907 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=1 rec=3 csn=5937cccd000700030000 [09/Jun/2017:11:23:59.248439671 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=claim-winter,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000500030000) not sent - empty [09/Jun/2017:11:23:59.249511773 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937cccd000500030000 [09/Jun/2017:11:23:59.250807498 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid 6cce4f02-6fe611e6-96f2be56-1da7a3c1, CSN 5937cccd000500030000): [09/Jun/2017:11:23:59.251791244 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=1 rec=2 csn=5937cccd000600030000 [09/Jun/2017:11:23:59.252850577 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=orange-surprise,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000700030000) [09/Jun/2017:11:23:59.253890242 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:23:59.254997201 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.256123172 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.257187333 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=rust-leeloo,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000600030000) [09/Jun/2017:11:23:59.258395524 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=orange-surprise,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000700030000) not sent - empty [09/Jun/2017:11:23:59.259420543 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937cccd000700030000 [09/Jun/2017:11:23:59.260414170 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid 63c7973e-705311e6-96f2be56-1da7a3c1, CSN 5937cccd000700030000): [09/Jun/2017:11:23:59.261456333 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=1 rec=4 csn=5937cccd000800030000 [09/Jun/2017:11:23:59.262493032 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.263755098 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:23:59.264958435 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.266036220 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=rust-leeloo,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000600030000) not sent - empty [09/Jun/2017:11:23:59.267213752 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937cccd000600030000 [09/Jun/2017:11:23:59.268403318 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid 56a8a935-704f11e6-96f2be56-1da7a3c1, CSN 5937cccd000600030000): [09/Jun/2017:11:23:59.269441700 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=carmine-pascal,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000800030000) [09/Jun/2017:11:23:59.270556133 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.271763440 +0000] NSMMReplicationPlugin - ruv_add_csn_inprogress: successfully inserted csn 593a8549000200040000 into pending list [09/Jun/2017:11:23:59.273021252 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=1 rec=3 csn=5937cccd000700030000 [09/Jun/2017:11:23:59.274163167 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.275240924 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=carmine-pascal,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000800030000) not sent - empty [09/Jun/2017:11:23:59.276258494 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937cccd000800030000 [09/Jun/2017:11:23:59.277296208 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid 5e1e8132-705411e6-96f2be56-1da7a3c1, CSN 5937cccd000800030000): [09/Jun/2017:11:23:59.339003700 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=1 rec=5 csn=5937cccd000900030000 [09/Jun/2017:11:23:59.340167578 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=orange-surprise,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000700030000) [09/Jun/2017:11:23:59.341967319 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.343885306 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.473976871 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=orange-surprise,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000700030000) not sent - empty [09/Jun/2017:11:23:59.475134422 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937cccd000700030000 [09/Jun/2017:11:23:59.476103287 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid 63c7973e-705311e6-96f2be56-1da7a3c1, CSN 5937cccd000700030000): [09/Jun/2017:11:23:59.477404633 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.634970515 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.635972943 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.637014347 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=1 rec=4 csn=5937cccd000800030000 [09/Jun/2017:11:23:59.637999767 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=yellow-word,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000900030000) [09/Jun/2017:11:23:59.669108492 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.670299094 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=yellow-word,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000900030000) not sent - empty [09/Jun/2017:11:23:59.671338294 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937cccd000900030000 [09/Jun/2017:11:23:59.672273023 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid 2300c133-744b11e6-96f2be56-1da7a3c1, CSN 5937cccd000900030000): [09/Jun/2017:11:23:59.693524887 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=1 rec=6 csn=5937cccd000a00030000 [09/Jun/2017:11:23:59.694654897 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=carmine-pascal,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000800030000) [09/Jun/2017:11:23:59.695873986 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=carmine-pascal,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000800030000) not sent - empty [09/Jun/2017:11:23:59.697086747 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937cccd000800030000 [09/Jun/2017:11:23:59.698226406 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid 5e1e8132-705411e6-96f2be56-1da7a3c1, CSN 5937cccd000800030000): [09/Jun/2017:11:23:59.699334764 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=1 rec=5 csn=5937cccd000900030000 [09/Jun/2017:11:23:59.706234640 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:23:59.707281062 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=yellow-word,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000900030000) [09/Jun/2017:11:23:59.708333989 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=maroon-han,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000a00030000) [09/Jun/2017:11:23:59.826311317 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=maroon-han,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000a00030000) not sent - empty [09/Jun/2017:11:23:59.827303065 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937cccd000a00030000 [09/Jun/2017:11:23:59.828244567 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid 24cd8306-745111e6-96f2be56-1da7a3c1, CSN 5937cccd000a00030000): [09/Jun/2017:11:24:00.119835159 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:00.121132287 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=1 rec=7 csn=5937cccd000b00030000 [09/Jun/2017:11:24:00.122246967 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:00.123418461 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=yellow-word,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000900030000) not sent - empty [09/Jun/2017:11:24:00.124528188 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937cccd000900030000 [09/Jun/2017:11:24:00.125736293 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid 2300c133-744b11e6-96f2be56-1da7a3c1, CSN 5937cccd000900030000): [09/Jun/2017:11:24:00.346203115 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=impress-spite,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000b00030000) [09/Jun/2017:11:24:00.347254280 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:00.348414055 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=1 rec=6 csn=5937cccd000a00030000 [09/Jun/2017:11:24:00.349554133 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=maroon-han,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000a00030000) [09/Jun/2017:11:24:00.351735287 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=maroon-han,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000a00030000) not sent - empty [09/Jun/2017:11:24:00.352846041 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937cccd000a00030000 [09/Jun/2017:11:24:00.353933852 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid 24cd8306-745111e6-96f2be56-1da7a3c1, CSN 5937cccd000a00030000): [09/Jun/2017:11:24:00.354913324 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=1 rec=7 csn=5937cccd000b00030000 [09/Jun/2017:11:24:00.356017624 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=impress-spite,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000b00030000) [09/Jun/2017:11:24:00.357138628 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=impress-spite,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000b00030000) not sent - empty [09/Jun/2017:11:24:00.358373469 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937cccd000b00030000 [09/Jun/2017:11:24:00.359560743 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid 3733de0b-479311e7-96f2be56-1da7a3c1, CSN 5937cccd000b00030000): [09/Jun/2017:11:24:00.360765077 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=1 rec=8 csn=5937cccd000c00030000 [09/Jun/2017:11:24:00.361908467 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=understanding-tradition-walk,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000c00030000) [09/Jun/2017:11:24:00.363132015 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=understanding-tradition-walk,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000c00030000) not sent - empty [09/Jun/2017:11:24:00.364337739 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937cccd000c00030000 [09/Jun/2017:11:24:00.365371180 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid 5a03cf19-753e11e6-96f2be56-1da7a3c1, CSN 5937cccd000c00030000): [09/Jun/2017:11:24:00.412383063 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=impress-spite,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000b00030000) not sent - empty [09/Jun/2017:11:24:00.413431885 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937cccd000b00030000 [09/Jun/2017:11:24:00.414386555 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid 3733de0b-479311e7-96f2be56-1da7a3c1, CSN 5937cccd000b00030000): [09/Jun/2017:11:24:00.415356502 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:00.516093595 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=1 rec=8 csn=5937cccd000c00030000 [09/Jun/2017:11:24:00.536011820 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=understanding-tradition-walk,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000c00030000) [09/Jun/2017:11:24:00.621969760 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=understanding-tradition-walk,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000c00030000) not sent - empty [09/Jun/2017:11:24:00.623073358 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937cccd000c00030000 [09/Jun/2017:11:24:00.624389007 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid 5a03cf19-753e11e6-96f2be56-1da7a3c1, CSN 5937cccd000c00030000): [09/Jun/2017:11:24:00.625780420 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:01.095045708 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:01.168977824 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:02.131027199 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:02.335544215 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:03.054906281 +0000] NSMMReplicationPlugin - conn=31891 op=109 Acquired consumer connection extension [09/Jun/2017:11:24:03.067325491 +0000] NSMMReplicationPlugin - conn=31891 op=109 repl="dc=ipa,dc=example,dc=com": Begin incremental protocol [09/Jun/2017:11:24:03.167477981 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:03.428535079 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:04.198918134 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:04.703565461 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:05.421976186 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:05.758162332 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:06.740878753 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:06.848889369 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:07.913970239 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:07.915242746 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:08.963329779 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:08.964473772 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:10.149965805 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:10.151179223 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:11.237996339 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:11.239111840 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:12.505969952 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:12.506989732 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:13.592971583 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:13.594640614 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:14.654656307 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:14.655773809 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:15.694634141 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:15.695886238 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:16.721904498 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:16.810970655 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:17.998988021 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:18.000108731 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:19.183980776 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:19.185207669 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:20.213470305 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:20.214487748 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:21.368495882 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:21.369491946 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:22.021620336 +0000] NSMMReplicationPlugin - ruv_update_ruv: successfully committed csn 593a8550000200030000 [09/Jun/2017:11:24:22.022751841 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - (cscb 0 - state 0) - csnPrevMax (5937ccd3000a00030000) csnMax (5937ccd3000a00030000) csnBuf (5937cccd000c00030000) csnConsumerMax (5937cccd000c00030000) [09/Jun/2017:11:24:22.023746956 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - (cscb 1 - state 1) - csnPrevMax (593a8512000400050000) csnMax (593a8512000400050000) csnBuf (5937cccd000c00030000) csnConsumerMax (593a8512000400050000) [09/Jun/2017:11:24:22.024744332 +0000] clcache_adjust_anchorcsn - anchor is now: 5937cccd000c00030000 [09/Jun/2017:11:24:22.025844615 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - (cscb 0 - state 0) - csnPrevMax (5937ccd3000a00030000) csnMax (5937ccd3000a00030000) csnBuf (5937cccd000c00030000) csnConsumerMax (5937cccd000c00030000) [09/Jun/2017:11:24:22.026883994 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - (cscb 1 - state 1) - csnPrevMax (593a852c001300040000) csnMax (593a852c001300040000) csnBuf (5937cccd000c00030000) csnConsumerMax (593a8549000200040000) [09/Jun/2017:11:24:22.027876070 +0000] clcache_adjust_anchorcsn - anchor is now: 5937cccd000c00030000 [09/Jun/2017:11:24:22.028914820 +0000] csngen_adjust_time: gen state before 593a85500004:1497007438:0:2 [09/Jun/2017:11:24:22.030027593 +0000] _csngen_adjust_local_time: gen state before 593a85500004:1497007438:0:2 [09/Jun/2017:11:24:22.031068677 +0000] _csngen_adjust_local_time: gen state after 593a85670000:1497007461:0:2 [09/Jun/2017:11:24:22.032197847 +0000] NSMMReplicationPlugin - conn=31891 op=109 repl="dc=ipa,dc=example,dc=com": Replica in use locking_purl=conn=25423 id=264374 [09/Jun/2017:11:24:22.033416768 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=2 rec=9 csn=5937cccd000d00030000 [09/Jun/2017:11:24:22.034446653 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=2 rec=9 csn=5937cccd000d00030000 [09/Jun/2017:11:24:22.035528149 +0000] NSMMReplicationPlugin - conn=31891 op=109 replica="dc=ipa,dc=example,dc=com": Unable to acquire replica: error: replica busy locked by conn=25423 id=264374 for incremental update [09/Jun/2017:11:24:22.036688318 +0000] NSMMReplicationPlugin - ruv_add_csn_inprogress: successfully inserted csn 593a8567000000030000 into pending list [09/Jun/2017:11:24:22.037813398 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=honest-leroy,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000d00030000) [09/Jun/2017:11:24:22.038846775 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=honest-leroy,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000d00030000) not sent - empty [09/Jun/2017:11:24:22.039950286 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937cccd000d00030000 [09/Jun/2017:11:24:22.040989356 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid eeed862c-f01211e6-96f2be56-1da7a3c1, CSN 5937cccd000d00030000): [09/Jun/2017:11:24:22.042106480 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=2 rec=10 csn=5937cccd000e00030000 [09/Jun/2017:11:24:22.043417515 +0000] NSMMReplicationPlugin - conn=31891 op=109 repl="dc=ipa,dc=example,dc=com": StartNSDS90ReplicationRequest: response=1 rc=0 [09/Jun/2017:11:24:22.044819547 +0000] NSMMReplicationPlugin - Purged state information from entry uid=dynamic-kepler,cn=users,cn=accounts,dc=ipa,dc=example,dc=com up to CSN 59314aac001300040000 [09/Jun/2017:11:24:22.046042245 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=honest-leroy,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000d00030000) [09/Jun/2017:11:24:22.047184987 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=friendly-amethyst-climate,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000e00030000) [09/Jun/2017:11:24:22.048320012 +0000] NSMMReplicationPlugin - conn=31891 op=109 Relinquishing consumer connection extension [09/Jun/2017:11:24:22.049402209 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=honest-leroy,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000d00030000) not sent - empty [09/Jun/2017:11:24:22.050571226 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937cccd000d00030000 [09/Jun/2017:11:24:22.052037522 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid eeed862c-f01211e6-96f2be56-1da7a3c1, CSN 5937cccd000d00030000): [09/Jun/2017:11:24:22.053218635 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=2 rec=10 csn=5937cccd000e00030000 [09/Jun/2017:11:24:22.054413196 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:24:22.055612365 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=friendly-amethyst-climate,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000e00030000) not sent - empty [09/Jun/2017:11:24:22.056669907 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937cccd000e00030000 [09/Jun/2017:11:24:22.057745711 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid 19f31b1b-754311e6-96f2be56-1da7a3c1, CSN 5937cccd000e00030000): [09/Jun/2017:11:24:22.058977638 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=2 rec=11 csn=5937cccd000f00030000 [09/Jun/2017:11:24:22.060789981 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=romantic-blanco-cat,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000f00030000) [09/Jun/2017:11:24:22.061949682 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=romantic-blanco-cat,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000f00030000) not sent - empty [09/Jun/2017:11:24:22.063192209 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937cccd000f00030000 [09/Jun/2017:11:24:22.064360191 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid c1596084-9f7c11e6-96f2be56-1da7a3c1, CSN 5937cccd000f00030000): [09/Jun/2017:11:24:22.065528999 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=2 rec=12 csn=5937cccd001000030000 [09/Jun/2017:11:24:22.066773800 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=friendly-amethyst-climate,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000e00030000) [09/Jun/2017:11:24:22.068014114 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:24:22.069217618 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=good-nemo,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd001000030000) [09/Jun/2017:11:24:22.070527918 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=good-nemo,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd001000030000) not sent - empty [09/Jun/2017:11:24:22.071734093 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937cccd001000030000 [09/Jun/2017:11:24:22.072954591 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid 5f5c3944-766611e6-96f2be56-1da7a3c1, CSN 5937cccd001000030000): [09/Jun/2017:11:24:22.316668767 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=friendly-amethyst-climate,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000e00030000) not sent - empty [09/Jun/2017:11:24:22.336969181 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937cccd000e00030000 [09/Jun/2017:11:24:22.337964863 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid 19f31b1b-754311e6-96f2be56-1da7a3c1, CSN 5937cccd000e00030000): [09/Jun/2017:11:24:22.737496231 +0000] NSMMReplicationPlugin - conn=31891 op=110 Acquired consumer connection extension [09/Jun/2017:11:24:22.739557773 +0000] NSMMReplicationPlugin - conn=31891 op=110 repl="dc=ipa,dc=example,dc=com": Begin incremental protocol [09/Jun/2017:11:24:22.740921837 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:22.742054562 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=2 rec=11 csn=5937cccd000f00030000 [09/Jun/2017:11:24:22.899110951 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:22.900184929 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=romantic-blanco-cat,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000f00030000) [09/Jun/2017:11:24:22.970633375 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=romantic-blanco-cat,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd000f00030000) not sent - empty [09/Jun/2017:11:24:22.971652475 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937cccd000f00030000 [09/Jun/2017:11:24:22.972599623 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid c1596084-9f7c11e6-96f2be56-1da7a3c1, CSN 5937cccd000f00030000): [09/Jun/2017:11:24:22.973604677 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=2 rec=12 csn=5937cccd001000030000 [09/Jun/2017:11:24:23.326980255 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=good-nemo,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd001000030000) [09/Jun/2017:11:24:23.333437765 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=good-nemo,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937cccd001000030000) not sent - empty [09/Jun/2017:11:24:23.341722698 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937cccd001000030000 [09/Jun/2017:11:24:23.345834898 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid 5f5c3944-766611e6-96f2be56-1da7a3c1, CSN 5937cccd001000030000): [09/Jun/2017:11:24:23.348830932 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - Skipping update because the consumer with Rid: [4] is ignored [09/Jun/2017:11:24:23.353132222 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - Skipping update because the consumer with Rid: [4] is ignored [09/Jun/2017:11:24:23.357254972 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - Skipping update because the consumer with Rid: [4] is ignored [09/Jun/2017:11:24:24.424104175 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:24.425487825 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:25.818975203 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:25.820046324 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:27.074028951 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:27.075209888 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:28.101314443 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:28.678977629 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:29.599917667 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:31.875977516 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:31.877211928 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:32.904632505 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:32.905859953 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:34.009979774 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:34.011150703 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:35.307732142 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:35.309119597 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:36.438972102 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:36.440050806 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:37.480882968 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:37.482043005 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:38.862963193 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:38.864129696 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:40.178969941 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:40.180059248 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:41.332969532 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:41.334125348 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:42.441284062 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:42.442379075 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:43.656977050 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:43.658143687 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:45.320909690 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:45.321979651 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:45.381466802 +0000] NSMMReplicationPlugin - ruv_update_ruv: successfully committed csn 593a8567000000030000 [09/Jun/2017:11:24:45.382649596 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - (cscb 0 - state 0) - csnPrevMax (5937ccd3000a00030000) csnMax (5937ccd3000a00030000) csnBuf (5937ccce000a00040000) csnConsumerMax (5937cccd001000030000) [09/Jun/2017:11:24:45.383858959 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - (cscb 1 - state 1) - csnPrevMax (593a852c001300040000) csnMax (593a852c001300040000) csnBuf (5937ccce000a00040000) csnConsumerMax (593a8549000200040000) [09/Jun/2017:11:24:45.385046911 +0000] clcache_adjust_anchorcsn - anchor is now: 5937ccce000a00040000 [09/Jun/2017:11:24:45.386261815 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - (cscb 0 - state 0) - csnPrevMax (5937ccd3000a00030000) csnMax (5937ccd3000a00030000) csnBuf (5937ccce000a00040000) csnConsumerMax (5937cccd001000030000) [09/Jun/2017:11:24:45.387577691 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - (cscb 1 - state 1) - csnPrevMax (593a8512000400050000) csnMax (593a8512000400050000) csnBuf (5937ccce000a00040000) csnConsumerMax (593a8512000400050000) [09/Jun/2017:11:24:45.388773441 +0000] clcache_adjust_anchorcsn - anchor is now: 5937ccce000a00040000 [09/Jun/2017:11:24:45.390049775 +0000] NSMMReplicationPlugin - Authorized replication managers is resync (1497007485) [09/Jun/2017:11:24:45.391213078 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=3 rec=18 csn=5937ccce001600030000 [09/Jun/2017:11:24:45.392608567 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - Skipping update because the consumer with Rid: [4] is ignored [09/Jun/2017:11:24:45.393999065 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - Skipping update because the consumer with Rid: [4] is ignored [09/Jun/2017:11:24:45.395213439 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=3 rec=18 csn=5937ccce001600030000 [09/Jun/2017:11:24:45.396591555 +0000] _csngen_adjust_local_time: gen state before 593a85670001:1497007461:0:2 [09/Jun/2017:11:24:45.397989075 +0000] _csngen_adjust_local_time: gen state after 593a857e0000:1497007484:0:2 [09/Jun/2017:11:24:45.399930736 +0000] csngen_adjust_time: gen state before 593a857e0001:1497007484:0:2 [09/Jun/2017:11:24:45.401174316 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=nieve-if,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937ccce001600030000) [09/Jun/2017:11:24:45.402698725 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=nieve-if,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937ccce001600030000) not sent - empty [09/Jun/2017:11:24:45.403821583 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937ccce001600030000 [09/Jun/2017:11:24:45.404946496 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid 71feb58d-7a4c11e6-96f2be56-1da7a3c1, CSN 5937ccce001600030000): [09/Jun/2017:11:24:45.406078787 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=3 rec=19 csn=5937ccce001700030000 [09/Jun/2017:11:24:45.407270475 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=nieve-if,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937ccce001600030000) [09/Jun/2017:11:24:45.410072396 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=nieve-if,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937ccce001600030000) not sent - empty [09/Jun/2017:11:24:45.411305199 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937ccce001600030000 [09/Jun/2017:11:24:45.412405115 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid 71feb58d-7a4c11e6-96f2be56-1da7a3c1, CSN 5937ccce001600030000): [09/Jun/2017:11:24:45.413573311 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=3 rec=19 csn=5937ccce001700030000 [09/Jun/2017:11:24:45.414738888 +0000] NSMMReplicationPlugin - conn=31891 op=110 repl="dc=ipa,dc=example,dc=com": Replica in use locking_purl=conn=25423 id=264374 [09/Jun/2017:11:24:45.415819170 +0000] NSMMReplicationPlugin - conn=31891 op=110 replica="dc=ipa,dc=example,dc=com": Unable to acquire replica: error: replica busy locked by conn=25423 id=264374 for incremental update [09/Jun/2017:11:24:45.417492568 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=user_api,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937ccce001700030000) [09/Jun/2017:11:24:45.418677205 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=user_api,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937ccce001700030000) not sent - empty [09/Jun/2017:11:24:45.419926966 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937ccce001700030000 [09/Jun/2017:11:24:45.421485957 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid 3ac43904-492311e6-96f2be56-1da7a3c1, CSN 5937ccce001700030000): [09/Jun/2017:11:24:45.422597851 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - Skipping update because the consumer with Rid: [4] is ignored [09/Jun/2017:11:24:45.423875359 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=user_api,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937ccce001700030000) [09/Jun/2017:11:24:45.425009740 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=user_api,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937ccce001700030000) not sent - empty [09/Jun/2017:11:24:45.426012140 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937ccce001700030000 [09/Jun/2017:11:24:45.427217498 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid 3ac43904-492311e6-96f2be56-1da7a3c1, CSN 5937ccce001700030000): [09/Jun/2017:11:24:45.428339841 +0000] NSMMReplicationPlugin - ruv_add_csn_inprogress: successfully inserted csn 593a857e000000030000 into pending list [09/Jun/2017:11:24:45.429633603 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - (cscb 0 - state 0) - csnPrevMax (5937ccd3000a00030000) csnMax (5937ccd3000a00030000) csnBuf (5937ccce001700040000) csnConsumerMax (5937ccce001700030000) [09/Jun/2017:11:24:45.431017786 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - (cscb 1 - state 1) - csnPrevMax (593a8512000400050000) csnMax (593a8512000400050000) csnBuf (5937ccce001700040000) csnConsumerMax (593a8512000400050000) [09/Jun/2017:11:24:45.432188915 +0000] clcache_adjust_anchorcsn - anchor is now: 5937ccce001700040000 [09/Jun/2017:11:24:45.433367469 +0000] NSMMReplicationPlugin - Purged state information from entry uid=admin,cn=users,cn=accounts,dc=ipa,dc=example,dc=com up to CSN 59314aac001300040000 [09/Jun/2017:11:24:45.434496240 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - (cscb 0 - state 0) - csnPrevMax (5937ccd3000a00030000) csnMax (5937ccd3000a00030000) csnBuf (5937ccce001700040000) csnConsumerMax (5937ccce001700030000) [09/Jun/2017:11:24:45.436049132 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - (cscb 1 - state 1) - csnPrevMax (593a852c001300040000) csnMax (593a852c001300040000) csnBuf (5937ccce001700040000) csnConsumerMax (593a8549000200040000) [09/Jun/2017:11:24:45.437140358 +0000] clcache_adjust_anchorcsn - anchor is now: 5937ccce001700040000 [09/Jun/2017:11:24:45.438251461 +0000] NSMMReplicationPlugin - conn=31891 op=110 repl="dc=ipa,dc=example,dc=com": StartNSDS90ReplicationRequest: response=1 rc=0 [09/Jun/2017:11:24:45.439401654 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - Skipping update because the consumer with Rid: [4] is ignored [09/Jun/2017:11:24:45.440409080 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - Skipping update because the consumer with Rid: [4] is ignored [09/Jun/2017:11:24:45.441410977 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - Skipping update because the consumer with Rid: [4] is ignored [09/Jun/2017:11:24:45.442780004 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - load=4 rec=24 csn=5937ccd0000500030000 [09/Jun/2017:11:24:45.444131710 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:24:45.445468007 +0000] agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - load=4 rec=24 csn=5937ccd0000500030000 [09/Jun/2017:11:24:45.446512142 +0000] NSMMReplicationPlugin - conn=31891 op=110 Relinquishing consumer connection extension [09/Jun/2017:11:24:45.447571353 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Sending modify operation (dn="uid=frank-alizarin-wife,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937ccd0000500030000) [09/Jun/2017:11:24:45.448537321 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: modifys operation (dn="uid=frank-alizarin-wife,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937ccd0000500030000) not sent - empty [09/Jun/2017:11:24:45.449614060 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): replay_update: Consumer successfully sent operation with csn 5937ccd0000500030000 [09/Jun/2017:11:24:45.450649912 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389): Skipping update operation with no message_id (uniqueid 0f2f0d86-7a9011e6-96f2be56-1da7a3c1, CSN 5937ccd0000500030000): [09/Jun/2017:11:24:45.451826292 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Sending modify operation (dn="uid=frank-alizarin-wife,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937ccd0000500030000) [09/Jun/2017:11:24:45.452815681 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: modifys operation (dn="uid=frank-alizarin-wife,cn=users,cn=accounts,dc=ipa,dc=example,dc=com" csn=5937ccd0000500030000) not sent - empty [09/Jun/2017:11:24:45.453774071 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): replay_update: Consumer successfully sent operation with csn 5937ccd0000500030000 [09/Jun/2017:11:24:45.454752897 +0000] NSMMReplicationPlugin - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389): Skipping update operation with no message_id (uniqueid 0f2f0d86-7a9011e6-96f2be56-1da7a3c1, CSN 5937ccd0000500030000): [09/Jun/2017:11:24:45.455761552 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - (cscb 0 - state 0) - csnPrevMax (5937ccd3000a00030000) csnMax (5937ccd3000a00030000) csnBuf (5937ccd0000500030000) csnConsumerMax (5937ccd0000500030000) [09/Jun/2017:11:24:45.457682337 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - (cscb 1 - state 1) - csnPrevMax (593a8512000400050000) csnMax (593a8512000400050000) csnBuf (5937ccd0000500030000) csnConsumerMax (593a8512000400050000) [09/Jun/2017:11:24:45.458781212 +0000] clcache_adjust_anchorcsn - anchor is now: 5937ccd0000500030000 [09/Jun/2017:11:24:45.459836378 +0000] NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName: found DB object 7fc617e39fb0 for database /var/lib/dirsrv/slapd-IPA-EXAMPLE-COM/cldb/9e9a320c-492211e6-b8bdad3d-6f36d78c_57867ff5000000040000.db [09/Jun/2017:11:24:45.460908735 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - (cscb 0 - state 0) - csnPrevMax (5937ccd3000a00030000) csnMax (5937ccd3000a00030000) csnBuf (5937ccd0000500030000) csnConsumerMax (5937ccd0000500030000) [09/Jun/2017:11:24:45.461953737 +0000] clcache_adjust_anchorcsn - agmt="cn=meTofreeipa03.mgmt.example.com" (freeipa03:389) - (cscb 1 - state 1) - csnPrevMax (593a852c001300040000) csnMax (593a852c001300040000) csnBuf (5937ccd0000500030000) csnConsumerMax (593a8549000200040000) [09/Jun/2017:11:24:45.463009813 +0000] clcache_adjust_anchorcsn - anchor is now: 5937ccd0000500030000 [09/Jun/2017:11:24:45.464034007 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - Skipping update because the consumer with Rid: [4] is ignored [09/Jun/2017:11:24:45.465052954 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - Skipping update because the consumer with Rid: [4] is ignored [09/Jun/2017:11:24:45.466086437 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - Skipping update because the consumer with Rid: [4] is ignored [09/Jun/2017:11:24:45.467117597 +0000] agmt="cn=meTofreeipa01.mgmt.example.com" (freeipa01:389) - Skipping update because the consumer with Rid: [4] is ignored [09/Jun/2017:11:24:47.326964434 +0000] NSMMReplicationPlugin - conn=31891 op=111 Acquired consumer connection extension [09/Jun/2017:11:24:47.328250272 +0000] NSMMReplicationPlugin - conn=31891 op=111 repl="dc=ipa,dc=example,dc=com": Begin incremental protocol [09/Jun/2017:11:24:47.329402730 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:47.547967746 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:48.458900902 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:48.784073495 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:49.899058335 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:49.900125522 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:51.016070114 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:51.017234474 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:52.124155685 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:52.125252246 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:53.215232214 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:53.216294330 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:54.256159985 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:54.257198516 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:55.301698936 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:55.302865381 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:56.358462954 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:56.359879193 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:57.405304224 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:57.406763420 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:58.479617762 +0000] repl5_inc_result_threadmain: read result for message_id 0 [09/Jun/2017:11:24:58.480672207 +0000] repl5_inc_result_threadmain: read result for message_id 0

On 08/06/17 15:45, Mark Reynolds wrote:

...

On 06/07/2017 10:58 AM, Nick Campion via FreeIPA-users wrote:

...
Hi all,

We have a 3 master setup that is failing to replicate changes from a particular node to the other IPA instances. The replication status says it's all fine, however the record hasn't been changed on the other servers. We've seen this on user password changes, adding hosts and services. The only thing we've found that seems to fix this temporarily is to re-initialize from the master with the changed record. A force-sync doesn't pick up the changed record.

What is the change you making, what attribute are you updating? Could it be possible that its being excluded by fractional replication? Or is it all changes?

Any errors in the logs on the nodes(good and bad): /var/log/dirsrv/slapd-INSTANCE/errors

Do you see replication sessions starting between the bad node and good ones? Are they talking? Check the access log ( /var/log/dirsrv/slapd-INSTANCE/access) on a good node and look for "connection from <BAD NODE IP address>"

Next would be to enable replication logging on the bad node and reproduce the problem (then disable repl logging right away), then send us the logs to look at. See https://access.redhat.com/documentation/en-us/red_hat_directory_server/10/ht...

Regards, Mark

...
Not sure what logs would be helpful to diagnose what is happening in this setup.

# ipa-replica-manage -v list `hostname` freeipa03.mgmt.example.com: replica last init status: None last init ended: 1970-01-01 00:00:00+00:00 last update status: Error (0) Replica acquired successfully: Incremental update succeeded last update ended: 2017-06-07 14:43:53+00:00 freeipa02.mgmt.example.com: replica last init status: None last init ended: 1970-01-01 00:00:00+00:00 last update status: Error (0) Replica acquired successfully: Incremental update succeeded last update ended: 2017-06-07 14:43:53+00:00

# ldapsearch -W -x -D "cn=directory manager" -b "cn=users,cn=accounts,dc=ipa,dc=example,dc=com" "nsds5ReplConflict=*" * nsds5ReplConflict Enter LDAP Password: # extended LDIF # # LDAPv3 # base <cn=users,cn=accounts,dc=ipa,dc=example,dc=com> with scope subtree # filter: nsds5ReplConflict=* # requesting: * nsds5ReplConflict #

# search result search: 2 result: 0 Success

# numResponses: 1

Any help in what else can be checked or what logs would be helpful would be appreciated.

Thanks

Nick

FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org

Nick Campion

12 Jun 12 Jun

12:32 p.m.

Thanks Mark,

As far as I'm aware, there is no fractal replication set up.

Freeipa01:

Freeipa02:

Freeipa03:

Errors on Freeipa02:

The other nodes have no errors from this data.

Access logs:

Freeipa01:

Freeipa02:

Shows no logs "to" the other 2 nodes.

Freeipa03:

Freeipa02 replication logging:

[09/Jun/2017:11:24:58.827281135 +0000] NSMMReplicationPlugin - csnplCommitALL: processing data csn 593964af000900030000

Repeats 800 - 900 time per second with a different csn.

Full logs attached.

On 08/06/17 15:45, Mark Reynolds wrote:

...

On 06/07/2017 10:58 AM, Nick Campion via FreeIPA-users wrote:

...
Hi all,

We have a 3 master setup that is failing to replicate changes from a particular node to the other IPA instances. The replication status says it's all fine, however the record hasn't been changed on the other servers. We've seen this on user password changes, adding hosts and services. The only thing we've found that seems to fix this temporarily is to re-initialize from the master with the changed record. A force-sync doesn't pick up the changed record.

What is the change you making, what attribute are you updating? Could it be possible that its being excluded by fractional replication? Or is it all changes?

Any errors in the logs on the nodes(good and bad): /var/log/dirsrv/slapd-INSTANCE/errors

Do you see replication sessions starting between the bad node and good ones? Are they talking? Check the access log ( /var/log/dirsrv/slapd-INSTANCE/access) on a good node and look for "connection from <BAD NODE IP address>"

Next would be to enable replication logging on the bad node and reproduce the problem (then disable repl logging right away), then send us the logs to look at. See https://access.redhat.com/documentation/en-us/red_hat_directory_server/10/ht...

Regards, Mark

...
Not sure what logs would be helpful to diagnose what is happening in this setup.

# ipa-replica-manage -v list `hostname` freeipa03.mgmt.example.com: replica last init status: None last init ended: 1970-01-01 00:00:00+00:00 last update status: Error (0) Replica acquired successfully: Incremental update succeeded last update ended: 2017-06-07 14:43:53+00:00 freeipa02.mgmt.example.com: replica last init status: None last init ended: 1970-01-01 00:00:00+00:00 last update status: Error (0) Replica acquired successfully: Incremental update succeeded last update ended: 2017-06-07 14:43:53+00:00

# ldapsearch -W -x -D "cn=directory manager" -b "cn=users,cn=accounts,dc=ipa,dc=example,dc=com" "nsds5ReplConflict=*" * nsds5ReplConflict Enter LDAP Password: # extended LDIF # # LDAPv3 # base <cn=users,cn=accounts,dc=ipa,dc=example,dc=com> with scope subtree # filter: nsds5ReplConflict=* # requesting: * nsds5ReplConflict #

# search result search: 2 result: 0 Success

# numResponses: 1

Any help in what else can be checked or what logs would be helpful would be appreciated.

Thanks

Nick

FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org

Mark Reynolds

6:29 p.m.

On 06/12/2017 07:32 AM, Nick Campion via FreeIPA-users wrote:

...

Thanks Mark,

So this example is a user password change using kinit, the password has been changed on freeipa02 but not then replicated to the others. This happens for other records, but I don't have examples of these at the moment.

As far as I'm aware, there is no fractal replication set up.

IPA uses fractional replication, and it's possible these attributes are ignored/skipped. To confirm you can run this search on freeipa02:

ldapsearch -D "cn=directory manager" -W -b cn=config -xLLL objectclass=nsds5ReplicationAgreement

Then please share these entries so we can see how they are configured. Perhaps do this on freeipa01 as well for comparison.

...

Freeipa01:

# dynamic-kepler, users, accounts, ipa.example.com dn: uid=dynamic-kepler,cn=users,cn=accounts,dc=ipa,dc=example,dc=com uid: dynamic-kepler krbLastPwdChange: 20170608170011Z krbPasswordExpiration: 20170608170011Z

Freeipa02:

# dynamic-kepler, users, accounts, ipa.example.com dn: uid=dynamic-kepler,cn=users,cn=accounts,dc=ipa,dc=example,dc=com uid: dynamic-kepler krbLastPwdChange: 20170608170021Z krbPasswordExpiration: 20170906170021Z

Freeipa03:

# dynamic-kepler, users, accounts, ipa.example.com dn: uid=dynamic-kepler,cn=users,cn=accounts,dc=ipa,dc=example,dc=com uid: dynamic-kepler krbLastPwdChange: 20170608170011Z krbPasswordExpiration: 20170608170011Z

Errors on Freeipa02:

[08/Jun/2017:01:46:50.635529447 +0000] replica_generate_next_csn: opcsn=5938ac8b000500030000 <= basecsn=5938ac8b000500040000, adjusted opcsn=5938ac8b000600030000 [08/Jun/2017:12:16:46.497249649 +0000] replica_generate_next_csn: opcsn=5939402f000500030000 <= basecsn=5939402f000800040000, adjusted opcsn=5939402f000900030000 [08/Jun/2017:23:38:48.197750001 +0000] replica_generate_next_csn: opcsn=5939e009000100030000 <= basecsn=5939e009000f00040000, adjusted opcsn=5939e009001000030000

The other nodes have no errors from this data.

Access logs:

Freeipa01:

[08/Jun/2017:01:46:50.635529447 +0000] replica_generate_next_csn: opcsn=5938ac8b000500030000 <= basecsn=5938ac8b000500040000, adjusted opcsn=5938ac8b000600030000 [08/Jun/2017:12:16:46.497249649 +0000] replica_generate_next_csn: opcsn=5939402f000500030000 <= basecsn=5939402f000800040000, adjusted opcsn=5939402f000900030000 [08/Jun/2017:23:38:48.197750001 +0000] replica_generate_next_csn: opcsn=5939e009000100030000 <= basecsn=5939e009000f00040000, adjusted opcsn=5939e009001000030000

This is from an error log :-)

...

Freeipa02:

Shows no logs "to" the other 2 nodes.

Well it would only show incoming connections, not outgoing.

...

Freeipa03:

[08/Jun/2017:17:10:06.343697044 +0000] conn=9237 fd=70 slot=70 connection from 192.168.0.12 to 192.168.0.13 [08/Jun/2017:19:54:05.025713675 +0000] conn=9665 fd=70 slot=70 connection from 192.168.0.12 to 192.168.0.13

Freeipa02 replication logging:

[09/Jun/2017:11:24:58.827281135 +0000] NSMMReplicationPlugin - csnplCommitALL: processing data csn 593964af000900030000

Repeats 800 - 900 time per second with a different csn.

It looks like its replicating to other replicas, but some updates are skipped. This again could be fractional replication "working".

If you look through freeipa01's access log what operation is this csn from: 5937cccd000f00030000 ? Could this be one of the password updates that is not replicated? This update is not sent to the other replicas that's why I'm asking.

Thanks, Mark

...

On 08/06/17 15:45, Mark Reynolds wrote:

...
On 06/07/2017 10:58 AM, Nick Campion via FreeIPA-users wrote:

...
Hi all,

We have a 3 master setup that is failing to replicate changes from a particular node to the other IPA instances. The replication status says it's all fine, however the record hasn't been changed on the other servers. We've seen this on user password changes, adding hosts and services. The only thing we've found that seems to fix this temporarily is to re-initialize from the master with the changed record. A force-sync doesn't pick up the changed record.

What is the change you making, what attribute are you updating? Could it be possible that its being excluded by fractional replication? Or is it all changes?

Any errors in the logs on the nodes(good and bad): /var/log/dirsrv/slapd-INSTANCE/errors

Do you see replication sessions starting between the bad node and good ones? Are they talking? Check the access log ( /var/log/dirsrv/slapd-INSTANCE/access) on a good node and look for "connection from <BAD NODE IP address>"

Next would be to enable replication logging on the bad node and reproduce the problem (then disable repl logging right away), then send us the logs to look at. See https://access.redhat.com/documentation/en-us/red_hat_directory_server/10/ht...

Regards, Mark

...
Not sure what logs would be helpful to diagnose what is happening in this setup.

# ipa-replica-manage -v list `hostname` freeipa03.mgmt.example.com: replica last init status: None last init ended: 1970-01-01 00:00:00+00:00 last update status: Error (0) Replica acquired successfully: Incremental update succeeded last update ended: 2017-06-07 14:43:53+00:00 freeipa02.mgmt.example.com: replica last init status: None last init ended: 1970-01-01 00:00:00+00:00 last update status: Error (0) Replica acquired successfully: Incremental update succeeded last update ended: 2017-06-07 14:43:53+00:00

# ldapsearch -W -x -D "cn=directory manager" -b "cn=users,cn=accounts,dc=ipa,dc=example,dc=com" "nsds5ReplConflict=*" * nsds5ReplConflict Enter LDAP Password: # extended LDIF # # LDAPv3 # base <cn=users,cn=accounts,dc=ipa,dc=example,dc=com> with scope subtree # filter: nsds5ReplConflict=* # requesting: * nsds5ReplConflict #

# search result search: 2 result: 0 Success

# numResponses: 1

Any help in what else can be checked or what logs would be helpful would be appreciated.

Thanks

Nick

FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org

FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org

Nick Campion

13 Jun 13 Jun

10:54 a.m.

On 12/06/17 18:29, Mark Reynolds wrote:

...

On 06/12/2017 07:32 AM, Nick Campion via FreeIPA-users wrote:

...
Thanks Mark,

So this example is a user password change using kinit, the password has been changed on freeipa02 but not then replicated to the others. This happens for other records, but I don't have examples of these at the moment.

As far as I'm aware, there is no fractal replication set up.

IPA uses fractional replication, and it's possible these attributes are ignored/skipped. To confirm you can run this search on freeipa02:

ldapsearch -D "cn=directory manager" -W -b cn=config -xLLL objectclass=nsds5ReplicationAgreement

Freeipa02:

dn: cn=meTofreeipa01.mgmt.example.com,cn=replica,cn=dc\3Dipa\2Cdc\3Dexample\2Cdc\3Dcom,cn=mapping tree,cn=config

cn: meTofreeipa01.mgmt.example.com

description: me to freeipa01.mgmt.example.com

nsDS5ReplicaBindMethod: SASL/GSSAPI

nsDS5ReplicaHost: freeipa01.mgmt.example.com

nsDS5ReplicaPort: 389

nsDS5ReplicaRoot: dc=ipa,dc=example,dc=com

nsDS5ReplicaTransportInfo: LDAP

nsDS5ReplicatedAttributeList: (objectclass=*) $ EXCLUDE memberof idnssoaserial entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount

nsDS5ReplicatedAttributeListTotal: (objectclass=*) $ EXCLUDE entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount

nsds50ruv: {replicageneration} 57867ff5000000040000

nsds50ruv: {replica 4 ldap://freeipa01.mgmt.example.com:389} 57867ffe000000040000 593693b7001100040000

nsds50ruv: {replica 3 ldap://freeipa02.mgmt.example.com:389} 57867ffa000000030000 5930e345000200030000 nsds50ruv: {replica 5 ldap://freeipa03.mgmt.example.com:389} 59355988000000050000 59369317000300050000 nsds5ReplicaEnabled: on nsds5ReplicaStripAttrs: modifiersName modifyTimestamp internalModifiersName internalModifyTimestamp nsds5replicaTimeout: 120 nsruvReplicaLastModified: {replica 4 ldap://freeipa01.mgmt.example.com:389} 00000000 nsruvReplicaLastModified: {replica 3 ldap://freeipa02.mgmt.example.com:389} 00000000 nsruvReplicaLastModified: {replica 5 ldap://freeipa03.mgmt.example.com:389} 00000000 objectClass: nsds5replicationagreement objectClass: top objectClass: ipaReplTopoManagedAgreement ipaReplTopoManagedAgreementState: managed agreement - controlled by topology plugin nsds5replicareapactive: 0 nsds5replicaLastUpdateStart: 20170613090432Z nsds5replicaLastUpdateEnd: 20170613090432Z nsds5replicaChangesSentSinceStartup:: MzoxNTkvMjM5ODI0NyA1OjI0LzAg nsds5replicaLastUpdateStatus: Error (0) Replica acquired successfully: Incremental update succeeded nsds5replicaUpdateInProgress: FALSE nsds5replicaLastInitStart: 19700101000000Z nsds5replicaLastInitEnd: 19700101000000Z

dn: cn=meTofreeipa03.mgmt.example.com,cn=replica,cn=dc\3Dipa\2Cdc\3Dexample2Cdc\3Dcom,cn=mapping tree,cn=config cn: meTofreeipa03.mgmt.example.com objectClass: nsds5replicationagreement objectClass: top objectClass: ipaReplTopoManagedAgreement nsDS5ReplicaTransportInfo: LDAP nsds5ReplicaStripAttrs: modifiersName modifyTimestamp internalModifiersName internalModifyTimestamp nsDS5ReplicaRoot: dc=ipa,dc=example,dc=com nsDS5ReplicaHost: freeipa03.mgmt.example.com nsds5replicaTimeout: 120 nsDS5ReplicaPort: 389 nsDS5ReplicaBindMethod: SASL/GSSAPI nsDS5ReplicatedAttributeList: (objectclass=*) $ EXCLUDE memberof idnssoaserial entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount description: me to freeipa03.mgmt.example.com nsDS5ReplicatedAttributeListTotal: (objectclass=*) $ EXCLUDE entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount ipaReplTopoManagedAgreementState: managed agreement - controlled by topology plugin nsds5ReplicaEnabled: on nsds50ruv: {replicageneration} 57867ff5000000040000 nsds50ruv: {replica 5 ldap://freeipa03.mgmt.example.com:389} 59355988000000050000 5936937b000200050000 nsds50ruv: {replica 3 ldap://freeipa02.mgmt.example.com:389} 57867ffa000000030000 5930e345000200030000 nsds50ruv: {replica 4 ldap://freeipa01.mgmt.example.com:389} 57867ffe000000040000 593693b7000c00040000 nsruvReplicaLastModified: {replica 5 ldap://freeipa03.mgmt.example.com:389} 00000000 nsruvReplicaLastModified: {replica 3 ldap://freeipa02.mgmt.example.com:389} 00000000 nsruvReplicaLastModified: {replica 4 ldap://freeipa01.mgmt.example.com:389} 00000000 nsds5replicareapactive: 0 nsds5replicaLastUpdateStart: 20170613090432Z nsds5replicaLastUpdateEnd: 20170613090432Z nsds5replicaChangesSentSinceStartup:: MzoxMzkvMTkxMDI0NSA0OjkwNS8wIA== nsds5replicaLastUpdateStatus: Error (0) Replica acquired successfully: Incremental update succeeded nsds5replicaUpdateInProgress: FALSE nsds5replicaLastInitStart: 19700101000000Z nsds5replicaLastInitEnd: 19700101000000Z

dn: cn=cloneAgreement1-freeipa02.mgmt.example.com-pki-tomcat,cn=replica,cn=o\3Dipaca,cn=mapping tree,cn=config cn: cloneAgreement1-freeipa02.mgmt.example.com-pki-tomcat description: cloneAgreement1-freeipa02.mgmt.example.com-pki-tomcat nsDS5ReplicaBindDN: cn=Replication Manager masterAgreement1-freeipa02.mgmt.example.com-pki-tomcat,ou=csusers,cn=config nsDS5ReplicaBindMethod: Simple nsDS5ReplicaCredentials: Redacted nsDS5ReplicaHost: freeipa01.mgmt.example.com nsDS5ReplicaPort: 389 nsDS5ReplicaRoot: o=ipaca nsDS5ReplicaTransportInfo: TLS nsds50ruv: {replicageneration} 57868040000000600000 nsds50ruv: {replica 96 ldap://freeipa01.mgmt.example.com:389} 57868041000000600000 593692b2000000600000 nsds50ruv: {replica 97 ldap://freeipa02.mgmt.example.com:389} 57868050000000610000 59355a39000400610000 nsruvReplicaLastModified: {replica 96 ldap://freeipa01.mgmt.example.com:389} 00000000 nsruvReplicaLastModified: {replica 97 ldap://freeipa02.mgmt.example.com:389} 00000000 objectClass: top objectClass: nsds5replicationagreement objectClass: ipaReplTopoManagedAgreement ipaReplTopoManagedAgreementState: managed agreement - controlled by topology plugin nsds5replicareapactive: 0 nsds5replicaLastUpdateStart: 20170613090226Z nsds5replicaLastUpdateEnd: 20170613090226Z nsds5replicaChangesSentSinceStartup: nsds5replicaLastUpdateStatus: Error (0) Replica acquired successfully: Incremental update succeeded nsds5replicaUpdateInProgress: FALSE nsds5replicaLastInitStart: 19700101000000Z nsds5replicaLastInitEnd: 19700101000000Z

...

Then please share these entries so we can see how they are configured. Perhaps do this on freeipa01 as well for comparison.

Freeipa01:

dn: cn=freeipa01.mgmt.example.com-to-freeipa03.mgmt.example.com,cn=replica,cn=dc\3Dipa\2Cdc\3Dexamle\2Cdc\3Dcom,cn=mapping tree,cn=config objectClass: nsds5replicationagreement objectClass: ipaReplTopoManagedAgreement objectClass: top cn: freeipa01.mgmt.example.com-to-freeipa03.mgmt.example.com nsDS5ReplicaHost: freeipa03.mgmt.example.com nsDS5ReplicaPort: 389 nsds5replicaTimeout: 300 nsDS5ReplicaRoot: dc=ipa,dc=example,dc=com description: freeipa01.mgmt.example.com to freeipa03.mgmt.example.com ipaReplTopoManagedAgreementState: managed agreement - generated by topology plugin nsDS5ReplicaTransportInfo: LDAP nsDS5ReplicaBindMethod: SASL/GSSAPI nsDS5ReplicatedAttributeList: (objectclass=*) $ EXCLUDE memberof idnssoaserial entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount nsds5ReplicaStripAttrs: modifiersName modifyTimestamp internalModifiersName internalModifyTimestamp nsDS5ReplicatedAttributeListTotal: (objectclass=*) $ EXCLUDE entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount nsds50ruv: {replicageneration} 57867ff5000000040000 nsds50ruv: {replica 5 ldap://freeipa03.mgmt.example.com:389} 59355988000000050000 593b4a2f000300050000 nsds50ruv: {replica 3 ldap://freeipa02.mgmt.example.com:389} 57867ffa000000030000 5937cccd000300030000 nsds50ruv: {replica 4 ldap://freeipa01.mgmt.example.com:389} 57867ffe000000040000 593b4b2f000700040000 nsruvReplicaLastModified: {replica 5 ldap://freeipa03.mgmt.example.com:389} 00000000 nsruvReplicaLastModified: {replica 3 ldap://freeipa02.mgmt.example.com:389} 00000000 nsruvReplicaLastModified: {replica 4 ldap://freeipa01.mgmt.example.com:389} 00000000 nsds5replicareapactive: 0 nsds5replicaLastUpdateStart: 20170613090421Z nsds5replicaLastUpdateEnd: 20170613090421Z nsds5replicaChangesSentSinceStartup:: NDoxMTM0MS8yNTkyNzgxMyA= nsds5replicaLastUpdateStatus: Error (0) Replica acquired successfully: Incremental update succeeded nsds5replicaUpdateInProgress: FALSE nsds5replicaLastInitStart: 19700101000000Z nsds5replicaLastInitEnd: 19700101000000Z

dn: cn=meTofreeipa02.mgmt.example.com,cn=replica,cn=dc\3Dipa\2Cdc\3Dexample\2Cdc\3Dcom,cn=mapping tree,cn=config cn: meTofreeipa02.mgmt.example.com description: me to freeipa02.mgmt.example.com nsDS5ReplicaBindMethod: SASL/GSSAPI nsDS5ReplicaHost: freeipa02.mgmt.example.com nsDS5ReplicaPort: 389 nsDS5ReplicaRoot: dc=ipa,dc=example,dc=com nsDS5ReplicaTransportInfo: LDAP nsDS5ReplicatedAttributeList: (objectclass=*) $ EXCLUDE memberof idnssoaserial entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount nsDS5ReplicatedAttributeListTotal: (objectclass=*) $ EXCLUDE entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount nsds50ruv: {replicageneration} 57867ff5000000040000 nsds50ruv: {replica 3 ldap://freeipa02.mgmt.example.com:389} 57867ffa000000030000 5937ccd3000a00030000 nsds50ruv: {replica 4 ldap://freeipa01.mgmt.example.com:389} 57867ffe000000040000 593b4b2f000700040000 nsds50ruv: {replica 5 ldap://freeipa03.mgmt.example.com:389} 59355988000000050000 593b49d8000400050000 nsds5ReplicaEnabled: on nsds5ReplicaStripAttrs: modifiersName modifyTimestamp internalModifiersName internalModifyTimestamp nsds5replicaTimeout: 120 nsruvReplicaLastModified: {replica 3 ldap://freeipa02.mgmt.example.com:389} 00000000 nsruvReplicaLastModified: {replica 4 ldap://freeipa01.mgmt.example.com:389} 00000000 nsruvReplicaLastModified: {replica 5 ldap://freeipa03.mgmt.example.com:389} 00000000 objectClass: nsds5replicationagreement objectClass: top objectClass: ipaReplTopoManagedAgreement ipaReplTopoManagedAgreementState: managed agreement - controlled by topology plugin nsds5replicareapactive: 0 nsds5replicaLastUpdateStart: 20170613090421Z nsds5replicaLastUpdateEnd: 20170613090421Z nsds5replicaChangesSentSinceStartup:: NDoxMDkyNy8yNTYzNjIwNiA1OjM3OC8wIDA6MTQvMCA= nsds5replicaLastUpdateStatus: Error (0) Replica acquired successfully: Incremental update succeeded nsds5replicaUpdateInProgress: FALSE nsds5replicaLastInitStart: 19700101000000Z nsds5replicaLastInitEnd: 19700101000000Z

dn: cn=masterAgreement1-freeipa02.mgmt.example.com-pki-tomcat,cn=replica,cn=o\3Dipaca,cn=mapping tree,cn=config cn: masterAgreement1-freeipa02.mgmt.example.com-pki-tomcat description: masterAgreement1-freeipa02.mgmt.example.com-pki-tomcat nsDS5ReplicaBindDN: cn=Replication Manager cloneAgreement1-freeipa02.mgmt.example.com-pki-tomcat,ou=csusers,cn=config nsDS5ReplicaBindMethod: Simple nsDS5ReplicaCredentials: Redacted nsDS5ReplicaHost: freeipa02.mgmt.example.com nsDS5ReplicaPort: 389 nsDS5ReplicaRoot: o=ipaca nsDS5ReplicaTransportInfo: TLS nsds50ruv: {replicageneration} 57868040000000600000 nsds50ruv: {replica 97 ldap://freeipa02.mgmt.example.com:389} 57868050000000610000 59355a39000400610000 nsds50ruv: {replica 96 ldap://freeipa01.mgmt.example.com:389} 57868047000000600000 593b488f000000600000 nsruvReplicaLastModified: {replica 97 ldap://freeipa02.mgmt.example.com:389} 00000000 nsruvReplicaLastModified: {replica 96 ldap://freeipa01.mgmt.example.com:389} 00000000 objectClass: top objectClass: nsds5replicationagreement objectClass: ipaReplTopoManagedAgreement ipaReplTopoManagedAgreementState: managed agreement - controlled by topology plugin nsds5replicareapactive: 0 nsds5replicaLastUpdateStart: 20170613090225Z nsds5replicaLastUpdateEnd: 20170613090226Z nsds5replicaChangesSentSinceStartup:: OTY6MzM3LzAg nsds5replicaLastUpdateStatus: Error (0) Replica acquired successfully: Incremental update succeeded nsds5replicaUpdateInProgress: FALSE nsds5replicaLastInitStart: 19700101000000Z nsds5replicaLastInitEnd: 19700101000000Z

...

...
Freeipa01:

# dynamic-kepler, users, accounts, ipa.example.com dn: uid=dynamic-kepler,cn=users,cn=accounts,dc=ipa,dc=example,dc=com uid: dynamic-kepler krbLastPwdChange: 20170608170011Z krbPasswordExpiration: 20170608170011Z

Freeipa02:

# dynamic-kepler, users, accounts, ipa.example.com dn: uid=dynamic-kepler,cn=users,cn=accounts,dc=ipa,dc=example,dc=com uid: dynamic-kepler krbLastPwdChange: 20170608170021Z krbPasswordExpiration: 20170906170021Z

Freeipa03:

# dynamic-kepler, users, accounts, ipa.example.com dn: uid=dynamic-kepler,cn=users,cn=accounts,dc=ipa,dc=example,dc=com uid: dynamic-kepler krbLastPwdChange: 20170608170011Z krbPasswordExpiration: 20170608170011Z

Errors on Freeipa02:

[08/Jun/2017:01:46:50.635529447 +0000] replica_generate_next_csn: opcsn=5938ac8b000500030000 <= basecsn=5938ac8b000500040000, adjusted opcsn=5938ac8b000600030000 [08/Jun/2017:12:16:46.497249649 +0000] replica_generate_next_csn: opcsn=5939402f000500030000 <= basecsn=5939402f000800040000, adjusted opcsn=5939402f000900030000 [08/Jun/2017:23:38:48.197750001 +0000] replica_generate_next_csn: opcsn=5939e009000100030000 <= basecsn=5939e009000f00040000, adjusted opcsn=5939e009001000030000

The other nodes have no errors from this data.

Access logs:

Freeipa01:

[08/Jun/2017:01:46:50.635529447 +0000] replica_generate_next_csn: opcsn=5938ac8b000500030000 <= basecsn=5938ac8b000500040000, adjusted opcsn=5938ac8b000600030000 [08/Jun/2017:12:16:46.497249649 +0000] replica_generate_next_csn: opcsn=5939402f000500030000 <= basecsn=5939402f000800040000, adjusted opcsn=5939402f000900030000 [08/Jun/2017:23:38:48.197750001 +0000] replica_generate_next_csn: opcsn=5939e009000100030000 <= basecsn=5939e009000f00040000, adjusted opcsn=5939e009001000030000

This is from an error log :-)

...
Freeipa02:

Shows no logs "to" the other 2 nodes.

Well it would only show incoming connections, not outgoing.

...
Freeipa03:

[08/Jun/2017:17:10:06.343697044 +0000] conn=9237 fd=70 slot=70 connection from 192.168.0.12 to 192.168.0.13 [08/Jun/2017:19:54:05.025713675 +0000] conn=9665 fd=70 slot=70 connection from 192.168.0.12 to 192.168.0.13

Freeipa02 replication logging:

[09/Jun/2017:11:24:58.827281135 +0000] NSMMReplicationPlugin - csnplCommitALL: processing data csn 593964af000900030000

Repeats 800 - 900 time per second with a different csn.

It looks like its replicating to other replicas, but some updates are skipped. This again could be fractional replication "working".

If you look through freeipa01's access log what operation is this csn from: 5937cccd000f00030000 ? Could this be one of the password updates that is not replicated? This update is not sent to the other replicas that's why I'm asking.

I cant find that csn anywhere but the error log on freeipa02. Both servers are logging csn's around the same time, just not this one.

Cheers Nick

...

Thanks, Mark

...
On 08/06/17 15:45, Mark Reynolds wrote:

...
On 06/07/2017 10:58 AM, Nick Campion via FreeIPA-users wrote:

...
Hi all,

We have a 3 master setup that is failing to replicate changes from a particular node to the other IPA instances. The replication status says it's all fine, however the record hasn't been changed on the other servers. We've seen this on user password changes, adding hosts and services. The only thing we've found that seems to fix this temporarily is to re-initialize from the master with the changed record. A force-sync doesn't pick up the changed record.

What is the change you making, what attribute are you updating? Could it be possible that its being excluded by fractional replication? Or is it all changes?

Any errors in the logs on the nodes(good and bad): /var/log/dirsrv/slapd-INSTANCE/errors

Do you see replication sessions starting between the bad node and good ones? Are they talking? Check the access log ( /var/log/dirsrv/slapd-INSTANCE/access) on a good node and look for "connection from <BAD NODE IP address>"

Next would be to enable replication logging on the bad node and reproduce the problem (then disable repl logging right away), then send us the logs to look at. See https://access.redhat.com/documentation/en-us/red_hat_directory_server/10/ht...

Regards, Mark

...
Not sure what logs would be helpful to diagnose what is happening in this setup.

# ipa-replica-manage -v list `hostname` freeipa03.mgmt.example.com: replica last init status: None last init ended: 1970-01-01 00:00:00+00:00 last update status: Error (0) Replica acquired successfully: Incremental update succeeded last update ended: 2017-06-07 14:43:53+00:00 freeipa02.mgmt.example.com: replica last init status: None last init ended: 1970-01-01 00:00:00+00:00 last update status: Error (0) Replica acquired successfully: Incremental update succeeded last update ended: 2017-06-07 14:43:53+00:00

# ldapsearch -W -x -D "cn=directory manager" -b "cn=users,cn=accounts,dc=ipa,dc=example,dc=com" "nsds5ReplConflict=*" * nsds5ReplConflict Enter LDAP Password: # extended LDIF # # LDAPv3 # base <cn=users,cn=accounts,dc=ipa,dc=example,dc=com> with scope subtree # filter: nsds5ReplConflict=* # requesting: * nsds5ReplConflict #

# search result search: 2 result: 0 Success

# numResponses: 1

Any help in what else can be checked or what logs would be helpful would be appreciated.

Thanks

Nick

FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org

FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org

3189

Age (days ago)

3195

Last active (days ago)

freeipa-users@lists.fedorahosted.org

5 comments

2 participants

tags (0)

participants (2)

Mark Reynolds
Nick Campion