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