This service will be undergoing maintenance at 00:00 UTC, 2016-08-01. It is expected to last about 1 hours

Bug 754001

Summary: ssh_selinux_change_context: setcon failed with Invalid argument (openssh, krb5)
Product: [Fedora] Fedora Reporter: Bojan Smojver <bojan>
Component: krb5Assignee: Nalin Dahyabhai <nalin>
Status: CLOSED WONTFIX QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 16CC: andrew.kavalov, dwalsh, eddie, edgar.hoch, eparis, mike.cloaked, nalin, number.cruncher, philipp, sgallagh, ssorce, tkil-rh
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: krb5-1.9.2-3.fc16 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-02-13 21:54:50 EST Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Attachments:
Description Flags
fix various trivial issues with ssh_selinux_change_context none

Description Bojan Smojver 2011-11-14 23:42:35 EST
Description of problem:
Occasionally, I get this in the logs on the server side when I attempt to login:
-------------------
ssh_selinux_change_context: setcon failed with Invalid argument
-------------------

Kerberos authentication is enabled.

Audit log has:
-------------------
type=AVC msg=audit(1321329330.434:15353): avc:  denied  { create } for  pid=20609 comm="sshd" name="agent.20609" 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(1321329330.434:15354): avc:  denied  { rmdir } for  pid=20609 comm="sshd" name="ssh-ewOlW20609" dev=dm-0 ino=266955 scontext=system_u:system_r:sshd_t:s0-s0:c0.c1023 tcontext=system_u:object_r:krb5_host_rcache_t:s0 tclass=dir
-------------------

This translates to:
-------------------
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;
-------------------

Version-Release number of selected component (if applicable):
selinux-policy-3.10.0-55.fc16.noarch

How reproducible:
Sometimes.

Steps to Reproduce:
1. ssh <server> -Al root 'rsync -avz <client>:/path /server/path'
  
Actual results:
Client prints:
---------------
Permission denied, please try again.
Permission denied, please try again.
Permission denied (publickey,gssapi-keyex,gssapi-with-mic,password).
rsync: connection unexpectedly closed (0 bytes received so far) [Receiver]
rsync error: unexplained error (code 255) at io.c(601) [Receiver=3.0.8]
---------------

Server gets previous mentioned message in the /var/log/secure.

Expected results:
Worked OK in F-14 at least.

Additional info:
Comment 1 Miroslav Grepl 2011-11-15 05:37:13 EST
Could you execute

# semanage permissive -a sshd

on the server and re-test it. After that

# ausearch -m avc -ts recent
Comment 2 Daniel Walsh 2011-11-15 09:22:05 EST
Nalin and Simo, Any idea why kerberos libraries creating a sock_file?
Comment 3 Simo Sorce 2011-11-15 09:51:22 EST
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.
Comment 4 Daniel Walsh 2011-11-15 10:50:04 EST
Is it creating this in /var/cache/krb5rcache?  Or is this being caused by a setfscreatecon call?
Comment 5 Nalin Dahyabhai 2011-11-15 11:08:57 EST
No, this one's mine.  If there's no previously-set creation context, we're not resetting it after we expunge the replay cache.
Comment 6 Bojan Smojver 2011-11-15 16:18:02 EST
So, you still want me to run those commands or you have everything you need?
Comment 7 Nalin Dahyabhai 2011-11-15 16:34:38 EST
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.
Comment 8 Bojan Smojver 2011-11-15 17:41:49 EST
(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.
Comment 9 Bojan Smojver 2011-11-15 17:51:29 EST
(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.
Comment 10 Daniel Walsh 2011-11-16 09:03:01 EST
Should have been

# semanage permissive -a sshd_t

But you don't need to do this.  Nalin knows what to fix.
Comment 11 Bojan Smojver 2011-11-17 19:52:01 EST
(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. ;-)
Comment 12 Fedora Update System 2011-11-21 13:43:42 EST
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
Comment 13 Fedora Update System 2011-11-21 13:43:51 EST
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
Comment 14 Mike C 2011-11-25 10:15:22 EST
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?
Comment 15 Mike C 2011-11-25 10:20:42 EST
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?
Comment 16 Mike C 2011-11-25 10:24:37 EST
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.
Comment 17 Mike C 2011-11-25 10:26:06 EST
openssh-5.8p2-22.fc16.x86_64 continues to give the same log messages in /var/log/secure
Comment 18 Bojan Smojver 2011-11-25 17:32:05 EST
Yes, context errors are still there for me too (logwatch has 11 today). I did not see permission denied though (yet?).
Comment 19 NM 2011-11-28 00:26:34 EST
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
Comment 20 Nalin Dahyabhai 2011-11-28 16:53:47 EST
(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.
Comment 21 Bojan Smojver 2011-11-30 02:57:59 EST
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.
Comment 22 Daniel Walsh 2011-11-30 13:15:19 EST
What kerberos library do you have?

krb5-1.9.2-1.fc16 ?
Comment 23 Nalin Dahyabhai 2011-11-30 15:26:30 EST
*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.
Comment 24 Fedora Update System 2011-12-12 17:04:35 EST
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.
Comment 25 Tony Foiani 2011-12-19 14:24:43 EST
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?
Comment 26 Nalin Dahyabhai 2011-12-19 14:42:42 EST
(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.
Comment 27 Tony Foiani 2011-12-19 16:32:07 EST
(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!
Comment 28 Nalin Dahyabhai 2011-12-19 16:57:55 EST
(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!
Comment 29 Bojan Smojver 2011-12-19 17:14:06 EST
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.
Comment 30 Tony Foiani 2011-12-19 18:14:59 EST
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.
Comment 31 Tony Foiani 2011-12-19 18:23:17 EST
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
Comment 32 Tony Foiani 2011-12-20 13:40:38 EST
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.
Comment 33 Tony Foiani 2011-12-20 13:41:24 EST
(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.
Comment 34 Fedora Update System 2012-01-31 16:54:56 EST
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.
Comment 35 Fedora End Of Life 2013-02-13 21:54:56 EST
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.