[Freeipa-users] sudo runs despite being denied by HBAC rules

[Ian Collier]

Can anyone help me to understand these logs... is there maybe a bug here?

The basic situation is that there is no HBAC rule that would allow
sudo.  When people try it, sss accepts their password but then denies
them access to the sudo command.  But despite this, our logs still
contain some entries indicating that sudo was actually run. Of course
the sudoers file then denied them access and sent the sysadmin an
email.

Here's a journal extract:

Feb 09 11:34:58 hostname sudo[24453]: pam_unix(sudo:auth): authentication failure; logname=xxxx uid=12113 euid=0 tty=/dev/pts/1 ruser=xxxx rhost=  user=xxxx
Feb 09 11:34:58 hostname sudo[24453]: pam_sss(sudo:auth): authentication success; logname=xxxx uid=12113 euid=0 tty=/dev/pts/1 ruser=xxxx rhost= user=xxxx
Feb 09 11:34:58 hostname audit[24453]: <audit-1100> pid=24453 uid=12113 auid=12113 ses=54 msg='op=PAM:authentication grantors=pam_succeed_if,pam_sss acct="xxxx" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
Feb 09 11:34:58 hostname sudo[24453]: pam_sss(sudo:account): Access denied for user xxxx: 6 (Permission denied)
Feb 09 11:34:58 hostname audit[24453]: <audit-1101> pid=24453 uid=12113 auid=12113 ses=54 msg='op=PAM:accounting grantors=? acct="xxxx" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=failed'
Feb 09 11:35:05 hostname sudo[24453]: pam_sss(sudo:auth): authentication success; logname=xxxx uid=12113 euid=0 tty=/dev/pts/1 ruser=xxxx rhost= user=xxxx
Feb 09 11:35:05 hostname audit[24453]: <audit-1100> pid=24453 uid=12113 auid=12113 ses=54 msg='op=PAM:authentication grantors=pam_succeed_if,pam_sss acct="xxxx" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
Feb 09 11:35:05 hostname sudo[24453]: pam_sss(sudo:account): Access denied for user xxxx: 6 (Permission denied)
Feb 09 11:35:05 hostname audit[24453]: <audit-1101> pid=24453 uid=12113 auid=12113 ses=54 msg='op=PAM:accounting grantors=? acct="xxxx" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=failed'
Feb 09 11:35:08 hostname sudo[24453]: pam_unix(sudo:auth): auth could not identify password for [xxxx]
Feb 09 11:35:08 hostname sudo[24453]: pam_sss(sudo:auth): authentication failure; logname=xxxx uid=12113 euid=0 tty=/dev/pts/1 ruser=xxxx rhost= user=xxxx
Feb 09 11:35:08 hostname sudo[24453]: pam_sss(sudo:auth): received for user xxxx: 7 (Authentication failure)
Feb 09 11:35:08 hostname audit[24453]: <audit-1100> pid=24453 uid=12113 auid=12113 ses=54 msg='op=PAM:authentication grantors=? acct="xxxx" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=failed'
Feb 09 11:35:08 hostname audit[24453]: <audit-1123> pid=24453 uid=12113 auid=12113 ses=54 msg='cwd=2F6175xxx cmd=617074xxx terminal=pts/1 res=failed'
Feb 09 11:35:08 hostname audit[24453]: <audit-1123> pid=24453 uid=12113 auid=12113 ses=54 msg='cwd=2F6175xxx cmd=617074xxx terminal=pts/1 res=failed'
Feb 09 11:35:08 hostname sudo[24453]:  xxxx : user NOT in sudoers ; TTY=pts/1 ; PWD=/xxxxx ; USER=root ; COMMAND=xxxxx
Feb 09 11:35:09 hostname sSMTP[24463]: Sent mail for root at cs.ox.ac.uk (221 mail.cs.ox.ac.uk closing connection) uid=0 xxxx=root outbytes=607

What this seems to say:

 1. pam_unix failed the password (expected because passwords are managed by IPA)
 2. pam_sss accepted the password
 3. pam_sss denied access to sudo:account

 Presumably sudo asked the user to try again and they re-typed the password

 4. pam_sss accepted the password
 5. pam_sss denied access to sudo:account

 6. Three seconds later pam_unix said it "could not identify password" (?)
 7. This time pam_sss failed the password and returned 7 (Authentication failure)
 8. sudo ran anyway!

I can't duplicate this behaviour myself but looking through the logs in
our computer lab there are a few of these.  See for instance the following
which appears to deny access three times and then just run it anyway:

Feb 02 10:31:12 hostname2 sudo[24468]: pam_unix(sudo:auth): authentication failure; logname=xyyx uid=12106 euid=0 tty=/dev/pts/1 ruser=xyyx rhost=  user=xyyx
Feb 02 10:31:14 hostname2 sudo[24468]: pam_sss(sudo:auth): authentication success; logname=xyyx uid=12106 euid=0 tty=/dev/pts/1 ruser=xyyx rhost= user=xyyx
Feb 02 10:31:14 hostname2 audit[24468]: <audit-1100> pid=24468 uid=12106 auid=12106 ses=39 msg='op=PAM:authentication grantors=pam_succeed_if,pam_sss acct="xyyx" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
Feb 02 10:31:15 hostname2 sudo[24468]: pam_sss(sudo:account): Access denied for user xyyx: 6 (Permission denied)
Feb 02 10:31:15 hostname2 audit[24468]: <audit-1101> pid=24468 uid=12106 auid=12106 ses=39 msg='op=PAM:accounting grantors=? acct="xyyx" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=failed'
Feb 02 10:31:26 hostname2 sudo[24468]: pam_sss(sudo:auth): authentication success; logname=xyyx uid=12106 euid=0 tty=/dev/pts/1 ruser=xyyx rhost= user=xyyx
Feb 02 10:31:26 hostname2 audit[24468]: <audit-1100> pid=24468 uid=12106 auid=12106 ses=39 msg='op=PAM:authentication grantors=pam_succeed_if,pam_sss acct="xyyx" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
Feb 02 10:31:26 hostname2 sudo[24468]: pam_sss(sudo:account): Access denied for user xyyx: 6 (Permission denied)
Feb 02 10:31:26 hostname2 audit[24468]: <audit-1101> pid=24468 uid=12106 auid=12106 ses=39 msg='op=PAM:accounting grantors=? acct="xyyx" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=failed'
Feb 02 10:31:46 hostname2 sudo[24468]: pam_sss(sudo:auth): authentication success; logname=xyyx uid=12106 euid=0 tty=/dev/pts/1 ruser=xyyx rhost= user=xyyx
Feb 02 10:31:46 hostname2 audit[24468]: <audit-1100> pid=24468 uid=12106 auid=12106 ses=39 msg='op=PAM:authentication grantors=pam_succeed_if,pam_sss acct="xyyx" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
Feb 02 10:31:46 hostname2 sudo[24468]: pam_sss(sudo:account): Access denied for user xyyx: 6 (Permission denied)
Feb 02 10:31:46 hostname2 audit[24468]: <audit-1101> pid=24468 uid=12106 auid=12106 ses=39 msg='op=PAM:accounting grantors=? acct="xyyx" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=failed'
Feb 02 10:31:46 hostname2 audit[24468]: <audit-1123> pid=24468 uid=12106 auid=12106 ses=39 msg='cwd="/xxxx" cmd=6E616Exxx terminal=pts/1 res=failed'
Feb 02 10:31:46 hostname2 audit[24468]: <audit-1123> pid=24468 uid=12106 auid=12106 ses=39 msg='cwd="/xxxx" cmd=6E616Exxx terminal=pts/1 res=failed'
Feb 02 10:31:46 hostname2 sudo[24468]: xyyx : user NOT in sudoers ; TTY=pts/1 ; PWD=/xxxxxx ; USER=root ; COMMAND=xxxxxx
Feb 02 10:31:47 hostname2 sSMTP[24489]: Sent mail for root at cs.ox.ac.uk (221 mail.cs.ox.ac.uk closing connection) uid=0 username=root outbytes=589

Now since sudoers denies access, this isn't necessarily a security
problem for us.  But it's rather puzzling and it does mean a trickle
of incoming emails to the sysadmin.

The clients here are Fedora 22 with pam 1.1.8, sssd 1.13.3 and sudo 1.8.15.
The IPA servers are RHEL 6 with ipa-server 3.0.0.

Ian Collier.