Bug 1345871 - Cannot mount NFSv4 export with krb5 auth exported from Fedora 24 server
Summary: Cannot mount NFSv4 export with krb5 auth exported from Fedora 24 server
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: gssproxy
Version: 24
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Robbie Harwood
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-06-13 11:00 UTC by Aleksandar Krsteski
Modified: 2016-06-18 18:29 UTC (History)
3 users (show)

Fixed In Version: gssproxy-0.5.1-2.fc24
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-06-18 18:29:08 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

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.


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