nfs server does not respond if access is denied

[csabahenk]

@vponomaryov reported:

if access is not allowed to client, next thing appear:

[ 4182.497622] nfs: server 10.0.0.2 not responding, timed out

And it takes very long time until adding rule for access.

[dpkshetty]

Dumping the debug info I have collected using rpcdebug for this issue

Setup:
Standard devstack+manila. Generic driver in manila.conf
Using csaba's cirros image as the service VM image in manila.conf
Using ubuntu_nfs_cifs.qcow2 as the devstack nova instance

From a NFS perspective:
cirros service VM image - 64bit - NFS server
ubuntu nova instance - 32bit - NFS client

Problem in brief:

1. During manila access-allow, we use exportfs to add a export entry for NFS server
2. Then a mount from NFS client (nova instance) works
3. During manila access-deny, we use exportfs to remove the export entry in NFS server
4. Mounting from NFS client (nova instance) hangs in this case. Expectation is that it should either timeout or error out gracefully, but doesn't doesn't happen

Debug data:

*** Client side data ***

Client IP: 10.0.0.2

ubuntu@ubuntu:~$ dpkg-query -W nfs
knfs
libnfsidmap1
libnfsidmap2 0.25-1ubuntu2
nfs-client
nfs-common 1:1.2.5-3ubuntu3.1
nfs-kernel-server 1:1.2.5-3ubuntu3.1
nfs-server

ubuntu@ubuntu:$ ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 16436 qdisc noqueue state UNKNOWN
link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
inet 127.0.0.1/8 scope host lo
inet6 ::1/128 scope host
valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000
link/ether fa:16:3e:df:46:7c brd ff:ff:ff:ff:ff:ff
inet 10.0.0.2/24 brd 10.0.0.255 scope global eth0
inet6 fe80::f816:3eff:fedf:467c/64 scope link
valid_lft forever preferred_lft forever
ubuntu@ubuntu:$

ubuntu@ubuntu:~$ uname -a
Linux ubuntu 3.2.0-59-virtual #90-Ubuntu SMP Tue Jan 7 23:27:45 UTC 2014 i686 athlon i386 GNU/Linux

ubuntu@ubuntu:~$ nfsstat --version
nfsstat: 1.2.5

ubuntu@ubuntu:~$ lsmod| grep nfs
nfsd 229991 13
nfs 372273 0
lockd 78865 2 nfsd,nfs
fscache 50642 1 nfs
auth_rpcgss 39597 2 nfsd,nfs
nfs_acl 12771 2 nfsd,nfs
sunrpc 215112 19 nfsd,nfs,lockd,auth_rpcgss,nfs_acl

ubuntu@ubuntu:$ dmesg | grep -i nfs
[ 18.891846] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 20.545747] FS-Cache: Netfs 'nfs' registered for caching
[ 21.379591] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
[ 66.483909] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
[ 66.497380] NFSD: starting 90-second grace period
ubuntu@ubuntu:$

ubuntu@ubuntu:/$ sudo rpcdebug -m nfs all
sudo: unable to resolve host ubuntu
nfs vfs dircache lookupcache pagecache proc xdr file root callback client mount

ubuntu@ubuntu:/$ sudo dmesg --clear

ubuntu@ubuntu:/$ time sudo mount -t nfs -vv -o vers=4 10.254.0.3:/shares/share-8b2d529a-0688-4a51-9641-9ee8d781380c /mnt
sudo: unable to resolve host ubuntu
mount.nfs: timeout set for Tue Jul 1 12:46:54 2014
mount.nfs: trying text-based options 'vers=4,addr=10.254.0.3,clientaddr=10.0.0.2'
^C ← HUNG, hence did Ctrl-C !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
real 3m43.594s
user 0m0.196s
sys 0m0.188s

ubuntu@ubuntu:~$ dmesg -T
[Tue Jul 1 12:44:53 2014] NFS: nfs mount opts='vers=4,addr=10.254.0.3,clientaddr=10.0.0.2'
[Tue Jul 1 12:44:53 2014] NFS: parsing nfs mount option 'vers=4'
[Tue Jul 1 12:44:53 2014] NFS: parsing nfs mount option 'addr=10.254.0.3'
[Tue Jul 1 12:44:53 2014] NFS: parsing nfs mount option 'clientaddr=10.0.0.2'
[Tue Jul 1 12:44:53 2014] NFS: MNTPATH: '/shares/share-8b2d529a-0688-4a51-9641-9ee8d781380c'
[Tue Jul 1 12:44:53 2014] --> nfs4_try_mount()
[Tue Jul 1 12:44:53 2014] --> nfs4_create_server()
[Tue Jul 1 12:44:53 2014] --> nfs4_init_server()
[Tue Jul 1 12:44:53 2014] --> nfs4_set_client()
[Tue Jul 1 12:44:53 2014] --> nfs_get_client(10.254.0.3,v4)
[Tue Jul 1 12:44:53 2014] NFS: get client cookie (0xc71bae00/0xc688d030)
[Tue Jul 1 12:44:53 2014] NFS: Callback listener port = 58338 (af 2)
[Tue Jul 1 12:44:53 2014] NFS: Callback listener port = 58222 (af 10)
[Tue Jul 1 12:44:53 2014] --> nfs_get_client() = c71bae00 [new]
[Tue Jul 1 12:44:53 2014] <-- nfs4_set_client() = 0 [new c71bae00]
[Tue Jul 1 12:44:53 2014] <-- nfs4_init_server() = 0
[Tue Jul 1 12:44:53 2014] --> nfs4_get_rootfh()
[Tue Jul 1 12:44:53 2014] encode_compound: tag=
[Tue Jul 1 12:45:53 2014] encode_compound: tag=
[Tue Jul 1 12:45:53 2014] encode_compound: tag=
[Tue Jul 1 12:47:53 2014] nfs: server 10.254.0.3 not responding, still trying
[Tue Jul 1 12:47:53 2014] encode_compound: tag=
[Tue Jul 1 12:47:53 2014] encode_compound: tag=

ubuntu@ubuntu:~$ dmesg
[13532.875229] NFS: nfs mount opts='vers=4,addr=10.254.0.3,clientaddr=10.0.0.2'
[13532.876382] NFS: parsing nfs mount option 'vers=4'
[13532.882223] NFS: parsing nfs mount option 'addr=10.254.0.3'
[13532.883462] NFS: parsing nfs mount option 'clientaddr=10.0.0.2'
[13532.883858] NFS: MNTPATH: '/shares/share-8b2d529a-0688-4a51-9641-9ee8d781380c'
[13532.883934] --> nfs4_try_mount()
[13532.888564] --> nfs4_create_server()
[13532.889029] --> nfs4_init_server()
[13532.889160] --> nfs4_set_client()
[13532.889212] --> nfs_get_client(10.254.0.3,v4)
[13532.889851] NFS: get client cookie (0xc63ad600/0xc688d030)
[13532.937062] NFS: Callback listener port = 40560 (af 2)
[13532.938085] NFS: Callback listener port = 44198 (af 10)
[13532.939346] --> nfs_get_client() = c63ad600 [new]
[13532.939468] <-- nfs4_set_client() = 0 [new c63ad600]
[13532.941944] <-- nfs4_init_server() = 0
[13532.942539] --> nfs4_get_rootfh()
[13532.943172] encode_compound: tag=

*** server side data ***

Server IP: 10.254.0.3

Since its a cirros image, it doens't have a pkg manager, so can't really query for pkg versions !
Closest I can do is below, if that helps ...

$ nfsstat --version
nfsstat: 1.2.6

$ uname -a
Linux cirros 3.11.0-17-generic #31-Ubuntu SMP Mon Feb 3 21:52:43 UTC 2014 x86_64 GNU/Linux
$
$ lsmod| grep nfs
nfsd 280346 7
auth_rpcgss 54830 1 nfsd
nfsv4 253863 0
nfsv3 39326 0
nfs_acl 12837 2 nfsd,nfsv3
nfsv2 24316 0
nfs 180906 3 nfsv4,nfsv3,nfsv2
lockd 94016 4 nfsd,nfsv3,nfsv2,nfs
sunrpc 271857 22 nfsd,auth_rpcgss,nfsv4,nfsv3,nfs_acl,nfsv2,nfs,lockd
fscache 58860 3 cifs,nfsv4,nfs

$ ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue
link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
inet 127.0.0.1/8 scope host lo
valid_lft forever preferred_lft forever
inet6 ::1/128 scope host
valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast qlen 1000
link/ether fa:16:3e:de:1c:79 brd ff:ff:ff:ff:ff:ff
inet 10.254.0.3/29 brd 10.254.0.7 scope global eth0
valid_lft forever preferred_lft forever
inet6 fe80::f816:3eff:fede:1c79/64 scope link
valid_lft forever preferred_lft forever

$ sudo exportfs (when share access-allow is done in manila)
/shares/share-8b2d529a-0688-4a51-9641-9ee8d781380c
10.0.0.2

$ sudo exportfs (when share access-deny is done in manila)
$

$ dmesg | grep -i nfs
[ 5.306556] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 5.359405] FS-Cache: Netfs 'nfs' registered for caching
[ 5.494300] NFS: Registering the id_resolver key type
[ 5.570337] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
[ 15.823181] NFSD: the nfsdcld client tracking upcall will be removed in 3.10. Please transition to using nfsdcltrack.
[ 15.828906] NFSD: starting 90-second grace period (net ffffffff81cd2d00)
[ 136.033358] NFSD: Unable to end grace period: -110
[10856.545789] NFSD: Unable to create client record on stable storage: -110
[10913.633651] NFSD: Unable to create client record on stable storage: -110
[10964.832655] NFSD: Unable to create client record on stable storage: -110

[dpkshetty]

I also have the tcpdump data captured at the time of the mount hanging. If needed I can share the tcpdump raw binary data too. It gives the same conclusion that dmesg above gives... the client sends PUTROOTFH and hangs waiting for server to respond to it!

[dpkshetty]

With all the setup remaining same as above, I tried with 64bit NFS client now ...

From a NFS perspective:
cirros service VM image - 64bit - NFS server
Fedora20 cloud image as nova instance - 64bit - NFS client

Debug data for the case where manila access-deny was successfully executed:

[root@host-10-0-0-5 ~]# uname -a
Linux test-vm-fedora 3.11.10-301.fc20.x86_64 #1 SMP Thu Dec 5 14:01:17 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
c[root@host-10-0-0-5 ~]# cat /etc/issue
Fedora release 20 (Heisenbug)
Kernel \r on an \m (\l)

[root@host-10-0-0-5 ~]#

[root@host-10-0-0-5 ~]# lsmod | grep nfs
nfsv4 251490 0
dns_resolver 13096 1 nfsv4
nfs 169149 1 nfsv4
fscache 61532 2 nfs,nfsv4
nfsd 279847 1
auth_rpcgss 54254 1 nfsd
nfs_acl 12741 1 nfsd
lockd 93436 2 nfs,nfsd
sunrpc 253362 15 nfs,nfsd,auth_rpcgss,lockd,nfsv4,nfs_acl
[root@host-10-0-0-5 ~]#

[root@host-10-0-0-5 ~]# rpcdebug -m nfs all
nfs vfs dircache lookupcache pagecache proc xdr file root callback client mount fscache pnfs pnfs_ld state

[root@host-10-0-0-5 ~]# dmesg --clear

[root@host-10-0-0-5 ~]# mount -t nfs -vv -o vers=4 10.254.0.3:/shares/share-2df4b2a5-1bfa-486f-9a92-a7c35422193b /mnt
mount.nfs: timeout set for Fri Aug 8 12:04:39 2014
mount.nfs: trying text-based options 'vers=4,addr=10.254.0.3,clientaddr=10.0.0.5'
^C
[root@host-10-0-0-5 ~]# dmesg -T
[Fri Aug 8 12:02:38 2014] NFS: nfs mount opts='vers=4,addr=10.254.0.3,clientaddr=10.0.0.5'
[Fri Aug 8 12:02:38 2014] NFS: parsing nfs mount option 'vers=4'
[Fri Aug 8 12:02:38 2014] NFS: parsing nfs mount option 'addr=10.254.0.3'
[Fri Aug 8 12:02:38 2014] NFS: parsing nfs mount option 'clientaddr=10.0.0.5'
[Fri Aug 8 12:02:38 2014] NFS: MNTPATH: '/shares/share-2df4b2a5-1bfa-486f-9a92-a7c35422193b'
[Fri Aug 8 12:02:38 2014] --> nfs4_try_mount()
[Fri Aug 8 12:02:38 2014] --> nfs4_create_server()
[Fri Aug 8 12:02:38 2014] --> nfs4_init_server()
[Fri Aug 8 12:02:38 2014] --> nfs4_set_client()
[Fri Aug 8 12:02:38 2014] --> nfs_get_client(10.254.0.3,v4)
[Fri Aug 8 12:02:38 2014] NFS: get client cookie (0xffff8800036a9c00/0xffff880004d20050)
[Fri Aug 8 12:02:38 2014] nfs_callback_create_svc: service created
[Fri Aug 8 12:02:38 2014] NFS: create per-net callback data; net=ffffffff81cbdec0
[Fri Aug 8 12:02:38 2014] NFS: Callback listener port = 34727 (af 2, net ffffffff81cbdec0)
[Fri Aug 8 12:02:38 2014] NFS: Callback listener port = 33849 (af 10, net ffffffff81cbdec0)
[Fri Aug 8 12:02:39 2014] nfs_callback_up: service started
[Fri Aug 8 12:02:39 2014] NFS: nfs4_discover_server_trunking: testing '10.254.0.3'
[Fri Aug 8 12:02:39 2014] NFS call setclientid auth=UNIX, 'Linux NFSv4.0 10.0.0.5/10.254.0.3 tcp'
[Fri Aug 8 12:03:32 2014] NFS reply setclientid: -512
[Fri Aug 8 12:03:32 2014] NFS: nfs4_discover_server_trunking unhandled error -512. Exiting with error EIO
[Fri Aug 8 12:03:32 2014] NFS: nfs4_discover_server_trunking: status = -5
[Fri Aug 8 12:03:32 2014] --> nfs_put_client({1})
[Fri Aug 8 12:03:32 2014] NFS: destroy per-net callback data; net=ffffffff81cbdec0
[Fri Aug 8 12:03:32 2014] nfs_callback_down: service stopped
[Fri Aug 8 12:03:32 2014] nfs_callback_down: service destroyed
[Fri Aug 8 12:03:32 2014] --> nfs_free_client(4)
[Fri Aug 8 12:03:32 2014] NFS: releasing client cookie (0xffff8800036a9c00/0xffff880004d20050)
[Fri Aug 8 12:03:32 2014] <-- nfs_free_client()
[Fri Aug 8 12:03:32 2014] <-- nfs4_init_client() = xerror -5
[Fri Aug 8 12:03:32 2014] <-- nfs4_set_client() = xerror -5
[Fri Aug 8 12:03:32 2014] <-- nfs4_init_server() = -5
[Fri Aug 8 12:03:32 2014] --> nfs_free_server()
[Fri Aug 8 12:03:32 2014] <-- nfs_free_server()
[Fri Aug 8 12:03:32 2014] <-- nfs4_create_server() = error -5
[Fri Aug 8 12:03:32 2014] <-- nfs4_try_mount() = -5 [error]

[bswartz]

I'm wondering if this issue is something specific to do with NFSv4 and/or not having any shares at all. If I had 2 shares and I denied access to one of them, would I experience a timeout or an access denied when trying to access the it? It seems to me that having no shares at all might put the NFS server into a special state where it stops listening.

[bswartz]

If the above is true then the workaround would be to always share at least one directory -- presumably some empty, read-only directory.

[dpkshetty]

Valeiry had suggested similar and IIRC he himself later posted on IRC after testing with cirros image that have 1 share always present doesn't solve the problem. Per Valeriy, I tested in manila devstack context. As part of create-share I added a export for the share-server serving the same share to its own IP and access-allow adds another entry for that share to the instance IP, then when we do deny-access the instance IP entry is removed from exportfs (share server IP entry remains) and the problem (NFS client hang) did reproduce in this case too. So having 1 entry always doesn't seem to solve the issue.