Bug 754001

Could you execute

# semanage permissive -a sshd

on the server and re-test it. After that

# ausearch -m avc -ts recent

Nalin and Simo, Any idea why kerberos libraries creating a sock_file?

If I read it correctly it seem like sshd is creating the ssh-agent socket ?
Not sure it really has anything to do with libkrb5.

Is it creating this in /var/cache/krb5rcache?  Or is this being caused by a setfscreatecon call?

No, this one's mine.  If there's no previously-set creation context, we're not resetting it after we expunge the replay cache.

So, you still want me to run those commands or you have everything you need?

The first would still be useful to confirm.

If you can, please check if the krb5-1.9.2-1.fc16 build at https://koji.fedoraproject.org/koji/buildinfo?buildID=274228 prevents this from happening.  After you update the package, you'll want to run "restorecon -v /var/tmp/host_0" to get the system back to a sane state and restart sshd to make sure it's using the updated library.

(In reply to comment #1)
> Could you execute
> 
> # semanage permissive -a sshd
> 
> on the server and re-test it.

Got this:
--------------------
[root@beauty ~]# semanage permissive -a sshd
libsepol.print_missing_requirements: permissive_sshd's global requirements were not met: type/attribute sshd (No such file or directory).
libsemanage.semanage_link_sandbox: Link packages failed (No such file or directory).
/usr/sbin/semanage: Could not commit semanage transaction
--------------------

Anyway, I installed the 1.9.2 packages on both client and server and will retest, after restarting sshd.

(In reply to comment #8)
 
> Anyway, I installed the 1.9.2 packages on both client and server and will
> retest, after restarting sshd.

Cannot immediately replicate it, but then again, it was always an intermittent problem, so it may take a while to resurface.

Will keep you posted.

Should have been

# semanage permissive -a sshd_t

But you don't need to do this.  Nalin knows what to fix.

(In reply to comment #9)
 
> Will keep you posted.

Still haven't had a failure with the new packages. Of course, now that I said it twice, I'm sure it will fail the next time I run it. ;-)

krb5-1.9.2-1.fc15 has been submitted as an update for Fedora 15.
https://admin.fedoraproject.org/updates/krb5-1.9.2-1.fc15

krb5-1.9.2-1.fc16 has been submitted as an update for Fedora 16.
https://admin.fedoraproject.org/updates/krb5-1.9.2-1.fc16

I am also running x86_64 f16 - and I do not have krb5 installed at all!

In my logwatch I get every day:
**Unmatched Entries**
 ssh_selinux_change_context: setcon failed with Invalid argument : 2 time(s)

In /var/log/messages I get always a pair of lines where this occurs:

Nov 24 20:24:48 home1 sshd[19038]: pam_unix(sshd:session): session opened for user mike by (uid=0)
Nov 24 20:24:48 home1 sshd[19041]: ssh_selinux_change_context: setcon failed with Invalid argument

Since I don't have krb5 installed presumably this is not related to the krb5 package?  Or am I naive?

I have just updated openssh to openssh-5.8p2-22.fc16.x86_64 from updates testing and will see if this continues to give the same log messages.

I also have selinux policy selinux-policy-3.10.0-56.fc16.noarch and I know there are newer versions in updates-testing but don't know if the newer versions have any fixes related to this bug?

I don't know if this is relevant or not but I start the ssh-agent with a shell script containing:

#!/bin/bash
#

  # Call this from window manager startup to initialize the 
  # agent with passphrase
  #
  . ${HOME}/etc/profile.d/ssh-agent-start.sh

  /usr/bin/ssh-add

where the file ssh-agent-start.sh contains:


#!/bin/bash
#

agent="/usr/bin/ssh-agent"
info=${HOME}/.ssh-agent-info
#
#askpass="/usr/bin/ksshaskpass"
#
askpass="/usr/libexec/openssh/ssh-askpass"


  start_agent () {
    eval "$agent |egrep -v 'echo Agent pid' > $info"
    . $info
    SSH_ASKPASS=$askpass
    echo "SSH_ASKPASS=$askpass ; export SSH_ASKPASS;" >> $info
  }


  if [ -f $info ] ; then
     . $info > /dev/null 2>&1
  fi

  if [ -x $agent ] ; then
    if [ -z "${SSH_AUTH_SOCK}" ] ; then
        ## NOTE: a root login will kill *all* users' ssh-agents
        #echo "no SSH_AUTH_SOCK - starting"
        killall ssh-agent
        start_agent
    else
       # Gnome sets SSH_AUTH_SOCK but unlike ssh-agent - it does
       # not set SSH_AGENT_PID in of ssh-agent - so we use this
       # Should probably check if I am the owner of the process too ...
       if [ -z "$SSH_AGENT_PID" ] ; then
          #echo "no SSH_AGENT_PID - starting"
          start_agent
       else
          pid=${SSH_AGENT_PID}
          #runningpid=$(ps -p $pid -o pid= | sed  -e 's# ##')
          running=$(ps -p $pid -l|egrep ssh-agent)
          if [ x"$running" = "x" ] ; then
          #if  [ x"$runningpid" = "x" -o x"$pid" != x"$runningpid" ] ; then
            # not running
            #echo "no running agent on pid $pid"
            start_agent

          else
            if [ -f $info ] ; then
              . $info
            else
              #echo "Missing $info .. starting agent"
              start_agent
            fi
          fi
       fi
    fi
  fi

I suppose running this may be my culprit - but worth knowing if there is a bug elsewhere?

Correction to comment #14 - the two lines appear in /var/log/secure - not the messages file.  I can also confirm that the lines appear as soon as an incoming ssh call is made to the sshd server.

openssh-5.8p2-22.fc16.x86_64 continues to give the same log messages in /var/log/secure

Yes, context errors are still there for me too (logwatch has 11 today). I did not see permission denied though (yet?).

Same here: 

Nov 27 23:20:06 a1 sshd[3474]: Accepted publickey for NM from 10.64.6.141 port 43734 ssh2
Nov 27 23:20:06 a1 sshd[3476]: ssh_selinux_change_context: setcon failed with Invalid argument

NM

(In reply to comment #14)
> I am also running x86_64 f16 - and I do not have krb5 installed at all!
> 
> In my logwatch I get every day:
> **Unmatched Entries**
>  ssh_selinux_change_context: setcon failed with Invalid argument : 2 time(s)
> 
> In /var/log/messages I get always a pair of lines where this occurs:
> 
> Nov 24 20:24:48 home1 sshd[19038]: pam_unix(sshd:session): session opened for
> user mike by (uid=0)
> Nov 24 20:24:48 home1 sshd[19041]: ssh_selinux_change_context: setcon failed
> with Invalid argument
> 
> Since I don't have krb5 installed presumably this is not related to the krb5
> package?  Or am I naive?

It shouldn't be related -- libkrb5's not creating any files, so it can't be setting the file creation context for a replay cache and then subsequently failing to reset it.  The logged AVC errors indicated that that's what was happening, and it should be fixed by the update.

The error message that SSH is printing seems to be unrelated -- the only reference to that function I see is a call to set the type portion of the execution context to either sshd_sftpd_t or sftpd_t, both of which appear to be hard-wired under the assumption that they are defined by the currently-loaded SELinux policy.  If you run with debug level 3 (which I think means running sshd with -d -d -d, at least), sshd should log which context it's attempting to set.  If it logs a type which doesn't exist, then that'll confirm a mismatch between sshd and the policy.  If not, we'll at least have a better idea of what's going on.

Of course, I have to eat my words. Again. Just happened:
-------------------
Nov 30 18:48:59 <server> sshd[30207]: error: bind: Permission denied
-------------------

The authentication was with public key.

Got two denials:
-------------------
type=AVC msg=audit(1322639339.510:20660): avc:  denied  { create } for  pid=30207 comm="sshd" name="agent.30207" scontext=system_u:system_r:sshd_t:s0-s0:c0.c1023 tcontext=system_u:object_r:krb5_host_rcache_t:s0 tclass=sock_file
type=AVC msg=audit(1322639339.510:20661): avc:  denied  { rmdir } for  pid=30207 comm="sshd" name="ssh-nXnNm30207" dev=dm-0 ino=267280 scontext=system_u:system_r:sshd_t:s0-s0:c0.c1023 tcontext=system_u:object_r:krb5_host_rcache_t:s0 tclass=dir
-------------------

Which is:
-------------------
require {
	type krb5_host_rcache_t;
	type sshd_t;
	class sock_file create;
	class dir rmdir;
}

#============= sshd_t ==============
allow sshd_t krb5_host_rcache_t:dir rmdir;
allow sshd_t krb5_host_rcache_t:sock_file create
-------------------

This is with selinux-policy-targeted-3.10.0-61.fc16.noarch (just updated an hour ago or so).

Subsequent attempt to do the same thing worked.

What kerberos library do you have?

krb5-1.9.2-1.fc16 ?

*facepalm*  The patch change didn't actually have the desired effect.  I've revised it again and double-checked by comparing strace runs with before/after versions, so the creation context should be reset correctly this time.

krb5-1.9.2-4.fc16 has been pushed to the Fedora 16 stable repository.  If problems still persist, please make note of it in this bug report.

I'm still seeing this issue on my Fedora 16 x86-64 system, trying to serve svn+ssh.  (It's a fresh install, but the svn directory was copied from the previous F15 install, and probably started its life on a PPC F12 install...)

I have the krb5 libs installed, but they are not used by sshd (they're commented out of the configuration).

I'm not seeing any obvious AVC notices, though.

Here's the relevant audit entries:

time->Mon Dec 19 10:52:08 2011
type=LOGIN msg=audit(1324317128.538:38586): login pid=29477 uid=0 old auid=4294967295 new auid=991 old ses=4294967295 new ses=228
----
time->Mon Dec 19 10:52:08 2011
type=USER_ROLE_CHANGE msg=audit(1324317128.674:38587): user pid=29477 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='pam: default-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 selected-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023: exe="/usr/sbin/sshd" hostname=? addr=? terminal=? res=success'
----
time->Mon Dec 19 10:52:08 2011
type=USER_START msg=audit(1324317128.876:38588): user pid=29477 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=PAM:session_open acct="svn" exe="/usr/sbin/sshd" hostname=pelowitzllc.com addr=75.150.19.17 terminal=ssh res=success'
----
time->Mon Dec 19 10:52:08 2011
type=CRYPTO_KEY_USER msg=audit(1324317128.877:38589): user pid=29477 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=destroy kind=session fp=? direction=both spid=29477 suid=0 rport=2016 laddr=192.168.1.12 lport=22 : exe="/usr/sbin/sshd" hostname=? addr=75.150.19.17 terminal=? res=success'
----
time->Mon Dec 19 10:52:08 2011
type=CRYPTO_KEY_USER msg=audit(1324317128.877:38590): user pid=29480 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=destroy kind=server fp=3c:f9:e2:5e:4b:d1:f0:13:47:4a:01:18:2f:e2:a9:f0 direction=? spid=29480 suid=0 : exe="/usr/sbin/sshd" hostname=? addr=75.150.19.17 terminal=? res=success'
----
time->Mon Dec 19 10:52:08 2011
type=CRYPTO_KEY_USER msg=audit(1324317128.878:38591): user pid=29480 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=destroy kind=server fp=af:00:5e:a5:f1:3c:9e:85:83:ed:4b:6a:dd:e5:7d:d5 direction=? spid=29480 suid=0 : exe="/usr/sbin/sshd" hostname=? addr=75.150.19.17 terminal=? res=success'
----
time->Mon Dec 19 10:52:08 2011
type=CRED_ACQ msg=audit(1324317128.903:38592): user pid=29480 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=PAM:setcred acct="svn" exe="/usr/sbin/sshd" hostname=pelowitzllc.com addr=75.150.19.17 terminal=ssh res=success'
----
time->Mon Dec 19 10:52:09 2011
type=USER_LOGIN msg=audit(1324317129.245:38593): user pid=29477 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=login id=991 exe="/usr/sbin/sshd" hostname=pelowitzllc.com addr=75.150.19.17 terminal=ssh res=success'
----
time->Mon Dec 19 10:52:09 2011
type=USER_START msg=audit(1324317129.294:38594): user pid=29477 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=login id=991 exe="/usr/sbin/sshd" hostname=pelowitzllc.com addr=75.150.19.17 terminal=ssh res=success'
----
time->Mon Dec 19 10:52:09 2011
type=USER_END msg=audit(1324317129.898:38595): user pid=29477 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=login id=991 exe="/usr/sbin/sshd" hostname=pelowitzllc.com addr=75.150.19.17 terminal=ssh res=success'
----
time->Mon Dec 19 10:52:09 2011
type=USER_LOGOUT msg=audit(1324317129.923:38596): user pid=29477 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=login id=991 exe="/usr/sbin/sshd" hostname=pelowitzllc.com addr=75.150.19.17 terminal=ssh res=success'
----
time->Mon Dec 19 10:52:09 2011
type=CRYPTO_KEY_USER msg=audit(1324317129.923:38597): user pid=29477 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=destroy kind=session fp=? direction=both spid=29480 suid=991 rport=2016 laddr=192.168.1.12 lport=22 : exe="/usr/sbin/sshd" hostname=? addr=75.150.19.17 terminal=? res=success'
----
time->Mon Dec 19 10:52:10 2011
type=USER_END msg=audit(1324317130.117:38598): user pid=29477 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=PAM:session_close acct="svn" exe="/usr/sbin/sshd" hostname=pelowitzllc.com addr=75.150.19.17 terminal=ssh res=success'
----
time->Mon Dec 19 10:52:10 2011
type=CRED_DISP msg=audit(1324317130.143:38599): user pid=29477 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=PAM:setcred acct="svn" exe="/usr/sbin/sshd" hostname=pelowitzllc.com addr=75.150.19.17 terminal=ssh res=success'
----
time->Mon Dec 19 10:52:10 2011
type=CRYPTO_KEY_USER msg=audit(1324317130.144:38600): user pid=29477 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=destroy kind=server fp=3c:f9:e2:5e:4b:d1:f0:13:47:4a:01:18:2f:e2:a9:f0 direction=? spid=29477 suid=0 : exe="/usr/sbin/sshd" hostname=? addr=75.150.19.17 terminal=? res=success'
----
time->Mon Dec 19 10:52:10 2011
type=CRYPTO_KEY_USER msg=audit(1324317130.145:38601): user pid=29477 uid=0 auid=991 ses=228 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=destroy kind=server fp=af:00:5e:a5:f1:3c:9e:85:83:ed:4b:6a:dd:e5:7d:d5 direction=? spid=29477 suid=0 : exe="/usr/sbin/sshd" hostname=? addr=75.150.19.17 terminal=? res=success'

And the errors in /var/log/secure:

Dec 19 10:52:08 dell-f16 sshd[29477]: Accepted publickey for svn from 75.150.19.17 port 2016 ssh2
Dec 19 10:52:08 dell-f16 sshd[29477]: pam_unix(sshd:session): session opened for user svn by (uid=0)
Dec 19 10:52:08 dell-f16 sshd[29480]: ssh_selinux_change_context: setcon failed with Invalid argument
Dec 19 10:52:09 dell-f16 sshd[29477]: pam_unix(sshd:session): session closed for user svn

Versions:

krb5-libs.x86_64                  1.9.2-4.fc16            @updates   
krb5-workstation.x86_64           1.9.2-4.fc16            @updates   
openssh-server.x86_64             5.8p2-23.fc16           @updates   
pam_krb5.x86_64                   2.3.13-1.fc16           @anaconda-0

Anything else I can do to help track this down?

(In reply to comment #25)
> I'm still seeing this issue on my Fedora 16 x86-64 system, trying to serve
> svn+ssh.  (It's a fresh install, but the svn directory was copied from the
> previous F15 install, and probably started its life on a PPC F12 install...)
> 
> I have the krb5 libs installed, but they are not used by sshd (they're
> commented out of the configuration).

If you're using pubkey authentication, then there's no call to the bits of krb5-libs that we're fixing here, but there could be other things going on.

> Anything else I can do to help track this down?

Can you run sshd with debug level set to 3 or higher (with -d -d -d on its command line)?  At that point sshd should start logging which context it's attempting to pass to setcon(), which will help us figure out how it got there.

(In reply to comment #26)
> If you're using pubkey authentication, then there's no call to the bits of
> krb5-libs that we're fixing here, but there could be other things going on.

Right.  I was posting here because it looked like the same problem, and others have already posted "not using Kerberos but still having the problem" (comment #14, comment #19).

I'd worry about hijacking the ticket, but at this point I wonder if the problem is in the openssh package and not krb5 at all?

> Can you run sshd with debug level set to 3 or higher (with -d -d -d on its
> command line)?  At that point sshd should start logging which context it's
> attempting to pass to setcon(), which will help us figure out how it got there.

Made the change, now to wait for the bug to happen again.

Thanks!

(In reply to comment #27)
> (In reply to comment #26)
> > If you're using pubkey authentication, then there's no call to the bits of
> > krb5-libs that we're fixing here, but there could be other things going on.
> 
> Right.  I was posting here because it looked like the same problem, and others
> have already posted "not using Kerberos but still having the problem" (comment
> #14, comment #19).
> 
> I'd worry about hijacking the ticket, but at this point I wonder if the problem
> is in the openssh package and not krb5 at all?

Oh, there was definitely a problem in the patch in the krb5 package.  At the moment I'm just trying to figure out if there's an unexpected call being made into the libraries or if there's a separate bug that just happens to result in the same error being logged.  That you're still seeing it with the latest version of the package suggests to me that there's a second bug, and hopefully the debug output will help us determine for certain.

> > Can you run sshd with debug level set to 3 or higher (with -d -d -d on its
> > command line)?  At that point sshd should start logging which context it's
> > attempting to pass to setcon(), which will help us figure out how it got there.
> 
> Made the change, now to wait for the bug to happen again.

Thanks!

My logwatch also says (in the SSHD section):

ssh_selinux_change_context: setcon failed with Invalid argument : 9 time(s)

That is with the latest krb5 packages. So, yeah, looks like there is a second bug in OpenSSH.

And it looks like there might be a problem with the debugging code.  :)

==> messages <==
Dec 19 16:12:55 dell-f16 sshd[455]: debug1: do_cleanup
Dec 19 16:12:55 dell-f16 sshd[455]: debug1: PAM: cleanup
Dec 19 16:12:55 dell-f16 sshd[455]: debug1: PAM: closing session
Dec 19 16:12:55 dell-f16 sshd[455]: debug1: PAM: deleting credentials
Dec 19 16:12:55 dell-f16 sshd[455]: debug3: PAM: sshpam_thread_cleanup entering
Dec 19 16:12:55 dell-f16 systemd[1]: sshd.service: main process exited, code=exited, status=255

==> audit/audit.log <==
type=USER_START msg=audit(1324336375.824:39085): user pid=455 uid=0 auid=991 ses=244 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=login id=991 exe="/usr/sbin/sshd" hostname=192.168.1.27 addr=192.168.1.27 terminal=ssh res=success'

==> messages <==
Dec 19 16:12:55 dell-f16 systemd[1]: Unit sshd.service entered failed state.

But it looks like it did find the offending call (before dying for whatever reason):

Dec 19 16:12:55 dell-f16 sshd[455]: debug3: ssh_selinux_setup_variables: setting execution context
Dec 19 16:12:55 dell-f16 sshd[455]: debug3: ssh_selinux_change_context: setting context from 'system_u:system_r:sshd_t:s0-s0:c0.c1023' to 'system_u:system_r:sshd_sftpd_t:s0-s0:c0.c1023'
Dec 19 16:12:55 dell-f16 sshd[455]: ssh_selinux_change_context: setcon failed with Invalid argument
Dec 19 16:12:55 dell-f16 sshd[455]: debug1: permanently_set_uid: 991/988

Created attachment 548922 [details]
fix various trivial issues with ssh_selinux_change_context

This patch does a couple of different things.  (My apologies for not providing separate patches, which would have been more correct, but 'git' was annoying me last night, and I really wanted to get this change up here so others could decide whether or not to apply it...)

1. bug fix: 'oldctx' was freed with "xfree" instead of "freecon".

2. bug fix: 'oldctx' was not freed if we exited early due to errors.

3. output change: output old and new contexts when the "setcon" fails.  This might make the log too verbose, and I don't know if exposing context strings is considered a security issue, but the advantage is that we don't need to have reporters iterate on the "restart with debugging and hope it happens again".

4. style: remove space between function name and following open paren.

5. style: break compound conditionals at highest possible level.

6. style: try to use vertical whitespace consistently.

7. style: if we're going to break a debug/printf anyway, put format string on first line and values on the second.

(In reply to comment #32)
> Created attachment 548922 [details]
> fix various trivial issues with ssh_selinux_change_context

Having said all that, should we instead just use the functions in <selinux/context.h>?

Anyway.

krb5-1.9.2-4.fc15 has been pushed to the Fedora 15 stable repository.  If problems still persist, please make note of it in this bug report.

Fedora 16 changed to end-of-life (EOL) status on 2013-02-12. Fedora 16 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.