Bug 1345871

Summary: Cannot mount NFSv4 export with krb5 auth exported from Fedora 24 server
Product: [Fedora] Fedora Reporter: Aleksandar Krsteski <alekrsteski>
Component: gssproxyAssignee: Robbie Harwood <rharwood>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: high Docs Contact:
Priority: unspecified    
Version: 24CC: gdeschner, rharwood, ssorce
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: gssproxy-0.5.1-2.fc24 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-06-18 18:29:08 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Aleksandar Krsteski 2016-06-13 11:00:59 UTC
Description of problem:
I am using Fedora as a server install for my home NAS. NFSv4 with krb5 authentication worked fine on Fedora 23, but after upgrading to Fedora 24 (clean install) I am not able to make it work.

I think that I might be hitting this bug described on following links for Arch Linux:
http://wyldeplayground.net/nfs-kerberos-mount-failure-with-gssproxy-0-5-workaround/
https://bbs.archlinux.org/viewtopic.php?pid=1632463

The forum topic refers to following commit as a fix:
https://git.fedorahosted.org/cgit/gss-proxy.git/commit/?id=b5d1a189da2037d87283eac8998af4bfb1aefa79

Version-Release number of selected component (if applicable):
Name        : gssproxy
Arch        : x86_64
Epoch       : 0
Version     : 0.5.0
Release     : 4.fc24

How reproducible:
Always.

Steps to Reproduce:
I am trying to locally mount NFS on the server itself in order to localize the problem on the server. But I have also tested from Arch Linux client with same result.
1. I have valid krb5 authentication configuration and I am able to login to the server through SSH using my Kerberos credentials.
2. I configured NFSv4 export with krb5 authentication. My export line is as follows:
/storage/aleksandar *(rw,sec=krb5:krb5i:krb5p)
3. I have following line added to my fstab:
nas:/storage/aleksandar                   /tmp/testmount          nfs     users,nfsvers=4,intr,sec=krb5 0 0
4. Try to mount /tmp/testmount.

Actual results:
When I execute "mount -v /tmp/testmount", I get following access denied error:
mount.nfs: timeout set for Mon Jun 13 12:46:51 2016
mount.nfs: trying text-based options 'intr,sec=krb5,vers=4,addr=192.168.1.3,clientaddr=192.168.1.3'
mount.nfs: mount(2): Permission denied
mount.nfs: access denied by server while mounting nas:/storage/aleksandar

Expected results:
/tmpp/testmount should be mounted successfully.

Additional info:
Relevant part of journalctl with verbose logging enabled for rpc.gssd (edited to replace my domain with example.com):
Jun 13 12:44:51 nas.example.com rpc.idmapd[491]: New client: d
Jun 13 12:44:51 nas.example.com rpc.idmapd[491]: Opened /var/lib/nfs/rpc_pipefs//nfs/clntd/idmap
Jun 13 12:44:51 nas.example.com rpc.gssd[537]:
                                             handle_gssd_upcall: 'mech=krb5 uid=0 service=* enctypes=18,17,16,23,3,1,2 ' (nfs/clntd)
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: krb5_use_machine_creds: uid 0 tgtname (null)
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Full hostname for 'nas.example.com' is 'nas.example.com'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Full hostname for 'nas.example.com' is 'nas.example.com'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Success getting keytab entry for 'nas$@EXAMPLE.COM'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1465899132
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1465899132
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: creating tcp client for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: DEBUG: port already set to 2049
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: creating context with server nfs.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Failed to create krb5 context for user with uid 0 for server nfs.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Failed to create machine krb5 context with cred cache FILE:/tmp/krb5ccmachine_EXAMPLE.COM for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Machine cache prematurely expired or corrupted trying to recreate cache for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Full hostname for 'nas.example.com' is 'nas.example.com'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Full hostname for 'nas.example.com' is 'nas.example.com'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Success getting keytab entry for 'nas$@EXAMPLE.COM'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1465899132
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1465899132
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: creating tcp client for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: DEBUG: port already set to 2049
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: creating context with server nfs.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Failed to create krb5 context for user with uid 0 for server nfs.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Failed to create machine krb5 context with cred cache FILE:/tmp/krb5ccmachine_EXAMPLE.COM for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: ERROR: Failed to create machine krb5 context with any credentials cache for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: doing error downcall
Jun 13 12:44:51 nas.example.com rpc.gssd[537]:
                                             handle_gssd_upcall: 'mech=krb5 uid=0 enctypes=18,17,16,23,3,1,2 ' (nfs/clntd)
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: krb5_use_machine_creds: uid 0 tgtname (null)
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Full hostname for 'nas.example.com' is 'nas.example.com'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Full hostname for 'nas.example.com' is 'nas.example.com'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Success getting keytab entry for 'nas$@EXAMPLE.COM'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1465899132
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1465899132
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: creating tcp client for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: DEBUG: port already set to 2049
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: creating context with server nfs.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Failed to create krb5 context for user with uid 0 for server nfs.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Failed to create machine krb5 context with cred cache FILE:/tmp/krb5ccmachine_EXAMPLE.COM for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Machine cache prematurely expired or corrupted trying to recreate cache for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Full hostname for 'nas.example.com' is 'nas.example.com'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Full hostname for 'nas.example.com' is 'nas.example.com'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Success getting keytab entry for 'nas$@EXAMPLE.COM'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1465899132
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1465899132
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: creating tcp client for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: DEBUG: port already set to 2049
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: creating context with server nfs.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Failed to create krb5 context for user with uid 0 for server nfs.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Failed to create machine krb5 context with cred cache FILE:/tmp/krb5ccmachine_EXAMPLE.COM for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: ERROR: Failed to create machine krb5 context with any credentials cache for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: doing error downcall
Jun 13 12:44:51 nas.example.com rpc.idmapd[491]: New client: e
Jun 13 12:44:51 nas.example.com rpc.idmapd[491]: New client: 10
Jun 13 12:44:51 nas.example.com rpc.gssd[537]:
                                             handle_gssd_upcall: 'mech=krb5 uid=0 enctypes=18,17,16,23,3,1,2 ' (nfs/clntd)
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: krb5_use_machine_creds: uid 0 tgtname (null)
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Full hostname for 'nas.example.com' is 'nas.example.com'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Full hostname for 'nas.example.com' is 'nas.example.com'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Success getting keytab entry for 'nas$@EXAMPLE.COM'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1465899132
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1465899132
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: creating tcp client for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: DEBUG: port already set to 2049
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: creating context with server nfs.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Failed to create krb5 context for user with uid 0 for server nfs.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Failed to create machine krb5 context with cred cache FILE:/tmp/krb5ccmachine_EXAMPLE.COM for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Machine cache prematurely expired or corrupted trying to recreate cache for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Full hostname for 'nas.example.com' is 'nas.example.com'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Full hostname for 'nas.example.com' is 'nas.example.com'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: Success getting keytab entry for 'nas$@EXAMPLE.COM'
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1465899132
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_EXAMPLE.COM' are good until 1465899132
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: creating tcp client for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: DEBUG: port already set to 2049
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: creating context with server nfs.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Failed to create krb5 context for user with uid 0 for server nfs.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: WARNING: Failed to create machine krb5 context with cred cache FILE:/tmp/krb5ccmachine_EXAMPLE.COM for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: ERROR: Failed to create machine krb5 context with any credentials cache for server nas.example.com
Jun 13 12:44:51 nas.example.com rpc.gssd[537]: doing error downcall
Jun 13 12:44:51 nas.example.com rpc.idmapd[491]: Stale client: 10
Jun 13 12:44:51 nas.example.com rpc.idmapd[491]:         -> closed /var/lib/nfs/rpc_pipefs//nfs/clnt10/idmap
Jun 13 12:44:51 nas.example.com rpc.idmapd[491]: Stale client: d
Jun 13 12:44:51 nas.example.com rpc.idmapd[491]:         -> closed /var/lib/nfs/rpc_pipefs//nfs/clntd/idmap
Jun 13 12:44:51 nas.example.com rpc.idmapd[491]: Stale client: e
Jun 13 12:44:51 nas.example.com rpc.idmapd[491]:         -> closed /var/lib/nfs/rpc_pipefs//nfs/clnte/idmap

Comment 1 Fedora Update System 2016-06-13 19:39:12 UTC
gssproxy-0.5.1-1.fc24 has been submitted as an update to Fedora 24. https://bodhi.fedoraproject.org/updates/FEDORA-2016-fb765637bd

Comment 2 Fedora Update System 2016-06-14 03:57:25 UTC
gssproxy-0.5.1-1.fc24 has been pushed to the Fedora 24 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-fb765637bd

Comment 3 Aleksandar Krsteski 2016-06-14 08:08:29 UTC
gssproxy-0.5.1-1.fc24 does not completely fix the issue. After updating to gssproxy-0.5.1-1.fc24 it was still not mounting, until I manually created /var/lib/gssproxy/rcache directory.

gssproxy.service is configuring KRB5RCACHEDIR=/var/lib/gssproxy/rcache, but the directory does not exist on the file-system and gssproxy fails with following messages in the log (debug_level=2):
[2016/06/14 07:51:11]: gp_rpc_execute: executing 9 (GSSX_ACCEPT_SEC_CONTEXT) for service "nfs-server", euid: 0,socket: /run/gssproxy.sock
     GSSX_ARG_ACCEPT_SEC_CONTEXT( call_ctx: { "" [  ] [ { [ exported.context... ] [ 6c696e75785f6c756369645f76310 ] } { [ exported.creds.t... ] [ 6c696e75785f63726564735f76310 ] } ] } context_handle: <Null> cred_handle: <Null> input_token: [ ...q....H.......... ] input_cb: <Null> ret_deleg_cred: 0 )
     GSSX_RES_ACCEPT_SEC_CONTEXT( status: { 851968 <None> 2529639083 "Unspecified GSS failure.  Minor code may provide more information" "Cannot create replay cache: No such file or directory" [  ] } context_handle: <Null> output_token: <Null> delegated_cred_handle: <Null> )

So the problem of mounting NFSv4 with krb5 is solved with following steps:
1. dnf install gssproxy-0.5.1-1.fc24
2. mkdir /var/lib/gssproxy/rcache

Maybe the package should create this directory automatically on install, or we need to change KRB5RCACHEDIR var in .service file.

Comment 4 Fedora Update System 2016-06-14 19:22:22 UTC
gssproxy-0.5.1-2.fc24 has been submitted as an update to Fedora 24. https://bodhi.fedoraproject.org/updates/FEDORA-2016-497d5d862d

Comment 5 Aleksandar Krsteski 2016-06-14 21:32:26 UTC
gssproxy-0.5.1-2.fc24 completely fixes this issue.

Comment 6 Fedora Update System 2016-06-15 16:56:42 UTC
gssproxy-0.5.1-2.fc24 has been pushed to the Fedora 24 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-497d5d862d

Comment 7 Fedora Update System 2016-06-18 18:29:06 UTC
gssproxy-0.5.1-2.fc24 has been pushed to the Fedora 24 stable repository. If problems still persist, please make note of it in this bug report.