Found the culprit: nsslapd-unhashed-pw-switch: off
After upgrade, that one was turned off.... On Wed, Sep 30, 2020 at 8:01 PM Mihai Carabas <[email protected]> wrote: > 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 >
_______________________________________________ 389-users mailing list -- [email protected] To unsubscribe send an email to [email protected] 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/[email protected]
