Bug 1607082 - ssh-delegated credentials not cached sssd-kcm
Summary: ssh-delegated credentials not cached sssd-kcm
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: sssd
Version: 30
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Michal Zidek
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 1670457 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-07-21 17:38 UTC by James
Modified: 2020-03-03 16:04 UTC (History)
13 users (show)

Fixed In Version: sssd-2.1.0-2.fc30.x86_64
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-05-03 21:53:21 UTC
Type: Bug


Attachments (Terms of Use)

Description James 2018-07-21 17:38:36 UTC
Description of problem:
When using sssd-kcm, Kerberos credentials forwarded over SSH are not cached. This works OK when using the kernel keyring.

A worked example. Connecting to 'kowalski' from 'iseult'. First let's purge the cache on kowalski:


[james@iseult ~]$ ssh kowalski
Last login: Sat Jul 21 18:33:52 2018 from 192.168.0.146
[james@kowalski ~]$ klist
klist: Credentials cache 'KCM:1402400001' not found
[james@kowalski ~]$ su james
First Factor: 
Second Factor: 
[james@kowalski ~]$ klist
Ticket cache: KCM:1402400001:84894
Default principal: james@CB.ETTLE

Valid starting     Expires            Service principal
21/07/18 18:34:22  22/07/18 18:34:22  krbtgt/CB.ETTLE@CB.ETTLE
[james@kowalski ~]$ kdestroy
[james@kowalski ~]$ klist
klist: Credentials cache 'KCM:1402400001' not found


Now, back on iseult the credentials are:


[james@iseult ~]$ klist -A
Ticket cache: KCM:1402400001:38015
Default principal: james@CB.ETTLE

Valid starting     Expires            Service principal
21/07/18 16:46:29  22/07/18 15:24:21  host/kowalski.cb.ettle@CB.ETTLE
21/07/18 15:24:21  22/07/18 15:24:21  krbtgt/CB.ETTLE@CB.ETTLE
21/07/18 16:37:07  22/07/18 15:24:21  host/buck.cb.ettle@CB.ETTLE
21/07/18 18:15:13  22/07/18 15:24:21  host/skipper.cb.ettle@CB.ETTLE


Let's try logging into kowalski again with delegation:


[james@iseult ~]$ ssh -K kowalski
Last login: Sat Jul 21 18:34:23 2018
[james@kowalski ~]$ klist
klist: Credentials cache 'KCM:1402400001' not found


I'd expect a new ccache here, like with kernel keyring. I have to 'su james' and re-authenticate to get tickets.

Version-Release number of selected component (if applicable):
sssd-kcm-1.16.2-4.fc28.x86_64
openssh-7.7p1-5.fc28.x86_64

Comment 1 Jason Tibbitts 2018-11-17 23:57:08 UTC
I was not using KCM in F28 but now I'm testing F29 for deployment and the KCM is default there.  Immediately I'm seeing what I think is the problem described above: ssh-delegated credentials just don't go into the KCM at all.

So I install a fresh F29 machine and give it a host principal.  Then I ssh into it:

ἐπιθυμία:~❯ ssh -vvv -x ld00
[...]
debug1: Offering GSSAPI proposal: gss-gex-sha1-toWM5Slw5Ew8Mqkay+al2g==,gss-group14-sha1-toWM5Slw5Ew8Mqkay+al2g==,gss-gex-sha1-eipGX3TCiQSrx573bT1o1Q==,gss-group14-sha1-eipGX3TCiQSrx573bT1o1Q==
[...]
debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
debug3: start over, passed a different list publickey,gssapi-keyex,gssapi-with-mic,password
debug3: preferred gssapi-keyex,gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_lookup gssapi-keyex
debug3: remaining preferred: gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-keyex
debug1: Next authentication method: gssapi-keyex
debug1: No valid Key exchange context
debug2: we did not send a packet, disable method
debug3: authmethod_lookup gssapi-with-mic
debug3: remaining preferred: publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-with-mic
debug1: Next authentication method: gssapi-with-mic
debug3: send packet: type 50
debug2: we sent a gssapi-with-mic packet, wait for reply
debug3: receive packet: type 60
debug1: Delegating credentials
debug3: send packet: type 61
debug3: receive packet: type 61
debug1: Delegating credentials
debug3: send packet: type 66
debug3: receive packet: type 52
debug1: Authentication succeeded (gssapi-with-mic).
Authenticated to ld00 ([172.21.84.191]:22).
[...]
Last login: Sat Nov 17 09:22:30 2018 from 172.21.86.85
Could not chdir to home directory /home/tibbs: Permission denied
[tibbs@ld00]/% klist
klist: Credentials cache 'KCM:7225' not found
[tibbs@ld00]/%

I can at this point do kinit just fine, though, and that does let me see my home directory and do kerberos stuff as usual.  

If I log out and (as root on another login) simply comment out those lines from /etc/krb5.conf.d/kcm_default_ccache while changing nothing else, principal forwarding works:

ἐπιθυμία:~❯ ssh -vvv -x ld00
[...]
debug1: Offering GSSAPI proposal: gss-gex-sha1-toWM5Slw5Ew8Mqkay+al2g==,gss-group14-sha1-toWM5Slw5Ew8Mqkay+al2g==,gss-gex-sha1-eipGX3TCiQSrx573bT1o1Q==,gss-group14-sha1-eipGX3TCiQSrx573bT1o1Q==
[...]
debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
debug3: start over, passed a different list publickey,gssapi-keyex,gssapi-with-mic,password
debug3: preferred gssapi-keyex,gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_lookup gssapi-keyex
debug3: remaining preferred: gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-keyex
debug1: Next authentication method: gssapi-keyex
debug1: No valid Key exchange context
debug2: we did not send a packet, disable method
debug3: authmethod_lookup gssapi-with-mic
debug3: remaining preferred: publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-with-mic
debug1: Next authentication method: gssapi-with-mic
debug3: send packet: type 50
debug2: we sent a gssapi-with-mic packet, wait for reply
debug3: receive packet: type 60
debug1: Delegating credentials
debug3: send packet: type 61
debug3: receive packet: type 61
debug1: Delegating credentials
debug3: send packet: type 66
debug3: receive packet: type 52
debug1: Authentication succeeded (gssapi-with-mic).
[...]
Last login: Sat Nov 17 09:57:59 2018 from 172.21.86.85

ld00:~❯ klist
Ticket cache: KEYRING:persistent:7225:krb_ccache_Chv18D6
Default principal: tibbs@MATH.UH.EDU

Valid starting       Expires              Service principal
11/17/2018 09:58:52  11/17/2018 22:43:39  krbtgt/MATH.UH.EDU@MATH.UH.EDU
        renew until 11/23/2018 22:43:39

I dropped this into /etc/sssd/conf.d/11_kcm.conf:
[kcm]
debug_level = 10
debug_microseconds = true

[secrets]
debug_level = 10
debug_microseconds = true

but there is nothing at all in /var/log/sssd/sssd_kcm.log besides 

(Sat Nov 17 09:32:30 2018) [sssd[kcm]] [orderly_shutdown] (0x0010): SIGTERM: killing children

and nothing useful in the journal, either:

Nov 17 09:22:29 ld00.e.math.uh.edu systemd[1]: Started SSSD Kerberos Cache Manager.
Nov 17 09:22:29 ld00.e.math.uh.edu sssd[kcm][2603]: Starting up
Nov 17 09:32:30 ld00.e.math.uh.edu sssd[kcm][2603]: Shutting down
Nov 17 09:49:32 ld00.e.math.uh.edu systemd[1]: Started SSSD Kerberos Cache Manager.
Nov 17 09:49:32 ld00.e.math.uh.edu sssd[kcm][4147]: Starting up

I did strace the sssd_kcm process and verified that it is at least doing something when I connect, though it seems that a third of the calls it makes are to getpid().  Grepping those out, here's what it does when I ssh in:

strace: Process 5550 attached
epoll_wait(4, [{EPOLLIN, {u32=2410360752, u64=94079374012336}}], 1, 3566) = 1
accept(3, {sa_family=AF_UNIX}, [110->2]) = 14
getsockopt(14, SOL_SOCKET, SO_PEERCRED, {pid=5969, uid=7225, gid=7225}, [12]) = 0
getsockopt(14, SOL_SOCKET, SO_PEERSEC, "system_u:system_r:sshd_t:s0-s0:c"..., [256->40]) = 0
epoll_ctl(4, EPOLL_CTL_ADD, 14, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=2431352320, u64=94079395003904}}) = 0
epoll_wait(4, [{EPOLLIN, {u32=2431352320, u64=94079395003904}}], 1, 696) = 1
readv(14, [{iov_base="\0\0\0\4", iov_len=4}], 1) = 4
readv(14, [{iov_base="\2\0\0\3", iov_len=4}], 1) = 4
epoll_ctl(4, EPOLL_CTL_DEL, 14, 0x7fff48f60944) = 0
geteuid()                               = 0
geteuid()                               = 0
epoll_create(64)                        = 15
fcntl(15, F_GETFD)                      = 0
fcntl(15, F_SETFD, FD_CLOEXEC)          = 0
fcntl(13, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=168, l_len=40000}) = 0
fcntl(13, F_SETLKW, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=40168, l_len=0}) = 0
fcntl(13, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=168, l_len=0}) = 0
close(15)                               = 0
epoll_ctl(4, EPOLL_CTL_ADD, 14, {EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=2431352320, u64=94079395003904}}) = 0
epoll_wait(4, [{EPOLLOUT, {u32=2431352320, u64=94079395003904}}], 1, 691) = 1
writev(14, [{iov_base="\0\0\0\17", iov_len=4}], 1) = 4
writev(14, [{iov_base="\0\0\0\0", iov_len=4}], 1) = 4
writev(14, [{iov_base="\0\0\0\0007225:91481\0", iov_len=15}], 1) = 15
epoll_ctl(4, EPOLL_CTL_DEL, 14, 0x7fff48f60954) = 0
epoll_ctl(4, EPOLL_CTL_ADD, 14, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=2431352320, u64=94079395003904}}) = 0
epoll_wait(4, [{EPOLLIN, {u32=2431352320, u64=94079395003904}}], 1, 690) = 1
readv(14, [{iov_base="\0\0\0\17", iov_len=4}], 1) = 4
readv(14, [{iov_base="\2\0\0\0257225:91481\0", iov_len=15}], 1) = 15
epoll_ctl(4, EPOLL_CTL_DEL, 14, 0x7fff48f60944) = 0
geteuid()                               = 0
geteuid()                               = 0
epoll_create(64)                        = 15
fcntl(15, F_GETFD)                      = 0
fcntl(15, F_SETFD, FD_CLOEXEC)          = 0
fcntl(13, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=168, l_len=40000}) = 0
fcntl(13, F_SETLKW, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=40168, l_len=0}) = 0
fcntl(13, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=168, l_len=0}) = 0
close(15)                               = 0
epoll_ctl(4, EPOLL_CTL_ADD, 14, {EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=2431352320, u64=94079395003904}}) = 0
epoll_wait(4, [{EPOLLOUT, {u32=2431352320, u64=94079395003904}}], 1, 689) = 1
writev(14, [{iov_base="\0\0\0\0", iov_len=4}], 1) = 4
writev(14, [{iov_base="\226\307:\215", iov_len=4}], 1) = 4
epoll_ctl(4, EPOLL_CTL_DEL, 14, 0x7fff48f60954) = 0
epoll_ctl(4, EPOLL_CTL_ADD, 14, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=2431352320, u64=94079395003904}}) = 0
epoll_wait(4, [], 1, 689)               = 0
epoll_wait(4, 0x7fff48f60a14, 1, 10000) = -1 EINTR (Interrupted system call)
--- SIGRT_2 {si_signo=SIGRT_2, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_value={int=-1878190400, ptr=0x7fc3900d16c0}} ---
rt_sigreturn({mask=[INT FPE USR1 USR2 PIPE]}) = -1 EINTR (Interrupted system call)
epoll_wait(4,

But note that at some point earlier in my F29 prep, the problem mysteriously stopped and everything started working.  But I have no idea what changed and since the last reinstall the system has stayed in the broken state illustrated here.  (I do know the NFS client will cache user principals even after you do kdestroy; that's not what I'm talking about here.)

The machine in question is running sssd-kcm-2.0.0-4.fc29.x86_64 and openssh-server-7.9p1-1.fc29.x86_64.    The machine where I'm calling ssh is running openssh-7.8p1-3.fc28.x86_64.

Comment 2 Jason Tibbitts 2018-11-19 16:20:23 UTC
A relevant SSSD ticket which discusses the underlying technical issue is https://pagure.io/SSSD/sssd/issue/3873

Comment 3 Orion Poplawski 2018-11-20 16:04:24 UTC
FWIW - I'm seeing the same with RHEL 8 beta as well.

Comment 4 Ben Cotton 2019-05-02 19:23:34 UTC
This message is a reminder that Fedora 28 is nearing its end of life.
On 2019-May-28 Fedora will stop maintaining and issuing updates for
Fedora 28. It is Fedora's policy to close all bug reports from releases
that are no longer maintained. At that time this bug will be closed as
EOL if it remains open with a Fedora 'version' of '28'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 28 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 5 Ben Cotton 2019-05-02 19:50:19 UTC
This message is a reminder that Fedora 28 is nearing its end of life.
On 2019-May-28 Fedora will stop maintaining and issuing updates for
Fedora 28. It is Fedora's policy to close all bug reports from releases
that are no longer maintained. At that time this bug will be closed as
EOL if it remains open with a Fedora 'version' of '28'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 28 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 6 Jakub Hrozek 2019-05-03 10:10:53 UTC
This was fixed in 2.1 upstream, can't we close this bug?

Comment 7 Orion Poplawski 2019-05-03 21:53:21 UTC
Works for me, closing.

Comment 8 Alexey Tikhonov 2019-11-22 12:11:44 UTC
*** Bug 1670457 has been marked as a duplicate of this bug. ***


Note You need to log in before you can comment on or make changes to this bug.