Bug 1182477

I verified this is a bug, I will clone an upstream ticket.

Upstream ticket:
https://fedorahosted.org/freeipa/ticket/4841

I investigated this bug, I personally doubt it is a regression from 7.0 unless something changed in the Directory Server - the last update was done in
https://fedorahosted.org/freeipa/ticket/3007
which is in older RHELs. Rich or Noriko, any idea what could be the root cause?

When checking plugins debug log, I see following pattern, being the probable root cause:

[14/Jan/2015:18:12:52 -0500] ipa-winsync - --> ipa_winsync_pre_ds_mod_user_cb -- begin
[14/Jan/2015:18:12:52 -0500] ipa-winsync - <-- sync_acct_disable - the AD entry corresponding to [uid=duser,cn=users,cn=accounts,dc=mkosek-f21,dc=test] is NULL - skipping
[14/Jan/2015:18:12:52 -0500] ipa-winsync - do_force_sync - forcing sync of AD entry [(none)] with DS entry [uid=duser,cn=users,cn=accounts,dc=mkosek-f21,dc=test]
[14/Jan/2015:18:12:52 -0500] ipa-winsync - <-- ipa_winsync_pre_ds_mod_user_cb -- end

See origin DS errors log for full log.

After I fixed the calls in the code, from

~~~~~~~
    sync_acct_disable(cbdata, rawentry, ds_entry, ACCT_DISABLE_TO_DS,
                      ds_entry, NULL, NULL);
~~~~~~~

to

~~~~~~~
    sync_acct_disable(cbdata, ad_entry, ds_entry, ACCT_DISABLE_TO_DS,
                      ds_entry, NULL, NULL);
~~~~~~~

at least the AD->IPA side started working, see the attached patch and second log.

However, IPA->AD side is still not working as I could not update this part:

~~~~~~~
    LOG("--> ipa_winsync_pre_ad_mod_user_mods_cb -- begin\n");

    /* wrap the modstosend in a Slapi_Mods for convenience */
    smods = slapi_mods_new();
    slapi_mods_init_passin(smods, *modstosend);
    sync_acct_disable(cbdata, rawentry, (Slapi_Entry *)ds_entry,
                      ACCT_DISABLE_TO_AD, NULL, smods, NULL);
~~~~~~~

as I did not have access to ad_entry there. Any idea how to fix it?

Created attachment 980479 [details]
Original DS errors - before fix

Created attachment 980480 [details]
DS errors - after fix

Created attachment 980481 [details]
Partial patch, fixing AD->IPA direction

Martin,

Your code change looks familiar.  Please take a look at this ticket:
https://fedorahosted.org/389/ticket/47763

We were reported that posix plugin's modify part got broken and a patch was provided.  The patch contains the same change in your comment5 on TO_DS.

1153	 	    sync_acct_disable(cbdata, rawentry, ds_entry, ACCT_DISABLE_TO_DS, ds_entry, NULL, NULL); 
 	1206	    sync_acct_disable(cbdata, ad_entry, ds_entry, ACCT_DISABLE_TO_DS, ds_entry, NULL, NULL); 

I thought TO_AD was not affected...  If you are interested in to replace "rawentry" with "ad_entry" in this call,
    sync_acct_disable(cbdata, rawentry, (Slapi_Entry *)ds_entry,
                      ACCT_DISABLE_TO_AD, NULL, smods, NULL);

the third argument passed to the callback is "ad_entry":
void
winsync_plugin_call_pre_ad_mod_user_cb(const Repl_Agmt *ra, const Slapi_Entry *rawentry,
                                       Slapi_Entry *ad_entry, Slapi_Entry *ds_entry,
                                       Slapi_Mods *smods, int *do_modify)
{
 WINSYNC_PLUGIN_CALL_PLUGINS_COOKIE_BEGIN(WINSYNC_PLUGIN_PRE_AD_MOD_USER_CB,winsync_pre_mod_cb,thefunc)
        (*thefunc)(cookie, rawentry, ad_entry, ds_entry, smods, do_modify);
                                     ^^^^^^^^^
    WINSYNC_PLUGIN_CALL_PLUGINS_END;

    return;
}

Please see also this bug (this is just a cloned bug).
https://bugzilla.redhat.com/show_bug.cgi?id=1118060
Bug 1118060 - winsync plugin modify is broken

I'm going to add the test steps to verify enabling/disabling an account is synchronized between AD and DS.

Thanks,
--noriko

Ah, thanks for info. The problem as I see it is that rawentry is suddenly NULL. I assume that it was not NULL before the referred DS update as this code was not touched in IPA since the last release.

We can fix AD->DS with my patch. However, the DS->AD direction still seems broken. The callback winsync_plugin_call_pre_ad_mod_user_cb with ad_entry available is not called. Instead, ipa_winsync_pre_ad_mod_user_mods_cb is being called:

[14/Jan/2015:18:30:05 -0500] ipa-winsync - --> ipa_winsync_pre_ad_mod_user_mods_cb -- begin
[14/Jan/2015:18:30:05 -0500] ipa-winsync - <-- sync_acct_disable - the AD entry corresponding to [uid=testuser,cn=users,cn=accounts,dc=mkosek-f21,dc=test] is NULL - skipping
[14/Jan/2015:18:30:05 -0500] ipa-winsync - <-- ipa_winsync_pre_ad_mod_user_mods_cb -- end

This does not have the ad_entry available, so the sync_acct_disable fails. Can you please advise what should we change then in the ipa-winsync plugin, besides the patch already provided?

Justification: By this bug, activated state of accounts would mismatch between DS and AD.  The mismatch causes the security issue.

See this comment for the verification steps using 389-ds-base only.
https://bugzilla.redhat.com/show_bug.cgi?id=1183820#c2

Verified in version
389-ds-base-1.3.3.1-13.el7.x86_64
ipa-server-4.1.0-16.el7.x86_64
sssd-ipa-1.12.2-47.el7.x86_64


::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
:: [   LOG    ] :: ipa_winsync_0009: Synchronization behaviour of account lock status
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

ipawinsyncacctdisable: both
:: [   PASS   ] :: Winsync account disable set to "both" by default 
:: [ 15:30:55 ] :: Testing with Winsync account disable set to"both"
:: [  BEGIN   ] :: Creating ldif file to reset ipawinsyncacctdisable to "both" :: actually running 'acctdisable_ldif both'
:: [   PASS   ] :: Creating ldif file to reset ipawinsyncacctdisable to "both" (Expected 0, got 0)
:: [  BEGIN   ] :: Setting disabled account to sync to both servers :: actually running 'ldapmodify -x -D "cn=Directory Manager" -w Secret123 -f acctdisable.ldif'
modifying entry "cn=ipa-winsync,cn=plugins,cn=config"

:: [   PASS   ] :: Setting disabled account to sync to both servers (Expected 0, got 0)
:: [  BEGIN   ] :: aduser1 is enabled on IPA :: actually running 'ipa user-show aduser1 | grep "Account disabled: False"'
  Account disabled: False
:: [   PASS   ] :: aduser1 is enabled on IPA (Expected 0, got 0)
:: [  BEGIN   ] :: Creating ldif file for disabling aduser1 :: actually running 'ADuser_cntrl_ldif aduser1 ads 514'
:: [   PASS   ] :: Creating ldif file for disabling aduser1 (Expected 0, got 0)
:: [  BEGIN   ] :: Disable aduser1 on AD :: actually running 'ldapmodify -ZZ -h squab.adrelm.com -D "CN=Administrator,CN=Users,DC=adrelm,DC=com" -w Secret123 -f ADuser_cntrl.ldif'
modifying entry "CN=aduser1 ads,CN=Users,DC=adrelm,DC=com"

:: [   PASS   ] :: Disable aduser1 on AD (Expected 0, got 0)
:: [  BEGIN   ] :: aduser1 disabled in AD :: actually running 'ldapsearch -x -ZZ -h squab.adrelm.com -D "CN=Administrator,CN=Users,DC=adrelm,DC=com" -w Secret123 -b "CN=aduser1 ads,CN=Users,DC=adrelm,DC=com" | grep "userAccountControl: 514"'
userAccountControl: 514
:: [   PASS   ] :: aduser1 disabled in AD (Expected 0, got 0)
:: [  BEGIN   ] :: Waiting for sync :: actually running 'sleep 30'
:: [   PASS   ] :: Waiting for sync (Expected 0, got 0)
:: [  BEGIN   ] :: Running 'sleep 5'
:: [   PASS   ] :: Command 'sleep 5' (Expected 0, got 0)
:: [  BEGIN   ] :: After sync aduser1 disabled on IPA as well :: actually running 'ipa user-show aduser1 | grep "Account disabled: True"'
  Account disabled: True
:: [   PASS   ] :: After sync aduser1 disabled on IPA as well (Expected 0, got 0)
:: [  BEGIN   ] :: Running 'ipa user-enable aduser1'
------------------------------
Enabled user account "aduser1"
------------------------------
:: [   PASS   ] :: Command 'ipa user-enable aduser1' (Expected 0, got 0)
:: [  BEGIN   ] :: Re-enabled aduser1 from IPA :: actually running 'ipa user-show aduser1 | grep "Account disabled: False"'
  Account disabled: False
:: [   PASS   ] :: Re-enabled aduser1 from IPA (Expected 0, got 0)
:: [  BEGIN   ] :: Giving 5 seconds to inform AD :: actually running 'sleep 5'
:: [   PASS   ] :: Giving 5 seconds to inform AD (Expected 0, got 0)
:: [  BEGIN   ] :: aduser1 is enabled in AD as well :: actually running 'ldapsearch -x -ZZ -h squab.adrelm.com -D "CN=Administrator,CN=Users,DC=adrelm,DC=com" -w Secret123 -b "CN=aduser1 ads,CN=Users,DC=adrelm,DC=com" | grep "userAccountControl: 512"'
userAccountControl: 512
:: [   PASS   ] :: aduser1 is enabled in AD as well (Expected 0, got 0)
:: [  BEGIN   ] :: Running 'sleep 5'
:: [   PASS   ] :: Command 'sleep 5' (Expected 0, got 0)
:: [ 15:31:49 ] :: Testing with Winsync account disable set to "none"
:: [  BEGIN   ] :: Creating ldif file to set ipawinsyncacctdisable to none :: actually running 'acctdisable_ldif none'
:: [   PASS   ] :: Creating ldif file to set ipawinsyncacctdisable to none (Expected 0, got 0)
:: [  BEGIN   ] :: Setting disabled account to not sync to IPA :: actually running 'ldapmodify -x -D "cn=Directory Manager" -w Secret123 -f acctdisable.ldif'
modifying entry "cn=ipa-winsync,cn=plugins,cn=config"

:: [   PASS   ] :: Setting disabled account to not sync to IPA (Expected 0, got 0)
:: [  BEGIN   ] :: Disable aduser1 on AD :: actually running 'ldapmodify -ZZ -h squab.adrelm.com -D "CN=Administrator,CN=Users,DC=adrelm,DC=com" -w Secret123 -f ADuser_cntrl.ldif'
modifying entry "CN=aduser1 ads,CN=Users,DC=adrelm,DC=com"

:: [   PASS   ] :: Disable aduser1 on AD (Expected 0, got 0)
:: [  BEGIN   ] :: aduser1 disabled in AD :: actually running 'ldapsearch -x -ZZ -h squab.adrelm.com -D "CN=Administrator,CN=Users,DC=adrelm,DC=com" -w Secret123 -b "CN=aduser1 ads,CN=Users,DC=adrelm,DC=com" | grep "userAccountControl: 514"'
userAccountControl: 514
:: [   PASS   ] :: aduser1 disabled in AD (Expected 0, got 0)
:: [  BEGIN   ] :: Waiting for sync :: actually running 'sleep 30'
:: [   PASS   ] :: Waiting for sync (Expected 0, got 0)
:: [  BEGIN   ] :: Running 'sleep 5'
:: [   PASS   ] :: Command 'sleep 5' (Expected 0, got 0)
:: [  BEGIN   ] :: aduser1 is not disabled on IPA expected :: actually running 'ipa user-show aduser1 | grep "Account disabled: False"'
  Account disabled: False
:: [   PASS   ] :: aduser1 is not disabled on IPA expected (Expected 0, got 0)
:: [ 15:32:27 ] :: Testing reverting change for ipawinsyncacctdisable does not trigger a rescan of AD
:: [  BEGIN   ] :: Creating ldif file to reset ipawinsyncacctdisable to "both" :: actually running 'acctdisable_ldif both'
:: [   PASS   ] :: Creating ldif file to reset ipawinsyncacctdisable to "both" (Expected 0, got 0)
:: [  BEGIN   ] :: Resetting disabled account to sync to both servers :: actually running 'ldapmodify -x -D "cn=Directory Manager" -w Secret123 -f acctdisable.ldif'
modifying entry "cn=ipa-winsync,cn=plugins,cn=config"

:: [   PASS   ] :: Resetting disabled account to sync to both servers (Expected 0, got 0)
:: [  BEGIN   ] :: Waiting for sync :: actually running 'sleep 30'
:: [   PASS   ] :: Waiting for sync (Expected 0, got 0)
:: [  BEGIN   ] :: Running 'sleep 5'

MARK-LWD-LOOP -- 2015-01-27 15:32:59 --
:: [   PASS   ] :: Command 'sleep 5' (Expected 0, got 0)
:: [  BEGIN   ] :: aduser1 is still enabled on IPA after account lock status change to both. As expected :: actually running 'ipa user-show aduser1 | grep "Account disabled: False"'
  Account disabled: False
:: [   PASS   ] :: aduser1 is still enabled on IPA after account lock status change to both. As expected (Expected 0, got 0)
:: [  BEGIN   ] :: Running 'ADuser_cntrl_ldif aduser1 ads 512'
:: [   PASS   ] :: Command 'ADuser_cntrl_ldif aduser1 ads 512' (Expected 0, got 0)
:: [  BEGIN   ] :: Re-enable aduser1 on AD :: actually running 'ldapmodify -ZZ -h squab.adrelm.com -D "CN=Administrator,CN=Users,DC=adrelm,DC=com" -w Secret123 -f ADuser_cntrl.ldif'
modifying entry "CN=aduser1 ads,CN=Users,DC=adrelm,DC=com"

:: [   PASS   ] :: Re-enable aduser1 on AD (Expected 0, got 0)
:: [  BEGIN   ] :: aduser1 re-enabled in AD :: actually running 'ldapsearch -x -ZZ -h squab.adrelm.com -D "CN=Administrator,CN=Users,DC=adrelm,DC=com" -w Secret123 -b "CN=aduser1 ads,CN=Users,DC=adrelm,DC=com" | grep "userAccountControl: 512"'
userAccountControl: 512
:: [   PASS   ] :: aduser1 re-enabled in AD (Expected 0, got 0)
:: [  BEGIN   ] :: Waiting for sync :: actually running 'sleep 30'
:: [   PASS   ] :: Waiting for sync (Expected 0, got 0)
:: [  BEGIN   ] :: Running 'sleep 5'
:: [   PASS   ] :: Command 'sleep 5' (Expected 0, got 0)
:: [  BEGIN   ] :: aduser1 is enabled in IPA :: actually running 'ipa user-show aduser1 | grep "Account disabled: False"'
  Account disabled: False
:: [   PASS   ] :: aduser1 is enabled in IPA (Expected 0, got 0)
:: [  BEGIN   ] :: Running 'sleep 10'
:: [   PASS   ] :: Command 'sleep 10' (Expected 0, got 0)
'0effef4f-b44c-46b3-8bc9-6331c6b2f860'
ipa-winsync-0009-Synchronization-behaviour-of-account-lock-status result: PASS

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHSA-2015-0416.html