Hi Guys,
389-Directory/1.4.3.2
The password sync from 389 to windows(2012) is not working:
# dsconf RNP repl-winsync-agmt create --suffix=dc=rnp,dc=local --host=gti-df-dc01 --port=636 --conn-protocol=LDAPS --bind-dn="CN=my_win_account" --bind-passwd=password --win-subtree=dc=my,dc=domain --ds-subtree=dc=my,dc=domain --win-domain=RNP --sync-users=on --sync-groups=on --init AD-DF-DC01
Double checked everything including the user permissions on windows AD side , also checked the windows log and passync log, could not found anything related (at least the 389 trying to update my user's password or any error)
From windows to 389 works fine.
Attaching the log (in replication debug mode)
Don't know what else to look
Thanks.
[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="<GUID=49c65f0f65411f47b2f46906ae5e66ef>" 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="<GUID=49c65f0f65411f47b2f46906ae5e66ef>"
[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="<GUID=49c65f0f65411f47b2f46906ae5e66ef>" 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="<GUID=49c65f0f65411f47b2f46906ae5e66ef>"
[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="<GUID=49c65f0f65411f47b2f46906ae5e66ef>" 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="<GUID=49c65f0f65411f47b2f46906ae5e66ef>"
[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="<GUID=49c65f0f65411f47b2f46906ae5e66ef>" 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="<GUID=49c65f0f65411f47b2f46906ae5e66ef>"
[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="<GUID=49c65f0f65411f47b2f46906ae5e66ef>" 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="<GUID=49c65f0f65411f47b2f46906ae5e66ef>"
[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_______________________________________________ 389-users mailing list -- 389-users@xxxxxxxxxxxxxxxxxxxxxxx To unsubscribe send an email to 389-users-leave@xxxxxxxxxxxxxxxxxxxxxxx Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/389-users@xxxxxxxxxxxxxxxxxxxxxxx
