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

Bug 720814

Summary: Mounting multiple NFSv4 exports from same server results in can't create tcp rpc_clnt to server on NFSv4 server
Product: [Fedora] Fedora Reporter: Anthony Messina <amessina>
Component: nfs-utilsAssignee: Steve Dickson <steved>
Status: CLOSED WONTFIX QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: low Docs Contact:
Priority: unspecified    
Version: 15CC: bfields, jlayton, steved
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-08-07 14:39:43 EDT Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Attachments:
Description Flags
tcpdump on NFSv4 server
none
Wireshark capture as requested during the client boot none

Description Anthony Messina 2011-07-12 16:31:25 EDT
I have a Kerberized NFSv4 server which exports many directories.  When a client attempts to mount more than one of those directories, the NFSv4 server reports the rpc.gssd errors shown below.  The mounts work just fine and the client is able to access files on all of the mounted directories without issue.

This issue DOES NOT occur on systems when only one NFSv4 mountpoint is mounted on the client.

I've Google'd to death to try to find out how to "fix" this issue as it appears related to nfsd4 callback.

Is there a more appropriate way to mount multiple NFSv4 exports from the same server?

The clients are using nfs-utils-1.2.4-0.fc15.x86_64
The server is using nfs-utils-1.2.3-11.fc15.x86_64 pending the fix for bug #719776.

NFSv4 server: /etc/exports:
/export                 *.messinet.com(fsid=0,sec=krb5p)
/export/home            *.messinet.com(rw,nohide,sec=krb5p)
/export/koji            *.messinet.com(ro,nohide,sec=krb5p,all_squash)

NFSv4 client: /etc/fstab:
messinet.com:/          /mnt/chicago            nfs4    rw,comment=systemd.automount,sec=krb5p  0 0                                                                                                            
messinet.com:/home      /home                   nfs4    rw,comment=systemd.automount,sec=krb5p  0 0
messinet.com:/koji      /mnt/koji               nfs4    ro,comment=systemd.automount,sec=krb5p  0 0


NFSv4 server rpc.gssd errors when the second and third mounts are attempted from the NFSv4 client:
Jul 12 15:04:37 chicago rpc.gssd[20615]: process_krb5_upcall: service is '*'
Jul 12 15:04:37 chicago rpc.gssd[20615]: Full hostname for 'linux-ws2.messinet.com' is 'linux-ws2.messinet.com'
Jul 12 15:04:37 chicago rpc.gssd[20615]: Full hostname for 'messinet.com' is 'messinet.com'
Jul 12 15:04:37 chicago rpc.gssd[20615]: No key table entry found for root/messinet.com@MESSINET.COM while getting keytab entry for 'root/messinet.com@MESSINET.COM'
Jul 12 15:04:38 chicago rpc.gssd[20615]: Success getting keytab entry for 'nfs/messinet.com@MESSINET.COM'
Jul 12 15:04:38 chicago rpc.gssd[20615]: INFO: Credentials in CC 'FILE:/tmp/krb5cc_machine_MESSINET.COM' are good until 1310581415
Jul 12 15:04:38 chicago rpc.gssd[20615]: INFO: Credentials in CC 'FILE:/tmp/krb5cc_machine_MESSINET.COM' are good until 1310581415
Jul 12 15:04:38 chicago rpc.gssd[20615]: using FILE:/tmp/krb5cc_machine_MESSINET.COM as credentials cache for machine creds
Jul 12 15:04:38 chicago rpc.gssd[20615]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_machine_MESSINET.COM
Jul 12 15:04:38 chicago rpc.gssd[20615]: creating context using fsuid 0 (save_uid 0)
Jul 12 15:04:38 chicago rpc.gssd[20615]: creating tcp client for server linux-ws2.messinet.com
Jul 12 15:04:38 chicago rpc.gssd[20615]: DEBUG: port already set to 52727
Jul 12 15:04:38 chicago rpc.gssd[20615]: WARNING: can't create tcp rpc_clnt to server linux-ws2.messinet.com for user with uid 0: RPC: Remote system error - Permission denied
Jul 12 15:04:38 chicago rpc.gssd[20615]: WARNING: Failed to create machine krb5 context with credentials cache FILE:/tmp/krb5cc_machine_MESSINET.COM for server linux-ws2.messinet.com
Jul 12 15:04:38 chicago rpc.gssd[20615]: WARNING: Machine cache is prematurely expired or corrupted trying to recreate cache for server linux-ws2.messinet.com
Jul 12 15:04:38 chicago rpc.gssd[20615]: Full hostname for 'linux-ws2.messinet.com' is 'linux-ws2.messinet.com'
Jul 12 15:04:38 chicago rpc.gssd[20615]: Full hostname for 'messinet.com' is 'messinet.com'
Jul 12 15:04:38 chicago rpc.gssd[20615]: No key table entry found for root/messinet.com@MESSINET.COM while getting keytab entry for 'root/messinet.com@MESSINET.COM'
Jul 12 15:04:38 chicago rpc.gssd[20615]: Success getting keytab entry for 'nfs/messinet.com@MESSINET.COM'
Jul 12 15:04:38 chicago rpc.gssd[20615]: INFO: Credentials in CC 'FILE:/tmp/krb5cc_machine_MESSINET.COM' are good until 1310581415
Jul 12 15:04:38 chicago rpc.gssd[20615]: INFO: Credentials in CC 'FILE:/tmp/krb5cc_machine_MESSINET.COM' are good until 1310581415
Jul 12 15:04:38 chicago rpc.gssd[20615]: using FILE:/tmp/krb5cc_machine_MESSINET.COM as credentials cache for machine creds
Jul 12 15:04:38 chicago rpc.gssd[20615]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_machine_MESSINET.COM
Jul 12 15:04:38 chicago rpc.gssd[20615]: creating context using fsuid 0 (save_uid 0)
Jul 12 15:04:38 chicago rpc.gssd[20615]: creating tcp client for server linux-ws2.messinet.com
Jul 12 15:04:38 chicago rpc.gssd[20615]: DEBUG: port already set to 52727
Jul 12 15:04:38 chicago rpc.gssd[20615]: WARNING: can't create tcp rpc_clnt to server linux-ws2.messinet.com for user with uid 0: RPC: Remote system error - Permission denied
Jul 12 15:04:38 chicago rpc.gssd[20615]: WARNING: Failed to create machine krb5 context with credentials cache FILE:/tmp/krb5cc_machine_MESSINET.COM for server linux-ws2.messinet.com
Jul 12 15:04:38 chicago rpc.gssd[20615]: WARNING: Failed to create machine krb5 context with any credentials cache for server linux-ws2.messinet.com
Jul 12 15:04:38 chicago rpc.gssd[20615]: doing error downcall
Comment 1 J. Bruce Fields 2011-07-12 16:54:20 EDT
"WARNING: can't create tcp rpc_clnt to server linux-ws2.messinet.com for user with uid 0: RPC: Remote system error - Permission denied"

A network trace might be helpful, as would any errors logged on the client around the same time.

However, this isn't a fatal error, as you've noticed.  It means the server is failing to establish a callback path to the client, so that delegations will be turned off.
Comment 2 Anthony Messina 2011-07-12 17:07:44 EDT
(In reply to comment #1)
> "WARNING: can't create tcp rpc_clnt to server linux-ws2.messinet.com for user
> with uid 0: RPC: Remote system error - Permission denied"
> 
> A network trace might be helpful, as would any errors logged on the client
> around the same time.

On the clients, I experience zero errors at mount time.

Ok, I'll try to do a trace.  Any recommendations on how to do so?  I haven't had to trace NFSv4 traffic before.

> However, this isn't a fatal error, as you've noticed.  It means the server is
> failing to establish a callback path to the client, so that delegations will be
> turned off.

That's what I though.  It seems with NFSv4, I would only mount the root of the export, then somehow bind mount or symlink the /home and /mnt/koji directories, but after Googling and attempting, neither of these options seems to work.
Comment 3 Anthony Messina 2011-07-12 17:36:07 EDT
Ok, I tried this:
tcpdump -s1536 -w /tmp/dump tcp and host linux-ws2.messinet.com and not port 10050 and not port 80 and not port 25

I will attach the dump.
Comment 4 Anthony Messina 2011-07-12 17:36:34 EDT
Created attachment 512526 [details]
tcpdump on NFSv4 server
Comment 5 Anthony Messina 2011-07-12 18:09:13 EDT
I also tried setting options nfs callback_tcpport=801 for nfs, opening up port 801 on the client and ensuring that the server is allowed via tcp_wrappers, but I still get the following on the server when the client mounts the second and third exports:

rpc.gssd[20615]: DEBUG: port already set to 57973
Comment 6 Steve Dickson 2011-07-26 08:16:06 EDT
(In reply to comment #3)
> Ok, I tried this:
> tcpdump -s1536 -w /tmp/dump tcp and host linux-ws2.messinet.com and not port
> 10050 and not port 80 and not port 25
> 
> I will attach the dump.
tcpdump does not have NFSv4 support. Please use wireshark.

yum install wireshark
tshark -w /tmp/data.pcap host linux-ws2.messinet.com and not port 10050 and not port 80 and not port 25
bzip2 /tmp/data.pcap
Comment 7 Anthony Messina 2011-07-26 17:06:26 EDT
Created attachment 515370 [details]
Wireshark capture as requested during the client boot

This capture was taken AFTER the upgrade to https://admin.fedoraproject.org/updates/nfs-utils-1.2.4-1.fc15
Comment 8 Fedora End Of Life 2012-08-07 14:39:45 EDT
This message is a notice that Fedora 15 is now at end of life. Fedora
has stopped maintaining and issuing updates for Fedora 15. It is
Fedora's policy to close all bug reports from releases that are no
longer maintained. At this time, all open bugs with a Fedora 'version'
of '15' have been closed as WONTFIX.

(Please note: Our normal process is to give advanced warning of this
occurring, but we forgot to do that. A thousand apologies.)

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

Bug Reporter: Thank you for reporting this issue and we are sorry that
we were unable to fix it before Fedora 15 reached 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 to click on
"Clone This Bug" (top right of this page) and open it against that
version of Fedora.

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.

The process we are following is described here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping