Created attachment 1040217 [details] rpc-gssd and gssproxy output after login attempt After just upgrading to systemd-219-18.fc22.x86_64 and nfs-utils-1.3.2-8.fc22.x86_64, I am no longer able to login to my F22 KDE-based workstation with an NFS/KRB5 mounted /home. Investigating the issue has revealed that no machine credentials cache is actually present after rpc-gssd.service startup: # file /tmp/krb5ccmachine_EXAMPLE.COM /tmp/krb5ccmachine_EXAMPLE.COM: cannot open `/tmp/krb5ccmachine_EXAMPLE.COM' (No such file or directory) I am using gssproxy-0.4.1-1.fc22.x86_64. # journalctl -ab -u rpc-gssd -u gssproxy -o cat Starting GSSAPI Proxy Daemon... Started GSSAPI Proxy Daemon. Starting RPC security service for NFS client and server... doing a full rescan Started RPC security service for NFS client and server. inotify event for topdir (nfs) - ev->wd (8) ev->name (clnt0) ev->mask (0x40000100) inotify event for topdir (nfs) - ev->wd (8) ev->name (clnt1) ev->mask (0x40000100) inotify event for clntdir (nfs/clnt1) - ev->wd (12) ev->name (gssd) ev->mask (0x00000100) inotify event for clntdir (nfs/clnt0) - ev->wd (11) ev->name (gssd) ev->mask (0x00000100) inotify event for clntdir (nfs/clnt1) - ev->wd (12) ev->name (krb5) ev->mask (0x00000100) inotify event for clntdir (nfs/clnt0) - ev->wd (11) ev->name (krb5) ev->mask (0x00000100) inotify event for clntdir (nfs/clnt0) - ev->wd (11) ev->name (idmap) ev->mask (0x00000100) handling gssd upcall (nfs/clnt0) handle_gssd_upcall: 'mech=krb5 uid=0 service=* enctypes=18,17,16,23,3,1,2 ' handling krb5 upcall (nfs/clnt0) process_krb5_upcall: service is '*' Full hostname for 'ds.example.com' is 'ds.example.com' Full hostname for 'linux-ws1.example.com' is 'linux-ws1.example.com' No key table entry found for LINUX-WS1$@EXAMPLE.COM while getting keytab entry for 'LINUX-WS1$@EXAMPLE.COM' No key table entry found for root/linux-ws1.example.com while getting keytab entry for 'root/linux-ws1.example.com' No key table entry found for nfs/linux-ws1.example.com while getting keytab entry for 'nfs/linux-ws1.example.com' Success getting keytab entry for 'host/linux-ws1.example.com' Successfully obtained machine credentials for principal 'host/linux-ws1.example.com' stored in ccache 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1434670328 using FILE:/tmp/krb5ccmachine_EXAMPLE.COM as credentials cache for machine creds using environment variable to select krb5 ccache FILE:/tmp/krb5ccmachine_EXAMPLE.COM gssproxy[705]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure. Minor code may provide more information, No credentials cache found (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure. Minor code may provide more information, No credentials cache found creating tcp client for server ds.example.com DEBUG: port already set to 2049 creating context with server nfs.com DEBUG: serialize_krb5_ctx: lucid version! prepare_krb5_rfc4121_buffer: protocol 1 prepare_krb5_rfc4121_buffer: serializing key with enctype 18 and size 32 doing downcall: lifetime_rec=86400 acceptor=nfs.com inotify event for clntdir (nfs/clnt1) - ev->wd (12) ev->name (idmap) ev->mask (0x00000100) handling gssd upcall (nfs/clnt1) handle_gssd_upcall: 'mech=krb5 uid=0 service=* enctypes=18,17,16,23,3,1,2 ' handling krb5 upcall (nfs/clnt1) process_krb5_upcall: service is '*' Full hostname for 'chicago.example.com' is 'chicago.example.com' Full hostname for 'linux-ws1.example.com' is 'linux-ws1.example.com' No key table entry found for LINUX-WS1$@EXAMPLE.COM while getting keytab entry for 'LINUX-WS1$@EXAMPLE.COM' No key table entry found for root/linux-ws1.example.com while getting keytab entry for 'root/linux-ws1.example.com' No key table entry found for nfs/linux-ws1.example.com while getting keytab entry for 'nfs/linux-ws1.example.com' Success getting keytab entry for 'host/linux-ws1.example.com' Successfully obtained machine credentials for principal 'host/linux-ws1.example.com' stored in ccache 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1434670330 using FILE:/tmp/krb5ccmachine_EXAMPLE.COM as credentials cache for machine creds using environment variable to select krb5 ccache FILE:/tmp/krb5ccmachine_EXAMPLE.COM (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure. Minor code may provide more information, No credentials cache found creating tcp client for server chicago.example.com DEBUG: port already set to 2049 creating context with server nfs.com gssproxy[705]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure. Minor code may provide more information, No credentials cache found DEBUG: serialize_krb5_ctx: lucid version! prepare_krb5_rfc4121_buffer: protocol 1 prepare_krb5_rfc4121_buffer: serializing key with enctype 18 and size 32 inotify event for topdir (nfs) - ev->wd (8) ev->name (clnt2) ev->mask (0x40000100) inotify event for topdir (nfs) - ev->wd (8) ev->name (clnt3) ev->mask (0x40000100) inotify event for topdir (nfs) - ev->wd (8) ev->name (clnt4) ev->mask (0x40000100) handling gssd upcall (nfs/clnt1) handle_gssd_upcall: 'mech=krb5 uid=0 enctypes=18,17,16,23,3,1,2 ' handling krb5 upcall (nfs/clnt1) process_krb5_upcall: service is '<null>' Full hostname for 'chicago.example.com' is 'chicago.example.com' Full hostname for 'linux-ws1.example.com' is 'linux-ws1.example.com' No key table entry found for LINUX-WS1$@EXAMPLE.COM while getting keytab entry for 'LINUX-WS1$@EXAMPLE.COM' No key table entry found for root/linux-ws1.example.com while getting keytab entry for 'root/linux-ws1.example.com' No key table entry found for nfs/linux-ws1.example.com while getting keytab entry for 'nfs/linux-ws1.example.com' Success getting keytab entry for 'host/linux-ws1.example.com' Successfully obtained machine credentials for principal 'host/linux-ws1.example.com' stored in ccache 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1434670330 using FILE:/tmp/krb5ccmachine_EXAMPLE.COM as credentials cache for machine creds using environment variable to select krb5 ccache FILE:/tmp/krb5ccmachine_EXAMPLE.COM (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure. Minor code may provide more information, No credentials cache found creating tcp client for server chicago.example.com DEBUG: port already set to 2049 creating context with server nfs.com handling gssd upcall (nfs/clnt0) handle_gssd_upcall: 'mech=krb5 uid=0 enctypes=18,17,16,23,3,1,2 ' handling krb5 upcall (nfs/clnt0) process_krb5_upcall: service is '<null>' Full hostname for 'ds.example.com' is 'ds.example.com' Full hostname for 'linux-ws1.example.com' is 'linux-ws1.example.com' No key table entry found for LINUX-WS1$@EXAMPLE.COM while getting keytab entry for 'LINUX-WS1$@EXAMPLE.COM' No key table entry found for root/linux-ws1.example.com while getting keytab entry for 'root/linux-ws1.example.com' No key table entry found for nfs/linux-ws1.example.com while getting keytab entry for 'nfs/linux-ws1.example.com' Success getting keytab entry for 'host/linux-ws1.example.com' Successfully obtained machine credentials for principal 'host/linux-ws1.example.com' stored in ccache 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1434670330 using FILE:/tmp/krb5ccmachine_EXAMPLE.COM as credentials cache for machine creds using environment variable to select krb5 ccache FILE:/tmp/krb5ccmachine_EXAMPLE.COM (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure. Minor code may provide more information, No credentials cache found gssproxy[705]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure. Minor code may provide more information, No credentials cache found gssproxy[705]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure. Minor code may provide more information, No credentials cache found inotify event for topdir (nfs) - ev->wd (8) ev->name (clnt5) ev->mask (0x40000100) inotify event for topdir (nfs) - ev->wd (8) ev->name (clnt6) ev->mask (0x40000100) inotify event for clntdir (nfs/clnt5) - ev->wd (16) ev->name (info) ev->mask (0x00000200) inotify event for clntdir (nfs/clnt5) - ev->wd (16) ev->name (<?>) ev->mask (0x00008000) inotify event for clntdir (nfs/clnt2) - ev->wd (13) ev->name (info) ev->mask (0x00000200) inotify event for clntdir (nfs/clnt2) - ev->wd (13) ev->name (<?>) ev->mask (0x00008000) inotify event for topdir (nfs) - ev->wd (8) ev->name (clnt7) ev->mask (0x40000100) inotify event for topdir (nfs) - ev->wd (8) ev->name (clnt8) ev->mask (0x40000100) inotify event for clntdir (nfs/clnt7) - ev->wd (18) ev->name (info) ev->mask (0x00000200) inotify event for clntdir (nfs/clnt7) - ev->wd (18) ev->name (<?>) ev->mask (0x00008000) inotify event for clntdir (nfs/clnt4) - ev->wd (15) ev->name (info) ev->mask (0x00000200) inotify event for clntdir (nfs/clnt4) - ev->wd (15) ev->name (<?>) ev->mask (0x00008000) When I try to login to via SDDM to KDE, SDDM sits there; loginctl shows I have an active session, but KDE doesn't start. I've attached a file with the output from gssproxy and rpc-gssd after trying to login.
I'm seeing something like this, though it doesn't appear to be causing problems for me. I just get a bunch of log spew: Jul 16 10:51:52 ld61.e.math.uh.edu gssproxy[646]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure. Minor code may provide more information, No credentials cache found Jul 16 10:51:52 ld61.e.math.uh.edu gssproxy[632]: gssproxy[646]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure. Minor code may provide more information, No credentials cache found The /tmp/krb5ccmachine_* file isn't present on any of my F22 machines but there on everything earlier. I thought the creds might be in /var/lib/gssproxy somewhere but there's nothing save the socket and an empty clients directory (no change from F21).
Moving to gssproxy for investigation.
This package has changed ownership in the Fedora Package Database. Reassigning to the new owner of this component.
I'm curious about the Unspecified GSS failure messages too.
We've just released gssproxy-0.5.0 into fedora. When you get the chance, would you mind testing this with the new version? (And it's still an issue we should bump the affected version so it doesn't fall off the world when f22 EOLs.)
(In reply to Robbie Harwood from comment #5) > We've just released gssproxy-0.5.0 into fedora. When you get the chance, > would you mind testing this with the new version? (And it's still an issue > we should bump the affected version so it doesn't fall off the world when > f22 EOLs.) Sure. Are you planning on releasing 0.5.0 for F23? I don't see it in Bodhi.
It might be too much of an update to push into F23, but building a local copy is rather trivial; the rawhide package builds on F23 without any adjustments. Here's a scratchn build: http://koji.fedoraproject.org/koji/taskinfo?taskID=13928162 BTW, the gssproxy spec could use some cleanup. I wish I could just send a pull request.... And even though it builds, it has a broken dep: Error: nothing provides libini_onfig needed by gssproxy-0.5.0-1.fc23.x86_64 Looks like a typo: diff --git a/gssproxy.spec b/gssproxy.spec index df2ab07..2734b41 100644 --- a/gssproxy.spec +++ b/gssproxy.spec @@ -20,7 +20,7 @@ BuildRoot: %(mktemp -ud %{_tmppath}/%{name}-%{version}-%{release}-XXXXXX) Requires: krb5-libs >= 1.12.0 Requires: keyutils-libs Requires: libverto-tevent -Requires: libini_onfig +Requires: libini_config Requires(post): systemd-units Requires(preun): systemd-units Requires(postun): systemd-units Updated scratch build at http://koji.fedoraproject.org/koji/taskinfo?taskID=13928201
And, oops, it fails to start. Runnig from the terminal: [root@epithumia ~]# /usr/sbin/gssproxy -i -d [2016/05/05 06:00:44]: Debug Enabled (level: 1) [2016/05/05 06:00:44]: Debug Enabled (level: 1) [2016/05/05 06:00:44]: Config file(s) not found! I've no idea what it isn't finding. I do see this: time->Thu May 5 00:59:00 2016 type=AVC msg=audit(1462427940.274:789697): avc: denied { getattr } for pid=2309 comm="gssproxy" name="/" dev="dm-0" ino=2 scontext=system_u:system_r:gssproxy_t:s0 tcontext=system_u:object_r:fs_t:s0 tclass=filesystem permissive=0 but that only appears when trying to start the daemon via systemctl, and setenforce 0 doesn't change the behavior in any case. strace shows that it opens /etc/gsproxy and calls getdents, but nothing says what it's looking for.
Looks like /etc/gssproxy/gssproxy.conf in 0.5.0 contains only: [gssproxy] While 0.4.1 has that and two other sections with various settings: [service/nfs-server] and [service]nfs-client]. This comes from examples/gssproxy.conf.in in the source tree, which in 0.5.0 is similarly empty. I put my original config file back in place and it's running OK now. At least at first clance, I don't get the "No credentials cache found" log spam, but I'll let it run for a while.
I guess I really should make another ticket, but... Overnight, something happened to gssproxy 0.5.0 on my test NFS4/krb5p server to cause it to start refusing mounts. Restarting it didn't help. Downgrading back to the F23 version (and restarting, of course) fixed it immediately. Clients just saw: mount.nfs: trying text-based options 'vers=4.2,addr=172.21.86.85,clientaddr=172.21.86.100' mount.nfs: mount(2): Operation not permitted The server logged: May 05 09:08:34 epithumia.math.uh.edu gssproxy[3873]: [2016/05/05 14:08:34]: gp_rpc_execute: executing 9 (GSSX_ACCEPT_SEC_CO May 05 09:08:34 epithumia.math.uh.edu gssproxy[3873]: [2016/05/05 14:08:34]: gp_rpc_execute: executing 9 (GSSX_ACCEPT_SEC_CO May 05 09:09:42 epithumia.math.uh.edu gssproxy[3873]: [2016/05/05 14:09:42]: gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) May 05 09:09:42 epithumia.math.uh.edu gssproxy[3873]: [2016/05/05 14:09:42]: gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONT May 05 09:09:42 epithumia.math.uh.edu gssproxy[3873]: [2016/05/05 14:09:42]: gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONT May 05 09:09:42 epithumia.math.uh.edu gssproxy[3873]: [2016/05/05 14:09:42]: gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) May 05 09:09:42 epithumia.math.uh.edu gssproxy[3873]: [2016/05/05 14:09:42]: gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONT May 05 09:09:42 epithumia.math.uh.edu gssproxy[3873]: [2016/05/05 14:09:42]: gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONT May 05 09:09:42 epithumia.math.uh.edu gssproxy[3873]: [2016/05/05 14:09:42]: gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) May 05 09:09:42 epithumia.math.uh.edu gssproxy[3873]: [2016/05/05 14:09:42]: gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONT May 05 09:09:42 epithumia.math.uh.edu gssproxy[3873]: [2016/05/05 14:09:42]: gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONT May 05 09:09:45 epithumia.math.uh.edu gssproxy[3873]: [2016/05/05 14:09:45]: Exiting after receiving a signal but after reset, just logged the GSSX_ACCEPT_SEC_CONTEXT message even though mounts were failing. Otherwise the kernel only logged a successful mount request: May 05 09:10:51 epithumia.math.uh.edu rpc.mountd[1101]: authenticated mount request from ld00.e.math.uh.edu:987 for /export/h-tibbs (/export/h-tibbs)
gssproxy-0.5.0-2 has been created (rawhide & f24) to address the missing config snippets. Anthony, we weren't planning to update f23 since 0.5.0 isn't known to fix any bugs there; additionally, since I've had some trouble releasing, we should probably wait a bit to make sure the dust has settled.
(In reply to Robbie Harwood from comment #11) > gssproxy-0.5.0-2 has been created (rawhide & f24) to address the missing > config snippets. > > Anthony, we weren't planning to update f23 since 0.5.0 isn't known to fix > any bugs there; additionally, since I've had some trouble releasing, we > should probably wait a bit to make sure the dust has settled. Ok, Robbie. I'm going to have to hold off a bit in light of the issues raised here as well as the lack of the F23 update. I will keep an eye out however and see how quickly post F24 release I can upgrade.
Please reopen if the issue persists in gssproxy-0.5.1-1 (or whatever is the latest).