Bug 1040823

Summary: sudo credential cache or LDAP performance impact of krbLastSuccessfulAuth updates in high ssh traffic with IPA replica's, large nscpEntryWSI
Product: Red Hat Enterprise Linux 6 Reporter: Marc Sauton <msauton>
Component: ipaAssignee: Martin Kosek <mkosek>
Status: CLOSED NOTABUG QA Contact: Namita Soman <nsoman>
Severity: high Docs Contact:
Priority: unspecified    
Version: 6.6CC: dpal, jhrozek, msauton, rcritten, rmeggins
Target Milestone: rcFlags: mkosek: needinfo? (msauton)
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-02-06 13:23:33 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On:    
Bug Blocks: 1061410    

Description Marc Sauton 2013-12-12 07:54:31 UTC
Description of problem:

Could be a RFE or be considered as a defect for the component sssd or ipa.

The initial report came as an IPA performance problem, then it appeared the LDAP service had some long etime for some MOD operation.
We found out a monitoring system was heavily using ssh and sudo with one user entry, to collect host informations, from 100's of systems, resulting in high disk I/O against ns-slapd to update the attribute krbLastSuccessfulAuth.

The problem is, with IPA masters and LDAP replication, the very frequent value changes of the attribute krbLastSuccessfulAuth created a very large entry to replicate, containing the operational attribute nscpEntryWSI (Netscape Entry With State Information), causing a lot of disk I/O's, too many.

The workaround was to globally disable krbLastSuccessfulAuth, but this may not be the correct thing to do, or only a temporary workaround.
As soon as the customer disabled krbLastSuccessfulAuth, the system load on the IPA server and ns-slapd went down to "reasonable" levels.

So either krbLastSuccessfulAuth is updated too often, or SSSD may need to cache sudo credentials (?).

Or change the schema definition of krbLastSuccessfulAuth from single-value to multi-value??

/etc/dirsrv/slapd-EXAMPLE-COM/schema/60kerberos.ldif:attributetypes: ( 2.16.840.1.113719.1.301.4.48.1 NAME 'krbLastSuccessfulAuth' EQUALITY generalizedTimeMatch SYNTAX 1.3.6.1.4.1.1466.115.121.1.24 SINGLE-VALUE)



Version-Release number of selected component (if applicable):
Red Hat Enterprise Linux Server release 6.4 (Santiago)
ipa-client-3.0.0-25.el6.x86_64
sssd-1.9.2-82.7.el6_4.x86_64
sssd-client-1.9.2-82.7.el6_4.x86_64
libipa_hbac-1.9.2-82.7.el6_4.x86_64
libipa_hbac-python-1.9.2-82.7.el6_4.x86_64
libsss_idmap-1.9.2-82.7.el6_4.x86_64
libsss_sudo-1.9.2-82.7.el6_4.x86_64


How reproducible:
the trick is to be able to generate a high load for the test system used.
The notes below do not show the repetition of the ssh and sudo calls, only one test.


Steps to Reproduce:

1. need a RHEL 6.4 IdM/IPA server is already installed, configured and functional

2. need a RHEL 6.4 IdM/IPA client is already installed, configured and functional

3. verify or install the package libsss_sudo is installed on the IPA client
yum install -y libsss_sudo

4. duplicate and edit /etc/sssd/sssd.conf to add LDAP and SUDO configuration information
less /etc/sssd/sssd.conf
[domain/example.com]
...
sudo_provider = ldap
ldap_uri = ldap://ipaserver1.example.com
ldap_sudo_search_base = ou=sudoers,dc=example,dc=com
...
[sssd]
services = nss, pam, ssh, sudo

less /etc/nsswitch.conf
...
passwd:     files sss
shadow:     files sss
group:      files sss
sudoers: sss
...

5. restart SSSD
/etc/init.d/sssd restart

6. have some test user entry on the IPA server
echo "password" | ipa user-add testipauser1 --first=testipa1 --last=user1 --password
su - testipauser1
id
uid=1006(testipauser1) gid=1006(testipauser1) groups=1006(testipauser1) context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023

7. create a SUDO rule and add that test user entry on the IPA server
ipa sudorule-add testrule --hostcat all --cmdcat all --runasusercat all --runasgroupcat all
ipa sudorule-add-user testrule --users testipauser1

8. login as the test user on an IPA client and test SUDO access
su - testipauser1
id
uid=1006(testipauser1) gid=1006(testipauser1) groups=1006(testipauser1) context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
sudo -l
User testipauser1 may run the following commands on this host:
    (ALL) ALL

-sh-4.1$ sudo id
Dec 11 15:06:19 ipaclient1 sudo: testipauser1 : TTY=pts/0 ; PWD=/root ; USER=root ; COMMAND=/usr/bin/id
uid=0(root) gid=0(root) groups=0(root) context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
-sh-4.1$ 

9. try to generate "many" ssh and sudo calls..


Actual results:
in a simple one time test, krbLastSuccessfulAuth is updated twice, once during the ssh, and once during the sudo operation
if the sssh and sudo are configured without password prompt, and if there are many ssh calls, in the context of multi-masters, the replication data in the nscpEntryWSI operational attribute will grow very large and cause a lot of disk I/O.


Expected results:
less impact from krbLastSuccessfulAuth updates in ns-slapd (less disk I/O)
Change the schema definition of krbLastSuccessfulAuth from single-value to multi-value??


Additional info:

test notes, there are 2 MOD for each ssh and sudo calls, it was apparently enough to cause ns-slapd performance issues in the customer's environment.


ipa server

tail -f /var/log/dirsrv/slapd-EXAMPLE-COM/audit &
tail -f /var/log/dirsrv/slapd-EXAMPLE-COM/access | grep testipauser1 &


ipa client

tail -f /var/log/secure &


remote client

ssh testipauser1.5.181 /usr/bin/sudo id
testipauser1.5.181's password:

ipa server

time: 20131211152633
dn: fqdn=ipaclient1.example.com,cn=computers,cn=accounts,dc=example,dc=com
changetype: modify
replace: krbLastSuccessfulAuth
krbLastSuccessfulAuth: 20131211232633Z
-
replace: modifiersname
modifiersname: cn=Directory Manager
-
replace: modifytimestamp
modifytimestamp: 20131211232633Z
-
replace: entryusn
entryusn: 3593
-

time: 20131211152638
dn: uid=testipauser1,cn=users,cn=accounts,dc=example,dc=com
changetype: modify
replace: krbLastSuccessfulAuth
krbLastSuccessfulAuth: 20131211232638Z
-
replace: modifiersname
modifiersname: cn=Directory Manager
-
replace: modifytimestamp
modifytimestamp: 20131211232638Z
-
replace: entryusn
entryusn: 3594
-


[root@ipaserver1 ~]#

[11/Dec/2013:15:15:00 -0800] conn=622 op=111 SRCH base="cn=accounts,dc=example,dc=com" scope=2 filter="(&(uid=testipauser1)(objectClass=posixAccount))" attrs="objectClass uid userPassword uidNumber gidNumber gecos homeDirectory loginShell krbPrincipalName cn memberOf nsUniqueId modifyTimestamp entryusn shadowLastChange shadowMin shadowMax shadowWarning shadowInactive shadowExpire shadowFlag krbLastPwdChange krbPasswordExpiration pwdattribute authorizedService accountexpires useraccountcontrol nsAccountLock host logindisabled loginexpirationtime loginallowedtimemap ipaSshPubKey"
[11/Dec/2013:15:15:00 -0800] conn=622 op=112 SRCH base="cn=accounts,dc=example,dc=com" scope=2 filter="(&(uid=testipauser1)(objectClass=posixAccount))" attrs="objectClass uid userPassword uidNumber gidNumber gecos homeDirectory loginShell krbPrincipalName cn memberOf nsUniqueId modifyTimestamp entryusn shadowLastChange shadowMin shadowMax shadowWarning shadowInactive shadowExpire shadowFlag krbLastPwdChange krbPasswordExpiration pwdattribute authorizedService accountexpires useraccountcontrol nsAccountLock host logindisabled loginexpirationtime loginallowedtimemap ipaSshPubKey"
[11/Dec/2013:15:15:00 -0800] conn=622 op=113 SRCH base="cn=accounts,dc=example,dc=com" scope=2 filter="(&(uid=testipauser1)(objectClass=posixAccount))" attrs="objectClass uid userPassword uidNumber gidNumber gecos homeDirectory loginShell krbPrincipalName cn memberOf nsUniqueId modifyTimestamp entryusn shadowLastChange shadowMin shadowMax shadowWarning shadowInactive shadowExpire shadowFlag krbLastPwdChange krbPasswordExpiration pwdattribute authorizedService accountexpires useraccountcontrol nsAccountLock host logindisabled loginexpirationtime loginallowedtimemap ipaSshPubKey"
[11/Dec/2013:15:15:01 -0800] conn=622 op=114 SRCH base="cn=accounts,dc=example,dc=com" scope=2 filter="(&(uid=testipauser1)(objectClass=posixAccount))" attrs="objectClass uid userPassword uidNumber gidNumber gecos homeDirectory loginShell krbPrincipalName cn memberOf nsUniqueId modifyTimestamp entryusn shadowLastChange shadowMin shadowMax shadowWarning shadowInactive shadowExpire shadowFlag krbLastPwdChange krbPasswordExpiration pwdattribute authorizedService accountexpires useraccountcontrol nsAccountLock host logindisabled loginexpirationtime loginallowedtimemap ipaSshPubKey"
[11/Dec/2013:15:15:01 -0800] conn=622 op=115 SRCH base="cn=accounts,dc=example,dc=com" scope=2 filter="(&(uid=testipauser1)(objectClass=posixAccount))" attrs="objectClass uid userPassword uidNumber gidNumber gecos homeDirectory loginShell krbPrincipalName cn memberOf nsUniqueId modifyTimestamp entryusn shadowLastChange shadowMin shadowMax shadowWarning shadowInactive shadowExpire shadowFlag krbLastPwdChange krbPasswordExpiration pwdattribute authorizedService accountexpires useraccountcontrol nsAccountLock host logindisabled loginexpirationtime loginallowedtimemap ipaSshPubKey"
[11/Dec/2013:15:15:05 -0800] conn=622 op=117 SRCH base="cn=accounts,dc=example,dc=com" scope=2 filter="(&(uid=testipauser1)(objectClass=posixAccount))" attrs="objectClass uid userPassword uidNumber gidNumber gecos homeDirectory loginShell krbPrincipalName cn memberOf nsUniqueId modifyTimestamp entryusn shadowLastChange shadowMin shadowMax shadowWarning shadowInactive shadowExpire shadowFlag krbLastPwdChange krbPasswordExpiration pwdattribute authorizedService accountexpires useraccountcontrol nsAccountLock host logindisabled loginexpirationtime loginallowedtimemap ipaSshPubKey"
[11/Dec/2013:15:15:06 -0800] conn=4 op=8683 SRCH base="dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal)(objectClass=ipakrbprincipal))(|(ipaKrbPrincipalAlias=testipauser1)(krbPrincipalName=testipauser1)))" attrs="krbPrincipalName krbCanonicalName ipaKrbPrincipalAlias krbUPEnabled krbPrincipalKey krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbExtraData krbLastAdminUnlock krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge nsAccountLock passwordHistory objectClass"
[11/Dec/2013:15:15:06 -0800] conn=4 op=8687 SRCH base="dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal)(objectClass=ipakrbprincipal))(|(ipaKrbPrincipalAlias=testipauser1)(krbPrincipalName=testipauser1)))" attrs="krbPrincipalName krbCanonicalName ipaKrbPrincipalAlias krbUPEnabled krbPrincipalKey krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbExtraData krbLastAdminUnlock krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge nsAccountLock passwordHistory objectClass"
[11/Dec/2013:15:15:06 -0800] conn=4 op=8691 SRCH base="uid=testipauser1,cn=users,cn=accounts,dc=example,dc=com" scope=0 filter="(objectClass=*)" attrs="objectClass uid cn gidNumber krbPrincipalName krbCanonicalName krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbLastAdminUnlock krbTicketFlags ipaNTSecurityIdentifier ipaNTLogonScript ipaNTProfilePath ipaNTHomeDirectory ipaNTHomeDirectoryDrive"
[11/Dec/2013:15:15:06 -0800] conn=4 op=8692 SRCH base="uid=testipauser1,cn=users,cn=accounts,dc=example,dc=com" scope=0 filter="(objectClass=*)" attrs="objectClass uid cn gidNumber krbPrincipalName krbCanonicalName krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbLastAdminUnlock krbTicketFlags ipaNTSecurityIdentifier ipaNTLogonScript ipaNTProfilePath ipaNTHomeDirectory ipaNTHomeDirectoryDrive"
[11/Dec/2013:15:15:06 -0800] conn=4 op=8693 MOD dn="uid=testipauser1,cn=users,cn=accounts,dc=example,dc=com"
[11/Dec/2013:15:15:06 -0800] conn=4 op=8697 SRCH base="dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal))(krbPrincipalName=testipauser1))" attrs="krbPrincipalName krbCanonicalName ipaKrbPrincipalAlias krbUPEnabled krbPrincipalKey krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbExtraData krbLastAdminUnlock krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge nsAccountLock passwordHistory objectClass"

ipa client

Dec 11 15:15:05 ipaclient1 sshd[4695]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.3.228.173  user=testipauser1
Dec 11 15:15:06 ipaclient1 sshd[4695]: pam_sss(sshd:auth): authentication success; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.3.228.173 user=testipauser1
Dec 11 15:15:07 ipaclient1 sshd[4695]: Accepted password for testipauser1 from 10.3.228.173 port 49936 ssh2
Dec 11 15:15:07 ipaclient1 sshd[4695]: pam_unix(sshd:session): session opened for user testipauser1 by (uid=0)


remote client

Could not chdir to home directory /home/testipauser1: No such file or directory
[sudo] password for testipauser1:


ipa server

time: 20131211152715
dn: uid=testipauser1,cn=users,cn=accounts,dc=example,dc=com
changetype: modify
replace: krbLastSuccessfulAuth
krbLastSuccessfulAuth: 20131211232715Z
-
replace: modifiersname
modifiersname: cn=Directory Manager
-
replace: modifytimestamp
modifytimestamp: 20131211232715Z
-
replace: entryusn
entryusn: 3595
-


[11/Dec/2013:15:15:32 -0800] conn=622 op=128 SRCH base="cn=accounts,dc=example,dc=com" scope=2 filter="(&(uid=testipauser1)(objectClass=posixAccount))" attrs="objectClass uid userPassword uidNumber gidNumber gecos homeDirectory loginShell krbPrincipalName cn memberOf nsUniqueId modifyTimestamp entryusn shadowLastChange shadowMin shadowMax shadowWarning shadowInactive shadowExpire shadowFlag krbLastPwdChange krbPasswordExpiration pwdattribute authorizedService accountexpires useraccountcontrol nsAccountLock host logindisabled loginexpirationtime loginallowedtimemap ipaSshPubKey"
[11/Dec/2013:15:15:32 -0800] conn=4 op=8700 SRCH base="dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal)(objectClass=ipakrbprincipal))(|(ipaKrbPrincipalAlias=testipauser1)(krbPrincipalName=testipauser1)))" attrs="krbPrincipalName krbCanonicalName ipaKrbPrincipalAlias krbUPEnabled krbPrincipalKey krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbExtraData krbLastAdminUnlock krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge nsAccountLock passwordHistory objectClass"
[11/Dec/2013:15:15:32 -0800] conn=4 op=8704 SRCH base="dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal)(objectClass=ipakrbprincipal))(|(ipaKrbPrincipalAlias=testipauser1)(krbPrincipalName=testipauser1)))" attrs="krbPrincipalName krbCanonicalName ipaKrbPrincipalAlias krbUPEnabled krbPrincipalKey krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbExtraData krbLastAdminUnlock krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge nsAccountLock passwordHistory objectClass"
[11/Dec/2013:15:15:32 -0800] conn=4 op=8708 SRCH base="uid=testipauser1,cn=users,cn=accounts,dc=example,dc=com" scope=0 filter="(objectClass=*)" attrs="objectClass uid cn gidNumber krbPrincipalName krbCanonicalName krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbLastAdminUnlock krbTicketFlags ipaNTSecurityIdentifier ipaNTLogonScript ipaNTProfilePath ipaNTHomeDirectory ipaNTHomeDirectoryDrive"
[11/Dec/2013:15:15:32 -0800] conn=4 op=8709 SRCH base="uid=testipauser1,cn=users,cn=accounts,dc=example,dc=com" scope=0 filter="(objectClass=*)" attrs="objectClass uid cn gidNumber krbPrincipalName krbCanonicalName krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbLastAdminUnlock krbTicketFlags ipaNTSecurityIdentifier ipaNTLogonScript ipaNTProfilePath ipaNTHomeDirectory ipaNTHomeDirectoryDrive"
[11/Dec/2013:15:15:32 -0800] conn=4 op=8710 MOD dn="uid=testipauser1,cn=users,cn=accounts,dc=example,dc=com"
[11/Dec/2013:15:15:32 -0800] conn=4 op=8714 SRCH base="dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal))(krbPrincipalName=testipauser1))" attrs="krbPrincipalName krbCanonicalName ipaKrbPrincipalAlias krbUPEnabled krbPrincipalKey krbTicketPolicyReference krbPrincipalExpiration krbPasswordExpiration krbPwdPolicyReference krbPrincipalType krbPwdHistory krbLastPwdChange krbPrincipalAliases krbLastSuccessfulAuth krbLastFailedAuth krbLoginFailedCount krbExtraData krbLastAdminUnlock krbObjectReferences krbTicketFlags krbMaxTicketLife krbMaxRenewableAge nsAccountLock passwordHistory objectClass"

ipa client

Dec 11 15:15:32 ipaclient1 sudo: pam_unix(sudo:auth): authentication failure; logname=testipauser1 uid=1006 euid=0 tty=/dev/pts/2 ruser=testipauser1 rhost=  user=testipauser1
Dec 11 15:15:33 ipaclient1 sudo: pam_sss(sudo:auth): authentication success; logname=testipauser1 uid=1006 euid=0 tty=/dev/pts/2 ruser=testipauser1 rhost= user=testipauser1
Dec 11 15:15:33 ipaclient1 sudo: testipauser1 : TTY=pts/2 ; PWD=/ ; USER=root ; COMMAND=/usr/bin/id
Dec 11 15:15:33 ipaclient1 sshd[4703]: Received disconnect from 10.3.228.173: 11: disconnected by user
Dec 11 15:15:33 ipaclient1 sshd[4695]: pam_unix(sshd:session): session closed for user testipauser1


remote client
uid=0(root) gid=0(root) groups=0(root) context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
Connection to 10.14.5.181 closed.

Comment 1 Dmitri Pal 2013-12-13 17:01:42 UTC
Is there any way to reduce the number of hits against KDC?
There are different tricks that can be done.

It seems that the account is requesting TGT on every single connection this is wrong. By switching SSH to use to GSSAPI the user should not hit KDC this often (pretty much once in several ours). For sudo there is a timeout and caching in sudo itself to allow executing multiple supo commands without the re-authentication.

It seems that the solution should be in the ssh & sudo configuration and SSO rather than in IdM. 

I do not think this is a bug or legit RFE.

Comment 3 Martin Kosek 2014-01-03 09:35:18 UTC
Setting needsinfo until we have answers for Dmitri's (valid) questions.

Comment 4 Rich Megginson 2014-01-06 15:38:03 UTC
(In reply to Martin Kosek from comment #3)
> Setting needsinfo until we have answers for Dmitri's (valid) questions.

Who is responsible for answering these questions?  The customer didn't know how to configure the client to cache the credentials or use gssapi.  Is there someone who can help the customer?

Comment 5 Martin Kosek 2014-01-21 08:48:29 UTC
(In reply to Rich Megginson from comment #4)
> Is there someone who can help the customer?

Jakub, can you please advise?

Comment 6 Jakub Hrozek 2014-01-21 11:39:35 UTC
I think this is simply a matter of configuration, if I got the problem (too many hits to KDC when doing too many ssh && sudo invocations).

In order to not hit the KDC on auths they can configure GSSAPI authentication.

In order to not hit the KDC on sudo invocation they can set a longer timestamp_timeout option for sudo (I haven't tested this actually, but that's whan man sudoers says)

Comment 7 Martin Kosek 2014-02-06 13:23:33 UTC
Thanks for info, Jakub. I agree that this is really rather a configuration issue. I also see that customer case was closed. Closing this Bugzilla as well.