[28/Jan/2020:15:14:05.227345257 -0300] - DEBUG - _csngen_adjust_local_time - gen state before 5e3078f80001:1580235000:0:0 [28/Jan/2020:15:14:05.229488136 -0300] - DEBUG - _csngen_adjust_local_time - gen state after 5e3079ed0000:1580235245:0:0 [28/Jan/2020:15:14:05.231056011 -0300] - DEBUG - NSMMReplicationPlugin - csnplInsert: CSN Pending list content: [28/Jan/2020:15:14:05.232632900 -0300] - DEBUG - NSMMReplicationPlugin - 5e3079ed000000640000,(prim 5e3079ed000000640000), not committed [28/Jan/2020:15:14:05.234067827 -0300] - DEBUG - NSMMReplicationPlugin - ruv_add_csn_inprogress - Successfully inserted csn 5e3079ed000000640000 into pending list [28/Jan/2020:15:14:05.237694457 -0300] - DEBUG - NSMMReplicationPlugin - purge_entry_state_information - From entry uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain up to CSN 5e273d8c000100640000 [28/Jan/2020:15:14:05.244637351 -0300] - DEBUG - NSMMReplicationPlugin - write_changelog_and_ruv - Writing change for uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain (uniqid: 0c57800e-050011e8-b998ed08-97c36f4f, optype: 8) to changelog csn 5e3079ed000000640000 [28/Jan/2020:15:14:05.247287379 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x603002db4250 for database /var/lib/dirsrv/slapd-RNP/changelogdb/0f6cd003-41ef11ea-8a6bdfdc-87dde3bc_5e3067ae000000640000.db [28/Jan/2020:15:14:05.248833286 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - cl5WriteOperationTxn - Successfully written entry with csn (5e3079ed000000640000) [28/Jan/2020:15:14:05.250304674 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x603002db4250 for database /var/lib/dirsrv/slapd-RNP/changelogdb/0f6cd003-41ef11ea-8a6bdfdc-87dde3bc_5e3067ae000000640000.db [28/Jan/2020:15:14:05.251745720 -0300] - DEBUG - NSMMReplicationPlugin - replica_update_ruv: csn 5e3079ed000000640000 [28/Jan/2020:15:14:05.253328215 -0300] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: committing all csns for csn 5e3079ed000000640000 [28/Jan/2020:15:14:05.254869769 -0300] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: processing data csn 5e3079ed000000640000 [28/Jan/2020:15:14:05.256878796 -0300] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Successfully committed csn 5e3079ed000000640000 [28/Jan/2020:15:14:05.258359789 -0300] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Rolled up to csn 5e3079ed000000640000 [28/Jan/2020:15:14:05.260578238 -0300] - DEBUG - replication - multimaster_mmr_postop - error 0 for oparation 561. [28/Jan/2020:15:14:05.269990759 -0300] - DEBUG - NSMMReplicationPlugin - csnplInsert: CSN Pending list content: [28/Jan/2020:15:14:05.271523944 -0300] - DEBUG - NSMMReplicationPlugin - 5e3079ed000100640000,(prim 5e3079ed000100640000), not committed [28/Jan/2020:15:14:05.273148253 -0300] - DEBUG - NSMMReplicationPlugin - ruv_add_csn_inprogress - Successfully inserted csn 5e3079ed000100640000 into pending list [28/Jan/2020:15:14:05.275876323 -0300] - DEBUG - NSMMReplicationPlugin - purge_entry_state_information - From entry uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain up to CSN 5e273f6d000000640000 [28/Jan/2020:15:14:05.281959252 -0300] - DEBUG - NSMMReplicationPlugin - write_changelog_and_ruv - Writing change for uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain (uniqid: 0c57800e-050011e8-b998ed08-97c36f4f, optype: 8) to changelog csn 5e3079ed000100640000 [28/Jan/2020:15:14:05.283398691 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x603002db4250 for database /var/lib/dirsrv/slapd-RNP/changelogdb/0f6cd003-41ef11ea-8a6bdfdc-87dde3bc_5e3067ae000000640000.db [28/Jan/2020:15:14:05.284977636 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - cl5WriteOperationTxn - Successfully written entry with csn (5e3079ed000100640000) [28/Jan/2020:15:14:05.286387677 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x603002db4250 for database /var/lib/dirsrv/slapd-RNP/changelogdb/0f6cd003-41ef11ea-8a6bdfdc-87dde3bc_5e3067ae000000640000.db [28/Jan/2020:15:14:05.287743801 -0300] - DEBUG - NSMMReplicationPlugin - replica_update_ruv: csn 5e3079ed000100640000 [28/Jan/2020:15:14:05.289256958 -0300] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: committing all csns for csn 5e3079ed000100640000 [28/Jan/2020:15:14:05.291099542 -0300] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: processing data csn 5e3079ed000100640000 [28/Jan/2020:15:14:05.292304558 -0300] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Successfully committed csn 5e3079ed000100640000 [28/Jan/2020:15:14:05.293542503 -0300] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Rolled up to csn 5e3079ed000100640000 [28/Jan/2020:15:14:05.294850149 -0300] - DEBUG - replication - multimaster_mmr_postop - error 0 for oparation 561. [28/Jan/2020:15:14:05.299055598 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): State: wait_for_changes -> wait_for_changes [28/Jan/2020:15:14:05.300333166 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): State: wait_for_changes -> ready_to_acquire_replica [28/Jan/2020:15:14:05.302496771 -0300] - DEBUG - NSMMReplicationPlugin - csnplInsert: CSN Pending list content: [28/Jan/2020:15:14:05.303769373 -0300] - DEBUG - NSMMReplicationPlugin - 5e3079ed000200640000,(prim 5e3079ed000200640000), not committed [28/Jan/2020:15:14:05.305207000 -0300] - DEBUG - NSMMReplicationPlugin - ruv_add_csn_inprogress - Successfully inserted csn 5e3079ed000200640000 into pending list [28/Jan/2020:15:14:05.306610208 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - acquire_replica, supplier RUV: [28/Jan/2020:15:14:05.307950112 -0300] - DEBUG - NSMMReplicationPlugin - supplier: {replicageneration} 5e3067ae000000640000 [28/Jan/2020:15:14:05.309282271 -0300] - DEBUG - NSMMReplicationPlugin - supplier: {replica 100 ldap://idc01.ldap.my.domain:389} 5e3067b2000000640000 5e3079ed000100640000 5e3079ed [28/Jan/2020:15:14:05.310536345 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - acquire_replica, consumer RUV: [28/Jan/2020:15:14:05.311843763 -0300] - DEBUG - NSMMReplicationPlugin - consumer: {replicageneration} 5e3067ae000000640000 [28/Jan/2020:15:14:05.313130168 -0300] - DEBUG - NSMMReplicationPlugin - consumer: {replica 100 ldap://idc01.ldap.my.domain:389} 5e3067b2000000640000 5e30780c000100640000 5e3078f4 [28/Jan/2020:15:14:05.314503988 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - acquire_replica, supplier RUV is newer [28/Jan/2020:15:14:05.316019663 -0300] - DEBUG - NSMMReplicationPlugin - purge_entry_state_information - From entry uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain up to CSN 5e273f6d000100640000 [28/Jan/2020:15:14:05.317376452 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_conn_connect - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): Trying secure slapi_ldap_init_ext [28/Jan/2020:15:14:05.320194561 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_conn_connect - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): binddn = CN=Conta de sincronizacao do AD com LDAP 389,OU=APLICACOES,dc=my,dc=domain, passwd = {AES-TUhNR0NTcUdTSWIzRFFFRkRUQm1NRVVHQ1NxR1NJYjNEUUVGRERBNEJDUTBPV1psTXpoak15MDNPRFZrTXpZMg0KTnkxaE56VXhZMkUwWlMxbE5UazJNemhrWkFBQ0FRSUNBU0F3Q2dZSUtvWklodmNOQWdjd0hRWUpZSVpJQVdVRA0KQkFFcUJCRHFQbGRxU2U0UnJoYjFyelF0eWQxSQ==}Mdvj5wiwXO2IlChZElQJRdrhHgRbLNujtBvY2f5s2gk= [28/Jan/2020:15:14:05.321474807 -0300] - DEBUG - NSMMReplicationPlugin - write_changelog_and_ruv - Writing change for uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain (uniqid: 0c57800e-050011e8-b998ed08-97c36f4f, optype: 8) to changelog csn 5e3079ed000200640000 [28/Jan/2020:15:14:05.323111536 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x603002db4250 for database /var/lib/dirsrv/slapd-RNP/changelogdb/0f6cd003-41ef11ea-8a6bdfdc-87dde3bc_5e3067ae000000640000.db [28/Jan/2020:15:14:05.324470243 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - cl5WriteOperationTxn - Successfully written entry with csn (5e3079ed000200640000) [28/Jan/2020:15:14:05.325742846 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x603002db4250 for database /var/lib/dirsrv/slapd-RNP/changelogdb/0f6cd003-41ef11ea-8a6bdfdc-87dde3bc_5e3067ae000000640000.db [28/Jan/2020:15:14:05.327080832 -0300] - DEBUG - NSMMReplicationPlugin - replica_update_ruv: csn 5e3079ed000200640000 [28/Jan/2020:15:14:05.328374706 -0300] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: committing all csns for csn 5e3079ed000200640000 [28/Jan/2020:15:14:05.329808630 -0300] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: processing data csn 5e3079ed000200640000 [28/Jan/2020:15:14:05.331105485 -0300] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Successfully committed csn 5e3079ed000200640000 [28/Jan/2020:15:14:05.332458241 -0300] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Rolled up to csn 5e3079ed000200640000 [28/Jan/2020:15:14:05.334522453 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_conn_connect - detected Win2k3 or later peer [28/Jan/2020:15:14:05.335931314 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_conn_cancel_linger - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): No linger to cancel on the connection [28/Jan/2020:15:14:05.337182438 -0300] - DEBUG - replication - multimaster_mmr_postop - error 0 for oparation 561. [28/Jan/2020:15:14:05.338733516 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - windows_acquire_replica returned success (101) [28/Jan/2020:15:14:05.340505923 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): State: ready_to_acquire_replica -> sending_updates [28/Jan/2020:15:14:05.342161850 -0300] - DEBUG - csngen_adjust_time - gen state before 5e3079ed0004:1580235245:0:0 [28/Jan/2020:15:14:05.343734849 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFile - found DB object 0x603002db4250 for database /var/lib/dirsrv/slapd-RNP/changelogdb/0f6cd003-41ef11ea-8a6bdfdc-87dde3bc_5e3067ae000000640000.db [28/Jan/2020:15:14:05.345262198 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5PositionCursorForReplay - (agmt="cn=AD-DF-DC01" (gti-df-dc01:636)): Consumer RUV: [28/Jan/2020:15:14:05.346542542 -0300] - DEBUG - NSMMReplicationPlugin - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): {replicageneration} 5e3067ae000000640000 [28/Jan/2020:15:14:05.348000579 -0300] - DEBUG - NSMMReplicationPlugin - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): {replica 100 ldap://idc01.ldap.my.domain:389} 5e3067b2000000640000 5e30780c000100640000 5e3078f4 [28/Jan/2020:15:14:05.349214724 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5PositionCursorForReplay - (agmt="cn=AD-DF-DC01" (gti-df-dc01:636)): Supplier RUV: [28/Jan/2020:15:14:05.350725881 -0300] - DEBUG - NSMMReplicationPlugin - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): {replicageneration} 5e3067ae000000640000 [28/Jan/2020:15:14:05.352104997 -0300] - DEBUG - NSMMReplicationPlugin - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): {replica 100 ldap://idc01.ldap.my.domain:389} 5e3067b2000000640000 5e3079ed000200640000 5e3079ed [28/Jan/2020:15:14:05.353358357 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_get_buffer - found thread private buffer cache 0x611001c71940 [28/Jan/2020:15:14:05.354894386 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_get_buffer - _pool is 0x604000140450 _pool->pl_busy_lists is 0x603002f7d4b0 _pool->pl_busy_lists->bl_buffers is 0x611001c71940 [28/Jan/2020:15:14:05.356926228 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_initial_anchorcsn - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - (cscb 0 - state 0) - csnPrevMax () csnMax (5e3079ed000200640000) csnBuf (5e30780c000100640000) csnConsumerMax (5e30780c000100640000) [28/Jan/2020:15:14:05.359568670 -0300] - DEBUG - clcache_initial_anchorcsn - anchor is now: 5e30780c000100640000 [28/Jan/2020:15:14:05.362626800 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): CSN 5e30780c000100640000 found, position set for replay [28/Jan/2020:15:14:05.365384970 -0300] - DEBUG - NSMMReplicationPlugin - csnplInsert: CSN Pending list content: [28/Jan/2020:15:14:05.366842515 -0300] - DEBUG - NSMMReplicationPlugin - 5e3079ed000400640000,(prim 5e3079ed000400640000), not committed [28/Jan/2020:15:14:05.368190488 -0300] - DEBUG - NSMMReplicationPlugin - ruv_add_csn_inprogress - Successfully inserted csn 5e3079ed000400640000 into pending list [28/Jan/2020:15:14:05.369598358 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_get_next_change - load=1 rec=1 csn=5e3079ed000000640000 [28/Jan/2020:15:14:05.370816929 -0300] - DEBUG - NSMMReplicationPlugin - purge_entry_state_information - From entry uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain up to CSN 5e273f6d000200640000 [28/Jan/2020:15:14:05.372142522 -0300] - ERR - log_result - Internal unindexed search: source (cn=Multimaster Replication Plugin,cn=plugins,cn=config) search base="dc=my,dc=domain" filter="(&(|(objectclass=*)(objectclass=ldapsubentry))(nsUniqueid=0c57800e-050011e8-b998ed08-97c36f4f))" etime=0.001210057 nentries=1 notes=U details="Partially Unindexed Filter [28/Jan/2020:15:14:05.375232488 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_replay_update - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) -Looking at modify operation local dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" (ours,user,not group) [28/Jan/2020:15:14:05.377138630 -0300] - DEBUG - NSMMReplicationPlugin - write_changelog_and_ruv - Writing change for uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain (uniqid: 0c57800e-050011e8-b998ed08-97c36f4f, optype: 8) to changelog csn 5e3079ed000400640000 [28/Jan/2020:15:14:05.379000373 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - map_entry_dn_outbound - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Looking for AD entry for DS dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" guid="49c65f0f65411f47b2f46906ae5e66ef" [28/Jan/2020:15:14:05.380704376 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x603002db4250 for database /var/lib/dirsrv/slapd-RNP/changelogdb/0f6cd003-41ef11ea-8a6bdfdc-87dde3bc_5e3067ae000000640000.db [28/Jan/2020:15:14:05.382064660 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_search_entry_ext - Calling windows entry search request plugin [28/Jan/2020:15:14:05.383476676 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - cl5WriteOperationTxn - Successfully written entry with csn (5e3079ed000400640000) [28/Jan/2020:15:14:05.385141495 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x603002db4250 for database /var/lib/dirsrv/slapd-RNP/changelogdb/0f6cd003-41ef11ea-8a6bdfdc-87dde3bc_5e3067ae000000640000.db [28/Jan/2020:15:14:05.386589797 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_search_entry_ext - Received 2 messages, 1 entries, 0 references [28/Jan/2020:15:14:05.387880620 -0300] - DEBUG - NSMMReplicationPlugin - replica_update_ruv: csn 5e3079ed000400640000 [28/Jan/2020:15:14:05.389714108 -0300] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: committing all csns for csn 5e3079ed000400640000 [28/Jan/2020:15:14:05.391109321 -0300] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: processing data csn 5e3079ed000400640000 [28/Jan/2020:15:14:05.392493302 -0300] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Successfully committed csn 5e3079ed000400640000 [28/Jan/2020:15:14:05.394086821 -0300] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Rolled up to csn 5e3079ed000400640000 [28/Jan/2020:15:14:05.395428297 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - map_entry_dn_outbound - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Return code 0 from search for AD entry dn="" or dn="CN=Alberto Viana,OU=GTI,OU=RNP-RJ,OU=RNP,dc=my,dc=domain" [28/Jan/2020:15:14:05.396861331 -0300] - DEBUG - replication - multimaster_mmr_postop - error 0 for oparation 561. [28/Jan/2020:15:14:05.398688404 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - Windows_replay_update - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Processing modify operation local dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" remote dn="" [28/Jan/2020:15:14:05.401503655 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_get_next_change - load=1 rec=2 csn=5e3079ed000100640000 [28/Jan/2020:15:14:05.403924884 -0300] - ERR - log_result - Internal unindexed search: source (cn=Multimaster Replication Plugin,cn=plugins,cn=config) search base="dc=my,dc=domain" filter="(&(|(objectclass=*)(objectclass=ldapsubentry))(nsUniqueid=0c57800e-050011e8-b998ed08-97c36f4f))" etime=0.000733362 nentries=1 notes=U details="Partially Unindexed Filter [28/Jan/2020:15:14:05.405892372 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_replay_update - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) -Looking at modify operation local dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" (ours,user,not group) [28/Jan/2020:15:14:05.408236014 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - map_entry_dn_outbound - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Looking for AD entry for DS dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" guid="49c65f0f65411f47b2f46906ae5e66ef" [28/Jan/2020:15:14:05.409543600 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_search_entry_ext - Calling windows entry search request plugin [28/Jan/2020:15:14:05.412461427 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_search_entry_ext - Received 2 messages, 1 entries, 0 references [28/Jan/2020:15:14:05.417351670 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - map_entry_dn_outbound - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Return code 0 from search for AD entry dn="" or dn="CN=Alberto Viana,OU=GTI,OU=RNP-RJ,OU=RNP,dc=my,dc=domain" [28/Jan/2020:15:14:05.419166312 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - Windows_replay_update - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Processing modify operation local dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" remote dn="" [28/Jan/2020:15:14:05.421220312 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_get_next_change - load=1 rec=3 csn=5e3079ed000200640000 [28/Jan/2020:15:14:05.423481115 -0300] - ERR - log_result - Internal unindexed search: source (cn=Multimaster Replication Plugin,cn=plugins,cn=config) search base="dc=my,dc=domain" filter="(&(|(objectclass=*)(objectclass=ldapsubentry))(nsUniqueid=0c57800e-050011e8-b998ed08-97c36f4f))" etime=0.000798288 nentries=1 notes=U details="Partially Unindexed Filter [28/Jan/2020:15:14:05.425260271 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_replay_update - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) -Looking at modify operation local dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" (ours,user,not group) [28/Jan/2020:15:14:05.428309548 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - map_entry_dn_outbound - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Looking for AD entry for DS dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" guid="49c65f0f65411f47b2f46906ae5e66ef" [28/Jan/2020:15:14:05.429664716 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_search_entry_ext - Calling windows entry search request plugin [28/Jan/2020:15:14:05.431131664 -0300] - DEBUG - NSMMReplicationPlugin - csnplInsert: CSN Pending list content: [28/Jan/2020:15:14:05.432603238 -0300] - DEBUG - NSMMReplicationPlugin - 5e3079ed000500640000,(prim 5e3079ed000500640000), not committed [28/Jan/2020:15:14:05.433961148 -0300] - DEBUG - NSMMReplicationPlugin - ruv_add_csn_inprogress - Successfully inserted csn 5e3079ed000500640000 into pending list [28/Jan/2020:15:14:05.436702114 -0300] - DEBUG - NSMMReplicationPlugin - purge_entry_state_information - From entry uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain up to CSN 5e273f6d000400640000 [28/Jan/2020:15:14:05.440851253 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_search_entry_ext - Received 2 messages, 1 entries, 0 references [28/Jan/2020:15:14:05.443484553 -0300] - DEBUG - NSMMReplicationPlugin - write_changelog_and_ruv - Writing change for uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain (uniqid: 0c57800e-050011e8-b998ed08-97c36f4f, optype: 8) to changelog csn 5e3079ed000500640000 [28/Jan/2020:15:14:05.444892038 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x603002db4250 for database /var/lib/dirsrv/slapd-RNP/changelogdb/0f6cd003-41ef11ea-8a6bdfdc-87dde3bc_5e3067ae000000640000.db [28/Jan/2020:15:14:05.446228669 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - map_entry_dn_outbound - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Return code 0 from search for AD entry dn="" or dn="CN=Alberto Viana,OU=GTI,OU=RNP-RJ,OU=RNP,dc=my,dc=domain" [28/Jan/2020:15:14:05.448354287 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - cl5WriteOperationTxn - Successfully written entry with csn (5e3079ed000500640000) [28/Jan/2020:15:14:05.449723175 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - Windows_replay_update - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Processing modify operation local dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" remote dn="" [28/Jan/2020:15:14:05.451273824 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x603002db4250 for database /var/lib/dirsrv/slapd-RNP/changelogdb/0f6cd003-41ef11ea-8a6bdfdc-87dde3bc_5e3067ae000000640000.db [28/Jan/2020:15:14:05.452768226 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_adjust_anchorcsn - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - (cscb 0 - state 0) - csnPrevMax (5e3079ed000200640000) csnMax (5e3079ed000400640000) csnBuf (5e3079ed000200640000) csnConsumerMax (5e3079ed000200640000) [28/Jan/2020:15:14:05.454242846 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_adjust_anchorcsn - anchor is now: 5e3079ed000200640000 [28/Jan/2020:15:14:05.455634914 -0300] - DEBUG - NSMMReplicationPlugin - replica_update_ruv: csn 5e3079ed000500640000 [28/Jan/2020:15:14:05.457017585 -0300] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: committing all csns for csn 5e3079ed000500640000 [28/Jan/2020:15:14:05.458540433 -0300] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: processing data csn 5e3079ed000500640000 [28/Jan/2020:15:14:05.459899171 -0300] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Successfully committed csn 5e3079ed000500640000 [28/Jan/2020:15:14:05.461294570 -0300] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Rolled up to csn 5e3079ed000500640000 [28/Jan/2020:15:14:05.462685643 -0300] - DEBUG - replication - multimaster_mmr_postop - error 0 for oparation 561. [28/Jan/2020:15:14:05.465652493 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_get_next_change - load=2 rec=4 csn=5e3079ed000400640000 [28/Jan/2020:15:14:05.468399065 -0300] - ERR - log_result - Internal unindexed search: source (cn=Multimaster Replication Plugin,cn=plugins,cn=config) search base="dc=my,dc=domain" filter="(&(|(objectclass=*)(objectclass=ldapsubentry))(nsUniqueid=0c57800e-050011e8-b998ed08-97c36f4f))" etime=0.000978198 nentries=1 notes=U details="Partially Unindexed Filter [28/Jan/2020:15:14:05.470585728 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_replay_update - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) -Looking at modify operation local dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" (ours,user,not group) [28/Jan/2020:15:14:05.472009602 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - map_entry_dn_outbound - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Looking for AD entry for DS dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" guid="49c65f0f65411f47b2f46906ae5e66ef" [28/Jan/2020:15:14:05.473482079 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_search_entry_ext - Calling windows entry search request plugin [28/Jan/2020:15:14:05.475903749 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_search_entry_ext - Received 2 messages, 1 entries, 0 references [28/Jan/2020:15:14:05.481825618 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - map_entry_dn_outbound - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Return code 0 from search for AD entry dn="" or dn="CN=Alberto Viana,OU=GTI,OU=RNP-RJ,OU=RNP,dc=my,dc=domain" [28/Jan/2020:15:14:05.493148013 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - Windows_replay_update - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Processing modify operation local dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" remote dn="" [28/Jan/2020:15:14:05.496098976 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_adjust_anchorcsn - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - (cscb 0 - state 0) - csnPrevMax (5e3079ed000400640000) csnMax (5e3079ed000500640000) csnBuf (5e3079ed000400640000) csnConsumerMax (5e3079ed000400640000) [28/Jan/2020:15:14:05.497653108 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_adjust_anchorcsn - anchor is now: 5e3079ed000400640000 [28/Jan/2020:15:14:05.499149927 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_cursor_get - clcache: (16384 | 16) buf key len 21 reallocated and retry returns 0 [28/Jan/2020:15:14:05.500568127 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_get_next_change - load=3 rec=5 csn=5e3079ed000500640000 [28/Jan/2020:15:14:05.503132703 -0300] - ERR - log_result - Internal unindexed search: source (cn=Multimaster Replication Plugin,cn=plugins,cn=config) search base="dc=my,dc=domain" filter="(&(|(objectclass=*)(objectclass=ldapsubentry))(nsUniqueid=0c57800e-050011e8-b998ed08-97c36f4f))" etime=0.001040480 nentries=1 notes=U details="Partially Unindexed Filter [28/Jan/2020:15:14:05.505148372 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_replay_update - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) -Looking at modify operation local dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" (ours,user,not group) [28/Jan/2020:15:14:05.506433655 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - map_entry_dn_outbound - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Looking for AD entry for DS dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" guid="49c65f0f65411f47b2f46906ae5e66ef" [28/Jan/2020:15:14:05.507739207 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_search_entry_ext - Calling windows entry search request plugin [28/Jan/2020:15:14:05.510038468 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_search_entry_ext - Received 2 messages, 1 entries, 0 references [28/Jan/2020:15:14:05.514524220 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - map_entry_dn_outbound - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Return code 0 from search for AD entry dn="" or dn="CN=Alberto Viana,OU=GTI,OU=RNP-RJ,OU=RNP,dc=my,dc=domain" [28/Jan/2020:15:14:05.515840319 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - Windows_replay_update - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - Processing modify operation local dn="uid=alberto.viana,OU=GTI,OU=RNP-RJ,ou=RNP,dc=my,dc=domain" remote dn="" [28/Jan/2020:15:14:05.518170052 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_adjust_anchorcsn - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - (cscb 0 - state 1) - csnPrevMax (5e3079ed000500640000) csnMax (5e3079ed000500640000) csnBuf (5e3079ed000500640000) csnConsumerMax (5e3079ed000500640000) [28/Jan/2020:15:14:05.519607854 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_load_buffer - rc=-30988 [28/Jan/2020:15:14:05.521465014 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - send_updates - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): No more updates to send (cl5GetNextOperationToReplay) [28/Jan/2020:15:14:05.522890488 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_return_buffer - session end: state=5 load=3 sent=5 skipped=0 skipped_new_rid=0 skipped_csn_gt_cons_maxcsn=0 skipped_up_to_date=0 skipped_csn_gt_ruv=0 skipped_csn_covered=0 [28/Jan/2020:15:14:05.524331665 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - send_dirsync_search - Calling dirsync search request plugin [28/Jan/2020:15:14:05.525660400 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - send_dirsync_search - Sending dirsync search request [28/Jan/2020:15:14:05.528626421 -0300] - DEBUG - replication - copy_operation_parameters - replica is null. [28/Jan/2020:15:14:05.561492389 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_conn_start_linger - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): Beginning linger on the connection [28/Jan/2020:15:14:05.563965661 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): State: sending_updates -> wait_for_changes [28/Jan/2020:15:14:05.565541324 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): State: wait_for_changes -> ready_to_acquire_replica [28/Jan/2020:15:14:05.566871147 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - acquire_replica, supplier RUV: [28/Jan/2020:15:14:05.568310970 -0300] - DEBUG - NSMMReplicationPlugin - supplier: {replicageneration} 5e3067ae000000640000 [28/Jan/2020:15:14:05.572389341 -0300] - DEBUG - NSMMReplicationPlugin - supplier: {replica 100 ldap://idc01.ldap.my.domain:389} 5e3067b2000000640000 5e3079ed000500640000 5e3079ed [28/Jan/2020:15:14:05.573509690 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - acquire_replica, consumer RUV: [28/Jan/2020:15:14:05.574935602 -0300] - DEBUG - NSMMReplicationPlugin - consumer: {replicageneration} 5e3067ae000000640000 [28/Jan/2020:15:14:05.576807637 -0300] - DEBUG - NSMMReplicationPlugin - consumer: {replica 100 ldap://idc01.ldap.my.domain:389} 5e3067b2000000640000 5e3079ed000500640000 5e3079ed [28/Jan/2020:15:14:05.579446775 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_conn_cancel_linger - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): Cancelling linger on the connection [28/Jan/2020:15:14:05.581566481 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - windows_acquire_replica returned success (101) [28/Jan/2020:15:14:05.583451897 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): State: ready_to_acquire_replica -> sending_updates [28/Jan/2020:15:14:05.584988982 -0300] - DEBUG - csngen_adjust_time - gen state before 5e3079ed0007:1580235245:0:0 [28/Jan/2020:15:14:05.586294856 -0300] - DEBUG - csngen_adjust_time - gen state after 5e3079ed0008:1580235245:0:0 [28/Jan/2020:15:14:05.587689125 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFile - found DB object 0x603002db4250 for database /var/lib/dirsrv/slapd-RNP/changelogdb/0f6cd003-41ef11ea-8a6bdfdc-87dde3bc_5e3067ae000000640000.db [28/Jan/2020:15:14:05.589326166 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5PositionCursorForReplay - (agmt="cn=AD-DF-DC01" (gti-df-dc01:636)): Consumer RUV: [28/Jan/2020:15:14:05.590910743 -0300] - DEBUG - NSMMReplicationPlugin - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): {replicageneration} 5e3067ae000000640000 [28/Jan/2020:15:14:05.592117182 -0300] - DEBUG - NSMMReplicationPlugin - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): {replica 100 ldap://idc01.ldap.my.domain:389} 5e3067b2000000640000 5e3079ed000500640000 5e3079ed [28/Jan/2020:15:14:05.594001325 -0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5PositionCursorForReplay - (agmt="cn=AD-DF-DC01" (gti-df-dc01:636)): Supplier RUV: [28/Jan/2020:15:14:05.595976644 -0300] - DEBUG - NSMMReplicationPlugin - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): {replicageneration} 5e3067ae000000640000 [28/Jan/2020:15:14:05.597342376 -0300] - DEBUG - NSMMReplicationPlugin - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): {replica 100 ldap://idc01.ldap.my.domain:389} 5e3067b2000000640000 5e3079ed000500640000 5e3079ed [28/Jan/2020:15:14:05.598663304 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_get_buffer - found thread private buffer cache 0x611001c71940 [28/Jan/2020:15:14:05.601957696 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_get_buffer - _pool is 0x604000140450 _pool->pl_busy_lists is 0x603002f7d4b0 _pool->pl_busy_lists->bl_buffers is 0x611001c71940 [28/Jan/2020:15:14:05.603435840 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_initial_anchorcsn - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - (cscb 0 - state 1) - csnPrevMax () csnMax (5e3079ed000500640000) csnBuf (5e3079ed000500640000) csnConsumerMax (5e3079ed000500640000) [28/Jan/2020:15:14:05.605169166 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_load_buffer - rc=-30988 [28/Jan/2020:15:14:05.608752193 -0300] - DEBUG - agmt="cn=AD-DF-DC01" (gti-df-dc01:636) - clcache_return_buffer - session end: state=5 load=0 sent=0 skipped=0 skipped_new_rid=0 skipped_csn_gt_cons_maxcsn=0 skipped_up_to_date=0 skipped_csn_gt_ruv=0 skipped_csn_covered=0 [28/Jan/2020:15:14:05.611212275 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): No changes to send [28/Jan/2020:15:14:05.613314791 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - send_dirsync_search - Calling dirsync search request plugin [28/Jan/2020:15:14:05.616014100 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - send_dirsync_search - Sending dirsync search request [28/Jan/2020:15:14:05.619349049 -0300] - DEBUG - replication - copy_operation_parameters - replica is null. [28/Jan/2020:15:14:05.650162767 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_conn_start_linger - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): Beginning linger on the connection [28/Jan/2020:15:14:05.652307273 -0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - agmt="cn=AD-DF-DC01" (gti-df-dc01:636): State: sending_updates -> wait_for_changes