[389-users] Password update fails to Windows Replica

Hello,

Yesterday I upgraded our Fedora from 29 to 30, implicitly 389ds. We have a sync agreement with an Active Directory (2012R2).

From yesterday password synchronization from 389DS to AD is not working. Any other attribute is updated. At [1] is a detailed log of the replication when changing password for tmp_stud12. Any insight why this is happening?

Thank you,
Mihai

[1] 

[30/Sep/2020:19:55:32.233009987 +0300] - DEBUG - _csngen_adjust_local_time - gen state before 5f74b8640001:1601484900:0:0
[30/Sep/2020:19:55:32.236215746 +0300] - DEBUG - _csngen_adjust_local_time - gen state after 5f74b8840000:1601484932:0:0
[30/Sep/2020:19:55:32.239259002 +0300] - DEBUG - NSMMReplicationPlugin - ruv_add_csn_inprogress - Successfully inserted csn 5f74b884000000010000 into pending list
[30/Sep/2020:19:55:32.243457280 +0300] - DEBUG - NSMMReplicationPlugin - purge_entry_state_information -  From entry uid=tmp_stud12,ou=SystemAccounts,ou=TCNIT,ou=People,dc=hidden,dc=my up to CSN 5f6b7db1000000010000
[30/Sep/2020:19:55:32.258805964 +0300] - DEBUG - NSMMReplicationPlugin - write_changelog_and_ruv - Writing change for uid=tmp_stud12,ou=SystemAccounts,ou=TCNIT,ou=People,dc=hidden,dc=my (uniqid: 2e5be882-7b1d11e4-a57dd2cd-46fac8b9, optype: 8) to changelog csn 5f74b884000000010000
[30/Sep/2020:19:55:32.262142425 +0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x7f178eb62ee0 for database /var/lib/dirsrv/slapd-ldap/changelogdb/b7808382-fe0211e4-aa4dd2cd-46fac8b9_547f9354000000010000.db
[30/Sep/2020:19:55:32.265014578 +0300] - DEBUG - NSMMReplicationPlugin - changelog program - cl5WriteOperationTxn - Successfully written entry with csn (5f74b884000000010000)
[30/Sep/2020:19:55:32.267843731 +0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x7f178eb62ee0 for database /var/lib/dirsrv/slapd-ldap/changelogdb/b7808382-fe0211e4-aa4dd2cd-46fac8b9_547f9354000000010000.db
[30/Sep/2020:19:55:32.270979889 +0300] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: committing all csns for csn 5f74b884000000010000
[30/Sep/2020:19:55:32.273990444 +0300] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: processing data csn 5f74b884000000010000
[30/Sep/2020:19:55:32.277450608 +0300] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Successfully committed csn 5f74b884000000010000
[30/Sep/2020:19:55:32.281341980 +0300] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Rolled up to csn 5f74b884000000010000
[30/Sep/2020:19:55:32.284517039 +0300] - DEBUG - replication - multimaster_mmr_postop - error 0 for operation 561.
[30/Sep/2020:19:55:32.289124924 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - agmt="cn=ad.hidden.my" (ad:636): State: wait_for_changes -> wait_for_changes
[30/Sep/2020:19:55:32.292220081 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - agmt="cn=ad.hidden.my" (ad:636): State: wait_for_changes -> ready_to_acquire_replica
[30/Sep/2020:19:55:32.295262337 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - acquire_replica, supplier RUV:
[30/Sep/2020:19:55:32.298563398 +0300] - DEBUG - NSMMReplicationPlugin - supplier: {replicageneration} 547f9354000000010000
[30/Sep/2020:19:55:32.301425351 +0300] - DEBUG - NSMMReplicationPlugin - supplier: {replica 1 ldap://ldap.hidden.my:389} 547f9663000000010000 5f74b884000000010000 5f74b884
[30/Sep/2020:19:55:32.304966716 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - acquire_replica, consumer RUV:
[30/Sep/2020:19:55:32.308563283 +0300] - DEBUG - NSMMReplicationPlugin - consumer: {replicageneration} 547f9354000000010000
[30/Sep/2020:19:55:32.312999165 +0300] - DEBUG - NSMMReplicationPlugin - consumer: {replica 1 ldap://ldap.hidden.my:389} 547f9663000000010000 5f74b831000000010000 5f74b831
[30/Sep/2020:19:55:32.316179024 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - acquire_replica, supplier RUV is newer
[30/Sep/2020:19:55:32.319248380 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_conn_cancel_linger - agmt="cn=ad.hidden.my" (ad:636): Cancelling linger on the connection
[30/Sep/2020:19:55:32.322436639 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - windows_acquire_replica returned success (101)
[30/Sep/2020:19:55:32.326057906 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - agmt="cn=ad.hidden.my" (ad:636): State: ready_to_acquire_replica -> sending_updates
[30/Sep/2020:19:55:32.329492969 +0300] - DEBUG - csngen_adjust_time - gen state before 5f74b8840002:1601484932:0:0
[30/Sep/2020:19:55:32.333250939 +0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFile - found DB object 0x7f178eb62ee0 for database /var/lib/dirsrv/slapd-ldap/changelogdb/b7808382-fe0211e4-aa4dd2cd-46fac8b9_547f9354000000010000.db
[30/Sep/2020:19:55:32.337062609 +0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5PositionCursorForReplay - (agmt="cn=ad.hidden.my" (ad:636)): Consumer RUV:
[30/Sep/2020:19:55:32.340427471 +0300] - DEBUG - NSMMReplicationPlugin - agmt="cn=ad.hidden.my" (ad:636): {replicageneration} 547f9354000000010000
[30/Sep/2020:19:55:32.343486228 +0300] - DEBUG - NSMMReplicationPlugin - agmt="cn=ad.hidden.my" (ad:636): {replica 1 ldap://ldap.hidden.my:389} 547f9663000000010000 5f74b831000000010000 5f74b831
[30/Sep/2020:19:55:32.346726488 +0300] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5PositionCursorForReplay - (agmt="cn=ad.hidden.my" (ad:636)): Supplier RUV:
[30/Sep/2020:19:55:32.349737943 +0300] - DEBUG - NSMMReplicationPlugin - agmt="cn=ad.hidden.my" (ad:636): {replicageneration} 547f9354000000010000
[30/Sep/2020:19:55:32.353373311 +0300] - DEBUG - NSMMReplicationPlugin - agmt="cn=ad.hidden.my" (ad:636): {replica 1 ldap://ldap.hidden.my:389} 547f9663000000010000 5f74b884000000010000 5f74b884
[30/Sep/2020:19:55:32.356297165 +0300] - DEBUG - agmt="cn=ad.hidden.my" (ad:636) - clcache_get_buffer - found thread private buffer cache 0x7f175aa3e000
[30/Sep/2020:19:55:32.359842730 +0300] - DEBUG - agmt="cn=ad.hidden.my" (ad:636) - clcache_get_buffer - _pool is 0x7f178eb9cb50 _pool->pl_busy_lists is 0x7f175aae09c0 _pool->pl_busy_lists->bl_buffers is 0x7f175aa3e000
[30/Sep/2020:19:55:32.363000989 +0300] - DEBUG - agmt="cn=ad.hidden.my" (ad:636) - clcache_initial_anchorcsn - agmt="cn=ad.hidden.my" (ad:636) - (cscb 0 - state 0) - csnPrevMax () csnMax (5f74b884000000010000) csnBuf (5f74b831000000010000) csnConsumerMax (5f74b831000000010000)
[30/Sep/2020:19:55:32.366373451 +0300] - DEBUG - clcache_initial_anchorcsn - anchor is now: 5f74b831000000010000
[30/Sep/2020:19:55:32.370214922 +0300] - DEBUG - NSMMReplicationPlugin - changelog program - agmt="cn=ad.hidden.my" (ad:636): CSN 5f74b831000000010000 found, position set for replay
[30/Sep/2020:19:55:32.374174595 +0300] - DEBUG - agmt="cn=ad.hidden.my" (ad:636) - clcache_get_next_change - load=1 rec=1 csn=5f74b884000000010000
[30/Sep/2020:19:55:32.379123586 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_replay_update - agmt="cn=ad.hidden.my" (ad:636) -Looking at modify operation local dn="uid=tmp_stud12,ou=SystemAccounts,ou=TCNIT,ou=People,dc=hidden,dc=my" (ours,user,not group)
[30/Sep/2020:19:55:32.383780572 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - map_entry_dn_outbound - agmt="cn=ad.hidden.my" (ad:636) - Looking for AD entry for DS dn="uid=tmp_stud12,ou=SystemAccounts,ou=TCNIT,ou=People,dc=hidden,dc=my" guid="2b8af7c84d7bc24f9afa7249765ba837"
[30/Sep/2020:19:55:32.387702345 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_search_entry_ext - Calling windows entry search request plugin
[30/Sep/2020:19:55:32.394396169 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_search_entry_ext - Received 2 messages, 1 entries, 0 references
[30/Sep/2020:19:55:32.398307741 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - map_entry_dn_outbound - agmt="cn=ad.hidden.my" (ad:636) - Return code 0 from search for AD entry dn="<GUID=2b8af7c84d7bc24f9afa7249765ba837>" or dn="CN=tmp_stud12 TMP_STUD12 (76196),OU=SystemAccounts,OU=TCNIT,OU=People,dc=hidden,dc=my"
[30/Sep/2020:19:55:32.402116111 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - Windows_replay_update - agmt="cn=ad.hidden.my" (ad:636) - Processing modify operation local dn="uid=tmp_stud12,ou=SystemAccounts,ou=TCNIT,ou=People,dc=hidden,dc=my" remote dn="<GUID=2b8af7c84d7bc24f9afa7249765ba837>"
[30/Sep/2020:19:55:32.405208768 +0300] - DEBUG - agmt="cn=ad.hidden.my" (ad:636) - clcache_adjust_anchorcsn - agmt="cn=ad.hidden.my" (ad:636) - (cscb 0 - state 1) - csnPrevMax (5f74b884000000010000) csnMax (5f74b884000000010000) csnBuf (5f74b884000000010000) csnConsumerMax (5f74b884000000010000)
[30/Sep/2020:19:55:32.408067021 +0300] - DEBUG - agmt="cn=ad.hidden.my" (ad:636) - clcache_load_buffer - rc=-30988
[30/Sep/2020:19:55:32.411291281 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - send_updates - agmt="cn=ad.hidden.my" (ad:636): No more updates to send (cl5GetNextOperationToReplay)
[30/Sep/2020:19:55:32.414409738 +0300] - DEBUG - agmt="cn=ad.hidden.my" (ad:636) - clcache_return_buffer - session end: state=5 load=1 sent=1 skipped=0 skipped_new_rid=0 skipped_csn_gt_cons_maxcsn=0 skipped_up_to_date=0 skipped_csn_gt_ruv=0 skipped_csn_covered=0
[30/Sep/2020:19:55:32.417788201 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - send_dirsync_search - Calling dirsync search request plugin
[30/Sep/2020:19:55:32.420946359 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - send_dirsync_search - Sending dirsync search request
[30/Sep/2020:19:55:32.425493743 +0300] - DEBUG - replication - copy_operation_parameters - replica is null.
[30/Sep/2020:19:55:32.437272261 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_conn_start_linger - agmt="cn=ad.hidden.my" (ad:636): Beginning linger on the connection
[30/Sep/2020:19:55:32.440276716 +0300] - DEBUG - NSMMReplicationPlugin - windows sync - windows_inc_run - agmt="cn=ad.hidden.my" (ad:636): State: sending_updates -> wait_for_changes